Choppy audio delivery - Logs attached for review

Discussion in '3CX Phone System - General' started by sixteamparlay, Mar 24, 2010.

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

    Joined:
    Dec 2, 2009
    Messages:
    3
    Likes Received:
    0
    Could someone take a look at the below logs from Netborder Express and 3CX to see if there is a big problem that I am missing. Calls connect from the 3cx to pstn but they are often choppy, "PBX delivers audio" is not checked off for the pstn gateway, Thanks for any advice you can give:


    Choppy audio from 3CX to pstn, attached is a phone log from netborder express/Sangoma card:

    Please remember to put your logs into code and /code brackets- MFM
    Code:
    2010-03-24 15:54:53:654 [2128] INFO - netborder.infra.CallLogger.Appender : Call start : 03/24/10 15:54:53
    2010-03-24 15:54:53:654 [2128] INFO - netborder.sip.message : RECEIVED SIP MESSAGE (REQUEST) via UDP from 127.0.0.1:5060 :
    INVITE sip:7556@172.16.4.115:5066 SIP/2.0
    Via: SIP/2.0/UDP 127.0.0.1:5060;rport=5060;branch=z9hG4bK-d8754z-783ed06648599c51-1---d8754z-
    Max-Forwards: 70
    Contact: <sip:10000@127.0.0.1:5060>
    To: <sip:7556@172.16.4.115:5066>;tag=ds-3bf6-964e1570
    From: "Angelo Arroyo" <sip:10000>;tag=e704c561
    Call-ID: ZjUxNjBiMWE1ODkwMzNiNjUzYmY2N2M2ZGRhNWY5MmY.
    CSeq: 1 INVITE
    Allow: INVITE
    Allow: ACK
    Allow: CANCEL
    Allow: OPTIONS
    Allow: BYE
    Allow: REGISTER
    Allow: SUBSCRIBE
    Allow: NOTIFY
    Allow: REFER
    Allow: INFO
    Allow: MESSAGE
    Content-Type: application/sdp
    User-Agent: 3CXPhoneSystem 8.0.10100.0
    Content-Length: 262
    
    v=0
    o=3cxPS 120124866560 318465114113 IN IP4 127.0.0.1
    s=3cxPS Audio call
    c=IN IP4 127.0.0.1
    t=0 0
    m=audio 7686 RTP/AVP 8 0 101
    c=IN IP4 127.0.0.1
    a=rtpmap:8 PCMA/8000
    a=rtpmap:0 PCMU/8000
    a=rtpmap:101 telephone-event/8000
    a=fmtp:101 0-16
    a=sendrecv
    
    
    2010-03-24 15:54:53:654 [2116] INFO - netborder.cdr : Call started 03/24/10 15:54:53
    2010-03-24 15:54:53:654 [2116] INFO - netborder.cdr : SIP IN
    2010-03-24 15:54:53:655 [2128] INFO - netborder.sip.message : SENDING SIP MESSAGE (RESPONSE) via UDP to 127.0.0.1:5060 :
    SIP/2.0 100 Trying
    Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK-d8754z-783ed06648599c51-1---d8754z-;rport=5060
    From: "Angelo Arroyo" <sip:10000>;tag=e704c561
    To: <sip:7556@172.16.4.115:5066>;tag=ds-3bf6-964e1570
    Call-ID: ZjUxNjBiMWE1ODkwMzNiNjUzYmY2N2M2ZGRhNWY5MmY.
    CSeq: 1 INVITE
    Content-Length: 0
    Server: Netborder Express Gateway/1.6.3
    Contact: <sip:NetborderExpressGateway@172.16.4.115:5066;transport=udp>
    
    
    
    2010-03-24 15:54:53:656 [2260] INFO - netborder.media.jrtp.endpoint : ept-id=0 RTCP is enabled
    2010-03-24 15:54:53:903 [2128] INFO - netborder.cdr.voip : IN From Header= sip:10000
    2010-03-24 15:54:53:903 [2128] INFO - netborder.cdr.voip : IN To Header= sip:7556@172.16.4.115:5066
    2010-03-24 15:54:53:905 [2108] INFO - netborder.gw.routing.GWRoutingSession : ROUTING RESULT:
    1 RULE(S) FIRED
    Trying:
    - q-value=0.001   Rule name=default_pstn_out   RoutedLegInfo=sip.in.requestUri=sip:7556@172.16.4.115:5066
                                                                 sip.in.requestUri.canonical=sip:7556@172.16.4.115:5066
                                                                 sip.in.from.uri=sip:10000
                                                                 sip.in.from.uri.canonical=sip:10000
                                                                 sip.in.from.displayName="Angelo Arroyo"
                                                                 sip.in.to.uri=sip:7556@172.16.4.115:5066
                                                                 sip.in.to.uri.canonical=sip:7556@172.16.4.115:5066
                                                                 sip.in.to.displayName=
                                                                 sip.in.header.Via=SIP/2.0/UDP 127.0.0.1:5060;rport=5060;branch=z9hG4bK-d8754z-783ed06648599c51-1---d8754z-
                                                                 sip.in.header.CSeq=1 INVITE
                                                                 sip.in.header.Call-ID=ZjUxNjBiMWE1ODkwMzNiNjUzYmY2N2M2ZGRhNWY5MmY.
                                                                 sip.in.header.Content-Length=262
                                                                 sip.in.header.Contact=<sip:10000@127.0.0.1:5060>
                                                                 media.rtp.stream0=sendrecv
                                                                 transfer=false
                                                                 pstn.out.phoneNumber=7556
                                                                 pstn.out.deviceGroup=default
                                                                 pstn.out.cpa.enable=false
    2010-03-24 15:54:53:905 [2116] INFO - paraxip.cdr : PSTN OUT
    2010-03-24 15:54:53:906 [2132] INFO - paraxip.pstn.BidirStateMachine.s0-XYZspan0-c23 :  Using channelName "s0-XYZspan0-c23" for pstn out
    2010-03-24 15:54:53:906 [2132] INFO - paraxip.pstn.BidirStateMachine.s0-XYZspan0-c23 : pstn.out.phoneNumber = 7556
    2010-03-24 15:54:53:906 [2132] INFO - netborder.cdr.pstn : Outgoing Leg DNIS = 7556
    2010-03-24 15:54:53:906 [2132] INFO - netborder.cdr.pstn : Outgoing Leg ANI = unknown-ani
    2010-03-24 15:54:53:906 [2068] INFO - netborder.pstn.sangoma.isdn.message.s0-XYZspan0-c23 : TRANSMITTING ISDN MESSAGE via span 0
    SETUP
      Crv: 0x0001
      Codeset: 0
        BEARER_CAPABILITY         04 03 80 90 a2
        CHANNEL_IDENTIFICATION    18 03 a9 83 97
        CALLED_PARTY_NUMBER       70 05 80 37 35 35 36
    2010-03-24 15:54:53:930 [2076] INFO - netborder.pstn.sangoma.isdn.message.s0-XYZspan0-c23 : RECEIVING ISDN MESSAGE in LAPD PRIMITIVE DL_DA_IN via span 0
    CALL_PROCEEDING
      Crv: 0x8001
      Codeset: 0
        CHANNEL_IDENTIFICATION    18 03 a9 83 97
    2010-03-24 15:54:53:960 [2076] INFO - netborder.pstn.sangoma.isdn.message.s0-XYZspan0-c23 : RECEIVING ISDN MESSAGE in LAPD PRIMITIVE DL_DA_IN via span 0
    ALERTING
      Crv: 0x8001
      Codeset: 0
        PROGRESS_INDICATOR        1e 02 81 88
    2010-03-24 15:54:53:960 [2116] INFO - netborder.gw.CallLegWrapper : INLEG inviteAccepted
    2010-03-24 15:54:53:961 [2128] INFO - netborder.sip.message : SENDING SIP MESSAGE (RESPONSE) via UDP to 127.0.0.1:5060 :
    SIP/2.0 180 Ringing
    Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK-d8754z-783ed06648599c51-1---d8754z-;rport=5060
    From: "Angelo Arroyo" <sip:10000>;tag=e704c561
    To: <sip:7556@172.16.4.115:5066>;tag=ds-3bf6-964e1570
    Call-ID: ZjUxNjBiMWE1ODkwMzNiNjUzYmY2N2M2ZGRhNWY5MmY.
    CSeq: 1 INVITE
    Content-Length: 232
    Content-Type: application/sdp
    Server: Netborder Express Gateway/1.6.3
    Contact: <sip:NetborderExpressGateway@172.16.4.115:5066;transport=udp>
    
    v=0
    o=Paraxip-Tech 1269460493 1269460542 IN IP4 172.16.4.115
    s=SIP Call
    c=IN IP4 172.16.4.115
    t=0 0
    m=audio 14300 RTP/AVP 8 101
    a=rtpmap:8 pcma/8000
    a=rtpmap:101 telephone-event/8000
    a=fmtp:101 0-15
    a=ptime:20
    a=sendrecv
    
    
    2010-03-24 15:55:00:674 [2076] INFO - netborder.pstn.sangoma.isdn.message.s0-XYZspan0-c23 : RECEIVING ISDN MESSAGE in LAPD PRIMITIVE DL_DA_IN via span 0
    CONNECT
      Crv: 0x8001
      Codeset: 0
        PROGRESS_INDICATOR        1e 02 81 82
        CONNECTED_NUMBER          4c 06 a1 37 37 35 35 36
      Codeset: 6
        DISPLAY                   28 0e 4b 6f 77 61 6c 73 6b 69 2c 20 47 65 6e 65
    2010-03-24 15:55:00:674 [2076] INFO - netborder.pstn.sangoma.isdn.message.s0-XYZspan0-c23 : TRANSMITTING ISDN MESSAGE via span 0
    CONNECT_ACKNOWLEDGE
      Crv: 0x0001
    2010-03-24 15:55:00:674 [2116] INFO - netborder.gw.CallLegWrapper : INLEG remoteConnected : NOTENABLED_CONNECT
    2010-03-24 15:55:00:674 [2116] INFO - paraxip.cdr : Call Connected 03/24/10 15:55:00
    2010-03-24 15:55:00:674 [2128] INFO - netborder.sip.message : SENDING SIP MESSAGE (RESPONSE) via UDP to 127.0.0.1:5060 :
    SIP/2.0 200 Ok
    Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK-d8754z-783ed06648599c51-1---d8754z-;rport=5060
    From: "Angelo Arroyo" <sip:10000>;tag=e704c561
    To: <sip:7556@172.16.4.115:5066>;tag=ds-3bf6-964e1570
    Call-ID: ZjUxNjBiMWE1ODkwMzNiNjUzYmY2N2M2ZGRhNWY5MmY.
    CSeq: 1 INVITE
    Content-Length: 232
    Content-Type: application/sdp
    Contact: <sip:NetborderExpressGateway@172.16.4.115:5066;transport=udp>
    Server: Netborder Express Gateway/1.6.3
    
    v=0
    o=Paraxip-Tech 1269460493 1269460543 IN IP4 172.16.4.115
    s=SIP Call
    c=IN IP4 172.16.4.115
    t=0 0
    m=audio 14300 RTP/AVP 8 101
    a=rtpmap:8 pcma/8000
    a=rtpmap:101 telephone-event/8000
    a=fmtp:101 0-15
    a=ptime:20
    a=sendrecv
    
    
    2010-03-24 15:55:00:778 [1652] INFO - netborder.sip.message : RECEIVED SIP MESSAGE (REQUEST) via UDP from 127.0.0.1:5060 :
    ACK sip:NetborderExpressGateway@172.16.4.115:5066;transport=udp SIP/2.0
    Via: SIP/2.0/UDP 127.0.0.1:5060;rport=5060;branch=z9hG4bK-d8754z-7f417f62250cb448-1---d8754z-
    Max-Forwards: 70
    Contact: <sip:10000@127.0.0.1:5060>
    To: <sip:7556@172.16.4.115:5066>;tag=ds-3bf6-964e1570
    From: "Angelo Arroyo" <sip:10000>;tag=e704c561
    Call-ID: ZjUxNjBiMWE1ODkwMzNiNjUzYmY2N2M2ZGRhNWY5MmY.
    CSeq: 1 ACK
    User-Agent: 3CXPhoneSystem 8.0.10100.0
    Content-Length: 0
    
    
    
    2010-03-24 15:55:10:059 [1652] INFO - netborder.sip.message : RECEIVED SIP MESSAGE (REQUEST) via UDP from 127.0.0.1:5060 :
    BYE sip:NetborderExpressGateway@172.16.4.115:5066;transport=udp SIP/2.0
    Via: SIP/2.0/UDP 127.0.0.1:5060;rport=5060;branch=z9hG4bK-d8754z-177f8048fd2d0a53-1---d8754z-
    Max-Forwards: 70
    Contact: <sip:10000@127.0.0.1:5060>
    To: <sip:7556@172.16.4.115:5066>;tag=ds-3bf6-964e1570
    From: "Angelo Arroyo" <sip:10000>;tag=e704c561
    Call-ID: ZjUxNjBiMWE1ODkwMzNiNjUzYmY2N2M2ZGRhNWY5MmY.
    CSeq: 2 BYE
    User-Agent: 3CXPhoneSystem 8.0.10100.0
    Content-Length: 0
    
    
    
    2010-03-24 15:55:10:059 [2128] INFO - netborder.sip.message : SENDING SIP MESSAGE (RESPONSE) via UDP to 127.0.0.1:5060 :
    SIP/2.0 200 Ok
    Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK-d8754z-177f8048fd2d0a53-1---d8754z-;rport=5060
    From: "Angelo Arroyo" <sip:10000>;tag=e704c561
    To: <sip:7556@172.16.4.115:5066>;tag=ds-3bf6-964e1570
    Call-ID: ZjUxNjBiMWE1ODkwMzNiNjUzYmY2N2M2ZGRhNWY5MmY.
    CSeq: 2 BYE
    Content-Length: 0
    
    
    
    2010-03-24 15:55:10:060 [2128] INFO - netborder.voip.StateMachine.In : sip call ended 03/24/10 15:55:10
    2010-03-24 15:55:10:060 [2116] INFO - netborder.gw.CallLegWrapper : INLEG hungup
    2010-03-24 15:55:10:060 [2116] INFO - netborder.gw.CallLegWrapper : OUTLEG : hanging up
    2010-03-24 15:55:10:060 [2116] INFO - netborder.cdr : Call ended 03/24/10 15:55:10
    2010-03-24 15:55:10:060 [2260] INFO - netborder.media.jrtp.endpoint : ept-id=0 RTP Stats
    Sent     805 packet(s)
    Received 215 packet(s)
    
    2010-03-24 15:55:10:061 [2068] INFO - netborder.pstn.sangoma.isdn.message.s0-XYZspan0-c23 : TRANSMITTING ISDN MESSAGE via span 0
    DISCONNECT
      Crv: 0x0001
      Codeset: 0
        CAUSE                     08 02 80 95
    2010-03-24 15:55:10:061 [2212] INFO - netborder.media.hostmedia.jitterBuffer : , ept-id=1269460493-950243-15574-454 
    Statistics
    ----------
    Number byte(s) written: 34400
    Number byte(s) read   : 128800
    Number silence byte(s): 93600
    Number dropped byte(s)
    due to overruns       : 6720
    Number dropped byte(s)
    due to late packets   : 0
    Number underrun(s)    : 12
    Number overrun(s)     : 10
    
    2010-03-24 15:55:10:061 [2260] INFO - netborder.media.hostmedia.jitterBuffer : , ept-id=1269460493-653360-32616-453 
    Statistics
    ----------
    Number byte(s) written: 128800
    Number byte(s) read   : 128800
    Number silence byte(s): 0
    Number dropped byte(s)
    due to overruns       : 0
    Number underrun(s)    : 0
    Number overrun(s)     : 0
    
    2010-03-24 15:55:10:083 [2076] INFO - netborder.pstn.sangoma.isdn.message.s0-XYZspan0-c23 : RECEIVING ISDN MESSAGE in LAPD PRIMITIVE DL_DA_IN via span 0
    RELEASE
      Crv: 0x8001
    2010-03-24 15:55:10:083 [2076] INFO - netborder.pstn.sangoma.isdn.message.s0-XYZspan0-c23 : TRANSMITTING ISDN MESSAGE via span 0
    RELEASE_COMPLETE
      Crv: 0x0001
    2010-03-24 15:58:10:064 [3412] INFO - netborder.infra.CallLogger.Appender : Call end : 03/24/10 15:58:10

    --------------------------------------
    the 3CX activity log for the same call:

    Code:
    15:55:09.950  [CM503008]: Call(176): Call is terminated
    15:55:00.669  [CM503007]: Call(176): Device joined: sip:10000@172.16.4.115:5066
    15:55:00.669  [CM503007]: Call(176): Device joined: sip:7730@172.16.10.30:5060
    15:54:53.950  [CM503002]: Call(176): Alerting sip:10000@172.16.4.115:5066
    15:54:53.606  [CM503025]: Call(176): Calling Unknown:7556@(Ln.10000@PSTNGATEWAY)@[Dev:sip:10000@172.16.4.115:5066]
    15:54:53.559  [CM503004]: Call(176): Route 1: Unknown:7556@(Ln.10000@PSTNGATEWAY)@[Dev:sip:10000@172.16.4.115:5066]
    15:54:53.543  [CM503010]: Making route(s) to <sip:7556@pbx.gntrad.local>
    15:54:53.543  [CM505001]: Ext.7730: Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [Slnk/12] PBX contact: [sip:7730@172.16.4.115:5060]
    15:54:53.543  [CM503001]: Call(176): Incoming call from Ext.7730 to <sip:7556@pbx.gntrad.local>
     
  2. mfm

    mfm Active Member

    Joined:
    Mar 4, 2010
    Messages:
    641
    Likes Received:
    2
    If you switch off PBX delivers audio does the situation improve?
     
    Stop hovering to collapse... Click to collapse... Hover to expand... Click to expand...
  3. SY

    SY Well-Known Member
    3CX Support

    Joined:
    Jan 26, 2007
    Messages:
    1,825
    Likes Received:
    2
    The verbose level of logs is required for troubleshooting.
    Please set it (verbose level of logs) and restart 3CX Phone system service (sorry for inconvenience). Then replicate problematic call and post new logs here.

    Thanks
     
    Stop hovering to collapse... Click to collapse... Hover to expand... Click to expand...
Thread Status:
Not open for further replies.