Wrong data Lenght in payload

Discussion in '3CX Phone System - General' started by ktikoft, Aug 8, 2007.

  1. ktikoft

    Joined:
    Jun 22, 2007
    Messages:
    59
    Likes Received:
    0
    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::eek: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::eek:nIncoming [CM103002] Call(45): Incoming call from 0283383400 (Ln:10001@MyNetPhone) to sip:09103140@10.0.0.31:41041
    14:51:11.265 StratLink::eek:nHangUp [CM104001] Call(44): Ext.3460 hung up call; cause: BYE; from IP:10.0.2.4
    14:51:08.062 CallLegImpl::eek: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::eek:nConnected [CM104005] Call(44): Setup completed for call from Ext.3460 to Ln:10001@MyNetPhone
    14:51:08.031 CallLegImpl::eek: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::eek:nProvisional [CM103003] Call(44): Ln:10001@MyNetPhone is ringing
    14:51:03.328 CallConf::eek:nIncoming [CM103002] Call(44): Incoming call from 3460 (Ext.3460) to sip:00283383414@10.0.0.31
     
  2. SY

    SY Well-Known Member
    3CX Staff

    Joined:
    Jan 26, 2007
    Messages:
    1,821
    Likes Received:
    1
    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. :)
     
  3. ktikoft

    Joined:
    Jun 22, 2007
    Messages:
    59
    Likes Received:
    0
    See log of call destination is 3460 call is from


    10:17:50.484|c:\svn\src\pbxserver\ServerSubscr.h(142)|Trace5|MessageSubscription|MessageSubscribeHandler::eek:nRefresh:eek:nRefresh
    10:17:50.484|c:\svn\src\pbxserver\ServerSubscr.h(162)|Trace5|MessageSubscription|MessageSubscribeHandler::eek:nReadyToSend:eek:nReadyToSend
    10:17:50.484|c:\svn\src\pbxserver\ServerSubscr.h(162)|Trace5|MessageSubscription|MessageSubscribeHandler::eek:nReadyToSend:eek:nReadyToSend
    10:17:50.671|DialogUsageManager.cxx(1190)|Trace5|Resip|>>:Got: SipResp: 200 tid=551d1f7e71771201 cseq=NOTIFY contact=3461@10.0.2.10: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 09103140@10.0.0.31:5060 tid=17dd5a05146ba5cec-ccb01-0 cseq=INVITE contact=0283383400@125.213.160.81: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::eek:nNewSession:Incoming: sis=436;oat=Offer;rl=INVITE sip:09103140@10.0.0.31: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::eek: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::eek:nReadyToSend:InviteSession(436) sends SIP/2.0 100 Trying
    10:18:27.265|.\CallConf.cpp(120)|Log2|CallControl|CallConf::eek:nIncoming:[CM103002] Call(42): Incoming call from 0283383400 (Ln:10001@MyNetPhone) to sip:09103140@10.0.0.31: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::eek:nIncoming:MediaServer could be used for this call
    10:18:27.328|.\ISHandler.cpp(157)|Trace5|CallControl|ISHandler::eek:nOffer:Offered: is=436; rl=INVITE sip:09103140@10.0.0.31:5060;user=phone SIP/2.0
    10:18:27.328|.\CallStrategies.cpp(643)|Trace5|CallManager|StratInOut::eek: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 contact=3460@10.0.2.4:5060 / 1 from(wire)
    10:18:27.390|Dialog.cxx(547)|Trace5|Resip|>>:Dialog::dispatch, ignoring stray response: SipResp: 180 tid=52229655233ff871 cseq=INVITE contact=3460@10.0.2.4: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::eek:nNewSession:Answered: sis=439;oat=None;rl=SIP/2.0 180 Ringing
    10:18:27.390|.\CallStrategies.cpp(598)|Trace5|CallManager|StratInOut::eek: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:3460@10.0.2.4:5060;transport=udp>]; From="0283383400"<sip:0283383400@sip00.mynetphone.com.au>;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::eek:nProvisional:provisional: cis=439;rl=SIP/2.0 180 Ringing
    10:18:27.406|.\CallConf.cpp(178)|Log2|CallControl|CallConf::eek:nProvisional:[CM103003] Call(42): Ext.3460 is ringing
    10:18:27.406|.\CallStrategies.cpp(658)|Trace5|CallManager|StratInOut::eek: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::eek: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 contact=3460@10.0.2.4:5060 / 1 from(wire)
    10:18:29.656|Dialog.cxx(547)|Trace5|Resip|>>:Dialog::dispatch, ignoring stray response: SipResp: 200 tid=52229655233ff871 cseq=INVITE contact=3460@10.0.2.4: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 3460@10.0.2.4:5060 tid=694437580a11445e cseq=ACK contact=0283383400@10.0.0.31:5060 / 1 from(tu)
    10:18:29.656|.\ISHandler.cpp(140)|Trace5|CallControl|ISHandler::eek:nReadyToSend:InviteSession(439) sends ACK sip:3460@10.0.2.4:5060;transport=udp SIP/2.0
    10:18:29.656|.\ISHandler.cpp(149)|Trace5|CallControl|ISHandler::eek:nAnswer:Answered: is=439; rl=SIP/2.0 200 OK
    10:18:29.656|.\CallStrategies.cpp(669)|Trace5|CallManager|StratInOut::eek:nAnswer:InOut: got answer from 3460@L:2@C:2a
    10:18:29.656|.\Call.cpp(1209)|Trace5|CallControl|CallLegImpl::provideAnswer:provide 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::eek:nReadyToSend:InviteSession(436) sends SIP/2.0 200 OK
    10:18:29.656|.\ISHandler.cpp(74)|Trace5|CallControl|ISHandler::eek:nConnected:ConnectedUAS: is=436;rl=SIP/2.0 200 OK
    10:18:29.656|.\Call.cpp(253)|Trace5|CallControl|CallLegImpl::eek:nConnected:Connected: 10001@L:1@C:2a
    10:18:29.656|.\CallStrategies.cpp(684)|Trace5|CallManager|StratInOut::eek:nConnected:InOut: got Connected from 10001@L:1@C:2a
    10:18:29.656|.\Call.cpp(266)|Log2|CallControl|CallLegImpl::eek: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::eek:nConnected:ConnectedUAC: cis=439;rl=SIP/2.0 200 OK
    10:18:29.656|.\Call.cpp(253)|Trace5|CallControl|CallLegImpl::eek:nConnected:Connected: 3460@L:2@C:2a
    10:18:29.656|.\CallStrategies.cpp(684)|Trace5|CallManager|StratInOut::eek:nConnected:InOut: got Connected from 3460@L:2@C:2a
    10:18:29.671|.\CallStrategies.cpp(705)|Log2|CallManager|StratInOut::eek: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::eek: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::eek:nConnCfmd:ConnCfmd: 3460@L:2@C:2a
    10:18:29.843|DialogUsageManager.cxx(1190)|Trace5|Resip|>>:Got: SipReq: ACK 09103140@10.0.0.31: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 09103140@10.0.0.31:5060 tid=17dd5a05146ba5cec-ccb01-1 cseq=ACK / 838401 from(wire)
    10:18:29.843|ServerInviteSession.cxx(684)|Trace5|Resip|>>:dispatchAccepted: SipReq: ACK 09103140@10.0.0.31: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::eek:nConnectedConfirmed:ConnCfmd: is=436;rl=ACK sip:09103140@10.0.0.31:5060 SIP/2.0
    10:18:29.843|.\Call.cpp(287)|Trace5|CallControl|CallLegImpl::eek: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
     
  4. SY

    SY Well-Known Member
    3CX Staff

    Joined:
    Jan 26, 2007
    Messages:
    1,821
    Likes Received:
    1
    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
     
  5. ktikoft

    Joined:
    Jun 22, 2007
    Messages:
    59
    Likes Received:
    0
    Thansk I have posted to you email
     
  6. SY

    SY Well-Known Member
    3CX Staff

    Joined:
    Jan 26, 2007
    Messages:
    1,821
    Likes Received:
    1
    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
     
  7. ktikoft

    Joined:
    Jun 22, 2007
    Messages:
    59
    Likes Received:
    0
    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 ?
     
  8. SY

    SY Well-Known Member
    3CX Staff

    Joined:
    Jan 26, 2007
    Messages:
    1,821
    Likes Received:
    1
    Yes. Did provider comment this situation?

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

    Anonymous Guest

    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.
     

Share This Page