Further information. Curl error Failed to receive SOCKS5 connect request ack. and from earlier, Tor log Mar 19 11:52:37.000 [notice] Tried for 32496 seconds to get a connection to [scrubbed]:80. Giving up.
More information: Mar 20 10:48:23.000 [warn] Your system clock just jumped 38788 seconds forward; assuming established circuits no longer work. This is starting to seem familiar: I searched the archives but nothing recent. NTP seems fine. If no-one has any better ideas I'll go back a version.
On Sun, Mar 19, 2017, at 02:20 PM, Geoff Down wrote:
Further information. Curl error Failed to receive SOCKS5 connect request ack. and from earlier, Tor log Mar 19 11:52:37.000 [notice] Tried for 32496 seconds to get a connection to [scrubbed]:80. Giving up.
-- http://www.fastmail.com - A no graphics, no pop-ups email service
tor-relays mailing list tor-relays@lists.torproject.org https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-relays
On 21 Mar 2017, at 00:09, Geoff Down geoffdown@fastmail.net wrote:
More information: Mar 20 10:48:23.000 [warn] Your system clock just jumped 38788 seconds forward; assuming established circuits no longer work. This is starting to seem familiar: I searched the archives but nothing recent. NTP seems fine. If no-one has any better ideas I'll go back a version.
On Sun, Mar 19, 2017, at 02:20 PM, Geoff Down wrote:
Further information. Curl error Failed to receive SOCKS5 connect request ack. and from earlier, Tor log Mar 19 11:52:37.000 [notice] Tried for 32496 seconds to get a connection to [scrubbed]:80. Giving up.
We fixed a bug like this in 0.2.9.6-rc.
It was caused by DNS resolves that received no reply and didn't timeout. (DNS resolution occurs on the main thread.)
Here's the ChangeLog entry and bug: https://gitweb.torproject.org/tor.git/tree/ChangeLog?id=1f6c8eda0073f464b7d2... https://trac.torproject.org/projects/tor/ticket/20423
You can help us diagnose this issue by providing the log lines just before:
[warn] Your system clock just jumped [0-9]* seconds forward; assuming established circuits no longer work.
Using debug logs should help us identify the exact function call causing the issue.
T
-- Tim Wilson-Brown (teor)
teor2345 at gmail dot com PGP C855 6CED 5D90 A0C5 29F6 4D43 450C BA7F 968F 094B ricochet:ekmygaiu4rzgsk6n xmpp: teor at torproject dot org ------------------------------------------------------------------------
On Mon, Mar 20, 2017, at 01:44 PM, teor wrote:
On 21 Mar 2017, at 00:09, Geoff Down geoffdown@fastmail.net wrote:
More information: Mar 20 10:48:23.000 [warn] Your system clock just jumped 38788 seconds forward; assuming established circuits no longer work.
Mar 19 11:52:37.000 [notice] Tried for 32496 seconds to get a connection to [scrubbed]:80. Giving up.
We fixed a bug like this in 0.2.9.6-rc.
It was caused by DNS resolves that received no reply and didn't timeout. (DNS resolution occurs on the main thread.)
Here's the ChangeLog entry and bug: https://gitweb.torproject.org/tor.git/tree/ChangeLog?id=1f6c8eda0073f464b7d2... https://trac.torproject.org/projects/tor/ticket/20423
You can help us diagnose this issue by providing the log lines just before:
[warn] Your system clock just jumped [0-9]* seconds forward; assuming established circuits no longer work.
Using debug logs should help us identify the exact function call causing the issue.
Thanks Tim, will do. The usual SIGINT shutdown hangs as well - have to send a second SIGINT. GD
On Mon, Mar 20, 2017, at 01:44 PM, teor wrote:
Mar 19 11:52:37.000 [notice] Tried for 32496 seconds to get a connection to [scrubbed]:80. Giving up.
We fixed a bug like this in 0.2.9.6-rc.
It was caused by DNS resolves that received no reply and didn't timeout. (DNS resolution occurs on the main thread.)
Here's the ChangeLog entry and bug: https://gitweb.torproject.org/tor.git/tree/ChangeLog?id=1f6c8eda0073f464b7d2... https://trac.torproject.org/projects/tor/ticket/20423
You can help us diagnose this issue by providing the log lines just before:
[warn] Your system clock just jumped [0-9]* seconds forward; assuming established circuits no longer work.
Mar 20 15:06:59.000 [debug] connection_or_process_cells_from_inbuf(): 52: starting, inbuf_datalen 0 (0 pending in tls object). Mar 20 15:06:59.000 [debug] connection_bucket_refill_helper(): global_read_bucket now 1073741824. Mar 20 15:06:59.000 [debug] connection_bucket_refill_helper(): global_write_bucket now 1073741824. Mar 20 15:06:59.000 [debug] connection_bucket_refill_helper(): global_relayed_read_bucket now 1073741824. Mar 20 15:06:59.000 [debug] connection_bucket_refill_helper(): global_relayed_write_bucket now 1073741824. Mar 20 15:06:59.000 [debug] connection_bucket_refill_helper(): or_conn->read_bucket now 1073741824. {repeat} Mar 20 15:06:59.000 [debug] connection_bucket_refill_helper(): or_conn->write_bucket now 1073741824. Mar 20 15:06:59.000 [debug] connection_bucket_refill_helper(): or_conn->read_bucket now 1073741824. {repeat} Mar 20 15:06:59.000 [warn] Your system clock just jumped 555 seconds forward; assuming established circuits no longer work.
On 21 Mar 2017, at 02:19, Geoff Down geoffdown@fastmail.net wrote:
On Mon, Mar 20, 2017, at 01:44 PM, teor wrote:
Mar 19 11:52:37.000 [notice] Tried for 32496 seconds to get a connection to [scrubbed]:80. Giving up.
We fixed a bug like this in 0.2.9.6-rc.
It was caused by DNS resolves that received no reply and didn't timeout. (DNS resolution occurs on the main thread.)
Here's the ChangeLog entry and bug: https://gitweb.torproject.org/tor.git/tree/ChangeLog?id=1f6c8eda0073f464b7d2... https://trac.torproject.org/projects/tor/ticket/20423
You can help us diagnose this issue by providing the log lines just before:
[warn] Your system clock just jumped [0-9]* seconds forward; assuming established circuits no longer work.
Mar 20 15:06:59.000 [debug] connection_or_process_cells_from_inbuf(): 52: starting, inbuf_datalen 0 (0 pending in tls object). Mar 20 15:06:59.000 [debug] connection_bucket_refill_helper(): global_read_bucket now 1073741824. Mar 20 15:06:59.000 [debug] connection_bucket_refill_helper(): global_write_bucket now 1073741824. Mar 20 15:06:59.000 [debug] connection_bucket_refill_helper(): global_relayed_read_bucket now 1073741824. Mar 20 15:06:59.000 [debug] connection_bucket_refill_helper(): global_relayed_write_bucket now 1073741824. Mar 20 15:06:59.000 [debug] connection_bucket_refill_helper(): or_conn->read_bucket now 1073741824. {repeat} Mar 20 15:06:59.000 [debug] connection_bucket_refill_helper(): or_conn->write_bucket now 1073741824. Mar 20 15:06:59.000 [debug] connection_bucket_refill_helper(): or_conn->read_bucket now 1073741824. {repeat} Mar 20 15:06:59.000 [warn] Your system clock just jumped 555 seconds forward; assuming established circuits no longer work.
Can you try setting an explicit IP address for your bridge, using: Address NNN.NNN.NNN.NNN in the torrc?
We might not have fixed all instances of this issue in 20423.
T
-- Tim Wilson-Brown (teor)
teor2345 at gmail dot com PGP C855 6CED 5D90 A0C5 29F6 4D43 450C BA7F 968F 094B ricochet:ekmygaiu4rzgsk6n xmpp: teor at torproject dot org ------------------------------------------------------------------------
On Tue, Mar 21, 2017, at 09:27 AM, teor wrote:
Can you try setting an explicit IP address for your bridge, using: Address NNN.NNN.NNN.NNN in the torrc?
We might not have fixed all instances of this issue in 20423.
Done, (SIGINT still hadn't shut down after 10 minutes btw) then Mar 21 14:24:01.000 [notice] Tor 0.2.9.10 opening new log file. ... Mar 21 14:50:40.000 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x6961720 for circ_id 3432589531, channel ID 4 (0x772e440) Mar 21 14:50:40.000 [debug] relay_lookup_conn(): found conn for stream 8331. Mar 21 14:50:40.000 [debug] circuit_receive_relay_cell(): Sending to origin. Mar 21 14:50:40.000 [debug] connection_edge_process_relay_cell(): Now seen 21024 relay cells here (command 2, stream 8331). Mar 21 14:50:40.000 [debug] connection_edge_process_relay_cell(): circ deliver_window now 991. Mar 21 14:50:40.000 [debug] connection_or_process_cells_from_inbuf(): 24: starting, inbuf_datalen 274 (0 pending in tls object). Mar 21 14:50:40.000 [debug] connection_bucket_refill_helper(): global_read_bucket now 1073741824. Mar 21 14:50:40.000 [debug] connection_bucket_refill_helper(): global_write_bucket now 1073741824. Mar 21 14:50:40.000 [debug] connection_bucket_refill_helper(): or_conn->read_bucket now 1073741824. Mar 21 14:50:40.000 [debug] connection_bucket_refill_helper(): or_conn->write_bucket now 1073741824. Mar 21 14:50:40.000 [warn] Your system clock just jumped 102 seconds forward; assuming established circuits no longer work. -- Mar 21 15:35:13.000 [debug] connection_bucket_refill_helper(): global_relayed_write_bucket now 1073741824. Mar 21 15:35:13.000 [debug] connection_bucket_refill_helper(): or_conn->read_bucket now 1073741824. Mar 21 15:35:13.000 [debug] connection_bucket_refill_helper(): or_conn->read_bucket now 1073741824. Mar 21 15:35:13.000 [debug] connection_bucket_refill_helper(): or_conn->write_bucket now 1073741824. Mar 21 15:35:13.000 [debug] connection_bucket_refill_helper(): or_conn->read_bucket now 1073741824. Mar 21 15:35:13.000 [debug] connection_bucket_refill_helper(): or_conn->write_bucket now 1073741824. Mar 21 15:35:13.000 [debug] connection_bucket_refill_helper(): or_conn->read_bucket now 1073741824. Mar 21 15:35:13.000 [debug] connection_bucket_refill_helper(): or_conn->read_bucket now 1073741824. Mar 21 15:35:13.000 [debug] connection_bucket_refill_helper(): or_conn->read_bucket now 1073741824. Mar 21 15:35:13.000 [debug] connection_bucket_refill_helper(): or_conn->write_bucket now 1073741824. Mar 21 15:35:13.000 [warn] Your system clock just jumped 2673 seconds forward; assuming established circuits no longer work.
Doesn't his mean there should be 102-second and 2673-second gaps in the logs? Unfortunately there is so much going on it is hard to spot any gaps. 2673 seconds is roughly the gap between those two warnings.
On 21 Mar 2017, at 01:42, Geoff Down geoffdown@fastmail.net wrote: ... The usual SIGINT shutdown hangs as well - have to send a second SIGINT.
No, this is by design, to allow users to migrate connections. See ShutdownWaitLength in the tor manual page.
This could also be happening if your relay's clock changes during the ShutdownWaitLength period.
What is ShutdownWaitLength set to in your torrc or default torrc?
On 22 Mar 2017, at 07:03, Geoff Down geoffdown@fastmail.net wrote:
On Tue, Mar 21, 2017, at 09:27 AM, teor wrote:
Can you try setting an explicit IP address for your bridge, using: Address NNN.NNN.NNN.NNN in the torrc?
We might not have fixed all instances of this issue in 20423.
Done, (SIGINT still hadn't shut down after 10 minutes btw) then
Please see my reply above: this could be a clock issue on your side, or it could be a config issue, or it could be a bug in tor.
I opened #21809 for this: https://trac.torproject.org/projects/tor/ticket/21809
Mar 21 14:24:01.000 [notice] Tor 0.2.9.10 opening new log file. ... Mar 21 14:50:40.000 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x6961720 for circ_id 3432589531, channel ID 4 (0x772e440) Mar 21 14:50:40.000 [debug] relay_lookup_conn(): found conn for stream 8331. Mar 21 14:50:40.000 [debug] circuit_receive_relay_cell(): Sending to origin. Mar 21 14:50:40.000 [debug] connection_edge_process_relay_cell(): Now seen 21024 relay cells here (command 2, stream 8331). ... Mar 21 14:50:40.000 [warn] Your system clock just jumped 102 seconds forward; assuming established circuits no longer work. --
(Please don't put -- in your emails. Some people use broken mail readers that hide everything below a -- .)
Mar 21 15:35:13.000 [debug] connection_bucket_refill_helper(): global_relayed_write_bucket now 1073741824. ... Mar 21 15:35:13.000 [warn] Your system clock just jumped 2673 seconds forward; assuming established circuits no longer work.
Doesn't his mean there should be 102-second and 2673-second gaps in the logs? Unfortunately there is so much going on it is hard to spot any gaps. 2673 seconds is roughly the gap between those two warnings.
That's helpful. Thanks!
I made a note on #20423: https://trac.torproject.org/projects/tor/ticket/20423
T
-- Tim Wilson-Brown (teor)
teor2345 at gmail dot com PGP C855 6CED 5D90 A0C5 29F6 4D43 450C BA7F 968F 094B ricochet:ekmygaiu4rzgsk6n xmpp: teor at torproject dot org ------------------------------------------------------------------------
On Fri, Mar 24, 2017, at 07:35 AM, teor wrote:
On 21 Mar 2017, at 01:42, Geoff Down geoffdown@fastmail.net wrote: ... The usual SIGINT shutdown hangs as well - have to send a second SIGINT.
What is ShutdownWaitLength set to in your torrc or default torrc?
Not set.
Done, (SIGINT still hadn't shut down after 10 minutes btw) then
Please see my reply above: this could be a clock issue on your side, or it could be a config issue, or it could be a bug in tor.
I opened #21809 for this: https://trac.torproject.org/projects/tor/ticket/21809
Doesn't his mean there should be 102-second and 2673-second gaps in the
logs? Unfortunately there is so much going on it is hard to spot any gaps. 2673 seconds is roughly the gap between those two warnings.
That's helpful. Thanks!
I'm still getting occasional read timeouts (via Polipo) from a site that is entirely reliable over clearnet, and occasional 'Failed to receive SOCKS5 connect request ack' from another site when using curl in socks5hproxy mode. I've had no more clock jumps in the last 70 hours though. If there's nothing more I can do to debug this (and since my IP could change at any time), I'll go back a Tor version and remove the Address line. GD
On Fri, Mar 24, 2017, at 01:35 PM, Geoff Down wrote:
I'm still getting occasional read timeouts (via Polipo) from a site that is entirely reliable over clearnet, and occasional 'Failed to receive SOCKS5 connect request ack' from another site when using curl in
socks5hproxy mode.
I've had no more clock jumps in the last 70 hours though.
If there's nothing more I can do to debug this (and since my IP could change at any time), I'll go back a Tor version and remove the Address line.
72 hours now on 2.9.9 with no clock jumps. Still occasional timeouts as per above. GD
On Tue, Mar 28, 2017 at 02:22:17PM +0100, Geoff Down wrote:
72 hours now on 2.9.9 with no clock jumps. Still occasional timeouts as per above.
Hi Geoff,
Any news on your strange clock jumps? Have you tried Tor 0.3.0.x for your bridge or relay also?
I ask because https://trac.torproject.org/projects/tor/ticket/20423 remains open but nobody has any new news.
Thanks, --Roger
On Mon, May 15, 2017, at 10:20 AM, Roger Dingledine wrote:
On Tue, Mar 28, 2017 at 02:22:17PM +0100, Geoff Down wrote:
72 hours now on 2.9.9 with no clock jumps. Still occasional timeouts as per above.
Hi Geoff,
Any news on your strange clock jumps? Have you tried Tor 0.3.0.x for your bridge or relay also?
I ask because https://trac.torproject.org/projects/tor/ticket/20423 remains open but nobody has any new news.
Thanks, --Roger
with 2.9.9 it kept happening, for instance four times on the 12th May. I went back to 2.9.8 on that day , and have stopped being a relay altogether. No time jumps since then, but lots of hangups that only a HUP or a restart seem to fix. Do you suggest Tor 0.3.0.x in client mode first? GD
On Mon, May 15, 2017, at 10:20 AM, Roger Dingledine wrote:
On Tue, Mar 28, 2017 at 02:22:17PM +0100, Geoff Down wrote:
72 hours now on 2.9.9 with no clock jumps. Still occasional timeouts as per above.
Hi Geoff,
Any news on your strange clock jumps? Have you tried Tor 0.3.0.x for your bridge or relay also?
I ask because https://trac.torproject.org/projects/tor/ticket/20423 remains open but nobody has any new news.
Thanks, --Roger
First run client only: some old bad relays and all GB exits are excluded. May 18 09:50:56.000 [notice] Tor 0.3.0.7 (git-cfd9c1bdc0582656) opening new log file. May 18 09:50:56.507 [warn] You have asked to exclude certain relays from all positions in your circuits. Expect hidden services and other Tor features to be broken in unpredictable ways. ... May 18 10:11:16.000 [notice] Tor has successfully opened a circuit. Looks like client functionality is working. May 18 10:11:16.000 [notice] Bootstrapped 100%: Done May 18 15:45:50.000 [notice] Your system clock just jumped 19950 seconds forward; assuming established circuits no longer work. May 18 15:46:15.000 [notice] Tor has successfully opened a circuit. Looks like client functionality is working.
tor-relays@lists.torproject.org
-
Geoff Down -
Roger Dingledine -
teor