re-registration problem with voip provider (v10 SP6)

Discussion in '3CX Phone System - General' started by sjoukes, Feb 14, 2013.

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

    Joined:
    Apr 2, 2012
    Messages:
    4
    Likes Received:
    0
    Hi,
    I've got a strange problem which started out of the blue.

    Since a few days the re-registrations which are sent to my VoIP partner seem to be sent too later (after they've expired)
    For example 3CX sends a REGISTER command @ 21:11:45.675 with an expiration time of 180 S
    It receives a SIP OK @ 21:11:46.874 with an expire time of 300S (seen via wireshark)

    The following REGISTER command is sent at 21:16:16.052 which is +- 330 seconds later so the VoIP provider drops the connection until after the re-register

    Another strange thing is that 3CX doesn't show the correct registration time in the "Remote Connections" screen. There it shows the last time the server started or a manual registration was performed.

    I've shortened the registration time to 180 for debugging, normally it's set to 3600 seconds but then the re-registers don't seem to be sent at all.

    I've added a few sniplets from a tracelog:

    21:11:44.780|.\Transport.cxx(213)|Debug8|Resip|::ResipLogger:Adding message to tx buffer to: [ V4 217.21.192.91:5060 UDP target domain=unspecified mFlowKey=840 ]
    21:11:46.656|.\ClientRegistration.cxx(279)|Trace5|Resip|::ResipLogger:requesting refresh of ClientRegistration sip:123456@a.b.c.nl:5060
    21:11:46.656|.\ClientAuthManager.cxx(319)|Debug8|Resip|::ResipLogger: Add auth, 012E3EC8 in response to: Digest algorithm=MD5,realm="a.b.c.nl",nonce="1360858269417",method=REGISTER
    21:11:46.656|.\ClientAuthManager.cxx(344)|Debug8|Resip|::ResipLogger:ClientAuthManager::RealmState::addAuthentication, proxy: 0 Digest username="123456",realm="a.b.c.nl",nonce="1360858269417",uri="sip:a.b.c.nl:5060",response="3429b5f5e3fd16b96f6ff63762bd7a48",algorithm=MD5
    21:11:46.656|.\DialogUsageManager.cxx(866)|Debug8|Resip|::ResipLogger:SEND:

    REGISTER sip:a.b.c.nl:5060 SIP/2.0
    Via: SIP/2.0/ ;branch=z9hG4bK-d8754z-6025f2203d5e2a3c-1---d8754z-;rport
    Max-Forwards: 70
    Contact: <sip:123456@ip2.ip2.ip2.ip2:5060;rinstance=796fc4388cc8d59f>
    To: "123456"<sip:123456@a.b.c.nl:5060>
    From: "123456"<sip:123456@a.b.c.nl:5060>;tag=5b3f8e45
    Call-ID: MDljMmFlZGZmMDNmZjM5ZTIzZDU3OGQ3MTczN2U2YjE.
    CSeq: 56 REGISTER
    Expires: 180
    Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO, MESSAGE
    Supported: replaces
    User-Agent: 3CXPhoneSystem 10.0.23053.0
    Authorization: Digest username="123456",realm="a.b.c.nl",nonce="1360858269417",uri="sip:a.b.c.nl:5060",response="3429b5f5e3fd16b96f6ff63762bd7a48",algorithm=MD5
    Content-Length: 0


    21:11:46.780|.\Transport.cxx(213)|Debug8|Resip|::ResipLogger:Adding message to tx buffer to: [ V4 ip.ip.ip.ip:5060 UDP target domain=a.b.c.nl mFlowKey=0 ]
    21:11:46.809|.\Transport.cxx(287)|Debug8|Resip|::ResipLogger:incoming from: [ V4 ip.ip.ip.ip:5060 UDP target domain=unspecified mFlowKey=840 ]
    21:11:46.809|.\TimerQueue.cxx(85)|Debug8|Resip|::ResipLogger:Adding timer: Timer E2 tid=6025f2203d5e2a3c ms=4000
    21:11:46.809|.\DnsResult.cxx(206)|Debug8|Resip|::ResipLogger:Whitelisting a.b.c.nl(1): ip.ip.ip.ip
    21:11:46.809|.\dns\RRVip.cxx(129)|Debug8|Resip|::ResipLogger:updating an existing vip: ip.ip.ip.ip with ip.ip.ip.ip
    21:11:46.809|.\TransactionState.cxx(2112)|Debug8|Resip|::ResipLogger:Send to TU: TU: DialogUsageManager size=0

    SIP/2.0 100 Trying
    Via: SIP/2.0/UDP 192.168.122.6:5060;received=ip2.ip2.ip2.ip2;branch=z9hG4bK-d8754z-6025f2203d5e2a3c-1---d8754z-;rport=1030
    To: "123456"<sip:123456@a.b.c.nl:5060>
    From: "123456"<sip:123456@a.b.c.nl:5060>;tag=5b3f8e45
    Call-ID: MDljMmFlZGZmMDNmZjM5ZTIzZDU3OGQ3MTczN2U2YjE.
    CSeq: 56 REGISTER
    Content-Length: 0

    21:11:46.811|.\DialogUsageManager.cxx(1333)|Trace5|Resip|::ResipLogger:Got: SipResp: 100 tid=d22ba00cd0669c56 cseq=REGISTER / 56 from(wire)
    21:11:46.811|.\DialogUsageManager.cxx(1841)|Debug8|Resip|::ResipLogger:DialogUsageManager::processResponse:

    SipResp: 100 tid=d22ba00cd0669c56 cseq=REGISTER / 56 from(wire)
    21:11:46.811|.\UserProfile.cxx(158)|Debug8|Resip|::ResipLogger:Found credential for realm: realm=3CXPhoneSystem user=1000333CXPhoneSystem
    21:11:46.873|.\Transport.cxx(287)|Debug8|Resip|::ResipLogger:incoming from: [ V4 ip.ip.ip.ip:5060 UDP target domain=unspecified mFlowKey=840 ]
    21:11:46.873|.\DnsResult.cxx(206)|Debug8|Resip|::ResipLogger:Whitelisting a.b.c.nl(1): ip.ip.ip.ip
    21:11:46.873|.\dns\RRVip.cxx(129)|Debug8|Resip|::ResipLogger:updating an existing vip: ip.ip.ip.ip with ip.ip.ip.ip
    21:11:46.873|.\TransactionState.cxx(2112)|Debug8|Resip|::ResipLogger:Send to TU: TU: DialogUsageManager size=0

    SIP/2.0 200 OK
    Via: SIP/2.0/UDP 192.168.122.6:5060;received=ip2.ip2.ip2.ip2;branch=z9hG4bK-d8754z-6025f2203d5e2a3c-1---d8754z-;rport=1030
    Contact: <sip:123456@ip2.ip2.ip2.ip2:5060;rinstance=796fc4388cc8d59f>;expires=300;q=0.0
    To: "123456"<sip:123456@a.b.c.nl:5060>
    From: "123456"<sip:123456@a.b.c.nl:5060>;tag=5b3f8e45
    Call-ID: MDljMmFlZGZmMDNmZjM5ZTIzZDU3OGQ3MTczN2U2YjE.
    CSeq: 56 REGISTER
    Date: Thu, 14 Feb 2013 20:13:03 GMT
    Content-Length: 0


    21:11:46.874|.\TimerQueue.cxx(85)|Debug8|Resip|::ResipLogger:Adding timer: Timer K tid=6025f2203d5e2a3c ms=5000
    21:11:46.874|.\DialogUsageManager.cxx(1333)|Trace5|Resip|::ResipLogger:Got: SipResp: 200 tid=6025f2203d5e2a3c cseq=REGISTER contact=123456@ip2.ip2.ip2.ip2:5060 / 56 from(wire)
    21:11:46.874|.\DialogUsageManager.cxx(1841)|Debug8|Resip|::ResipLogger:DialogUsageManager::processResponse:

    SipResp: 200 tid=6025f2203d5e2a3c cseq=REGISTER contact=123456@ip2.ip2.ip2.ip2:5060 / 56 from(wire)
    21:11:46.874|.\UserProfile.cxx(158)|Debug8|Resip|::ResipLogger:Found credential for realm: realm=3CXPhoneSystem user=1234563CXPhoneSystem
    21:11:46.874|.\ClientAuthManager.cxx(41)|Debug8|Resip|::ResipLogger:ClientAuthManager::handle: transitioning MDljMmFlZGZmMDNmZjM5ZTIzZDU3OGQ3MTczN2U2YjE.-5b3f8e45to cached
    21:11:46.874|.\ClientAuthManager.cxx(198)|Debug8|Resip|::ResipLogger:ClientAuthManager::RealmState::transition from cached to cached
    21:11:46.874|.\DialogId.cxx(50)|Debug8|Resip|::ResipLogger:DialogId::DialogId: MDljMmFlZGZmMDNmZjM5ZTIzZDU3OGQ3MTczN2U2YjE.-5b3f8e45-
    21:11:46.874|.\ClientRegistration.cxx(402)|Debug8|Resip|::ResipLogger:Clearing service route ([])
    21:11:46.874|.\TimerQueue.cxx(105)|Debug8|Resip|::ResipLogger:Adding application timer: DumTimeout::Registration ClientRegistration sip:123456@a.b.c.nl:5060: duration=270 seq=55
    21:11:46.879|.\Transport.cxx(287)|Debug8|Resip|::ResipLogger:incoming from: [ V4 ip.ip.ip.ip:5060 UDP target domain=unspecified mFlowKey=840 ]
    21:11:46.879|.\DnsResult.cxx(206)|Debug8|Resip|::ResipLogger:Whitelisting a.b.c.nl(1): ip.ip.ip.ip
    21:11:46.879|.\dns\RRVip.cxx(129)|Debug8|Resip|::ResipLogger:updating an existing vip: ip.ip.ip.ip with ip.ip.ip.ip
    21:11:46.880|.\TransactionState.cxx(2112)|Debug8|Resip|::ResipLogger:Send to TU: TU: DialogUsageManager size=0


    21:16:16.897|.\Transport.cxx(213)|Debug8|Resip|::ResipLogger:Adding message to tx buffer to: [ V4 192.168.125.59:5060 UDP target domain=unspecified mFlowKey=872 ]
    21:16:16.911|.\ClientRegistration.cxx(279)|Trace5|Resip|::ResipLogger:requesting refresh of ClientRegistration sip:123456@a.b.c.nl:5060
    21:16:16.911|.\ClientAuthManager.cxx(319)|Debug8|Resip|::ResipLogger: Add auth, 012E3EC8 in response to: Digest algorithm=MD5,realm="a.b.c.nl",nonce="1360858269417",method=REGISTER
    21:16:16.911|.\ClientAuthManager.cxx(344)|Debug8|Resip|::ResipLogger:ClientAuthManager::RealmState::addAuthentication, proxy: 0 Digest username="123456",realm="a.b.c.nl",nonce="1360858269417",uri="sip:a.b.c.nl:5060",response="3429b5f5e3fd16b96f6ff63762bd7a48",algorithm=MD5
    21:16:16.911|.\DialogUsageManager.cxx(866)|Debug8|Resip|::ResipLogger:SEND:

    REGISTER sip:a.b.c.nl:5060 SIP/2.0
    Via: SIP/2.0/ ;branch=z9hG4bK-d8754z-1b40d6498271607d-1---d8754z-;rport
    Max-Forwards: 70
    Contact: <sip:123456@ip2.ip2.ip2.ip2:5060;rinstance=796fc4388cc8d59f>
    To: "123456"<sip:123456@a.b.c.nl:5060>
    From: "123456"<sip:123456@a.b.c.nl:5060>;tag=5b3f8e45
    Call-ID: MDljMmFlZGZmMDNmZjM5ZTIzZDU3OGQ3MTczN2U2YjE.
    CSeq: 57 REGISTER
    Expires: 180
    Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO, MESSAGE
    Supported: replaces
    User-Agent: 3CXPhoneSystem 10.0.23053.0
    Authorization: Digest username="123456",realm="a.b.c.nl",nonce="1360858269417",uri="sip:a.b.c.nl:5060",response="3429b5f5e3fd16b96f6ff63762bd7a48",algorithm=MD5
    Content-Length: 0
     
  2. sjoukes

    Joined:
    Apr 2, 2012
    Messages:
    4
    Likes Received:
    0
    Hint taken, but in my opinion it still shouldn't take 3CX 330 seconds to re-register since thats more than 300 seconds or am I wrong?

    I'm still analyzing trace logs and wireshark logging besides each other. The VoIP provider always sends 300 in responce which is ok, but I've seen 3CX take over 7 to 10 minutes to re-register leaving the line dead for up to 5 minutes.
    I've got over 24 hours of sniffing data an just taken a look at 1 hour of data.

    From when it was set to 3600 seconds I don't have wireshark data but know for certain that a re register won't happen for 30 minutes or more after expiration since I have to re-register manually (otherwise our company remains offline).
     
  3. SY

    SY Well-Known Member
    3CX Support

    Joined:
    Jan 26, 2007
    Messages:
    1,825
    Likes Received:
    2
    21:11:46.873 is the initial answer... (300 seconds are there)
    21:16:16.911 is the request which is send after 4 minutes and 30 seconds. 4 minutes and 30 seconds is equal to 270 seconds, isn't it?
     
    Stop hovering to collapse... Click to collapse... Hover to expand... Click to expand...
  4. sjoukes

    Joined:
    Apr 2, 2012
    Messages:
    4
    Likes Received:
    0
    You're totally right I've used a wrong example (sorry for that I'm workign on this for over 24 hours atm).

    I'll add a wireshark header sniplet:
    2710418 20h 2m 51.941929000s ip2.ip2.ip2.ip2 ip.ip.ip.ip SIP 885 Request: REGISTER sip:a.b.c.nl:8060 |
    Containing Expires: 180
    2710420 20h 2m 51.977040000s ip.ip.ip.ip ip2.ip2.ip2.ip2 SIP 416 Status: 100 Trying (0 bindings) |

    2710422 20h 2m 52.025063000s ip.ip.ip.ip ip2.ip2.ip2.ip2 SIP 536 Status: 200 OK (1 bindings) |
    Containing expires=300

    2711804 20h 9m 45.933195000s ip2.ip2.ip2.ip2 ip.ip.ip.ip SIP 885 Request: REGISTER sip:a.b.c.nl:8060 |
    Containing Expires: 180


    This one is over 300 seconds If I'm not to sleep deprived..

    P.s.
    is it normal that the "remote connections" screen doesn't show the re-register time?
    I normally don't look at that screen.
     
Thread Status:
Not open for further replies.