Libressl 3.2.1 with compatibility issues to Tor relays

changed title from Libressl 3.2.1 with compatibility issus to Tor relays to Libressl 3.2.1 with compatibility issues to Tor relays

changed the description

A Tor relay 0.4.5.0-alpha-dev here under a stable hardened Gentoo Linux with LibreSSL 3.2.1 showed only 50% of the amount of the connections as it had have before with 3.2.0 - and its TCP traffic dropped down by nearly 100%.

I recompiled Tor after LibreSSL to ensure, that it is not an ABI issue (whilst API looks fine).

Tor doesn't play well with LibreSSL 3.2.1 - will roll back here to LibreSSL 3.2.0.

gman found a similar issue on bsd with the NYCBUG1 relay. I think we've had enough reports that there is definitely something wrong here.

Calling @nickm's name since he is our resident ssl expert.

changed milestone to %Tor: 0.4.4.x-final

added Backlog Bug Regression labels

assigned to @nickm

Maybe this is related so on the advice of nickm, I'm going to outline the problem.

Recently, one of my relay has been emitting this protocol warning log roughly 2-5 times every hour:

Oct 21 16:22:54.355 [warn] Received a bad AUTHENTICATE cell on OR connection (handshaking (Tor, v3 handshake)) with 193.23.244.244:26528: Some field in the AUTHENTICATE cell body was not as expected

That IP is dannenberg directory authority. So I contacted Andreas and got some information out of him. Nothing much special in the logs about my relay. But dannenberg was recently moved from FreeBSD to OpenBSD. LibreSSL 3.2.2 is linked with tor at the moment.

@nickm asked me to dump the bad AUTHENTICATE cell in hex so we could inspect it:

From dannenberg (BAD):

00 03 01 60 41 55 54 48 30 30 30 33 84 5D D2 75 18 87 9B 24 2F 96 8C 5F 36 3A 
2E 20 27 5A 4D 2B EB 16 8A 7C 87 CF 34 EB 15 95 88 50 5F 3C 74 66 E0 2D 22 62
71 72 2E FC 87 CA BD 0E 87 1C 7F F3 BB 9F 05 E4 34 26 0E DC 30 84 3B 38 F7 FC 
45 6D 1F 56 83 12 40 8D 59 2A 8C 27 7F 4B FE 79 0F 58 AA 6C 07 9C 7C A4 DE 6A 
2E AF FC 48 E1 E7 61 1B 78 16 8C 94 31 C5 F3 29 19 99 87 3D 03 B7 4F 28 19 08 
73 B7 8B 17 88 D8 4A 60 F9 DE E9 F9 21 E9 D0 DE 96 33 2A DF F3 0F 32 4E FE DA
80 BD 5B 72 38 D9 43 1B F8 BC B7 B4 D2 1D 98 7C 64 49 FF 68 D7 83 0F E3 9A 10
1B 37 34 57 04 B7 A0 BE 4B FC D2 C9 F2 ED EC 6A D7 46 2E 8E C8 67 F7 49 E5 2A
D3 92 5B 25 76 5B A6 AC D3 09 16 F7 7B 4B 22 FD 91 1B 2F CE A8 23 8E 8B 82 53
DA 2F 6A C6 92 1F 08 3B 2F 8D D7 EA 58 AB 81 BA AB AE EB 96 E4 1D 57 54 96 83 
FE AA 9A 0D 47 A5 FC 74 3F B5 39 CA 7C 50 BD 2A EF 7D AB EE 39 09 1C DB 89 20
8D 59 34 6B 4A 72 50 57 DD AA 22 BA F6 EC FC 60 F4 9C 08 7B 68 76 17 76 C6 3D
3B 88 A7 36 6D 06 54 AA D8 15 52 08 E6 F4 42 B6 0C AA 60 EB 52 E3 80 8C 7D 54 
34 98 C0 D8 63 36 1E B7 FB 8E 7B EC FE 55 7B 0B 7F 0D

