One way audio

Discussion in '3CX Phone System - General' started by mposse, Feb 9, 2010.

Thread Status:
Not open for further replies.
  1. mposse

    Joined:
    Feb 9, 2010
    Messages:
    7
    Likes Received:
    0
    Hi All
    I am experiencing a problem and was hoping the community would have an answer.
    We have set up a Phone System and 2 SoftPhones (all 3CX) and configured our router with the appropriate forwarding.
    The firewall checked returns all success.
    We can make calls between extensions with no problems but when calling an external number, we can hear the recipient, but they can't hear us.
    After a lot of searching, I guess I will post the question here to see if someone has a good idea where to continue troubleshooting.

    Thanks in advance for any help

    Regards,
    Martin
     
  2. mposse

    Joined:
    Feb 9, 2010
    Messages:
    7
    Likes Received:
    0
    Just to complete a bit my last post, here is the server status log while I am running a test

    00:49:06.548 [CM503008]: Call(3): Call is terminated
    00:48:41.689 [CM503007]: Call(3): Device joined: sip:a10047saOU6XEwWA@67.216.35.162:5060
    00:48:41.689 [CM503007]: Call(3): Device joined: sip:100@127.0.0.1:3988;rinstance=5705b772fcb49f2e
    00:48:40.533 [CM505003]: Provider:[Gafachi] Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [] PBX contact: [sip:a10047saOU6XEwWA@200.68.91.65:5060]
    00:48:40.533 [CM503002]: Call(3): Alerting sip:a10047saOU6XEwWA@67.216.35.162:5060
    00:48:38.314 [CM503025]: Call(3): Calling VoIPline:13015289816@(Ln.10000@Gafachi)@[Dev:sip:a10047saOU6XEwWA@67.216.35.162:5060]
    00:48:37.986 [CM503004]: Call(3): Route 1: VoIPline:13015289816@(Ln.10000@Gafachi)@[Dev:sip:a10047saOU6XEwWA@67.216.35.162:5060]
    00:48:37.971 [CM503010]: Making route(s) to <sip:913015289816@192.168.0.10:5060>
    00:48:37.971 [CM505001]: Ext.100: Device info: Device Identified: [Man: 3CX Ltd.;Mod: 3CXVoipPhone;Rev: General] Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [3CXVoipPhone 4.0.9878.0] PBX contact: [sip:100@127.0.0.1:5060]
    00:48:37.971 [CM503001]: Call(3): Incoming call from Ext.100 to <sip:913015289816@192.168.0.10:5060>
     
  3. nb

    nb Support Team
    Staff Member 3CX Support

    Joined:
    Jun 7, 2007
    Messages:
    2,097
    Likes Received:
    142
    Through what are you calling the external recipient?

    What is the entity, voip provider, gateway / ISDN/Analog?

    You will need to specify make, model or provider company so I get an idea of where to start.
     
    Stop hovering to collapse... Click to collapse... Hover to expand... Click to expand...
  4. leejor

    leejor Well-Known Member

    Joined:
    Jan 22, 2008
    Messages:
    10,375
    Likes Received:
    231
    Usually the one way audio is the other way around, the 3Cx can't hear the VoIP caller because the router/firewall is blocking some incoming ports, which routers are very good at doing. Obviously, in this case, something is preventing the voice packets from getting out to your VoIP provider.

    I would try connecting the computer running 3CX directly to your modem, bypassing the router. This would give it a public IP (just for a short test). See if it makes a difference, if you do get voice both ways then you know it is a problem that your router is causing. What make/model router are you using?
     
  5. mposse

    Joined:
    Feb 9, 2010
    Messages:
    7
    Likes Received:
    0
    Hi
    Thanks for taking time to look at my post.
    I just spoke with Gafachi (VoIP provider) and they traced a test call.
    They tell me that the server is announcing voice to come in a given port (35461) and it is actually sending it in a different port (33413)

    The call is initiated by a 3CX softphone to a land line

    The caller can hear but the recipient can't.

    Hope that helps.

    Thanks a lot!
     
  6. SY

    SY Well-Known Member
    3CX Support

    Joined:
    Jan 26, 2007
    Messages:
    1,825
    Likes Received:
    2
    Please provide log for the specified call scenario.
    3CXmediaserver.trace.log reports everything about audio negotiations.
    Step by step procedure.
    1. Set verbose level of log
    2. Drop all active calls.
    3. restart only media server service
    4. after 5-10 seconds, replicate call scenario specified above

    post 3cxmediaserver.trace.log here (it is quite small)

    It will help us to avoid any kind of miscommunications

    Thanks
     
    Stop hovering to collapse... Click to collapse... Hover to expand... Click to expand...
  7. mposse

    Joined:
    Feb 9, 2010
    Messages:
    7
    Likes Received:
    0
    Ok, here is what I've got from the log.

    2010/02/09 >>
    18:06:58.218|.\MediaServer.cpp(428)|Log2||??:The number of RTP senders is set to 4
    18:06:58.218|.\MediaServer.cpp(447)|Log2||??:RTP sender[0]: use default thread settings
    18:06:58.218|.\MediaServer.cpp(447)|Log2||??:RTP sender[1]: use default thread settings
    18:06:58.218|.\MediaServer.cpp(447)|Log2||??:RTP sender[2]: use default thread settings
    18:06:58.218|.\MediaServer.cpp(447)|Log2||??:RTP sender[3]: use default thread settings
    18:06:58.233|.\RTPSender.cpp(195)|Trace5||??:RTPSenders::RTPSenders: size=4
    18:06:58.233|.\RTPSender.cpp(53)|Trace5||??:RTPSender::RTPSender[0]: Enter
    18:06:58.233|.\RTPSender.cpp(58)|Trace5||??:RTPSender::RTPSender[0]: Timer Created
    18:06:58.233|.\RTPSender.cpp(61)|Trace5||??:RTPSender::RTPSender[0]: thread created
    18:06:58.233|.\RTPSender.cpp(72)|Trace5||??:RTPSender::RTPSender[0]: Done
    18:06:58.233|.\RTPSender.cpp(207)|Trace5||??:RTPSenders::RTPSenders: sender[0] is valid
    18:06:58.233|.\RTPSender.cpp(209)|Trace5||??:RTPSenders::RTPSenders: sender[0] added
    18:06:58.233|.\RTPSender.cpp(53)|Trace5||??:RTPSender::RTPSender[1]: Enter
    18:06:58.233|.\RTPSender.cpp(58)|Trace5||??:RTPSender::RTPSender[1]: Timer Created
    18:06:58.233|.\RTPSender.cpp(61)|Trace5||??:RTPSender::RTPSender[1]: thread created
    18:06:58.233|.\RTPSender.cpp(72)|Trace5||??:RTPSender::RTPSender[1]: Done
    18:06:58.233|.\RTPSender.cpp(207)|Trace5||??:RTPSenders::RTPSenders: sender[1] is valid
    18:06:58.233|.\RTPSender.cpp(209)|Trace5||??:RTPSenders::RTPSenders: sender[1] added
    18:06:58.233|.\RTPSender.cpp(53)|Trace5||??:RTPSender::RTPSender[2]: Enter
    18:06:58.233|.\RTPSender.cpp(58)|Trace5||??:RTPSender::RTPSender[2]: Timer Created
    18:06:58.233|.\RTPSender.cpp(61)|Trace5||??:RTPSender::RTPSender[2]: thread created
    18:06:58.233|.\RTPSender.cpp(72)|Trace5||??:RTPSender::RTPSender[2]: Done
    18:06:58.233|.\RTPSender.cpp(207)|Trace5||??:RTPSenders::RTPSenders: sender[2] is valid
    18:06:58.233|.\RTPSender.cpp(209)|Trace5||??:RTPSenders::RTPSenders: sender[2] added
    18:06:58.233|.\RTPSender.cpp(53)|Trace5||??:RTPSender::RTPSender[3]: Enter
    18:06:58.233|.\RTPSender.cpp(58)|Trace5||??:RTPSender::RTPSender[3]: Timer Created
    18:06:58.233|.\RTPSender.cpp(61)|Trace5||??:RTPSender::RTPSender[3]: thread created
    18:06:58.233|.\RTPSender.cpp(72)|Trace5||??:RTPSender::RTPSender[3]: Done
    18:06:58.233|.\RTPSender.cpp(207)|Trace5||??:RTPSenders::RTPSenders: sender[3] is valid
    18:06:58.233|.\RTPSender.cpp(209)|Trace5||??:RTPSenders::RTPSenders: sender[3] added
    18:06:58.233|.\MediaServer.cpp(345)|Log2||??:The number of RTP receivers is set to 8
    18:06:58.233|.\MediaServer.cpp(365)|Log2||??:RTP receiver[0]: use default thread settings
    18:06:58.233|.\MediaServer.cpp(365)|Log2||??:RTP receiver[1]: use default thread settings
    18:06:58.233|.\MediaServer.cpp(365)|Log2||??:RTP receiver[2]: use default thread settings
    18:06:58.233|.\MediaServer.cpp(365)|Log2||??:RTP receiver[3]: use default thread settings
    18:06:58.249|.\MediaServer.cpp(365)|Log2||??:RTP receiver[4]: use default thread settings
    18:06:58.249|.\MediaServer.cpp(365)|Log2||??:RTP receiver[5]: use default thread settings
    18:06:58.249|.\MediaServer.cpp(365)|Log2||??:RTP receiver[6]: use default thread settings
    18:06:58.249|.\MediaServer.cpp(365)|Log2||??:RTP receiver[7]: use default thread settings
    18:06:58.265|.\Service.cpp(274)|Log2||??:*** Initialize ***
    18:06:58.327|.\Service.cpp(350)|Log2||??:*** Start Server ***
    18:06:58.327|.\Service.cpp(109)|Log2||??:*** Listen ***
    18:06:58.327|.\Service.cpp(125)|Log2||??:*** Connecting to [127.0.0.1:5482] ***
    18:06:58.343|.\Service.cpp(136)|Log2||??:*** Connected to dc5:5482/CallManager at 127.0.0.1:5482 ***
    18:06:58.421|.\Service.cpp(177)|Trace5||??:parametersUpdated:=====[003FA1A8]
    STUN=ARRAY
    [0]=stun.3cx.com:3478
    [1]=stun.3cx.com:3478
    ADD2833=1
    ANSP=0
    CS=62914560
    EXTADDR=
    EXTIF=
    FEP=9000
    FLP=7000
    LEP=9049
    LLP=7499
    LOCALADDR=
    MCFS=5242880
    MOH=C:\Documents and Settings\All Users\Application Data\3CX\Data\Ivr\Prompts\onhold.mp3
    MS_BLINDEXTPORTS=0
    MUSICONHOLDFILE=onhold.mp3
    STUNTOUT=3000
    TOS=0
    allowExternalOn=0.0.0.0/0
    allowSourceAsOutbound=0
    externalIPRange=
    reportSourceConflicts=0
    =================================

    18:06:58.436|.\MMFileReader.cpp(18)|Trace5||??:CoInitializeEx called for thread 4964.Returned value 0x0
    18:07:56.874|.\MSEndPoint.cpp(760)|Trace5||??:00000001@: RTP bind address 127.0.0.1:7000
    18:07:56.874|.\MSEndPoint.cpp(771)|Trace5||??:00000001@: RTCP bind address 127.0.0.1:7001
    18:07:57.921|.\MediaServer.cpp(815)|Trace5||??:EndPoint created: (destination=127.0.0.1)
    EndPoint: ID=00000001@(LOCAL)
    LOGID=C:22.1 Status: MSEP_LOCAL
    RTP:127.0.0.1:7000
    RTCP:127.0.0.1:7001
    STUN RTP:0.0.0.0:0
    STUN RTCP:0.0.0.0:0
    Coder:
    NOT SET
    101:telephony-event
    Party ptime:20
    Party RTP:0.0.0.0:0
    Party RTCP:0.0.0.0:0
    Decoders:
    <empty>

    18:07:57.921|.\MediaServer.cpp(1260)|Trace5||??:EP 00000001@ joined to call 22
    18:07:57.921|.\MediaServer.cpp(1269)|Trace5||??:starting send on new call 22
    18:07:57.937|.\MediaServer.cpp(912)|Trace5||??:Set Party EP:C:22.1SDP:v=0
    o=3cxVCE 310501440 324624120 IN IP4 127.0.0.1
    s=3cxVCE Audio Call
    c=IN IP4 127.0.0.1
    t=0 0
    m=audio 10102 RTP/AVP 8 3 0 101
    a=rtpmap:8 PCMA/8000
    a=rtpmap:3 GSM/8000
    a=rtpmap:0 PCMU/8000
    a=rtpmap:101 telephone-event/8000
    a=fmtp:101 0-15
    a=ptime:20
    a=sendrecv

    18:07:57.937|.\MSEndPoint.cpp(2949)|Trace5||??:New state00000001@ SILENCE
    18:07:57.937|.\MSEndPoint.cpp(1691)|Trace5||??:partyAddrRTP_ is set to 127.0.0.1:10102
    18:07:57.937|.\MSEndPoint.cpp(1692)|Trace5||??:partyAddrRTCP_ is set to 127.0.0.1:10103
    18:07:57.937|.\MSEndPoint.cpp(1914)|Log2||??:[MS210000] C:22.1:Offer received. RTP connection: 127.0.0.1:10102(10103)
    18:07:58.280|.\MSEndPoint.cpp(1007)|Trace5||??:Source ports: 9000 STUN RTP:200.68.91.65:9000 RTCP:200.68.91.65:9001 mapped to 200.68.91.65, ports 9000,9001
    18:07:58.280|.\MediaServer.cpp(815)|Trace5||??:EndPoint created: (destination=67.216.35.162)
    EndPoint: ID=00000002@(EXTERNAL)
    LOGID=C:22.2 Status: MSEP_STUN
    RTP:200.68.91.65:9000
    RTCP:200.68.91.65:9001
    STUN RTP:200.68.91.65:9000
    STUN RTCP:200.68.91.65:9001
    Coder:
    NOT SET
    101:telephony-event
    Party ptime:20
    Party RTP:0.0.0.0:0
    Party RTCP:0.0.0.0:0
    Decoders:
    <empty>

    18:07:58.280|.\MediaServer.cpp(1260)|Trace5||??:EP 00000002@ joined to call 22
    18:07:58.280|.\MediaServer.cpp(1305)|Trace5||??:EndPoint 00000002@ removed from call 22
    18:07:58.280|.\MediaServer.cpp(1260)|Trace5||??:EP 00000002@ joined to call 22
    18:07:58.280|.\MSEndPoint.cpp(1403)|Log2||??:[MS210002] C:22.2:Offer provided. Connection(transcoding mode): 200.68.91.65:9000(9001)
    18:07:58.280|.\MediaServer.cpp(850)|Trace5||??:Get Local SDP. EP:C:22.2SDP:v=0
    o=3cxPS 285699211264 305697652737 IN IP4 200.68.91.65
    s=3cxPS Audio call
    c=IN IP4 200.68.91.65
    t=0 0
    m=audio 9000 RTP/AVP 3 0 8 101
    c=IN IP4 200.68.91.65
    a=rtpmap:3 GSM/8000
    a=rtpmap:0 PCMU/8000
    a=rtpmap:8 PCMA/8000
    a=rtpmap:101 telephone-event/8000
    a=sendrecv

    18:07:58.280|.\MediaServer.cpp(1305)|Trace5||??:EndPoint 00000002@ removed from call 22
    18:08:00.577|.\MediaServer.cpp(1260)|Trace5||??:EP 00000002@ joined to call 22
    18:08:00.577|.\MediaServer.cpp(912)|Trace5||??:Set Party EP:C:22.2SDP:v=0
    o=root 1417540109 1417540109 IN IP4 67.216.38.5
    s=session
    c=IN IP4 67.216.38.5
    t=0 0
    m=audio 30004 RTP/AVP 0 101
    a=rtpmap:0 PCMU/8000
    a=rtpmap:101 telephone-event/8000
    a=fmtp:101 0-15
    a=silenceSupp:eek:ff - - - -
    a=ptime:20

    18:08:00.577|.\MSEndPoint.cpp(2949)|Trace5||??:New state00000002@ SILENCE
    18:08:00.577|.\MSEndPoint.cpp(1691)|Trace5||??:partyAddrRTP_ is set to 67.216.38.5:30004
    18:08:00.577|.\MSEndPoint.cpp(1692)|Trace5||??:partyAddrRTCP_ is set to 67.216.38.5:30005
    18:08:00.577|.\MSEndPoint.cpp(2949)|Trace5||??:New state00000002@ ACTIVE
    18:08:00.577|.\MSEndPoint.cpp(1919)|Log2||??:[MS210001] C:22.2:Answer received. RTP connection[unsecure]: 67.216.38.5:30004(30005)
    18:08:00.577|.\MSEndPoint.cpp(2949)|Trace5||??:New state00000001@ ACTIVE
    18:08:00.577|.\MSEndPoint.cpp(2949)|Trace5||??:New state00000002@ ACTIVE
    18:08:00.577|.\MSEndPoint.cpp(1408)|Log2||??:[MS210003] C:22.1:Answer provided. Connection(transcoding mode[unsecure]):127.0.0.1:7000(7001)
    18:08:00.577|.\MediaServer.cpp(850)|Trace5||??:Get Local SDP. EP:C:22.1SDP:v=0
    o=3cxPS 224059719680 224160382977 IN IP4 127.0.0.1
    s=3cxPS Audio call
    c=IN IP4 127.0.0.1
    t=0 0
    m=audio 7000 RTP/AVP 8 3 0 101
    c=IN IP4 127.0.0.1
    a=rtpmap:8 PCMA/8000
    a=rtpmap:3 GSM/8000
    a=rtpmap:0 PCMU/8000
    a=rtpmap:101 telephone-event/8000
    a=fmtp:101 0-15
    a=sendrecv

    18:08:00.890|.\MSEndPoint.cpp(2142)|Trace5||??:EP:00000002@ refreshed
    18:08:01.905|.\MediaServer.cpp(912)|Trace5||??:Set Party EP:C:22.2SDP:v=0
    o=root 1417540109 1417540110 IN IP4 67.216.38.5
    s=session
    c=IN IP4 67.216.38.5
    t=0 0
    m=audio 30004 RTP/AVP 0 101
    a=rtpmap:0 PCMU/8000
    a=rtpmap:101 telephone-event/8000
    a=fmtp:101 0-15
    a=silenceSupp:eek:ff - - - -
    a=ptime:20

    18:08:01.905|.\MSEndPoint.cpp(2949)|Trace5||??:New state00000002@ SILENCE
    18:08:01.905|.\MSEndPoint.cpp(1691)|Trace5||??:partyAddrRTP_ is set to 67.216.38.5:30004
    18:08:01.905|.\MSEndPoint.cpp(1692)|Trace5||??:partyAddrRTCP_ is set to 67.216.38.5:30005
    18:08:01.905|.\MSEndPoint.cpp(2949)|Trace5||??:New state00000002@ ACTIVE
    18:08:01.905|.\MSEndPoint.cpp(1919)|Log2||??:[MS210001] C:22.2:Answer received. RTP connection[unsecure]: 67.216.38.5:30004(30005)
    18:08:01.937|.\MSEndPoint.cpp(2135)|Trace5||??:resynchronization. timediff:544
    18:08:01.937|.\MSEndPoint.cpp(2142)|Trace5||??:EP:00000002@ refreshed
    18:08:02.687|.\MSEndPoint.cpp(2142)|Trace5||??:EP:00000001@ refreshed
    18:08:26.156|.\MediaServer.cpp(1305)|Trace5||??:EndPoint 00000001@ removed from call 22
    18:08:26.156|.\MediaServer.cpp(1305)|Trace5||??:EndPoint 00000002@ removed from call 22
    18:08:26.156|.\MediaServer.cpp(1065)|Trace5||??:references to EndPoint 00000001@ were removed
    18:08:26.359|.\MSEndPoint.cpp(847)|Trace5||??:EndPoint 00000001@ destroyed
    18:08:26.359|.\MSEndPoint.cpp(848)|Trace5||??:EndPoint 00000001@ destroyed statistics:
    Begin send:687231062
    LastSent:687256625
    TotalSent:1278
    MaxSendInterval:47
    MinSendInterval:0
    AvgSendInterval:20.0023
    SendDeviation:7.15996
    Begin recv:687233203
    Last recv:687256593
    TotalRecv:1171
    MaxRecvInterval:110
    MinRecvInterval:0
    AvgRecvInterval:19.9744
    ReceiveDeviation:25.4669

    18:08:26.453|.\MediaServer.cpp(1065)|Trace5||??:references to EndPoint 00000002@ were removed
    18:08:26.468|.\MediaServer.cpp(1383)|Trace5||??:references to call 22 were removed
    18:08:26.468|.\MSCallConf.cpp(36)|Trace5||??:Call: 22 destroyed
    18:08:27.859|.\MSEndPoint.cpp(847)|Trace5||??:EndPoint 00000002@ destroyed
    18:08:27.859|.\MSEndPoint.cpp(848)|Trace5||??:EndPoint 00000002@ destroyed statistics:
    Begin send:687231078
    LastSent:687256609
    TotalSent:1277
    MaxSendInterval:47
    MinSendInterval:0
    AvgSendInterval:19.9929
    SendDeviation:7.15668
    Begin recv:687232406
    Last recv:687256625
    TotalRecv:1211
    MaxRecvInterval:47
    MinRecvInterval:0
    AvgRecvInterval:19.9992
    ReceiveDeviation:10.8623
     
  8. SY

    SY Well-Known Member
    3CX Support

    Joined:
    Jan 26, 2007
    Messages:
    1,825
    Likes Received:
    2
    Sorry, but you see everything what was provided by PBX
    There is no correlation with
    Do you have any additional information?

    Thanks
     
    Stop hovering to collapse... Click to collapse... Hover to expand... Click to expand...
  9. mposse

    Joined:
    Feb 9, 2010
    Messages:
    7
    Likes Received:
    0
    200.68.91.65 is the address where the PBX box is (behind it actually)
    The ports I guess would change every time?

    67.216.35.162 is the provider the line is connected to.

    I don't know how to read the log, so I don't know what your comment means, nor I understand what Gafachi told me.
    They said that, when I placed the test call (yesterday before opening the post), they were able to see that the PBX presented the call and indicated that the audio was coming in one port, yet when the server actually sent the audio, it came through a different port and their system dropped the packets. Which makes sense, as I can hear the people in the other end, but they can't hear me.

    I noticed the following segments in the log. Do they seems wrong to you?

    c=IN IP4 67.216.38.5
    t=0 0
    m=audio 30004 RTP/AVP 0 101

    c=IN IP4 127.0.0.1
    t=0 0
    m=audio 7000 RTP/AVP 8 3 0 101

    Now, if the media server is doing it's job right, could it be that the firewall is changing the ports? I have to note though, that the firewall checker returns all tests successful.
    So, if not the media server, nor the firewall. Do anyone has any idea what could be happening?

    Thanks again!

    Martin.
     
  10. SY

    SY Well-Known Member
    3CX Support

    Joined:
    Jan 26, 2007
    Messages:
    1,825
    Likes Received:
    2
    Highlighted number is the port which (together with address) was resolved by media server using STUN server and was specified in SDP content of INVITE request sent to your VoIP provider.
    I have no idea why VoIP provider see 35461 at this place of the (SDP) text as well as I don't know why your firewall sends traffic (provided by media server from port 9000 of PBX host) using external port 33413.

    Thanks

    P.S. Sorry if my information is too "cryptic" :)
     
    Stop hovering to collapse... Click to collapse... Hover to expand... Click to expand...
  11. mposse

    Joined:
    Feb 9, 2010
    Messages:
    7
    Likes Received:
    0
    Re: RESOLVED - One way audio

    Guys, thank you very much for all your help
    I found the problem on the basic settings of my Linksys Gateway.
    It has an option called SIP Application Layer Gateway that I had enabled. I found information that indicate it should be disabled if I am using STUN to resolve the sip calls.
    As soon as I disabled it, it started working fine.
    I hope this helps someone else having the same problem.

    Thanks a lot!!!!
     
Thread Status:
Not open for further replies.