One way audio

[mposse]

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

 

[mposse]

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:[email protected]:5060
00:48:41.689 [CM503007]: Call(3): Device joined: sip:[email protected]: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:[email protected]:5060]
00:48:40.533 [CM503002]: Call(3): Alerting sip:[email protected]:5060
00:48:38.314 [CM503025]: Call(3): Calling VoIPline:13015289816@(Ln.10000@Gafachi)@[Dev:sip:[email protected]:5060]
00:48:37.986 [CM503004]: Call(3): Route 1: VoIPline:13015289816@(Ln.10000@Gafachi)@[Dev:sip:[email protected]:5060]
00:48:37.971 [CM503010]: Making route(s) to <sip:[email protected]: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:[email protected]:5060]
00:48:37.971 [CM503001]: Call(3): Incoming call from Ext.100 to <sip:[email protected]:5060>

 

[nb]

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.

 

[leejor]

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?

 

[mposse]

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!

 

[SY]

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

 

[mposse]

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||??arametersUpdated:=====[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||??artyAddrRTP_ is set to 127.0.0.1:10102
18:07:57.937|.\MSEndPoint.cpp(1692)|Trace5||??artyAddrRTCP_ 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=silenceSuppff - - - -
a=ptime:20

18:08:00.577|.\MSEndPoint.cpp(2949)|Trace5||??:New state00000002@ SILENCE
18:08:00.577|.\MSEndPoint.cpp(1691)|Trace5||??artyAddrRTP_ is set to 67.216.38.5:30004
18:08:00.577|.\MSEndPoint.cpp(1692)|Trace5||??artyAddrRTCP_ 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=silenceSuppff - - - -
a=ptime:20

18:08:01.905|.\MSEndPoint.cpp(2949)|Trace5||??:New state00000002@ SILENCE
18:08:01.905|.\MSEndPoint.cpp(1691)|Trace5||??artyAddrRTP_ is set to 67.216.38.5:30004
18:08:01.905|.\MSEndPoint.cpp(1692)|Trace5||??artyAddrRTCP_ 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

 

[SY]

Sorry, but you see everything what was provided by PBX

18:08:00.577|.\MediaServer.cpp(850)|Trace5||
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

There is no correlation with

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)

Do you have any additional information?

Thanks

 

[mposse]

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.

 

[SY]

m=audio 9000 RTP/AVP 3 0 8 101

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"

 

[mposse]

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!!!!