Delay in audio start for queues (and only queues)

Discussion in '3CX Phone System - General' started by millsey, Feb 24, 2012.

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

    millsey New Member

    Joined:
    Dec 21, 2011
    Messages:
    187
    Likes Received:
    0
    Hi

    If we dial our Reception audio starts immediately when they pick up. If I dial a group they are in, when they answer the audio does not work for around 1 to 1.5 seconds, I can hear the call has been answered (the MOH stops) but the first part of the conversation is lost.

    Is there a known cause or configuration which causes this? It happens for both inside and outside queue calls.

    Thanks
    Millsey
     
  2. leejor

    leejor Well-Known Member

    Joined:
    Jan 22, 2008
    Messages:
    10,356
    Likes Received:
    224
    You don't say what type of sets are involved, or if it happens on more than one type.
    A similar issue cropped up previously when using Yealink sets.

    http://www.3cx.com/forums/queue-answer-delay-9040.html#p93262
     
  3. millsey

    millsey New Member

    Joined:
    Dec 21, 2011
    Messages:
    187
    Likes Received:
    0
    Sorry,

    We are all Grandstream GXP2100. I have tried all sorts of different configs, changing codecs etc etc. The silence is compelte - no background noise or anything. I have just tried the beta Grandstream firmware which was very buggy but at least I know the same problem is there.

    Thanks
    Millsey
     
  4. leejor

    leejor Well-Known Member

    Joined:
    Jan 22, 2008
    Messages:
    10,356
    Likes Received:
    224
    Does the timeline of a call(verbose mode), in the 3CX log offer any explanation?
     
  5. millsey

    millsey New Member

    Joined:
    Dec 21, 2011
    Messages:
    187
    Likes Received:
    0
    I can see in the log the delay - this log snipped in reverse time order from when the phone is picked up, 89.0.5.0 is my desk phone. I don't really understand much of this log..


    13:20:01.069 [CM503008]: Call(2807): Call is terminated
    13:19:59.260 [CM503007]: Call(2807): Device joined: sip:103@89.0.5.0:5060;user=phone
    13:19:59.256 [CM503008]: Call(2808): Call is terminated
    13:19:59.251 [MS210003] C:2807.3:Answer provided. Connection(transcoding mode[unsecure]):89.0.3.1:7462(7463)
    13:19:59.251 [MS210002] C:2807.1:Offer provided. Connection(transcoding mode): 86.188.246.34:9006(9007)
    13:19:59.232 [MS210000] C:2807.3:Offer received. RTP connection: 89.0.5.0:5004(5005)
    13:19:59.231 Remote SDP is set for legC:2807.3
    13:19:59.231 [CM505001]: Ext.103: Device info: Device Identified: [Man: GrandStream;Mod: GXP series;Rev: General] Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [Grandstream GXP2100 1.0.1.110] PBX contact: [sip:103@89.0.3.1:5060]
    13:19:59.231 [CM503002]: Call(2807): Alerting sip:103@89.0.5.0:5060;user=phone
    13:19:58.468 [CM503025]: Call(2807): Calling @[Dev:sip:103@89.0.5.0:5060;user=phone]
    13:19:58.434 [CM505003]: Provider:[NODE4] Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [] PBX contact: [sip:1@86.188.246.34:5060]
    13:19:58.434 Replaces: C:2808.2
    13:19:58.434 Refer: from=<sip:820@127.0.0.1>;tag=df2fa02b; to="BM TEST:+447980586770"<sip:+447980586770@127.0.0.1:5060;nf=e>;tag=606d732b; RefTo=<sip:103@127.0.0.1:5060;nofwd=1;tag3cx=1365-TJLEFXFFTV?Replaces=MDlmMjNiNjJkMWU2OTNiOTljZWY3ZjY3ZTliOTIzNmI.%3Bto-tag%3D475ca379%3Bfrom-tag%3D7160e227>;tag=475ca379
    13:19:58.428 Session 405142 of leg C:2808.1 is confirmed
    13:19:58.208 [CM503007]: Call(2808): Device joined: sip:103@89.0.5.0:5060;user=phone
    13:19:58.206 [CM503007]: Call(2808): Device joined: sip:820@127.0.0.1:5488
    13:19:58.203 [MS210005] C:2808.1:Answer provided. Connection(proxy mode):127.0.0.1:7458(7459)
    13:19:58.201 [MS210001] C:2808.2:Answer received. RTP connection[unsecure]: 89.0.5.0:5004(5005)
    13:19:58.199 Remote SDP is set for legC:2808.2
     
  6. millsey

    millsey New Member

    Joined:
    Dec 21, 2011
    Messages:
    187
    Likes Received:
    0
    And another one,

    There seems to be an 0.8 second pause between the phone pickeing up and the call actually commencing;

    4:10:06.728 [CM503008]: Call(1): Call is terminated
    14:10:04.093 [CM503008]: Call(2): Call is terminated
    14:10:04.056 [CM503007]: Call(1): Device joined: sip:103@89.0.5.0:5060;user=phone
    14:10:04.053 [MS210003] C:1.3:Answer provided. Connection(transcoding mode[unsecure]):89.0.3.1:7006(7007)
    14:10:04.052 [MS210002] C:1.1:Offer provided. Connection(transcoding mode): 86.188.246.34:9000(9001)
    14:10:04.050 [MS210000] C:1.3:Offer received. RTP connection: 89.0.5.0:5004(5005)
    14:10:04.049 Remote SDP is set for legC:1.3
    14:10:04.049 [CM505001]: Ext.103: Device info: Device Identified: [Man: GrandStream;Mod: GXP series;Rev: General] Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [Grandstream GXP2100 1.0.1.110] PBX contact: [sip:103@89.0.3.1:5060]
    14:10:04.049 [CM503002]: Call(1): Alerting sip:103@89.0.5.0:5060;user=phone
    14:10:03.239 [CM503025]: Call(1): Calling @[Dev:sip:103@89.0.5.0:5060;user=phone]

    14:10:03.181 [CM505003]: Provider:[NODE4] Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [] PBX contact: [sip:1@86.188.246.34:5060]
    14:10:03.181 Replaces: C:2.2
    14:10:03.181 Refer: from=<sip:820@127.0.0.1>;tag=22239061; to="BM TEST:+447980586770"<sip:+447980586770@127.0.0.1:5060;nf=e>;tag=0013d27c; RefTo=<sip:103@127.0.0.1:5060;nofwd=1;tag3cx=2-HVACNHTHTS?Replaces=NmE0MTIyZmVhMzIzODlmYzFlNWRiODZmYmVmNDRlNjM.%3Bto-tag%3D8f7b1867%3Bfrom-tag%3Dcd0d9c15>;tag=8f7b1867
    14:10:03.176 Session 986 of leg C:2.1 is confirmed
    14:10:03.025 [CM503007]: Call(2): Device joined: sip:103@89.0.5.0:5060;user=phone
    14:10:03.024 [CM503007]: Call(2): Device joined: sip:820@127.0.0.1:5488
    14:10:03.021 [MS210005] C:2.1:Answer provided. Connection(proxy mode):127.0.0.1:7002(7003)
    14:10:03.019 [MS210001] C:2.2:Answer received. RTP connection[unsecure]: 89.0.5.0:5004(5005)
    14:10:03.018 Remote SDP is set for legC:2.2
    14:09:57.230 [CM505001]: Ext.103: Device info: Device Identified: [Man: GrandStream;Mod: GXP series;Rev: General] Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [Grandstream GXP2100 1.0.1.110] PBX contact: [sip:103@89.0.3.1:5060]
    14:09:57.230 [CM503002]: Call(2): Alerting sip:103@89.0.5.0:5060;user=phone
    14:09:57.053 [CM503025]: Call(2): Calling Ext:Ext.103@[Dev:sip:103@89.0.5.0:5060;user=phone]
    14:09:57.051 [MS210004] C:2.2:Offer provided. Connection(proxy mode): 89.0.3.1:7004(7005)
    14:09:57.005 [CM503004]: Call(2): Route 1: Ext:Ext.103@[Dev:sip:103@89.0.5.0:5060;user=phone]
    14:09:57.004 [CM503010]: Making route(s) to <sip:103@127.0.0.1:5060;nofwd=1;tag3cx=2-HVACNHTHTS>
    14:09:57.004 [MS210000] C:2.1:Offer received. RTP connection: 127.0.0.1:32002(32003)
    14:09:57.003 Remote SDP is set for legC:2.1
    14:09:57.002 [CM505001]: Ext.820: Device info: Device Identified: [Man: 3CX Ltd.;Mod: 3CX Queue;Rev: 1] Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [3CX Queue Manager (q=820)] PBX contact: [sip:820@127.0.0.1:5060]
    14:09:57.000 [CM503001]: Call(2): Incoming call from Ext.820 to <sip:103@127.0.0.1:5060;nofwd=1;tag3cx=2-HVACNHTHTS>
    14:09:56.994 [CM500002]: Info on incoming INVITE:
    INVITE sip:103@127.0.0.1:5060;nofwd=1;tag3cx=2-HVACNHTHTS SIP/2.0
    Via: SIP/2.0/UDP 127.0.0.1:5488;branch=z9hG4bK-d8754z-286ab02131770b77-1---d8754z-;rport=5488
    Max-Forwards: 70
    Contact: <sip:820@127.0.0.1:5488>
    To: <sip:103@127.0.0.1:5060;nofwd=1;tag3cx=2-HVACNHTHTS>
    From: "Systems:BM TEST:+447980586770"<sip:+447980586770@127.0.0.1:5060>;tag=cd0d9c15
    Call-ID: NmE0MTIyZmVhMzIzODlmYzFlNWRiODZmYmVmNDRlNjM.
    CSeq: 2 INVITE
    Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO, MESSAGE
    Proxy-Authorization: Digest username="820",realm="3CXPhoneSystem",nonce="414d535c055ace3449:723648d9a00eb431c16316217d50dfe6",uri="sip:103@127.0.0.1:5060;nofwd=1;tag3cx=2-HVACNHTHTS",response="bb6c8d3d41f5c0f9dfc811e54d65088a",algorithm=MD5
    Supported: replaces
    User-Agent: 3CX Queue Manager (q=820)
    Content-Length: 0
     
  7. millsey

    millsey New Member

    Joined:
    Dec 21, 2011
    Messages:
    187
    Likes Received:
    0
    . and here is a call answered ont eh same extn via 3CX Phone on my PC.

    16:20:00.677 [CM503008]: Call(12): Call is terminated
    16:19:50.722 [CM102001]: Authentication failed for SipReq: REGISTER 89.0.3.1 tid=1964081352 cseq=REGISTER contact=131@89.0.5.161:5060 / 51361 from(wire); Reason: Credentials don't match, check that authorization-ID and password match the ones in extension settings
    16:19:43.297 [MS105000] C:16.3: No RTP packets were received:remoteAddr=89.0.9.8:40022,extAddr=0.0.0.0:0,localAddr=89.0.3.1:7068
    16:19:42.322 [CM503008]: Call(16): Call is terminated
    16:19:39.688 Currently active calls - 2: [12,16]
    16:19:37.998 [MS105000] C:17.2: No RTP packets were received:remoteAddr=89.0.9.8:40022,extAddr=0.0.0.0:0,localAddr=89.0.3.1:7064
    16:19:36.709 [CM503007]: Call(16): Device joined: sip:103@89.0.9.8:64245;rinstance=a0d2de78622aa7b0
    16:19:36.702 [MS210003] C:16.3:Answer provided. Connection(transcoding mode[unsecure]):89.0.3.1:7068(7069)
    16:19:36.701 [MS210002] C:16.1:Offer provided. Connection(transcoding mode): 86.188.246.34:9018(9019)
    16:19:36.700 [MS210000] C:16.3:Offer received. RTP connection: 89.0.9.8:40022(40023)
    16:19:36.699 Remote SDP is set for legC:16.3
    16:19:36.699 [CM505001]: Ext.103: Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [3CXPhone 5.0.14900.0] PBX contact: [sip:103@89.0.3.1:5060]
    16:19:36.699 [CM503002]: Call(16): Alerting sip:103@89.0.9.8:64245;rinstance=a0d2de78622aa7b0
    16:19:36.695 [CM503008]: Call(17): Call is terminated
    16:19:36.480 [CM503025]: Call(16): Calling @[Dev:sip:103@89.0.9.8:64245;rinstance=a0d2de78622aa7b0]
    16:19:36.441 [CM505003]: Provider:[NODE4] Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [] PBX contact: [sip:1@86.188.246.34:5060]
    16:19:36.440 Replaces: C:17.2
    16:19:36.440 Refer: from=<sip:820@127.0.0.1>;tag=e72fd766; to="BM TEST:+447980586770"<sip:+447980586770@127.0.0.1:5060;nf=e>;tag=141bb30d; RefTo=<sip:103@127.0.0.1:5060;nofwd=1;tag3cx=13-TDTOSJSXSJ?Replaces=YTQ2YjhiNDc3ZTk4NGUzMDE1YWMwM2RhY2RmYzMyZTg.%3Bto-tag%3D4d6fa71a%3Bfrom-tag%3D5d036919>;tag=4d6fa71a
    16:19:36.434 Session 10231 of leg C:17.1 is confirmed
    16:19:36.398 [CM503003]: Call(17): Call to sip:103@89.0.3.1 has failed; Cause: 487 Request Terminated; from IP:89.0.5.0:5060
    16:19:36.214 [CM503007]: Call(17): Device joined: sip:103@89.0.9.8:64245;rinstance=a0d2de78622aa7b0
    16:19:36.212 [CM503007]: Call(17): Device joined: sip:820@127.0.0.1:5488
    16:19:36.208 [MS210005] C:17.1:Answer provided. Connection(proxy mode):127.0.0.1:7062(7063)
    16:19:36.206 [MS210001] C:17.2:Answer received. RTP connection[unsecure]: 89.0.9.8:40022(40023)
    16:19:36.205 Remote SDP is set for legC:17.2
    16:19:32.726 [CM505001]: Ext.103: Device info: Device Identified: [Man: GrandStream;Mod: GXP series;Rev: General] Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [Grandstream GXP2100 1.0.1.110] PBX contact: [sip:103@89.0.3.1:5060]
    16:19:32.726 [CM503002]: Call(17): Alerting sip:103@89.0.5.0:5060;user=phone
    16:19:32.704 [CM505001]: Ext.103: Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [3CXPhone 5.0.14900.0] PBX contact: [sip:103@89.0.3.1:5060]
    16:19:32.704 [CM503002]: Call(17): Alerting sip:103@89.0.9.8:64245;rinstance=a0d2de78622aa7b0
    16:19:32.557 [CM503025]: Call(17): Calling Ext:Ext.103@[Dev:sip:103@89.0.5.0:5060;user=phone]
    16:19:32.555 [MS210004] C:17.3:Offer provided. Connection(proxy mode): 89.0.3.1:7066(7067)
    16:19:32.549 [CM503025]: Call(17): Calling Ext:Ext.103@[Dev:sip:103@89.0.9.8:64245;rinstance=a0d2de78622aa7b0]
    16:19:32.547 [MS210004] C:17.2:Offer provided. Connection(proxy mode): 89.0.3.1:7064(7065)
    16:19:32.501 [CM503004]: Call(17): Route 1: Ext:Ext.103@[Dev:sip:103@89.0.9.8:64245;rinstance=a0d2de78622aa7b0,Dev:sip:103@89.0.5.0:5060;user=phone]
    16:19:32.500 [CM503010]: Making route(s) to <sip:103@127.0.0.1:5060;nofwd=1;tag3cx=13-TDTOSJSXSJ>
    16:19:32.500 [MS210000] C:17.1:Offer received. RTP connection: 127.0.0.1:32024(32025)
    16:19:32.499 Remote SDP is set for legC:17.1
    16:19:32.499 [CM505001]: Ext.820: Device info: Device Identified: [Man: 3CX Ltd.;Mod: 3CX Queue;Rev: 1] Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [3CX Queue Manager (q=820)] PBX contact: [sip:820@127.0.0.1:5060]
    16:19:32.496 [CM503001]: Call(17): Incoming call from Ext.820 to <sip:103@127.0.0.1:5060;nofwd=1;tag3cx=13-TDTOSJSXSJ>
    16:19:32.489 [CM500002]: Info on incoming INVITE:
    INVITE sip:103@127.0.0.1:5060;nofwd=1;tag3cx=13-TDTOSJSXSJ SIP/2.0
    Via: SIP/2.0/UDP 127.0.0.1:5488;branch=z9hG4bK-d8754z-d664d97ada17e477-1---d8754z-;rport=5488
    Max-Forwards: 70
    Contact: <sip:820@127.0.0.1:5488>
    To: <sip:103@127.0.0.1:5060;nofwd=1;tag3cx=13-TDTOSJSXSJ>
    From: "Systems:BM TEST:+447980586770"<sip:+447980586770@127.0.0.1:5060>;tag=5d036919
    Call-ID: YTQ2YjhiNDc3ZTk4NGUzMDE1YWMwM2RhY2RmYzMyZTg.
    CSeq: 2 INVITE
    Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO, MESSAGE
    Proxy-Authorization: Digest username="820",realm="3CXPhoneSystem",nonce="414d535c055aec9457:c5d83e3560e5ed4871244d783a18adb0",uri="sip:103@127.0.0.1:5060;nofwd=1;tag3cx=13-TDTOSJSXSJ",response="dd6845e0bdad23b6eca67cbe645c2dc0",algorithm=MD5
    Supported: replaces
    User-Agent: 3CX Queue Manager (q=820)
    Content-Length: 0

    Because there was no RTP audio (different problem) I was not able to confirm if the delay qwas there but is seems there is some difference to teh call setup.
     
  8. leejor

    leejor Well-Known Member

    Joined:
    Jan 22, 2008
    Messages:
    10,356
    Likes Received:
    224
    Is 3CX on a remote (to all sets) server? I'm just wondering if the delay is in part to the location of the various parts of your set-up. Some people have also had delays introduced by certain switches (or the settings), or other hardware, on their network. I would X out part of your pubic IP's just for security reasons.
     
  9. concs

    Joined:
    Apr 21, 2011
    Messages:
    29
    Likes Received:
    0
    I have had success in speeding up grandstreams by selecting use random port and nat traversal off in the phones config.
     
  10. millsey

    millsey New Member

    Joined:
    Dec 21, 2011
    Messages:
    187
    Likes Received:
    0
    Thanks guys,

    The 3CX is directly on the LAN on 89.0.3.1/255.255.0.0 the phones are DHCP'ed to 89.0.5.x/255.255.0.0

    I do note that we had to untick the option to disallow using the extension outside the LAN which I thought was odd. Without hat option the phones arere not registering tothe 3CX at all. I was wondering if there was some network oddness.

    I already found a recommendation on Grandstream's forums http://forums.grandstream.com/forums/index.php?topic=12250.0 to turn off NAT (was set as keep-alive) and also to turn off the phone saving its call log, but VERY oddly, today the Receptionist reported that if one of htem answered the call, the oterh was occasionally getting logged out of hte queue, I don't understand why that was happening but I amnot in work so I just restored the setting.

    Will test random port tomorrow, thanks for your input.

    Millsey
     
  11. leejor

    leejor Well-Known Member

    Joined:
    Jan 22, 2008
    Messages:
    10,356
    Likes Received:
    224
    Probably because your sets are on a different subnet. Why?
     
  12. millsey

    millsey New Member

    Joined:
    Dec 21, 2011
    Messages:
    187
    Likes Received:
    0
    They are not on different subnets, it is all one 89.0.x.x subnet with that mask.
     
  13. millsey

    millsey New Member

    Joined:
    Dec 21, 2011
    Messages:
    187
    Likes Received:
    0
    Reading up it looks like there may be a fundamental mistake in our network. Originally we had 89.0.4.x and 90.0.4.x both with a 255.255.255.0 mask, this appears correct when researching classFUL subnets.

    We got rid of the 90.0.4.x subnet as we didn't really need to route between the two offices, our bandwidth was good enough to allow us to not need any sort of routing or filtering.

    Recently we expanded 89.0.4.x to 89.0.x.x to give us more available IP's, This is fine from a CIDR classless routing point of view but what I am reading suggests this is not correct from a purist networking point of view - the addres range 1 to 126 is supposed to be used for class A network - that is 255.0.0.0 but not for class b which we are using it for.

    I will test forcing our phones to 89.0.3.x and see what happens.
     
  14. millsey

    millsey New Member

    Joined:
    Dec 21, 2011
    Messages:
    187
    Likes Received:
    0
    THIS IS FIXED

    Installed a syslog server, and on a queue call I could see the the call setup happened twice, and worked out this was caused by the setting (per extension) of "Supports Replaces" - not sure exactly the resultant issue but as the call setup was basically happening twice, the call was not functioning properly until the end of the second call setup.

    Switching off "Supports Replaces" per extension fixes this issue.

    Millsey
     
Thread Status:
Not open for further replies.