Difficulty login and outgoing is not working

[seb_fpl]

Hi,

since a few days I've been having quite a lot of errors with my ATA. It takes a several tries before a succesful login. And when I'm logged in, I only get a busy tone when trying to reach voicemail or make a simple call. Incoming calls do work when I'm logged in. No change in configuration recently on my part. I did reboot both router and ATA, not helping.

I'm using a Grandstream HT-502 with DD-WRT/milkfish for my outgoing proxy. This setup has been working for over 2 years perfectly.

This is what I get on my syslog server :

Registration attempt
Jan 30 23:36:11 HT-502 : [1.0.8.4] SIPStack(0)::cb_rcv4xx: Received 401 response for transaction 16(REGISTER)
Jan 30 23:36:11 HT-502 : [1.0.8.4] SIPStack(0)::run: Active transactions: 2
Jan 30 23:36:11 HT-502 : [1.0.8.4] SIPTransaction::waitForResponse: Request 16 got status code 401
Jan 30 23:36:11 HT-502 : [1.0.8.4] SigCtrl::performRegistration, transaction got code 0:401
Jan 30 23:36:15 HT-502 : [1.0.8.4] SIPStack(0)::run: Active transactions: 1
Jan 30 23:36:32 HT-502 : [1.0.8.4] SIPClientTransaction::sendRequest: Request 17 is sent
Jan 30 23:36:32 HT-502 : [1.0.8.4] SIPStack(0)::run: Active transactions: 1
Jan 30 23:36:32 HT-502 : [1.0.8.4] SIPStack(0)::cb_rcv4xx: Received 401 response for transaction 17(REGISTER)
Jan 30 23:36:32 HT-502 : [1.0.8.4] SIPStack(0)::run: Active transactions: 1
Jan 30 23:36:32 HT-502 : [1.0.8.4] SIPTransaction::waitForResponse: Request 17 got status code 401
Jan 30 23:36:32 HT-502 : [1.0.8.4] SIPStack(0)::run: Active transactions: 2
Jan 30 23:36:32 HT-502 : [1.0.8.4] SIPStack(0)::cb_rcv4xx: Received 401 response for transaction 18(REGISTER)
Jan 30 23:36:32 HT-502 : [1.0.8.4] SIPStack(0)::run: Active transactions: 2
Jan 30 23:36:32 HT-502 : [1.0.8.4] SIPTransaction::waitForResponse: Request 18 got status code 401
Jan 30 23:36:32 HT-502 : [1.0.8.4] SigCtrl::performRegistration, transaction got code 0:401
Jan 30 23:36:37 HT-502 : [1.0.8.4] SIPStack(0)::run: Active transactions: 2
Jan 30 23:36:37 HT-502 : [1.0.8.4] SIPStack(0)::run: Active transactions: 1
Jan 30 23:36:37 HT-502 : [1.0.8.4] SIPStack(0)::run: Active transactions: 1
Jan 30 23:36:54 HT-502 : [1.0.8.4] SIPClientTransaction::sendRequest: Request 19 is sent
Jan 30 23:36:54 HT-502 : [1.0.8.4] SIPStack(0)::run: Active transactions: 1
Jan 30 23:36:55 HT-502 : [1.0.8.4] SIPStack(0)::cb_rcvreqrexmit: Resend for transaction 19(REGISTER)
Jan 30 23:36:55 HT-502 : [1.0.8.4] SIPStack(0)::run: Active transactions: 1
Jan 30 23:36:55 HT-502 : [1.0.8.4] SIPStack(0)::cb_rcv2xx: Received 200 response for transaction 19 (REGISTER), inXfr : -1
Jan 30 23:36:55 HT-502 : [1.0.8.4] SIPStack(0)::run: Active transactions: 1
Jan 30 23:36:55 HT-502 : [1.0.8.4] SIPTransaction::waitForResponse: Request 19 got status code 200
Jan 30 23:36:55 HT-502 : [1.0.8.4] SigCtrl::performRegistration, transaction got code 0:200
Jan 30 23:36:55 HT-502 : [1.0.8.4] SigCtrl::processSigRegistered, Account 0 registered, tried 0; Next reg in 3000 seconds (5373) on voip.freephoneline.ca

