Opened 6 years ago

Closed 17 months ago

#8093 closed defect (fixed)

Jan 29 23:32:20.066 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.

Reported by: Gravitas Owned by: nickm
Priority: Medium Milestone: Tor: unspecified
Component: Core Tor/Tor Version: Tor: 0.2.4.9-alpha
Severity: Normal Keywords: spammy-warnings, tor-client, needs-insight
Cc: Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

Tor repeatedly logs the following warning to the log:

Jan 29 23:32:20.066 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.

My tor client is transferring up to 1MB per second. To give you an idea of how frequent the messages are, here is a sample from the log:

Jan 30 08:02:38.565 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:08:35.479 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:09:42.842 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:11:43.152 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:14:56.327 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:19:33.993 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:19:41.684 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:19:51.278 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:20:46.170 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:22:21.517 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:24:21.550 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:26:02.562 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:26:03.966 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:26:28.745 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:27:57.262 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:28:20.702 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:31:24.491 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:32:31.640 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:33:11.243 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:33:25.613 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:35:20.153 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:36:14.547 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:36:19.196 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:37:26.787 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:37:32.013 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:37:54.571 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:38:24.782 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:48:50.658 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 30 08:50:09.286 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.

Child Tickets

Attachments (1)

debug.log (46.8 KB) - added by alphawolf 4 years ago.

Download all attachments as: .zip

Change History (51)

comment:1 Changed 6 years ago by rransom

Are you running Tor as a client (only), or as a client and a relay?

comment:2 in reply to:  1 ; Changed 6 years ago by phw

Replying to rransom:

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.

comment:3 in reply to:  1 Changed 6 years ago by Gravitas

Replying to rransom:

Are you running Tor as a client (only), or as a client and a relay?

As a pure exit relay, on a dedicated server hired from an ISP.

comment:4 in reply to:  2 Changed 6 years ago by Gravitas

Replying to phw:

Replying to rransom:

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.

comment:5 Changed 6 years ago by Gravitas

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--

comment:6 Changed 6 years ago by mo

Please do not modify or filter traffic coming to or leaving your exit.

I also see these warnings sometimes on my exits, example:

# grep "Bug/attack: unexpected sendme" /var/log/tor/*.log | wc -l
46

comment:7 Changed 6 years ago by Gravitas

Update: the warnings are back with a vengance:

---start log---
Jan 31 08:11:49.542 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:13:35.014 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:16:10.171 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:16:16.895 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:16:28.954 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:17:32.695 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:17:53.896 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:18:41.288 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:20:44.638 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:22:23.963 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:24:10.043 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:24:59.323 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:27:05.278 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:29:47.892 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:33:17.447 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:35:33.338 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:36:32.884 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:38:58.541 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:39:33.750 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:39:42.330 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:41:26.476 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:43:53.599 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:46:10.349 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:47:29.534 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:47:55.306 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:52:00.818 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:52:50.208 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:53:16.634 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:53:43.310 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:56:06.643 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:56:31.151 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 08:58:49.008 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 09:00:03.030 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 09:01:23.370 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 09:03:50.104 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 09:04:53.564 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 09:07:22.295 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 09:07:26.398 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 09:07:44.884 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 09:08:36.473 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 09:09:11.167 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 09:12:12.392 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 09:12:15.185 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 09:13:19.426 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 09:13:49.986 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 09:13:50.922 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 09:14:07.208 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 09:15:34.350 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 09:17:03.395 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
Jan 31 09:19:07.867 [Warning] Bug/attack: unexpected sendme cell from client. Closing circ.
---end log---

comment:8 Changed 6 years ago by arma

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 for more background on why this log message went in.

comment:9 Changed 6 years ago by arma