Expected AUTHENTICATE:

00 03 00 00 41 55 54 48 30 30 30 33 84 5D D2 75 18 87 9B 24 2F 96 8C 5F 36 3A 
2E 20 27 5A 4D 2B EB 16 8A 7C 87 CF 34 EB 15 95 88 50 5F 3C 74 66 E0 2D 22 62
71 72 2E FC 87 CA BD 0E 87 1C 7F F3 BB 9F 05 E4 34 26 0E DC 30 84 3B 38 F7 FC 
45 6D 1F 56 83 12 40 8D 59 2A 8C 27 7F 4B FE 79 0F 58 AA 6C 07 9C 7C A4 DE 6A 
2E AF FC 48 E1 E7 61 1B 78 16 8C 94 31 C5 F3 29 19 99 87 3D 03 B7 4F 28 19 08 
73 B7 8B 17 88 D8 4A 60 F9 DE E9 F9 21 E9 D0 DE 96 33 2A DF F3 0F 32 4E FE DA
80 BD 5B 72 38 D9 43 1B F8 BC B7 B4 D2 1D 98 7C 64 49 FF 68 D7 83 0F E3 9A 10 
1B 37 34 57 04 B7 A0 BE 4B FC D2 C9 F2 ED EC 6A D7 46 2E 8E C8 67 F7 49 E5 2A
D3 92 5B 25 76 5B A6 AC D3 09 16 F7 7B 4B 22 FD 91 1B 2F CE A8 23 8E 8B 82 53
DA 2F 78 D5 2A F3 28 DB CA 28 1A 06 0E BC 77 DC 7B 02 67 E9 DB 00 52 56 F5 AE 
01 6B 4F EF F4 EE FC D6 9B 20 EA 5F D5 12 E6 B4 B5 88 30 55 3F AF 34 0B AE 09
35 77 BF 01 D5 79

Oh, oops. I need the AUTHENTICATE cell and the expected value. Around channeltls.c:2481 , that's the value of auth and the value of expected_cell->payload.

Okay, looking at those fields above: It appears that the TLSSECRETS field is different, but the other relevant fields are the same. That field is the one that is supposed to be the output of the RFC5705 exporter. I am suspecting that either there is a LibreSSL bug here, or there is some bug in how we are using SSL_export_keying_material().

added Doing label and removed Backlog label

I've been staring at the libressl code but to not much avail. Are we absolutely sure that libressl v3.2.0 works?

Oh! The problem here is not that any LibreSSL code changed, but that some code didn't change!

If I am diagnosing this correctly, it looks like tls1_export_keying_material() is unconditionally using the exporter function from RFC 5705. But TLS 1.3 defines a completely different exporter function, in RFC 8446 section 7.5. This means that whenever LibreSSL negotiates a TLS 1.3 connection and tries to export keying material, it does not generate the same result as other TLS 1.3 implementations.

It looks like we started encountering this with LibreSSL 3.2.1 because that's the version where LibreSSL enabled TLS 1.3 in TLS_method().

I've opened a LibreSSL issue at https://github.com/libressl-portable/portable/issues/629 . I'm not sure if that's the right place to report it, but there seems to be a fair amount of traffic on that github project, so I'm taking my chances.

added 1h 30m of time spent at 2020-10-22

Yay! Good find.

added Backlog label and removed Doing label

(Nothing else to do here on our end, but I'm going to leave this one open 'till LibreSSL patches their code.)

Thank you Nick for the discovery, I filed a ticket at Freebsd (https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=250613). So FreeBSD Bugzilla and the maintainer are informed.

mentioned in issue tpo/network-health/doctor#40008 (closed)

Tested right now with new LibreSSL 3.3.0:

Tor 0.4.5.2-alpha running on FreeBSD with Libevent 2.1.12-stable, OpenSSL LibreSSL 3.3.0, Zlib 1.2.11, Liblzma 5.2.4, Libzstd 1.4.5 and Unknown N/A as libc.

