Wrong data Lenght in payload

[ktikoft]

Hi I am trying to recive calls from an ip tel provider mynetphone and since upgrading to the new version it goes nuts on the call with the below error message what does the error mean ?? My outbound calls are ok and I think it was ok until i put on the new version 3.1.2434.0 up from the July release

14:52:58.046 MediaServerReporting::RTPReceiver [MS005001] Call(45) Ln:10001@MyNetPhone: Wrong data length 50 for payload 98
14:52:58.015 MediaServerReporting::RTPReceiver [MS005001] Call(45) Ln:10001@MyNetPhone: Wrong data length 50 for payload 98
14:52:57.984 MediaServerReporting::RTPReceiver [MS005001] Call(45) Ln:10001@MyNetPhone: Wrong data length 50 for payload 98
14:52:57.828 CallLegImpl:nConnected [CM103001] Call(45): Created audio channel for Ln:10001@MyNetPhone (125.213.160.71:16556) with Media Server (203.49.229.154:41056)
14:52:57.703 CallConf:nIncoming [CM103002] Call(45): Incoming call from 0283383400 (Ln:10001@MyNetPhone) to sip:[email protected]:41041
14:51:11.265 StratLink:nHangUp [CM104001] Call(44): Ext.3460 hung up call; cause: BYE; from IP:10.0.2.4
14:51:08.062 CallLegImpl:nConnected [CM103001] Call(44): Created audio channel for Ln:10001@MyNetPhone (125.213.160.71:14916) with Media Server (203.49.229.154:41042)
14:51:08.031 StratInOut:nConnected [CM104005] Call(44): Setup completed for call from Ext.3460 to Ln:10001@MyNetPhone
14:51:08.031 CallLegImpl:nConnected [CM103001] Call(44): Created audio channel for Ext.3460 (10.0.2.4:5004) with Media Server (10.0.0.31:7108)
14:51:04.250 CallConf:nProvisional [CM103003] Call(44): Ln:10001@MyNetPhone is ringing
14:51:03.328 CallConf:nIncoming [CM103002] Call(44): Incoming call from 3460 (Ext.3460) to sip:[email protected]

 

[SY]

Please provide detailed log for this call, I need to check SIP messages content. SIP messages will be printed in 3CXPhoneSystem.trace.log if logging level will be set to "Verbose (only used for debugging purposes)"

Right now I can just say that there is incorrect interpretation of iLBC codec parameters. Log will show who is a culprit.

 

[ktikoft]

See log of call destination is 3460 call is from