diff --git a/src/or/relay.c b/src/or/relay.c
index f711eae..1289f7d 100644
--- a/src/or/relay.c
+++ b/src/or/relay.c
@@ -1443,7 +1443,8 @@ connection_edge_process_relay_cell(cell_t *cell, circuit_
             /*XXXX024: Downgrade this back to LOG_PROTOCOL_WARN after a while*
             log_fn(LOG_WARN, LD_PROTOCOL,
                    "Bug/attack: unexpected sendme cell from client. "
-                   "Closing circ.");
+                   "Closing circ (window %d).",
+                   circ->package_window);
             return -END_CIRC_REASON_TORPROTOCOL;
           }
           circ->package_window += CIRCWINDOW_INCREMENT;

seems like the clear first step in debugging.

comment:10 Changed 6 years ago by mo

# egrep -ho '\(window.*\)' notices*.log | tr -d \(window\ \) | sort | uniq -c | sort -nr

     11 904
     11 901
     10 915
     10 905
      9 907
      8 902
      7 920
      7 906
      6 916
      6 914
      6 911
      6 909
      5 921
      5 903
      4 913
      4 910
      3 917
      3 912
      3 908
      2 942
      2 938
      2 932
      2 925
      2 924
      2 923
      2 922
      2 918
      1 943
      1 940
      1 939
      1 936
      1 934
      1 933
      1 929
      1 928
      1 927
      1 926
      1 919

comment:11 Changed 6 years ago by arma

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.

comment:12 Changed 6 years ago by nickm

Cypherpunks on #7889 suggests that the fix for that bug could be at fault here.

comment:13 Changed 6 years ago by arma

This warning message got integrated into Tor 0.2.3.21-rc, which came out Sept 2012.

Did anybody see the warning message between Sept 2012 and Jan 2013, which is when the #7889 fix came out?

comment:14 Changed 6 years ago by asn

FWIW, Mathilde in #tor IRC encountered this message in his/her exit relay running 0.2.4.10 (which includes the #7889 fix).

20:06:20 [WARN] Bug/attack: unexpected sendme cell from client. Closing circ (window 911).

comment:15 Changed 6 years ago by nickm

Keywords: tor-client added

comment:16 Changed 6 years ago by nickm

Is the answer that the #7889 fix needs to decrement the receive window, but doesn't?

comment:17 in reply to:  16 Changed 6 years ago by nickm

Replying to nickm:

Is the answer that the #7889 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.

comment:18 Changed 6 years ago by nickm

Oh duh; this could be related to bug #7889 in the other way. If you successfully got a circuit with stream ID 0 (possible before the bug #7889 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 fix IIRC.

comment:19 Changed 5 years ago by nickm

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 procede
20:23 < nickm> The fact that the mode is 901 suggests that "somebody's got a 
               bug" is the likeliest explanation
20: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 clients
20: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 weird
20:31 < athena> and add instrumentation

comment:20 Changed 5 years ago by nickm

Owner: set to nickm
Status: newaccepted

comment:21 Changed 5 years ago by nickm

Milestone: Tor: 0.2.4.x-finalTor: 0.2.5.x-final
Status: acceptednew

Okay, I've downgraded the warnings in 0.2.4, and made them rate-limited in 0.2.5.

Still to do:

  • "add some feature to count cells somewhere independently of the current count to see if there's any relay-side miscount"

comment:22 Changed 5 years ago by nickm

Keywords: 025-triaged added

comment:23 Changed 5 years ago by nickm

Milestone: Tor: 0.2.5.x-finalTor: 0.2.6.x-final

comment:24 Changed 4 years ago by alphawolf

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).

Jun 11 03:12:38.000 [warn] Unexpected sendme cell from client. Closing circ (window 1000).
Jun 11 03:12:38.000 [warn] connection_edge_process_relay_cell (away from origin) failed.
Jun 11 03:12:38.000 [warn] circuit_receive_relay_cell (forward) failed. Closing.
Jun 11 03:47:16.000 [warn] Unexpected sendme cell from client. Closing circ (window 1000).
Jun 11 03:47:16.000 [warn] connection_edge_process_relay_cell (away from origin) failed.
Jun 11 03:47:16.000 [warn] circuit_receive_relay_cell (forward) failed. Closing.
Jun 11 04:48:17.000 [warn] Unexpected sendme cell from client. Closing circ (window 1000).
Jun 11 04:48:17.000 [warn] connection_edge_process_relay_cell (away from origin) failed.
Jun 11 04:48:17.000 [warn] circuit_receive_relay_cell (forward) failed. Closing.

Version: Tor 0.2.5.4-alpha-dev (git-95d47a74815ede0e)

This is a relay that is also used as a client *only* for IRC.

comment:25 Changed 4 years ago by Gravitas

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?

comment:26 Changed 4 years ago by mo

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.

comment:27 Changed 4 years ago by cypherpunks

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.

Changed 4 years ago by alphawolf

Attachment: debug.log added

comment:28 Changed 4 years ago by alphawolf

Attached debug log corresponds with the 2/10 of a second before (and including) this warning:

Jun 20 13:13:54.178 [warn] Unexpected sendme cell from client. Closing circ (window 1000).

I noticed several instances of circuit_receive_relay_cell(): Passing on unrecognized cell, which seems odd.

This is a non-exit relay/directory mirror that has a SOCKS port open to the local network. IRC is the only client app ever attached to it. I

comment:29 Changed 4 years ago by keb

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.

Last edited 4 years ago by keb (previous) (diff)

comment:30 Changed 4 years ago by arma

I also get it on moria1 sometimes. My current theory is that it's some other implementation of a Tor client, which has a bug in it.

comment:31 Changed 4 years ago by nickm

Keywords: needs-insight added
Milestone: Tor: 0.2.6.x-finalTor: 0.2.???

comment:32 Changed 4 years ago by toralf

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.

comment:33 Changed 4 years ago by robink

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-tor
Sep 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.
Last edited 4 years ago by robink (previous) (diff)

comment:34 in reply to:  33 ; Changed 4 years ago by keb

Replying to robink:

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.

How are you getting so many control connections open that never close? If it is related to the unexpected cells, it would be some sort of exploit.

comment:35 in reply to:  34 ; Changed 4 years ago by robink

Replying to keb:

Replying to robink:

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.

How are you getting so many control connections open that never close? If it is related to the unexpected cells, it would be some sort of exploit.

It's only when I run arm that it logs that message:

sudo -u debian-tor arm

comment:36 in reply to:  35 ; Changed 4 years ago by arma

Replying to robink:

sudo -u debian-tor arm

Btw, you are running arm in an unsafe way: see item 14 on https://www.torproject.org/docs/tor-relay-debian for the better way.

comment:37 in reply to:  36 Changed 4 years ago by toralf

Replying to arma:

Replying to robink:

sudo -u debian-tor arm

Btw, you are running arm in an unsafe way: see item 14 on https://www.torproject.org/docs/tor-relay-debian for the better way.

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

comment:38 Changed 4 years ago by Sebastian

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.

comment:39 Changed 4 years ago by cypherpunks

From the timing of when these warnings occur, it's likely to be an attack. Is there a way to log where it's received from?

comment:40 Changed 4 years ago by Sebastian

Keywords: spammy-warnings added

comment:41 Changed 4 years ago by nanomo

It's happening to me too:

setup: non exit relay only, less than 10 hours after creation.
SO: ubuntu 14.04.1
Tor ver.: official tor repos, Tor 0.2.5.8-rc

13:23:57 [WARN] Unexpected sendme cell from client. Closing circ (window 1000).
10:43:33 [NOTICE] Circuit handshake stats since last time: 0/0 TAP, 7/7 NTor.
10:43:33 [NOTICE] TLS write overhead: 14%
10:43:33 [NOTICE] Average packaged cell fullness: 94.852%

Last edited 4 years ago by nanomo (previous) (diff)

comment:42 in reply to:  39 Changed 4 years ago by arma

Replying to cypherpunks:

From the timing of when these warnings occur, it's likely to be an attack. Is there a way to log where it's received from?

I don't follow your logic here. What does the timing of the warnings have to do with whether it's an attack?

Anybody can cause these warnings to appear, just by sending a sendme cell before you've received 100 relay data cells from that relay yet.

I wonder if Orchid (the Java Tor client) is doing this.

Last edited 3 years ago by arma (previous) (diff)

comment:43 Changed 4 years ago by arma

I support downgrading this log message to protocol-warn severity in 0.2.5.

comment:44 Changed 4 years ago by nickm

Downgraded to PROTOCOL_WARN with ab4b29625db720817f9af502199ebf1ee3ac5af7

comment:45 Changed 3 years ago by arma

Severity: Normal

Ok to close? It's been a long time.

(We should indeed use chutney to see if there are any window synchronization issues, but I think that's a separate and more long-term issue.)

comment:46 Changed 2 years ago by teor

Milestone: Tor: 0.2.???Tor: 0.3.???

Milestone renamed

comment:47 Changed 22 months ago by nickm

Keywords: tor-03-unspecified-201612 added
Milestone: Tor: 0.3.???Tor: unspecified

Finally admitting that 0.3.??? was a euphemism for Tor: unspecified all along.

comment:48 Changed 17 months ago by nickm

Keywords: tor-03-unspecified-201612 removed

Remove an old triaging keyword.

comment:49 Changed 17 months ago by nickm

Keywords: 025-triaged removed

remove an old triage keyword.

comment:50 in reply to:  45 Changed 17 months ago by nickm

Resolution: fixed
Status: newclosed

Replying to arma:

Ok to close? It's been a long time.

Note: See TracTickets for help on using tickets.