"Running" is not granted and is removed after 1 hour by six authorities. Please find the log for the not working version:

Nov 30 23:13:31.000 [notice] Self-testing indicates your ORPort x.x.x.x:443 is reachable from the outside. Excellent.
Nov 30 23:13:31.000 [notice] Now checking whether IPv4 ORPort x.x.x.x:443 is reachable... (this may take up to 20 minutes -- look for log messages indicating success)
Nov 30 23:13:31.000 [notice] Now checking whether IPv6 ORPort [y:y:y:y::y]:443 is reachable... (this may take up to 20 minutes -- look for log messages indicating success)
Nov 30 23:13:31.000 [notice] Now checking whether IPv4 DirPort x.x.x.x:80 is reachable... (this may take up to 20 minutes -- look for log messages indicating success)
Nov 30 23:13:31.000 [notice] Self-testing indicates your DirPort is reachable from the outside. Excellent.
Nov 30 23:13:34.000 [notice] Self-testing indicates your ORPort [y:y:y:y::y]:443 is reachable from the outside. Excellent. Publishing server descriptor.

Remarkable is that the self-test message was missing:

Performing bandwidth self-test...done.

I went back to 3.2.0 for now.

Yup; it looks like the ticket is still open on their tracker. Until LibreSSL fixes the issue, this won't get any better.

mentioned in commit gk/doctor@27f9e5c8

mentioned in merge request tpo/network-health/doctor!2 (merged)

They've merged a patch into LibreSSL that they say should fix this issue: https://github.com/libressl-portable/portable/issues/629 .

Tried to apply that patch on top of 3.3.0 here at a hardened Gentoo - failed here so far - will wait till tarballs of 3.3.x or 3.4.x are available

Update: Will no longer wait. Gentoo does no longer maintain LibreSSL - so I switched back to OpenSSL.

Neither works here. When I try to connect to a bridge with Libressl 330 + commit_6e2ae6018f8ad5bba7cd973e4360c215dee79bcc the TBB stalls at:

Negotiating with a Tor relay

BUT: 330 already has the patch. 322 did not.

The long story, log from TBB:

