Dismiss Notice
We would like to remind you that we’re updating our login process for all 3CX forums whereby you will be able to login with the same credentials you use for the Partner or Customer Portal. Click here to read more.

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.