re-registration problem with voip provider (v10 SP6)

[sjoukes]

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:[email protected]: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:[email protected]:5060;rinstance=796fc4388cc8d59f>
To: "123456"<sip:[email protected]:5060>
From: "123456"<sip:[email protected]: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:[email protected]:5060>
From: "123456"<sip:[email protected]: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|::ResipLoggerialogUsageManager:rocessResponse:

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:[email protected]:5060;rinstance=796fc4388cc8d59f>;expires=300;q=0.0
To: "123456"<sip:[email protected]:5060>
From: "123456"<sip:[email protected]: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 [email protected]:5060 / 56 from(wire)
21:11:46.874|.\DialogUsageManager.cxx(1841)|Debug8|Resip|::ResipLoggerialogUsageManager:rocessResponse:

SipResp: 200 tid=6025f2203d5e2a3c cseq=REGISTER [email protected]: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|::ResipLoggerialogId:ialogId: 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:[email protected]: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:[email protected]: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:[email protected]:5060;rinstance=796fc4388cc8d59f>
To: "123456"<sip:[email protected]:5060>
From: "123456"<sip:[email protected]: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

 

[sjoukes]

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).

 

[SY]

21:11:46.873 is the initial answer... (300 seconds are there)

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:[email protected]:5060;rinstance=796fc4388cc8d59f>;expires=300;q=0.0
To: "123456"<sip:[email protected]:5060>
From: "123456"<sip:[email protected]:5060>;tag=5b3f8e45
Call-ID: MDljMmFlZGZmMDNmZjM5ZTIzZDU3OGQ3MTczN2U2YjE.
CSeq: 56 REGISTER
Date: Thu, 14 Feb 2013 20:13:03 GMT
Content-Length: 0

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?

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:[email protected]:5060;rinstance=796fc4388cc8d59f>
To: "123456"<sip:[email protected]:5060>
From: "123456"<sip:[email protected]: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

 

[sjoukes]

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?

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.