[tor-bugs] #21019 [Core Tor/Tor]: logging when onion backend fails

[Tor Bug Tracker & Wiki]

#21019: logging when onion backend fails
------------------------------+-----------------------------
     Reporter:  weasel        |      Owner:
         Type:  defect        |     Status:  new
     Priority:  Medium        |  Milestone:
    Component:  Core Tor/Tor  |    Version:  Tor: 0.2.9.7-rc
     Severity:  Normal        |   Keywords:
Actual Points:                |  Parent ID:
       Points:                |   Reviewer:
      Sponsor:                |
------------------------------+-----------------------------
 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.

--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/21019>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online