Opened 8 years ago

Closed 8 years ago

Last modified 7 years ago

#3700 closed defect (fixed)

Warning when running Windows relay with bufferevents

Reported by: karsten Owned by:
Priority: High Milestone: Tor: 0.2.3.x-final
Component: Core Tor/Tor Version:
Severity: Keywords: tor-relay
Cc: Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

Here's a warning that I got 1.5 minutes after starting my relay running tor-0.2.3.2-alpha-bufferevents-win32.exe (from #2001):

Aug 08 13:21:59.000 [warn] TLS error while handshaking (with bufferevent) with [scrubbed]: http request (in SSL routines:SSL23_GET_CLIENT_HELLO:SSL23_ST_SR_CLNT_HELLO_A)

And just a second before submitting this bug, here are two more:

Aug 08 13:42:32.000 [warn] TLS error while handshaking (with bufferevent) with [scrubbed]: http request (in SSL routines:SSL23_GET_CLIENT_HELLO:SSL23_ST_SR_CLNT_HELLO_A)
Aug 08 13:42:52.000 [warn] TLS error while handshaking (with bufferevent) with [scrubbed]: http request (in SSL routines:SSL23_GET_CLIENT_HELLO:SSL23_ST_SR_CLNT_HELLO_A)

Child Tickets

Change History (16)

comment:1 Changed 8 years ago by nickm

Milestone: Tor: 0.2.3.x-final
Priority: normalmajor

Huh. It's reporting that it's failing because of the error... "http request" ? Can you get a stack trace on one of these? It's getting generated from tor_tls_log_one_error().

comment:2 Changed 8 years ago by karsten

How would I obtain a stack trace on Windows? Sebastian suggested adding an assert(0) and running tor.exe in gdb, but then it only tells me "No stack." Do you have a patch for me that logs the information you're looking for?

comment:3 Changed 8 years ago by nickm

Ugh, really? This is going to get ugly. If that doesn't work, then maybe running under gdb and using "break" to set a breakpoint would work. Or you might need a tor built with debugging symbols? This is something we need to figure out.

comment:4 Changed 8 years ago by nickm

Hm. One possibility that might make debugging easier is that some of these bugs might also appear on non-windows. IOW, there are three changes to make on stock Tor to get the final thing we want to have working:

  • enable bufferevents (build Tor using Libevent 2.0.13-stable with the --enable-bufferevents configure option)
  • Enable _filtering_ SSL bufferevents (you can do this manually with "_UseFilteringSSLBuffevents 1".
  • Run on windows.
  • Enable IOCP (This happens with bufferevents on Windows when DisableIOCP 0 is set).

So one way to help track this down would be to run on windows and turn stuff off till we find what works. In other words:

  • Does stuff work okay on a unix platform with bufferevents enabled?
  • Does stuff work okay on a unix platform with bufferevents enabled, and _UseFilteringSSLBufferevents 1 ?
  • Does stuff work okay on windows with bufferevents enabled and _UseFilteringSSLBufferevents 0, DisableIOCP 1? (What I think you've got now).
  • Does stuff work okay on windows with bufferevents disabled and _UseFilteringSSLBufferevents 1, DisableIOCP 1?
  • Does stuff work okay on windows with bufferevents enabled and _UseFilteringSSLBufferevents 1, DisableIOCP 0?

comment:5 Changed 8 years ago by Sebastian

getting backtraces with manual breaks works for me. Happy to help if karsten can't solve it?

comment:6 Changed 8 years ago by nickm

Any way to try to track down these issues would be great; I think this will be a hard problem needing all the attention we can give it.

comment:7 Changed 8 years ago by karsten

There we go (thanks, Sebastian!):

Breakpoint 1, tor_tls_log_one_error (tls=0x4a7c778, err=336027804,
    severity=4, domain=32768, doing=0x533260 "handshaking (with bufferevent)")
    at tortls.c:271
271       st = (tls && tls->ssl) ? tls->ssl->state : -1;
(gdb) bt
#0  tor_tls_log_one_error (tls=0x4a7c778, err=336027804, severity=4,
    domain=32768, doing=0x533260 "handshaking (with bufferevent)")
    at tortls.c:271
#1  0x004519a3 in connection_or_handle_event_cb (bufev=0x4417fb8, event=32,
    arg=0x44fad18) at connection_or.c:1275
#2  0x004f302c in bufferevent_run_deferred_callbacks_locked (_=0x44180a0,
    arg=0x4417fb8) at bufferevent.c:157
#3  0x004ee31e in event_process_deferred_callbacks (base=0xac6858, flags=0)
    at event.c:1347
#4  event_process_active (base=0xac6858, flags=0) at event.c:1386
#5  event_base_loop (base=0xac6858, flags=0) at event.c:1572
#6  0x0040531f in do_main_loop () at main.c:1797
#7  0x0040674c in tor_main (argc=3, argv=0xac27d0) at main.c:2471
#8  0x004013e0 in main (argc=3, argv=0xac27d0) at tor_main.c:30

I also found a second warning in the logs from two days ago:

Aug 08 13:52:14.000 [warn] TLS error while handshaking (with bufferevent) with [scrubbed]: ssl handshake failure (in SSL routines:SSL3_READ_BYTES:SSL3_ST_SR_CERT_A)

I can now compile and run any 0.2.3.x version or branch on Windows. If you have a patch for me, just let me know.

comment:8 Changed 8 years ago by Sebastian

Got this reproduced on non-windows. It happens when you make an http request to an orport, for a tor that is running with bufferevents. Fun extra thing: My tor even segfaults. I believe this could be because libevent linked against the system openssl and I linked tor against my own openssl. More debugging will be necessary.

comment:9 Changed 8 years ago by Sebastian

(don't have the ssl handshake failure tracked down yet)

comment:10 Changed 8 years ago by Sebastian

Yup, the segfault was the library version problem.

My analysis for the bug is that it isn't really a bug at all. openssl generates these errors for situations that are out of the user's control: Someone speaks http to the orport, someone goes away during the handshake. See ssl/s23_srvr.c in openssl, function ssl23_get_client_hello(). The only remaining question here is IMO whether we want _some_ of those errors to propagate to our log as warnings, but I think probably not?

comment:11 Changed 8 years ago by Sebastian

The handshake failure is generated in ssl3_read_bytes() in ssl/s3_pkt.c.

Hrm. Maybe we do want to learn about some of those errors... but certainly not the http request ones.

comment:12 Changed 8 years ago by Sebastian

(The "easy fix" is to change the LOG_WARN in the tor_tls_log_one_error() call in connection_or.c to LOG_INFO. But that means we will miss something we might care about.)

comment:13 Changed 8 years ago by Sebastian

Status: newneeds_review

pushed a fix that quiets the warnings to info message inside tor_tls_log_one_error() for a few of the "obviously not our fault" problems.

comment:14 Changed 8 years ago by nickm

Resolution: fixed
Status: needs_reviewclosed

Looks okay to me. Merged

comment:15 Changed 7 years ago by nickm

Keywords: tor-relay added

comment:16 Changed 7 years ago by nickm

Component: Tor RelayTor
Note: See TracTickets for help on using tickets.