10:17:50.484|c:\svn\src\pbxserver\ServerSubscr.h(142)|Trace5|MessageSubscription|MessageSubscribeHandler:nRefreshnRefresh
10:17:50.484|c:\svn\src\pbxserver\ServerSubscr.h(162)|Trace5|MessageSubscription|MessageSubscribeHandler:nReadyToSendnReadyToSend
10:17:50.484|c:\svn\src\pbxserver\ServerSubscr.h(162)|Trace5|MessageSubscription|MessageSubscribeHandler:nReadyToSendnReadyToSend
10:17:50.671|DialogUsageManager.cxx(1190)|Trace5|Resip|>>:Got: SipResp: 200 tid=551d1f7e71771201 cseq=NOTIFY [email protected]:19608 / 11 from(wire)
10:17:51.343|.\CAHandler.cpp(252)|Trace5||CAHandler::setStatus:[CM102005] CA request setStatus(dn=3460, status=0)
10:17:51.343|.\CAHandler.cpp(252)|Trace5||CAHandler::setStatus:[CM102005] CA request setStatus(dn=3461, status=2)
10:18:04.375|TuSelector.cxx(70)|Trace5|Resip|>>:Stats message
10:18:26.796|.\Endpoint.cpp(91)|Trace5|Endpoint|Endpoint::findSource:No Remote-Party-ID header found
10:18:26.843|.\Endpoint.cpp(111)|Trace5|Endpoint|Endpoint::findSource:Lines Is here
10:18:26.843|.\Endpoint.cpp(126)|Trace5|Endpoint|Endpoint::findSource:Only one lines is here
10:18:26.843|.\Endpoint.cpp(132)|Trace5|Endpoint|Endpoint::findSource:Settings for caller is found: CfgExtLine:10001
10:18:26.843|DialogUsageManager.cxx(1190)|Trace5|Resip|>>:Got: SipReq: INVITE [email protected]:5060 tid=17dd5a05146ba5cec-ccb01-0 cseq=INVITE [email protected]:5060 / 838401 from(wire)
10:18:26.843|.\CallMgr.cpp(349)|Trace5|CallControl|ADSFactory::createAppDialogSet:Creating ADS for INVITE
10:18:26.843|.\CallConf.cpp(506)|Trace5|CallControl|CallConf::CallConf:Call created: 42
10:18:26.843|.\CallConf.cpp(445)|Trace5|CallControl|CallConf::addCallLeg:Added leg# 1 to call 42
10:18:26.843|.\Call.cpp(1381)|Trace5|CallControl|CallLegImpl::CallLegImpl:Leg @L:1@C:2a is created
10:18:26.843|InviteSession.cxx(2046)|Trace5|Resip|>>:Transition UAS_Start -> UAS_Offer
10:18:26.843|.\ISHandler.cpp(21)|Trace5|CallControl|ISHandler:nNewSession:Incoming: sis=436;oat=Offer;rl=INVITE sip:[email protected]:5060;user=phone SIP/2.0
10:18:26.843|.\Endpoint.cpp(91)|Trace5|Endpoint|Endpoint::findSource:No Remote-Party-ID header found
10:18:26.890|.\Endpoint.cpp(111)|Trace5|Endpoint|Endpoint::findSource:Lines Is here
10:18:26.890|.\Endpoint.cpp(126)|Trace5|Endpoint|Endpoint::findSource:Only one lines is here
10:18:26.890|.\Endpoint.cpp(132)|Trace5|Endpoint|Endpoint::findSource:Settings for caller is found: CfgExtLine:10001
10:18:26.890|.\Call.cpp(125)|Trace5|CallControl|CallLegImpl:nIncoming:Endpoint is built: Ln:10001@MyNetPhone
10:18:27.265|.\Call.cpp(693)|Trace5|CallControl|CallLegImpl::initMSEndpoint:Created external MS endpoint for Ln:10001@MyNetPhone: addr=203.49.229.154:43297
10:18:27.265|ServerInviteSession.cxx(91)|Trace5|Resip|>>:UAS_Offer: provisional(100)
10:18:27.265|InviteSession.cxx(2046)|Trace5|Resip|>>:Transition UAS_Offer -> UAS_EarlyOffer
10:18:27.265|.\ISHandler.cpp(140)|Trace5|CallControl|ISHandler:nReadyToSend:InviteSession(436) sends SIP/2.0 100 Trying
10:18:27.265|.\CallConf.cpp(120)|Log2|CallControl|CallConf:nIncoming:[CM103002] Call(42): Incoming call from 0283383400 (Ln:10001@MyNetPhone) to sip:[email protected]:43209
10:18:27.265|.\CallStrategies.cpp(439)|Trace5|CallManager|StratInOut::initialize:Initialize InOut call strategy
10:18:27.296|.\ExtLine.cpp(250)|Trace5|Endpoints|ExtLine::getTargetOverride:Look for target override
10:18:27.312|.\Call.cpp(693)|Trace5|CallControl|CallLegImpl::initMSEndpoint:Created internal MS endpoint for Ext.3460: addr=10.0.0.31:7146
10:18:27.312|.\CallConf.cpp(445)|Trace5|CallControl|CallConf::addCallLeg:Added leg# 2 to call 42
10:18:27.312|.\Call.cpp(1381)|Trace5|CallControl|CallLegImpl::CallLegImpl:Leg 3460@L:2@C:2a is created
10:18:27.328|.\CallConf.cpp(132)|Trace5|CallControl|CallConf:nIncoming:MediaServer could be used for this call
10:18:27.328|.\ISHandler.cpp(157)|Trace5|CallControl|ISHandler:nOffer:Offered: is=436; rl=INVITE sip:[email protected]:5060;user=phone SIP/2.0
10:18:27.328|.\CallStrategies.cpp(643)|Trace5|CallManager|StratInOut:nOffer:InOut: got offer from 10001@L:1@C:2a
10:18:27.328|.\CallEvents.cpp(78)|Trace5||FireStatusEvent:Fire event: Calling; DN 10001
10:18:27.390|DialogUsageManager.cxx(1190)|Trace5|Resip|>>:Got: SipResp: 100 tid=52229655233ff871 cseq=INVITE / 1 from(wire)
10:18:27.390|DialogUsageManager.cxx(1190)|Trace5|Resip|>>:Got: SipResp: 180 tid=52229655233ff871 cseq=INVITE [email protected]:5060 / 1 from(wire)
10:18:27.390|Dialog.cxx(547)|Trace5|Resip|>>ialog::dispatch, ignoring stray response: SipResp: 180 tid=52229655233ff871 cseq=INVITE [email protected]:5060 / 1 from(wire)
10:18:27.390|InviteSession.cxx(2046)|Trace5|Resip|>>:Transition UAC_Start -> UAC_Early
10:18:27.390|.\ISHandler.cpp(31)|Trace5|CallControl|ISHandler:nNewSession:Answered: sis=439;oat=None;rl=SIP/2.0 180 Ringing
10:18:27.390|.\CallStrategies.cpp(598)|Trace5|CallManager|StratInOut:nAnswered:Call from Ln:10001@MyNetPhone is answered on Ext.3460
10:18:27.390|.\CallTarget.cpp(81)|Trace5|CallManager|CT_Simple::answered:Call is accepted on: Contact=[<sip:[email protected]:5060;transport=udp>]; From="0283383400"<sip:[email protected]>;tag=86126165
10:18:27.390|.\CallEvents.cpp(78)|Trace5||FireStatusEvent:Fire event: Ringing; DN 3460
10:18:27.406|ClientInviteSession.cxx(315)|Trace5|Resip|>>:UAC_Early: startStaleCallTimer
10:18:27.406|.\ISHandler.cpp(57)|Trace5|CallControl|ISHandler:nProvisionalrovisional: cis=439;rl=SIP/2.0 180 Ringing
10:18:27.406|.\CallConf.cpp(178)|Log2|CallControl|CallConf:nProvisional:[CM103003] Call(42): Ext.3460 is ringing
10:18:27.406|.\CallStrategies.cpp(658)|Trace5|CallManager|StratInOut:nProvisional:InOut: got provisional SIP/2.0 180 Ringing from 3460@L:2@C:2a
10:18:27.406|.\CallEvents.cpp(78)|Trace5||FireStatusEvent:Fire event: Calling; DN 10001
10:18:27.406|.\CallEvents.cpp(78)|Trace5||FireStatusEvent:Fire event: Ringing; DN 3460
10:18:27.406|ServerInviteSession.cxx(91)|Trace5|Resip|>>:UAS_EarlyOffer: provisional(180)
10:18:27.406|InviteSession.cxx(2046)|Trace5|Resip|>>:Transition UAS_EarlyOffer -> UAS_EarlyOffer
10:18:27.406|.\ISHandler.cpp(140)|Trace5|CallControl|ISHandler:nReadyToSend:InviteSession(436) sends SIP/2.0 180 Ringing
10:18:29.656|DialogUsageManager.cxx(1190)|Trace5|Resip|>>:Got: SipResp: 200 tid=52229655233ff871 cseq=INVITE [email protected]:5060 / 1 from(wire)
10:18:29.656|Dialog.cxx(547)|Trace5|Resip|>>ialog::dispatch, ignoring stray response: SipResp: 200 tid=52229655233ff871 cseq=INVITE [email protected]:5060 / 1 from(wire)
10:18:29.656|InviteSession.cxx(2046)|Trace5|Resip|>>:Transition UAC_Early -> InviteSession::Connected
10:18:29.656|InviteSession.cxx(2343)|Trace5|Resip|>>:Sending SipReq: ACK [email protected]:5060 tid=694437580a11445e cseq=ACK [email protected]:5060 / 1 from(tu)
10:18:29.656|.\ISHandler.cpp(140)|Trace5|CallControl|ISHandler:nReadyToSend:InviteSession(439) sends ACK sip:[email protected]:5060;transport=udp SIP/2.0
10:18:29.656|.\ISHandler.cpp(149)|Trace5|CallControl|ISHandler:nAnswer:Answered: is=439; rl=SIP/2.0 200 OK
10:18:29.656|.\CallStrategies.cpp(669)|Trace5|CallManager|StratInOut:nAnswer:InOut: got answer from 3460@L:2@C:2a
10:18:29.656|.\Call.cpp(1209)|Trace5|CallControl|CallLegImpl:rovideAnswerrovide answer (MS) to 10001@L:1@C:2a
10:18:29.656|ServerInviteSession.cxx(251)|Trace5|Resip|>>:UAS_EarlyOffer: provideAnswer
10:18:29.656|InviteSession.cxx(2046)|Trace5|Resip|>>:Transition UAS_EarlyOffer -> UAS_EarlyProvidedAnswer
10:18:29.656|ServerInviteSession.cxx(443)|Trace5|Resip|>>:UAS_EarlyProvidedAnswer: accept(200)
10:18:29.656|InviteSession.cxx(2046)|Trace5|Resip|>>:Transition UAS_EarlyProvidedAnswer -> UAS_Accepted
10:18:29.656|.\ISHandler.cpp(140)|Trace5|CallControl|ISHandler:nReadyToSend:InviteSession(436) sends SIP/2.0 200 OK
10:18:29.656|.\ISHandler.cpp(74)|Trace5|CallControl|ISHandler:nConnected:ConnectedUAS: is=436;rl=SIP/2.0 200 OK
10:18:29.656|.\Call.cpp(253)|Trace5|CallControl|CallLegImpl:nConnected:Connected: 10001@L:1@C:2a
10:18:29.656|.\CallStrategies.cpp(684)|Trace5|CallManager|StratInOut:nConnected:InOut: got Connected from 10001@L:1@C:2a
10:18:29.656|.\Call.cpp(266)|Log2|CallControl|CallLegImpl:nConnected:[CM103001] Call(42): Created audio channel for Ln:10001@MyNetPhone (125.213.160.71:17006) with Media Server (203.49.229.154:43297)
10:18:29.656|.\ISHandler.cpp(65)|Trace5|CallControl|ISHandler:nConnected:ConnectedUAC: cis=439;rl=SIP/2.0 200 OK
10:18:29.656|.\Call.cpp(253)|Trace5|CallControl|CallLegImpl:nConnected:Connected: 3460@L:2@C:2a
10:18:29.656|.\CallStrategies.cpp(684)|Trace5|CallManager|StratInOut:nConnected:InOut: got Connected from 3460@L:2@C:2a
10:18:29.671|.\CallStrategies.cpp(705)|Log2|CallManager|StratInOut:nConnected:[CM104005] Call(42): Setup completed for call from Ln:10001@MyNetPhone to Ext.3460
10:18:29.687|.\CallEvents.cpp(78)|Trace5||FireStatusEvent:Fire event: Connected; DN 10001
10:18:29.687|.\CallEvents.cpp(78)|Trace5||FireStatusEvent:Fire event: Connected; DN 3460
10:18:29.687|.\CallConf.cpp(463)|Trace5|CallControl|CallConf::changeStrategy:Call 42 changes strategy CS.InOut to CS.Link
10:18:29.687|.\CallStrategies.cpp(908)|Trace5|CallManager|StratInOut::~StratInOut:InOut: strategy is terminated
10:18:29.687|.\Call.cpp(266)|Log2|CallControl|CallLegImpl:nConnected:[CM103001] Call(42): Created audio channel for Ext.3460 (10.0.2.4:5004) with Media Server (10.0.0.31:7146)
10:18:29.687|.\Call.cpp(287)|Trace5|CallControl|CallLegImpl:nConnCfmd:ConnCfmd: 3460@L:2@C:2a
10:18:29.843|DialogUsageManager.cxx(1190)|Trace5|Resip|>>:Got: SipReq: ACK [email protected]:5060 tid=17dd5a05146ba5cec-ccb01-1 cseq=ACK / 838401 from(wire)
10:18:29.843|DialogUsageManager.cxx(1516)|Trace5|Resip|>>:Handling in-dialog request: SipReq: ACK [email protected]:5060 tid=17dd5a05146ba5cec-ccb01-1 cseq=ACK / 838401 from(wire)
10:18:29.843|ServerInviteSession.cxx(684)|Trace5|Resip|>>:dispatchAccepted: SipReq: ACK [email protected]:5060 tid=17dd5a05146ba5cec-ccb01-1 cseq=ACK / 838401 from(wire)
10:18:29.843|InviteSession.cxx(2046)|Trace5|Resip|>>:Transition UAS_Accepted -> InviteSession::Connected
10:18:29.843|.\ISHandler.cpp(82)|Trace5|CallControl|ISHandler:nConnectedConfirmed:ConnCfmd: is=436;rl=ACK sip:[email protected]:5060 SIP/2.0
10:18:29.843|.\Call.cpp(287)|Trace5|CallControl|CallLegImpl:nConnCfmd:ConnCfmd: 10001@L:1@C:2a
10:18:29.921|.\MSInterface.cpp(589)|Trace5||??:MSLogReports
10:18:29.921|.\SLServer.cpp(311)|Critical0|MediaServer|MediaServerReporting::RTPReceiver:[MS005001] Call(42) Ln:10001@MyNetPhone: Wrong data length 50 for payload 98

 

