Opened 7 years ago

Closed 3 years ago

#8585 closed defect (wontfix)

Figure out why weechat+ssl don't play nice with torsocks

Reported by: sysrqb Owned by: sysrqb
Priority: Medium Milestone:
Component: Core Tor/Torsocks Version:
Severity: Normal Keywords:
Cc: Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

weechat is socks aware, but it should also be usable with torsocks. On initial testing, weechat's irc plugin closes its connections and attempts to continue the ssl handshake on newly established conns. This could be a misinterpretation, though.

00:00:47 irc.oftc.net  -- | irc: connecting to server irc.oftc.net/6697 (SSL)...
00:01:20 irc.oftc.net =!= | irc: TLS handshake failed
00:01:20 irc.oftc.net =!= | irc: error: The TLS connection was non-properly terminated.
00:01:20 irc.oftc.net  -- | irc: reconnecting to server in 10 second
Mar 25 00:00:48.000 [debug] connection_ap_handshake_process_socks(): entered.
Mar 25 00:00:48.000 [debug] parse_socks(): socks5: checking request
Mar 25 00:00:48.000 [debug] parse_socks(): socks5: fqdn address type
Mar 25 00:00:48.000 [debug] connection_ap_handshake_rewrite_and_attach(): Client asked for irc.oftc.net:6697
...
Mar 25 00:00:49.600 [info] connection_ap_handshake_send_begin(): Sending relay cell 0 to begin stream 24137.
...
Mar 25 00:00:50.160 [debug] relay_lookup_conn(): found conn for stream 24137.
Mar 25 00:00:50.160 [debug] circuit_receive_relay_cell(): Sending to origin.
Mar 25 00:00:50.160 [debug] connection_edge_process_relay_cell(): Now seen 926 relay cells here (command 4, stream 24137).
Mar 25 00:00:50.160 [info] connection_edge_process_relay_cell_not_open(): 'connected' received after 1 seconds.
Mar 25 00:00:50.160 [info] addressmap_register(): Temporary addressmap ('irc.oftc.net' to '140.211.166.64') not performed, since it's already mapped to '50.197.126.29'
...
Mar 25 00:01:20.280 [debug] connection_or_process_cells_from_inbuf(): 12: starting, inbuf_datalen 512 (0 pending in tls object).
Mar 25 00:01:20.280 [debug] channel_queue_cell(): Directly handling incoming cell_t 0x38e973ff140 for channel 0x1e0c141140 (global ID 2)
Mar 25 00:01:20.280 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x1e0c22fcd0 for circ_id 3495, channel ID 2 (0x1e0c141140)
Mar 25 00:01:20.280 [debug] relay_lookup_conn(): found conn for stream 24137.
Mar 25 00:01:20.280 [debug] circuit_receive_relay_cell(): Sending to origin.
Mar 25 00:01:20.280 [debug] connection_edge_process_relay_cell(): Now seen 929 relay cells here (command 3, stream 24137).
Mar 25 00:01:20.280 [info] connection_edge_process_relay_cell(): 13: end cell (closed normally) for stream 24137. Removing stream.
Mar 25 00:01:20.280 [debug] connection_or_process_cells_from_inbuf(): 12: starting, inbuf_datalen 0 (0 pending in tls object).
Mar 25 00:01:20.280 [debug] conn_close_if_marked(): Cleaning up connection (fd 13).
Mar 25 00:01:20.280 [debug] connection_remove(): removing socket 13 (type Socks), n_conns now 5
Mar 25 00:01:20.280 [debug] connection_free_(): closing fd 13.
...
Mar 25 00:01:30.560 [debug] connection_handle_listener_read(): Connection accepted on socket 13 (child of fd 6).
Mar 25 00:01:30.560 [debug] connection_add_impl(): new conn type Socks, socket 13, address 127.0.0.1, n_conns 5.
Mar 25 00:01:30.560 [debug] connection_ap_handshake_process_socks(): entered.
Mar 25 00:01:30.560 [debug] parse_socks(): socks5: accepted method 0 (no authentication)
Mar 25 00:01:30.560 [debug] connection_ap_handshake_process_socks(): socks handshake not all here yet.
Mar 25 00:01:30.560 [debug] connection_ap_handshake_process_socks(): entered.
Mar 25 00:01:30.560 [debug] connection_ap_handshake_process_socks(): socks handshake not all here yet.
Mar 25 00:01:30.560 [debug] connection_ap_handshake_process_socks(): entered.
Mar 25 00:01:30.560 [debug] parse_socks(): socks5: checking request
Mar 25 00:01:30.560 [debug] parse_socks(): socks5: fqdn address type
Mar 25 00:01:30.560 [debug] conn_write_callback(): socket 13 wants to write.
Mar 25 00:01:30.560 [debug] conn_read_callback(): socket 13 wants to read.
Mar 25 00:01:30.560 [debug] connection_ap_handshake_rewrite_and_attach(): Client asked for irc.oftc.net:6697
Mar 25 00:01:31.000 [debug] conn_write_callback(): socket 13 wants to write.
...
Mar 25 00:01:31.000 [info] connection_edge_process_relay_cell_not_open(): 'connected' received after 1 seconds.
Mar 25 00:01:31.000 [info] addressmap_register(): Temporary addressmap ('irc.oftc.net' to '140.211.166.64') not performed, since it's already mapped to '50.197.126.29'
...
Mar 25 00:01:31.000 [debug] conn_write_callback(): socket 13 wants to write.
Mar 25 00:01:33.440 [debug] conn_read_callback(): socket 13 wants to read.
Mar 25 00:01:33.440 [debug] read_to_chunk(): Encountered eof on fd 13
Mar 25 00:01:33.440 [info] connection_edge_reached_eof(): conn (fd 13) reached eof. Closing.
Mar 25 00:01:33.440 [debug] connection_edge_end(): Sending end on conn (fd 13).
Mar 25 00:01:33.440 [debug] append_cell_to_circuit_queue(): Made a circuit active.
Mar 25 00:01:33.440 [debug] channel_flush_from_first_active_circuit(): Made a circuit inactive.
Mar 25 00:01:33.440 [debug] conn_close_if_marked(): Cleaning up connection (fd 13).
Mar 25 00:01:33.440 [debug] connection_remove(): removing socket 13 (type Socks), n_conns now 5
Mar 25 00:01:33.440 [debug] connection_free_(): closing fd 13.

