There is something really strange going on indeed. What I noticed is an increase of circuits and my device running out of memory until it stopped working so I had to reboot it on 31. Jan. Then again the memory usage increased until it leveled out at a rather unusual, high usage. The actual bandwidth usage is not unusual though (always around 2Mbps on my relay).
Attached a screenshot of my memory usage the last few days (I hope attachments do work here; it's in fact Tor using that memory as could be checked with ps and htop).
Heartbeat messages of the log are:
Jan 31 10:57:56.000 [notice] Heartbeat: Tor's uptime is 6:00 hours, with 447 circuits open. I've sent 2.66 GB and received 2.65 GB. Jan 31 16:57:56.000 [notice] Heartbeat: Tor's uptime is 12:00 hours, with 19764 circuits open. I've sent 9.59 GB and received 9.54 GB. Jan 31 22:57:56.000 [notice] Heartbeat: Tor's uptime is 18:00 hours, with 54178 circuits open. I've sent 12.36 GB and received 12.30 GB. Feb 01 04:57:56.000 [notice] Heartbeat: Tor's uptime is 23:50 hours, with 79333 circuits open. I've sent 14.89 GB and received 14.81 GB. Feb 01 10:57:56.000 [notice] Heartbeat: Tor's uptime is 1 day 5:50 hours, with 110815 circuits open. I've sent 19.55 GB and received 19.45 GB. Feb 01 16:57:56.000 [notice] Heartbeat: Tor's uptime is 1 day 11:50 hours, with 141724 circuits open. I've sent 24.03 GB and received 23.90 GB. Feb 01 22:57:56.000 [notice] Heartbeat: Tor's uptime is 1 day 17:50 hours, with 12829 circuits open. I've sent 29.96 GB and received 29.75 GB.
‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Friday, 1. February 2019 23:50, Roman Mamedov rm@romanrm.net wrote:
Hello,
There seems to be an issue with Tor's memory usage. Earlier today, with Tor 3.5.7 and 1.5 GB of RAM running two Tor processes, the machine got 430 MB into swap, slowing down to a crawl from iowait on accessing the swapped out memory. Typically 1.5 GB is more than enough for these. "VIRT" in top was ~1GB each, and "RES" was ~512MB each. Which is weird because that doesn't add up to exhausting the 1.5 GB, and there are no other heavy processes on the machine running. I rebooted it without further investigation.
And right now on another machine running 2.9.16 I see:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 22432 debian-+ 30 10 5806816 5.157g 10464 R 39.5 33.1 39464:19 tor
But not sure if it just accumulated 5.1GB of RAM slowly over time, or shot up recently.
Feb 01 17:00:49.000 [notice] Heartbeat: Tor's uptime is 82 days 23:59 hours, with 70705 circuits open. I've sent 66622.45 GB and received 65906.91 GB. Feb 01 17:00:49.000 [notice] Circuit handshake stats since last time: 11361/11361 TAP, 239752/239752 NTor. Feb 01 17:00:49.000 [notice] Since startup, we have initiated 0 v1 connections, 0 v2 connections, 10 v3 connections, and 3385644 v4 connections; and received 14 v1 connections, 78592 v2 connections, 822108 v3 connections, and 8779474 v4 connections. Feb 01 17:00:49.000 [notice] DoS mitigation since startup: 2899572 circuits rejected, 121 marked addresses. 561 connections closed. 21956 single hop clients refused. Feb 01 17:08:20.000 [warn] connection_edge_process_relay_cell (at origin) failed.
With respect, Roman
tor-relays mailing list tor-relays@lists.torproject.org https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-relays
On 02 Feb (04:10:02), petrarca@protonmail.ch wrote:
Hi, thanks for the report!
There is something really strange going on indeed. What I noticed is an increase of circuits and my device running out of memory until it stopped working so I had to reboot it on 31. Jan. Then again the memory usage increased until it leveled out at a rather unusual, high usage. The actual bandwidth usage is not unusual though (always around 2Mbps on my relay).
Attached a screenshot of my memory usage the last few days (I hope attachments do work here; it's in fact Tor using that memory as could be checked with ps and htop).
Heartbeat messages of the log are:
Jan 31 10:57:56.000 [notice] Heartbeat: Tor's uptime is 6:00 hours, with 447 circuits open. I've sent 2.66 GB and received 2.65 GB. Jan 31 16:57:56.000 [notice] Heartbeat: Tor's uptime is 12:00 hours, with 19764 circuits open. I've sent 9.59 GB and received 9.54 GB. Jan 31 22:57:56.000 [notice] Heartbeat: Tor's uptime is 18:00 hours, with 54178 circuits open. I've sent 12.36 GB and received 12.30 GB. Feb 01 04:57:56.000 [notice] Heartbeat: Tor's uptime is 23:50 hours, with 79333 circuits open. I've sent 14.89 GB and received 14.81 GB. Feb 01 10:57:56.000 [notice] Heartbeat: Tor's uptime is 1 day 5:50 hours, with 110815 circuits open. I've sent 19.55 GB and received 19.45 GB. Feb 01 16:57:56.000 [notice] Heartbeat: Tor's uptime is 1 day 11:50 hours, with 141724 circuits open. I've sent 24.03 GB and received 23.90 GB. Feb 01 22:57:56.000 [notice] Heartbeat: Tor's uptime is 1 day 17:50 hours, with 12829 circuits open. I've sent 29.96 GB and received 29.75 GB.
Do you see some sort of increase during that time period of the DoS mitigation stats? It would be the heartbeat line that starts with:
"DoS mitigation since startup:" ...
Burst of circuits are possible for many reasons. But, if that leads to high memory usage and that doesn't come back down to a normal level once the bursts are over, we may have a problem.
If you end up with any more logs about this or if your relay gets OOMed, please share so we can investigate what is going on.
Thanks! David
‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Friday, 1. February 2019 23:50, Roman Mamedov rm@romanrm.net wrote:
Hello,
There seems to be an issue with Tor's memory usage. Earlier today, with Tor 3.5.7 and 1.5 GB of RAM running two Tor processes, the machine got 430 MB into swap, slowing down to a crawl from iowait on accessing the swapped out memory. Typically 1.5 GB is more than enough for these. "VIRT" in top was ~1GB each, and "RES" was ~512MB each. Which is weird because that doesn't add up to exhausting the 1.5 GB, and there are no other heavy processes on the machine running. I rebooted it without further investigation.
And right now on another machine running 2.9.16 I see:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 22432 debian-+ 30 10 5806816 5.157g 10464 R 39.5 33.1 39464:19 tor
But not sure if it just accumulated 5.1GB of RAM slowly over time, or shot up recently.
Feb 01 17:00:49.000 [notice] Heartbeat: Tor's uptime is 82 days 23:59 hours, with 70705 circuits open. I've sent 66622.45 GB and received 65906.91 GB. Feb 01 17:00:49.000 [notice] Circuit handshake stats since last time: 11361/11361 TAP, 239752/239752 NTor. Feb 01 17:00:49.000 [notice] Since startup, we have initiated 0 v1 connections, 0 v2 connections, 10 v3 connections, and 3385644 v4 connections; and received 14 v1 connections, 78592 v2 connections, 822108 v3 connections, and 8779474 v4 connections. Feb 01 17:00:49.000 [notice] DoS mitigation since startup: 2899572 circuits rejected, 121 marked addresses. 561 connections closed. 21956 single hop clients refused. Feb 01 17:08:20.000 [warn] connection_edge_process_relay_cell (at origin) failed.
With respect, Roman
tor-relays mailing list tor-relays@lists.torproject.org https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-relays
tor-relays mailing list tor-relays@lists.torproject.org https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-relays
Observed some, but not huge.
CPU: [image: image.png]
Bandwidth: [image: image.png]
Connections (in: green, out: blue) (note: I've lost uplink on Tue) [image: image.png]
Mem [image: image.png]
Consensus (=green, rate limit=blue) [image: image.png]
DoS logs, increasing but no jumps (reduced line lengths) Jan 23 10:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 1305 single refused. Jan 23 16:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 1344 single refused. Jan 23 22:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 1412 single refused. Jan 24 04:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 1443 single refused. Jan 24 10:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 1483 single refused. Jan 24 16:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 1538 single refused. Jan 24 22:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 1604 single refused. Jan 25 04:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 1622 single refused. Jan 25 10:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 1650 single refused. Jan 25 16:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 1683 single refused. Jan 25 22:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 1734 single refused. Jan 26 04:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 1753 single refused. Jan 26 10:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 1782 single refused. Jan 26 16:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 1805 single refused. Jan 26 22:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 1828 single refused. Jan 27 04:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 1854 single refused. Jan 27 10:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 1870 single refused. Jan 27 16:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 1905 single refused. Jan 27 22:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 1940 single refused. Jan 28 04:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 1966 single refused. Jan 28 10:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 2019 single refused. Jan 28 16:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 2081 single refused. Jan 28 22:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 2187 single refused. Jan 29 04:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 2227 single refused. Jan 29 10:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 2252 single refused. Jan 29 16:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 2311 single refused. Jan 29 22:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 2365 single refused. Jan 30 04:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 2387 single refused. Jan 30 10:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 2409 single refused. Jan 30 16:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 2453 single refused. Jan 30 22:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 2503 single refused. Jan 31 04:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 2531 single refused. Jan 31 10:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 2545 single refused. Jan 31 16:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 2590 single refused. Jan 31 22:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 2653 single refused. Feb 01 04:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 2671 single refused. Feb 01 10:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 2699 single refused. Feb 01 16:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 2744 single refused. Feb 01 22:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 2784 single refused. Feb 02 04:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 2805 single refused. Feb 02 10:04:21 DoS: 0 killed. 0 rejected, 0 marked. 0 closed. 2828 single refused.
Seb
On Sat, 2 Feb 2019 at 11:02, David Goulet dgoulet@torproject.org wrote:
On 02 Feb (04:10:02), petrarca@protonmail.ch wrote:
Hi, thanks for the report!
There is something really strange going on indeed. What I noticed is an
increase of circuits and my device running out of memory until it stopped working so I had to reboot it on 31. Jan. Then again the memory usage increased until it leveled out at a rather unusual, high usage. The actual bandwidth usage is not unusual though (always around 2Mbps on my relay).
Attached a screenshot of my memory usage the last few days (I hope
attachments do work here; it's in fact Tor using that memory as could be checked with ps and htop).
Heartbeat messages of the log are:
Jan 31 10:57:56.000 [notice] Heartbeat: Tor's uptime is 6:00 hours, with
447 circuits open. I've sent 2.66 GB and received 2.65 GB.
Jan 31 16:57:56.000 [notice] Heartbeat: Tor's uptime is 12:00 hours,
with 19764 circuits open. I've sent 9.59 GB and received 9.54 GB.
Jan 31 22:57:56.000 [notice] Heartbeat: Tor's uptime is 18:00 hours,
with 54178 circuits open. I've sent 12.36 GB and received 12.30 GB.
Feb 01 04:57:56.000 [notice] Heartbeat: Tor's uptime is 23:50 hours,
with 79333 circuits open. I've sent 14.89 GB and received 14.81 GB.
Feb 01 10:57:56.000 [notice] Heartbeat: Tor's uptime is 1 day 5:50
hours, with 110815 circuits open. I've sent 19.55 GB and received 19.45 GB.
Feb 01 16:57:56.000 [notice] Heartbeat: Tor's uptime is 1 day 11:50
hours, with 141724 circuits open. I've sent 24.03 GB and received 23.90 GB.
Feb 01 22:57:56.000 [notice] Heartbeat: Tor's uptime is 1 day 17:50
hours, with 12829 circuits open. I've sent 29.96 GB and received 29.75 GB.
Do you see some sort of increase during that time period of the DoS mitigation stats? It would be the heartbeat line that starts with:
"DoS mitigation since startup:" ...Burst of circuits are possible for many reasons. But, if that leads to high memory usage and that doesn't come back down to a normal level once the bursts are over, we may have a problem.
If you end up with any more logs about this or if your relay gets OOMed, please share so we can investigate what is going on.
Thanks! David
‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Friday, 1. February 2019 23:50, Roman Mamedov rm@romanrm.net wrote:
Hello,
There seems to be an issue with Tor's memory usage. Earlier today, with Tor 3.5.7 and 1.5 GB of RAM running two Tor
processes, the
machine got 430 MB into swap, slowing down to a crawl from iowait on
accessing
the swapped out memory. Typically 1.5 GB is more than enough for
these. "VIRT"
in top was ~1GB each, and "RES" was ~512MB each. Which is weird
because that
doesn't add up to exhausting the 1.5 GB, and there are no other heavy processes on the machine running. I rebooted it without further
investigation.
And right now on another machine running 2.9.16 I see:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 22432 debian-+ 30 10 5806816 5.157g 10464 R 39.5 33.1 39464:19 tor
But not sure if it just accumulated 5.1GB of RAM slowly over time, or
shot up
recently.
Feb 01 17:00:49.000 [notice] Heartbeat: Tor's uptime is 82 days 23:59
hours,
with 70705 circuits open. I've sent 66622.45 GB and received 65906.91
GB.
Feb 01 17:00:49.000 [notice] Circuit handshake stats since last time: 11361/11361 TAP, 239752/239752 NTor. Feb 01 17:00:49.000 [notice] Since startup, we have initiated 0 v1 connections, 0 v2 connections, 10 v3 connections, and 3385644 v4
connections;
and received 14 v1 connections, 78592 v2 connections, 822108 v3
connections,
and 8779474 v4 connections. Feb 01 17:00:49.000 [notice] DoS mitigation since startup: 2899572
circuits
rejected, 121 marked addresses. 561 connections closed. 21956 single
hop clients refused.
Feb 01 17:08:20.000 [warn] connection_edge_process_relay_cell (at
origin)
failed.
With respect, Roman
tor-relays mailing list tor-relays@lists.torproject.org https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-relays
tor-relays mailing list tor-relays@lists.torproject.org https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-relays
-- UfBKIa+1kdl7DdvHs4X6EOXF+4kISRk8P8gM6dH/i1E= _______________________________________________ tor-relays mailing list tor-relays@lists.torproject.org https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-relays
A week or two ago someone was scanning entire 80-bit onion space in big parallel. They later said they stopped upon advisement of the futility. But you never know.
tor-relays@lists.torproject.org
-
David Goulet -
grarpamp -
petrarca＠protonmail.ch -
r1610091651