Are you running Tor as a client (only), or as a client and a relay?
Gravitas replied the following to the e-mail notification (which went to tor-assistants): "As a pure exit relay, on a dedicated server hired from an ISP.".
Gravitas: In the future, please reply on trac so that your reply is visible to everybody.
Are you running Tor as a client (only), or as a client and a relay?
Gravitas replied the following to the e-mail notification (which went to tor-assistants): "As a pure exit relay, on a dedicated server hired from an ISP.".
Gravitas: In the future, please reply on trac so that your reply is visible to everybody.
Will do. I thought that replying to the email notification would add it into the ticket, but now that I know that its just a notification, its no problem to manually submit any replies into the ticketing system.
Interesting: I am now running PeerBlock v1.1 on my Windows server, and the frequency of these errors has dramatically dropped. This is the complete log after running Tor for 3.5 hours (normally, I would expect a warning every minute or so):
---start log---
Jan 30 12:12:29.789 [Notice] Tor v0.2.4.9-alpha (git-23dd7c901287d7d8) running on Windows Vista [server] with Libevent 2.0.21-stable and OpenSSL 1.0.1c.
Jan 30 12:12:29.789 [Notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
Jan 30 12:12:29.789 [Notice] This version is not a stable Tor release. Expect more bugs than usual.
Jan 30 12:12:30.008 [Notice] Read configuration file "C:\Users\Administrator\AppData\Local\Vidalia\torrc".
Jan 30 12:12:30.226 [Notice] Opening Socks listener on 127.0.0.1:9050
Jan 30 12:12:30.226 [Notice] Opening Control listener on 127.0.0.1:9051
Jan 30 12:12:30.226 [Notice] Opening OR listener on 0.0.0.0:443
Jan 30 12:12:30.226 [Notice] Opening Directory listener on 0.0.0.0:9030
Jan 30 12:12:55.701 [Notice] Parsing GEOIP IPv4 file C:\Users\Administrator\AppData\Roaming\tor\geoip.
Jan 30 12:12:55.701 [Notice] Your Tor server's identity key fingerprint is 'programmercpp C3627DBECAF75618817C27DFB65DBF0C4CA52FA7'
Jan 30 12:12:55.701 [Notice] We now have enough directory information to build circuits.
Jan 30 12:12:55.701 [Notice] Bootstrapped 80%: Connecting to the Tor network.
Jan 30 12:12:55.701 [Notice] New control connection opened.
Jan 30 12:12:57.074 [Notice] Bootstrapped 85%: Finishing handshake with first hop.
Jan 30 12:12:57.604 [Notice] Bootstrapped 90%: Establishing a Tor circuit.
Jan 30 12:12:57.713 [Warning] Your Guard OnionSoup=08D22679377C9EF701193C1F199D9B0B3F1AEE3C is failing a very large amount of circuits. Most likely this means the Tor network is overloaded, but it could also mean an attack against you or the potentially the guard itself. Success counts are 71/154. 71 circuits completed, 0 were unusable, 0 collapsed, and 0 timed out. For reference, your timeout cutoff is 60 seconds.
Jan 30 12:13:00.194 [Notice] Tor has successfully opened a circuit. Looks like client functionality is working.
Jan 30 12:13:00.194 [Notice] Bootstrapped 100%: Done.
Jan 30 12:13:00.194 [Notice] Now checking whether ORPort 213.171.220.40:443 and DirPort 213.171.220.40:9030 are reachable... (this may take up to 20 minutes -- look for log messages indicating success)
Jan 30 12:13:08.571 [Notice] Self-testing indicates your ORPort is reachable from the outside. Excellent. Publishing server descriptor.
Jan 30 12:13:09.382 [Notice] Self-testing indicates your DirPort is reachable from the outside. Excellent.
Jan 30 12:17:07.033 [Notice] Performing bandwidth self-test...done.
Jan 30 13:34:24.725 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 13:41:00.841 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
---end log as of Jan 30 15:55:00.00--
This message happens when the client thinks the circuit packaging window has decreased sufficiently (meaning your exit relay has read-from-the-network-and-sent 100 cells on the circuit towards the client), but your exit relay doesn't think it has packaged and sent that many cells. So it can either happen because the client and exit are off-sync (bug), or because the client is sending the cell anyway (protocol violation). See #6252 (moved) for more background on why this log message went in.
That strengthens my "something on the exit side doesn't decrement the package window when it should, or something on the client side decrements the deliver window when it shouldn't" theory.
Is the answer that the #7889 (moved) fix needs to decrement the receive window, but doesn't?
I don't think that can be the answer, since it's the deliver window on the exit side that's not getting decremented. Still that's a bug. I've made a fix for it in not_bug8093.
Oh duh; this could be related to bug #7889 (moved) in the other way. If you successfully got a circuit with stream ID 0 (possible before the bug #7889 (moved) fix), then eventually the other side would send a SENDME with stream ID 0, meaning to refer to the stream, but eventually referring to the circuit.
We haven't yet put out an 0.2.3 with the #7889 (moved) fix IIRC.
20:23 < nickm> I think saying "bug/attack" here is misleading. It could be somebody else's bug. It could be our own bug. It could be an attack... probably not, though, since anybody doing this attack would be dumb to target servers that detect it, warn about it, and don't let it procede20:23 < nickm> The fact that the mode is 901 suggests that "somebody's got a bug" is the likeliest explanation20:26 < nickm> Maybe downgrade the warning to PROTOCOL_WARN in 0.2.4, leave it at warn but rewrite it in 0.2.5, and add some feature to count cells somewhere independently of the current count to see if there's any relay-side miscount?20:27 < nickm> The fact that this has only been reported relay-side suggests even stronger to me that it could be broken clients20:30 < nickm> does that seem plausible?20:31 < athena> yeah, agree make it PROTOCOL_WARN since we don't know the cause, just that we saw something weird20:31 < athena> and add instrumentation
Not sure if more information is needed here or not -- I noticed this warning in my logs from yesterday, accompanied by a few other warnings at the exact same time(s).
I think I may have some clue as to what's going on. It was my habit to use Google's DNS which is 8.8.8.8 and 8.8.4.4. This issue has been occurring continuously using these DNS settings.
I switched broadband company a few weeks ago, and as usual I configured everything to use Google's DNS. The problem continued. I then tried using the www.opendns.com settings which are 208.67.222.222 and 208.67.220.220, and all of these messages disappeared, and everything is running rock solid now.
I wonder why using Google's DNS settings would result in this behaviour?
Just a word of caution: OpenDNS and many other DNS providers heavily filter and manipulate DNS replies. If you want to continue to use OpenDNS on a Tor relay, make sure you register there and disable the filters.
I wonder why using Google's DNS settings would result in this behaviour?
Google do not filters DNS replies, and as said:
OpenDNS and many other DNS providers heavily filter and manipulate DNS replies
Client that triggers that message tried streams with target address filtered by OpenDNS. If stream failed then no circuit used and no broken number of sendme cells.
It's theory that could explain something.
Saw that warning message in Tor 0.2.5.6-alpha (git-4410634e67a43952), 2 occurrences in 1 day. Non-exit relay $D3ED911183DF31FDB744A22F94BE6A856AC77D12
Debian 6.0.10 using package "tor 0.2.5.6-alpha-1~d60.squeeze+1" from tpo repo.
FWIW I do experience this on a 0.2.5.8-rc Tor non-exit relay, where no Google DNS is used (AFAICT). It happened about 2 dozen times within last 2 days, but not before.
I haven't noticed this before - but I experience this as well, running 0.2.5.8-rc non-exit official repository from torproject.org on Ubuntu 12.04 LTS.
Using Google DNSes, speed average around 1.5 Mb/sec.
My log (short uptime of tor is because of the upgraded tor package):
Sep 28 14:14:38.000 [notice] Heartbeat: Tor's uptime is 3 days 6:00 hours, with 403 circuits open. I've sent 51.91 GB and received 49.34 GB.Sep 28 14:14:38.000 [notice] Average packaged cell fullness: 98.948%Sep 28 14:14:38.000 [notice] TLS write overhead: 5%Sep 28 14:14:38.000 [notice] Circuit handshake stats since last time: 21558/21558 TAP, 8622/8622 NTor.Sep 28 14:16:14.000 [warn] Unexpected sendme cell from client. Closing circ (window 1000).Sep 28 15:14:41.000 [warn] Unexpected sendme cell from client. Closing circ (window 1000).Sep 28 20:14:38.000 [notice] Heartbeat: Tor's uptime is 3 days 12:00 hours, with 447 circuits open. I've sent 55.19 GB and received 52.35 GB.Sep 28 20:14:38.000 [notice] Average packaged cell fullness: 98.945%Sep 28 20:14:38.000 [notice] TLS write overhead: 5%Sep 28 20:14:38.000 [notice] Circuit handshake stats since last time: 25245/25245 TAP, 9413/9413 NTor.Sep 28 22:37:04.000 [warn] Unexpected sendme cell from client. Closing circ (window 1000).Sep 28 22:51:32.000 [warn] Unexpected sendme cell from client. Closing circ (window 1000).Sep 28 23:48:50.000 [warn] Unexpected sendme cell from client. Closing circ (window 1000).Sep 29 02:14:38.000 [notice] Heartbeat: Tor's uptime is 3 days 18:00 hours, with 386 circuits open. I've sent 58.69 GB and received 55.67 GB.Sep 29 02:14:38.000 [notice] Average packaged cell fullness: 98.940%Sep 29 02:14:38.000 [notice] TLS write overhead: 5%Sep 29 02:14:38.000 [notice] Circuit handshake stats since last time: 18047/18047 TAP, 9571/9571 NTor.Sep 29 08:14:30.000 [notice] Caching new entry debian-tor for debian-torSep 29 08:14:38.000 [notice] Heartbeat: Tor's uptime is 4 days 0:00 hours, with 439 circuits open. I've sent 61.63 GB and received 58.46 GB.Sep 29 08:14:38.000 [notice] Average packaged cell fullness: 98.934%Sep 29 08:14:38.000 [notice] TLS write overhead: 5%Sep 29 08:14:38.000 [notice] Circuit handshake stats since last time: 17822/17822 TAP, 10663/10663 NTor.Sep 29 08:20:13.000 [warn] Unexpected sendme cell from client. Closing circ (window 1000).Sep 29 08:35:48.000 [notice] New control connection opened.Sep 29 08:36:16.000 [warn] Unexpected sendme cell from client. Closing circ (window 1000).Sep 29 08:37:14.000 [notice] New control connection opened.Sep 29 08:39:09.000 [notice] New control connection opened.Sep 29 08:46:51.000 [warn] Unexpected sendme cell from client. Closing circ (window 1000).Sep 29 08:57:17.000 [notice] New control connection opened.Sep 29 08:58:55.000 [notice] New control connection opened.
OT, and don't want hijack this bug, but : under Gentoo I'm also still looking for a way to avoid the sudo - currently it won't work, b/c the cookie can be read only by tor user itself, not by its group member
Can we decide whether this is bad and we need to fix it or not warn about it? I get up to
[warn] Unexpected sendme cell from client. Closing circ (window 1000). [60 similar message(s) suppressed in last 600 seconds]
in my logs (0.2.5.8-rc), which seems like a good way to get a lot of useless bug reports.