The tcpdump output is interesting too. Six of these sent less than a second apart without response from Tor before failing

        0x0020:  8018 0156 fef2 0000 0101 080a 01ea d3d5  ...V............
        0x0030:  01ea d3d4 1603 0000 c501 0000 c103 0351  ...............Q
        0x0040:  4e50 49b3 f165 b434 0a72 0e07 dafe da5f  NPI..e.4.r....._
        0x0050:  e0ab 06fb 1d07 c153 1cf4 7445 6c03 0700  .......S..tEl...
        0x0060:  0050 c02b c009 c023 c02c c00a c024 c008  .P.+...#.,...$..
        0x0070:  c02f c013 c027 c030 c014 c012 009c 002f  ./...'.0......./
        0x0080:  003c 0035 003d 0041 0084 000a 0005 0004  .<.5.=.A........
        0x0090:  009e 0033 0067 0039 006b 0045 0088 0016  ...3.g.9.k.E....
        0x00a0:  00a2 0032 0040 0038 006a 0044 0087 0013  ...2.@.8.j.D....
        0x00b0:  0066 0100 0048 0005 0005 0100 0000 00ff  .f...H..........
        0x00c0:  0100 0100 0023 0000 000a 000c 000a 0013  .....#..........
        0x00d0:  0015 0017 0018 0019 000b 0002 0100 000d  ................
        0x00e0:  001c 001a 0401 0402 0403 0501 0503 0601  ................
        0x00f0:  0603 0301 0302 0303 0201 0202 0203       ..............

Child Tickets

Change History (2)

comment:1 Changed 7 years ago by sysrqb

Owner: changed from ioerror to sysrqb
Status: newassigned

comment:2 Changed 3 years ago by dgoulet

Resolution: wontfix
Severity: Normal
Status: assignedclosed

Ok I took a quick look and this is because of multi process. It seems that the DNS resolution is done in a separate process, then connection to it as well. Once it's all good, that process passes it back to the main process through Unix socket FD passing which is something torsocks denies because there is no way we can really confirm that we did open that socket through Tor.

This to be fixed would require torsocks to support multi process which is very tricky. Irssi has a similar issue when resolving .onion where DNS resolution is done in a new process and the .onion pool is not shared between processes (#11727). Until we have a multi process support (shared memory or something), we won't be able to fix this. Closing in favor of the multi process ticket.

Note: See TracTickets for help on using tickets.