Phonecall attempt :
Feb 1 09:30:34 HT-502 : [1.0.8.4] ATACtrl::processPhoneOffHook on port 0:0, status = CALL_IDLE/CALL_IDLE, reg'd:1, allow calls w/o reg:1
Feb 1 09:30:35 HT-502 : [1.0.8.4] Creating Call object 2 at port 0:0, caller 1
Feb 1 09:30:36 HT-502 : [1.0.8.4] DialPlan Status : 0x1
Feb 1 09:30:36 HT-502 : [1.0.8.4] Call::run, Dialing *98
Feb 1 09:30:36 HT-502 : [1.0.8.4] SIPStack(0)::run: Active transactions: 1
Feb 1 09:30:36 HT-502 : [1.0.8.4] SIPClientTransaction::sendRequest: Request 208 is sent
Feb 1 09:30:36 HT-502 : [1.0.8.4] SIPStack(0)::cb_rcv1xx: Received 100 response for transaction 208 (INVITE)
Feb 1 09:30:36 HT-502 : [1.0.8.4] SIPStack(0)::run: Active transactions: 1
Feb 1 09:30:36 HT-502 : [1.0.8.4] SIPTransaction::waitForResponse: Request 208 got status code 100
Feb 1 09:30:37 HT-502 : [1.0.8.4] SIPStack(0)::cb_rcv4xx: Received 401 response for transaction 208(INVITE)
Feb 1 09:30:37 HT-502 : [1.0.8.4] SIPTransaction::waitForResponse: Request 208 got status code 401
Feb 1 09:30:37 HT-502 : [1.0.8.4] SIPStack(0)::run: Active transactions: 2
Feb 1 09:30:37 HT-502 : [1.0.8.4] SIPStack(0)::run: Active transactions: 2
Feb 1 09:30:37 HT-502 : [1.0.8.4] SIPStack(0)::cb_rcv1xx: Received 100 response for transaction 209 (INVITE)
Feb 1 09:30:37 HT-502 : [1.0.8.4] SIPStack(0)::run: Active transactions: 2
Feb 1 09:30:37 HT-502 : [1.0.8.4] SIPTransaction::waitForResponse: Request 209 got status code 100
Feb 1 09:30:37 HT-502 : [1.0.8.4] SIPStack(0)::cb_rcv4xx: Received 401 response for transaction 209(INVITE)
Feb 1 09:30:37 HT-502 : [1.0.8.4] SIPStack(0)::run: Active transactions: 2
Feb 1 09:30:37 HT-502 : [1.0.8.4] SIPTransaction::waitForResponse: Request 209 got status code 401
Feb 1 09:30:37 HT-502 : [1.0.8.4] cannot make the call, 0, throw call failed event, status 401
Feb 1 09:30:37 HT-502 : [1.0.8.4] Deleting Call object 2 port 0:0
Feb 1 09:30:37 HT-502 : [1.0.8.4] ATACtrl::processCallFailed on port 0:0, status = CALL_DIALED/CALL_IDLE stCode:401 canConf:1
Feb 1 09:30:40 HT-502 : [1.0.8.4] ATACtrl::processPhoneOnHook on port 0:0, status = CALL_ENDING/CALL_IDLE canConf:1 noreminder:0

So why I'm a getting so many 401 Unauthorized errors now?

[Jake]

what is your registration time set at?

[seb_fpl]

GMT-5, synced by NTP. I'm in Quebec.

[seb_fpl]

Actually, the NTP daemon wasn't running....clock was off by 305.364260 sec. Anyway, let me know if you need more info/test.

[FONGO_mike]

seb, i think there may be a missunderstanding, we are not looking for what time zone your ATA is set to, but what the registration times are set to (it should be set 3600)

[seb_fpl]

Currently it's set at the default value of 60min, or 3600 sec.

[seb_fpl]

Hmmm looking at the log, it seems to behave like it is set at 3000 sec, not 3600. I see a succesful login at 13h32, new registration starting at 14h22, failing until it's 14h34. So there is some form of throttling for registration time?