Opened 3 years ago

Closed 3 years ago

#21019 closed defect (fixed)

logging when onion backend fails

Reported by: weasel Owned by: dgoulet
Priority: Medium Milestone: Tor: 0.3.0.x-final
Component: Core Tor/Tor Version: Tor: 0.2.9.7-rc
Severity: Normal Keywords: tor-hs
Cc: Actual Points:
Parent ID: Points: 0.1
Reviewer: Sponsor:

Description

Hi,

I have this in my torrc.

HiddenServiceDir /var/lib/tor/other_hidden_service/
HiddenServicePort 80 unix:/var/lib/tor-onion-sockets/default/bla/bla

The socket is owned by root:root, and when it's mode 644, Tor cannot connect to it. Unfortunately, this is only logged at info level and thus easily missed in default configurations:

connect(13, {sa_family=AF_UNIX, sun_path="/var/lib/tor-onion-sockets/default/bla/bla"}, 110) = -1 EACCES (Permission denied)
Dec 17 22:23:45.000 [info] connection_connect_sockaddr(): connect() to socket failed: Permission denied

I think this should be logged at warn and provide more information.

Likewise, when the backend is a TCP port where nothing is listening, the diagnostics are not optimal:

connect(13, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
Dec 17 22:27:55.000 [debug] connection_connect_sockaddr(): Connection to socket in progress (sock 13).
Dec 17 22:27:55.000 [debug] connection_add_impl(): new conn type Exit, socket 13, address (rendezvous), n_conns 6.
Dec 17 22:27:55.000 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 514 (0 pending in tls object).
Dec 17 22:27:55.000 [debug] channel_queue_cell(): Directly handling incoming cell_t 0x7ffe4ab4d770 for channel 0x564abfc0f690 (global ID 0)
Dec 17 22:27:55.000 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x564abfc21980 for circ_id 3183663169, channel ID 0 (0x564abfc0f690)
Dec 17 22:27:55.000 [debug] relay_lookup_conn(): found conn for stream 55015.
Dec 17 22:27:55.000 [debug] circuit_receive_relay_cell(): Sending to origin.
Dec 17 22:27:55.000 [debug] connection_edge_process_relay_cell(): Now seen 329 relay cells here (command 2, stream 55015).
Dec 17 22:27:55.000 [debug] connection_edge_process_relay_cell(): circ deliver_window now 998.
Dec 17 22:27:55.000 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 0 (0 pending in tls object).
Dec 17 22:27:55.000 [debug] conn_read_callback(): socket 13 wants to read.
Dec 17 22:27:55.000 [debug] connection_edge_end(): Sending end on conn (fd 13).
Dec 17 22:27:55.000 [debug] relay_send_command_from_edge_(): delivering 3 cell forward.
Dec 17 22:27:55.000 [debug] relay_send_command_from_edge_(): Sending a RELAY_EARLY cell; 1 remaining.
Dec 17 22:27:55.000 [debug] circuit_package_relay_cell(): crypting a layer of the relay cell.
Dec 17 22:27:55.000 [debug] circuit_package_relay_cell(): crypting a layer of the relay cell.
Dec 17 22:27:55.000 [debug] circuit_package_relay_cell(): crypting a layer of the relay cell.
Dec 17 22:27:55.000 [debug] circuit_package_relay_cell(): crypting a layer of the relay cell.
Dec 17 22:27:55.000 [debug] circuit_package_relay_cell(): crypting a layer of the relay cell.
Dec 17 22:27:55.000 [debug] append_cell_to_circuit_queue(): Made a circuit active.
Dec 17 22:27:55.000 [debug] scheduler_channel_has_waiting_cells(): Channel 0 at 0x564abfc0f690 went from waiting_for_cells to pending
Dec 17 22:27:55.000 [info] connection_close_immediate(): fd 13, type Exit, state connecting, 289 bytes on outbuf.
Dec 17 22:27:55.000 [debug] conn_close_if_marked(): Cleaning up connection (fd -1).

"[info] connection_close_immediate(): fd 13, type Exit, state connecting, 289 bytes on outbuf." is quite obscure.

I recommend better log lines (at notice or warn.

Child Tickets

Change History (5)

comment:1 Changed 3 years ago by dgoulet

Keywords: tor-hs added
Milestone: Tor: 0.3.0.x-final
Owner: set to dgoulet
Points: 0.1
Status: newaccepted

comment:2 Changed 3 years ago by dgoulet

Status: acceptedneeds_review

Here is an attempt at this. Note that it will only log connection refused or timeout error on the service socket (and it's rate limited at 300 seconds). The other reasons could mean lots of noise I believe at the warn level. So, it looks like this:

Jan 10 08:34:27.000 [warn] Onion service connection to 127.0.0.1:19171 failed (connection refused)

See branch: bug21019_030_01

comment:3 Changed 3 years ago by nickm

Status: needs_reviewneeds_revision

I think we should safe_str the address here? And I wonder if we can extract any part of this huge function?

comment:4 Changed 3 years ago by dgoulet

Status: needs_revisionneeds_review

Good point, I've added a fixup commit to use safe_str and extracted that entire thing in a separate function (even though it's not that of a big function, cleaner that way :). Feel free to change the name of the function, no strong opinion :).

See fixup commit 5b776b4 in bug21019_030_01.

comment:5 Changed 3 years ago by dgoulet

Resolution: fixed
Status: needs_reviewclosed

Neat it has been merged :).

Note: See TracTickets for help on using tickets.