logging when onion backend fails
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.