Dec 07 21:33:23.000 [notice] Bootstrapped 1% (conn_pt): Connecting to pluggable transport
Dec 07 21:33:23.000 [notice] Bootstrapped 2% (conn_done_pt): Connected to pluggable transport
Dec 07 21:33:25.000 [notice] Bootstrapped 10% (conn_done): Connected to a relay
Dec 07 21:33:25.000 [notice] Bootstrapped 14% (handshake): Handshaking with a relay
Dec 07 21:33:26.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
Dec 07 21:33:26.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
...
Dec 07 21:35:22.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
Dec 07 21:35:22.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
Dec 07 21:35:23.000 [info] connection_ap_expire_beginning(): Tried for 120 seconds to get a connection to xxx. Giving up. (waiting for circuit)
Dec 07 21:35:23.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
Dec 07 21:35:23.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
Dec 07 21:35:23.000 [info] connection_free_minimal(): Freeing linked Socks connection [waiting for circuit] with 106 bytes on inbuf, 0 on outbuf.
Dec 07 21:35:23.000 [info] connection_dir_client_reached_eof(): 'fetch' response not all here, but we're at eof. Closing.
Dec 07 21:35:23.000 [info] entry_guards_note_guard_failure(): Recorded failure for primary guard xxx
Dec 07 21:35:23.000 [info] connection_dir_client_request_failed(): Giving up on serverdesc/extrainfo fetch from directory server at xxx; retrying
Dec 07 21:35:23.000 [info] connection_free_minimal(): Freeing linked Directory connection [client reading] with 0 bytes on inbuf, 0 on outbuf.
Dec 07 21:35:23.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
Dec 07 21:35:24.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
...
Dec 07 21:35:27.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
Dec 07 21:35:27.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
Dec 07 21:35:28.000 [info] connection_ap_make_link(): Making internal direct tunnel to xxx ...
Dec 07 21:35:28.000 [info] connection_ap_make_link(): ... application connection created and linked.
Dec 07 21:35:28.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
Dec 07 21:35:28.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
Dec 07 21:35:28.000 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for circuit' state. Leaving it on buffer.
Dec 07 21:35:28.000 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for circuit' state. Leaving it on buffer.
Dec 07 21:35:28.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
Dec 07 21:35:29.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
...
Dec 07 21:37:02.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
Dec 07 21:37:02.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
Dec 07 21:37:03.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
Dec 07 21:37:03.000 [info] circuit_n_chan_done(): Channel failed; closing circ.
Dec 07 21:37:03.000 [info] circuit_mark_for_close_(): Circuit 0 (id: 1) marked for close at circuitbuild.c:673 (orig reason: 8, new reason: 0)
Dec 07 21:37:03.000 [info] connection_or_note_state_when_broken(): Connection died in state 'handshaking (Tor, v3 handshake) with SSL state SSL negotiation finished successfully in OPEN'
Dec 07 21:37:03.000 [info] bto_status_rcvr(): ORCONN DELETE gid=7 status=2 reason=7
Dec 07 21:37:03.000 [warn] Problem bootstrapping. Stuck at 14% (handshake): Handshaking with a relay. (IOERROR; IOERROR; count 1; recommendation warn; host xxx)
Dec 07 21:37:03.000 [warn] 1 connections have failed:
Dec 07 21:37:03.000 [warn]  1 connections died in state handshaking (Tor, v3 handshake) with SSL state SSL negotiation finished successfully in OPEN
Dec 07 21:37:03.000 [info] circuit_build_failed(): Our circuit 0 (id: 1) died before the first hop with no connection
Dec 07 21:37:03.000 [info] connection_ap_fail_onehop(): Closing one-hop stream to xxx because the OR conn just failed.
Dec 07 21:37:03.000 [info] circuit_free_(): Circuit 0 (id: 1) has been freed.
Dec 07 21:37:03.000 [info] connection_free_minimal(): Freeing linked Socks connection [waiting for circuit] with 106 bytes on inbuf, 0 on outbuf.
Dec 07 21:37:03.000 [info] connection_dir_client_reached_eof(): 'fetch' response not all here, but we're at eof. Closing.
Dec 07 21:37:03.000 [info] entry_guards_note_guard_failure(): Recorded failure for primary guard xxx
Dec 07 21:37:03.000 [info] connection_dir_client_request_failed(): Giving up on serverdesc/extrainfo fetch from directory server at xxx; retrying
Dec 07 21:37:03.000 [info] connection_free_minimal(): Freeing linked Directory connection [client reading] with 0 bytes on inbuf, 0 on outbuf.
Dec 07 21:37:03.000 [info] set_max_file_descriptors(): This platform is missing getrlimit(). Proceeding.
Dec 07 21:37:03.000 [notice] Closing no-longer-configured Socks listener on 127.0.0.1:9150
Dec 07 21:37:03.000 [notice] DisableNetwork is set. Tor will not make or accept non-control network connections. Shutting down all existing connections.
Dec 07 21:37:03.000 [notice] Tor 0.4.4.6 (git-2a8b789ea6f308d0) opening log file.
Dec 07 21:37:03.000 [info] options_commit_listener_transaction(): Recomputed OOS thresholds: ConnLimit 1000, ConnLimit_ 14968, ConnLimit_high_thresh 14904, ConnLimit_low_thresh 11226
Dec 07 21:37:03.000 [info] select_scheduler(): Scheduler type KIST not built in
Dec 07 21:37:03.000 [info] scheduler_kist_set_lite_mode(): Setting KIST scheduler without kernel support (KISTLite mode)
Dec 07 21:37:03.000 [info] cmux_ewma_set_options(): Enabled cell_ewma algorithm because of value in CircuitPriorityHalflifeMsec in consensus; scale factor is 0.793701 per 10 seconds
Dec 07 21:37:03.000 [info] should_delay_dir_fetches(): Delaying dir fetches (DisableNetwork is set)
Dec 07 21:37:03.000 [info] should_delay_dir_fetches(): Delaying dir fetches (DisableNetwork is set)
Dec 07 21:37:04.000 [warn] Pluggable Transport process terminated with status code 0
Dec 07 21:37:04.000 [info] should_delay_dir_fetches(): Delaying dir fetches (DisableNetwork is set)
Dec 07 21:37:04.000 [info] should_delay_dir_fetches(): Delaying dir fetches (DisableNetwork is set)
Dec 07 21:37:05.000 [info] should_delay_dir_fetches(): Delaying dir fetches (DisableNetwork is set)