[SY]

Sorry, but it is not verbose level of log. I need a SIP messages.

So
1. open Logging level on Genesral settings Page and check which log level is currently set. if "verbose" then - switch it to "Medium" and press Ok.
(There will be Message box, just pross Ok on it).
2. Switch Logging level back to verbose and press Ok.
3. Restart 3CX PhoneSystem Service.
4. Make you call.
5. Open 3CXPhoneSystem.trace.log and post it here (or send me on e-mail specified in private message

Thanks,
Stepan

 

[ktikoft]

Thansk I have posted to you email

 

[SY]

Thansk I have posted to you email

I have answered it.

Since 2328 release PBX provides support for iLBC and SPEEX codec. Previous version didn't support them and used only PCMU/PCMA for this gateway(VoIP provider). So you have a choice to configure your gateway to don't use iLBC codec , or force it to use just one mode of iLBC.

Regards,
Stepan

 

[ktikoft]

Thanks Stephan

Are you saying the provider is sending the wrong codec?

I am using mynetphone nd the setup suggested i should be using g729 could this be the base cause of the issue. I am only in prelim setup at the moment but i thought it worked int he previous release ?

 

[SY]

Thanks Stephan

Are you saying the provider is sending the wrong codec?

Yes. Did provider comment this situation?

I am using mynetphone nd the setup suggested i should be using g729 could this be the base cause of the issue. I am only in prelim setup at the moment but i thought it worked int he previous release ?

If iLBC is listed in SDP then it can be used.
We don't support g729.

 

[Anonymous]

Ktikoft,

I hope this now sorted?

Being a customer of mine, feel free to contact me directly (24x7) you have my contact details (mobile) and have access to the direct support email with 3CX as well.


Thanks.