On 9 Nov. 2016, at 09:00, Tobias Sachs tobias@tobiassachs.de wrote:
Hey,
my Tor relay https://atlas.torproject.org/#details/B567E8E39641F61091C1F2CAAAF73D3D1BF9CF... balks with the following message which is repeated in the log with the "info" logging level up to 23251 times at the exact same millisecond.
I assume you are talking about the router_pick_published_address message.
The relay responds at :9030/tor/server/authority with a 503 error.
This is a temporary error when your relay is overloaded.
I just tried http://167.114.245.102:9030/tor/server/authority and it delivered the descriptor fine, with no error.
Yes but this is a rare case during the day Event,Date-Time,Reason,Duration,"Duration (in mins.)" Up,"2016-11-07 22:29:47","Keyword Found","25 hrs, 13 mins",1514 Down,"2016-11-07 22:28:30","Keyword Not Found","0 hrs, 1 mins",1 Up,"2016-11-07 22:23:29","Keyword Found","0 hrs, 5 mins",5 Down,"2016-11-07 22:22:05","Keyword Not Found","0 hrs, 1 mins",1 Up,"2016-11-06 13:56:42","Keyword Found","32 hrs, 25 mins",1945 Down,"2016-11-06 13:55:44","Keyword Not Found","0 hrs, 0 mins",1 Up,"2016-11-06 13:22:19","Keyword Found","0 hrs, 33 mins",33 Down,"2016-11-06 13:21:21","Keyword Not Found","0 hrs, 0 mins",1 Up,"2016-11-06 13:17:31","Keyword Found","0 hrs, 3 mins",4 Down,"2016-11-06 13:16:33","Keyword Not Found","0 hrs, 0 mins",1
I don't know it but htop was something strange. The cpu was yellow which is not documented and on 100%. The tor process itself had 0.0% cpu but still traffic. Maybe this was a bug which was related to some upstream kernel / package bugs. I rebooted the vm with the latest kernel and the issue is gone. I let you aware if uptimetobot and statuscake still sees some 503 errors.
I logged a ticket:
Relays should log a message when they return a 503 error to a client https://trac.torproject.org/projects/tor/ticket/20611
router_pick_published_address(): Success: chose address 'x.x.x.x'
This message is not an error, it is a success.
But I can see how it would be annoying:
Rate limit router_pick_published_address log message https://trac.torproject.org/projects/tor/ticket/20610
This is a counting from the log with the corresponding timestamp.
Nov 01 18:37:13.000 - 23251 Nov 01 18:37:22.000 - 59 Nov 01 18:38:17.000 - 23195 Nov 01 18:38:22.000 - 57 Nov 01 19:19:22.000 - 50 Nov 01 19:19:23.000 - 312 Nov 01 19:19:24.000 - 333 Nov 01 19:19:25.000 - 74 Nov 01 19:20:22.000 - 52 Nov 01 19:38:17.000 - 23207 Nov 01 20:38:17.000 - 23232
140 times exactly 49 repeats in around 2 hours.
Interesting is that there is no error about this 503 error in the log only my monitoring is aware of the issue.
I hope you coul'd help me out with this issue.
Maybe you should turn your log level down to notice? The less you log, the better.
I only used info log level to track down the issue with the 503 errors because there were no log entry :) Anyway thank you for opening the two tickets and your explanation.
T This doesn't help you solve your problem, but it's relevant.
I run Tor network simulations and see this all the time. I haven't taken the time to look into it, and always have assumed it's just a minor misconfiguration in the simulator or something that only exists _because_ it's a simulation.
And ... it looks like teor swooped in and opened a ticket for the log spam.
Matt
Nice to here that I am not alone and to help each other.
Best Regards Tobias