Libressl 320 works again.

added Next label and removed Backlog label

Libressl 331 still doesn't work. Cheers!

added Network health label

Apologies for not jumping on this sooner, but I've been dealing with this off gitlab.

This a useful relay following OpenBSD -current for any metrics history:

https://metrics.torproject.org/rs.html#details/3F092986E9B87D3FDA09B71FA3A602378285C77A

First, the issue first came up in October with some LibreSSL changes, as others are aware. Current LibreSSL is at version 3.3.1.

The commits to follow are here:

https://cvsweb.openbsd.org/src/lib/libressl/

With the OpenBSD snapshot #266 (closed) from around 20200109, the ssl handshakes started to complete. It's been fully operational since.

The following error continues to appear in the log is:

Jan 27 22:05:01.000 [warn] tor_tls_finish_handshake: Bug: For some reason, wasV2Handshake didn't get set. Fixing that. (on Tor 0.4.4.6 )

Note that v3 hidden services work if that is at all relevant.

Also, any fixes since October won't appear in -stable branch until its release around May 1, so to have an operational OpenBSD node you need to run -current or build with OpenSSL.

okay, so ... it works with the next libressl? Trying to make sure I understand here.

Going to move this to Icebox till somebody can clarify whether it is fixed.

added Icebox label and removed Next label

mentioned in issue #40353

Tried out Libre SSL 3.2.5 today. No change and is still not working. Back to 3.2.0 and all works again. Cheers!

The OpenSSL 1.1 TLSv1.3 API is not yet available

I think this is what we are waiting for, right?

https://github.com/libressl-portable/portable

LibreSSL Portable Release Notes:

3.3.3 - Stable release

	* This is the first stable release from the 3.3.x series.
	  There are no changes from 3.3.2.

3.3.2 - Development release

	* This release adds support for DTLSv1.2 and continues the rewrite
	  of the record layer for the legacy stack. Numerous bugs and
	  interoperability issues were fixed in the new verifier. A few bugs
	  and incompatibilities remain, so this release uses the old verifier
	  by default. The OpenSSL 1.1 TLSv1.3 API is not yet available.

Good news, Libressl seems to work for us with 3.4.1 (Freebsd ports libressl/devel).

Oct 22 21:06:26.894 [notice] Tor 0.4.6.7 running on FreeBSD with Libevent 2.1.12-stable, OpenSSL LibreSSL 3.4.1, Zlib 1.2.11, Liblzma 5.2.5, Libzstd 1.5.0 and Unknown N/A as libc.

It's the first time since 3.2.0:

LibreSSL Portable Release Notes:
3.4.1 - Stable release
	* New Features
	  - Added support for OpenSSL 1.1.1 TLSv1.3 APIs.

Thanks for the report! This is exactly the information I neeeded for #40445 (closed)!

mentioned in issue #40511 (closed)

#40511 (closed) is the issue to give a useful message about this situation.

closed

mentioned in merge request !487 (merged)

mentioned in commit cee6e7d9

added BugSmashFund label

mentioned in issue tpo/tpa/team#41605 (closed)

Libressl 3.2.1 with compatibility issues to Tor relays

Child items ...

Activity