Hiya. Been around the tor dev community a bit, but today is my first day on the legendary tor-dev mailing list. I am asking if it makes sense to apply a minor patch to Tor source, but first, the use case:
tor is very adamant at scrubbing the addresses that are being connected to in the logs, but I have the opposite wish case were I would like to have a terminal show me the addresses my tor is connecting to in real-time.
Could be that the "arm" app would be able to do that without taking up the screen space that vidalia takes, but for some irrelevant reasons I am not using that.
What I do is "Log [app]debug file /dev/shm/tor-log.txt", then run "tail -f /dev/shm/tor-log.txt | grep asked" to extract the "Client asked for <hostname>:<port>" lines, so I even get to see DNS requests independently from actual virtual circuits. I also have "SafeLogging" set appropriately.
Needless to say, the RAM disk fills up quickly, so the usefulness is limited. This is a case screaming for unix named pipes as follows:
mkfifo /dev/tor-log grep asked /dev/tor-log
But tor refuses to write to such a FIFO pipe because it can't seek to the end of it.
Couldn't open file for 'Log /dev/tor-log': Illegal seek
./or/config.c calls ./common/log.c's add_file_log which calls ./common/compat.c's tor_fd_seekend to make sure the stuff is appended at the end of a log.
In the case of a FIFO pipe this returns an ESPIPE code which currently makes tor throw up. In my understanding it should be safe to ignore it, instead. We should expect the user to know what she is doing if she puts a pipe where the log should be. Or am I missing something?
There is also a similar case of calling tor_fd_seekend in ./common/util.c which suggests there may be other use cases of mkfifo which are currently impeded by this.
So the question is, would it be okay to catch ESPIPE in all cases, thus having it ignored in tor_fd_seekend, or just catch it in add_file_log? Or is there a reason to impede the use of unix named pipes under all circumstances?
Best sockets from Berlin, CvL.
On Mon, Apr 14, 2014 at 5:32 AM, carlo von lynX lynX@time.to.get.psyced.org wrote: [...]
So the question is, would it be okay to catch ESPIPE in all cases, thus having it ignored in tor_fd_seekend, or just catch it in add_file_log? Or is there a reason to impede the use of unix named pipes under all circumstances?
I think it's fine to ignore that failure from tor_fd_seekend in this case. Actually, I'm not clear, looking at the code, why it's there at all: it seems to me that O_APPEND should already put us at the end of the file, right? It's not clear to me why we mask out O_APPEND in start_writing_to_file(). Maybe looking at the git logs will shine some light on it...
On Tue, Apr 15, 2014 at 2:27 PM, Nick Mathewson nickm@alum.mit.edu wrote:
On Mon, Apr 14, 2014 at 5:32 AM, carlo von lynX lynX@time.to.get.psyced.org wrote: [...]
So the question is, would it be okay to catch ESPIPE in all cases, thus having it ignored in tor_fd_seekend, or just catch it in add_file_log? Or is there a reason to impede the use of unix named pipes under all circumstances?
I think it's fine to ignore that failure from tor_fd_seekend in this case. Actually, I'm not clear, looking at the code, why it's there at all: it seems to me that O_APPEND should already put us at the end of the file, right? It's not clear to me why we mask out O_APPEND in start_writing_to_file(). Maybe looking at the git logs will shine some light on it...
Ah. Apparently, O_APPEND has additional semantics beyond when we're opening the file. See commit 37bd9181f07b198ce43489adb5fdb457eef8cfff
On Tue, Apr 15, 2014 at 02:28:17PM -0400, Nick Mathewson wrote:
On Tue, Apr 15, 2014 at 2:27 PM, Nick Mathewson nickm@alum.mit.edu wrote:
On Mon, Apr 14, 2014 at 5:32 AM, carlo von lynX lynX@time.to.get.psyced.org wrote: [...]
So the question is, would it be okay to catch ESPIPE in all cases, thus having it ignored in tor_fd_seekend, or just catch it in add_file_log? Or is there a reason to impede the use of unix named pipes under all circumstances?
I think it's fine to ignore that failure from tor_fd_seekend in this case. Actually, I'm not clear, looking at the code, why it's there at all: it seems to me that O_APPEND should already put us at the end of the file, right? It's not clear to me why we mask out O_APPEND in start_writing_to_file(). Maybe looking at the git logs will shine some light on it...
Ah. Apparently, O_APPEND has additional semantics beyond when we're opening the file. See commit 37bd9181f07b198ce43489adb5fdb457eef8cfff
Thank you for finding your own commit from many years ago. So apparently O_APPEND ensures that we are always at the end of the file. Is that bad? If so, then let's add that ESPIPE exception and allow for conscious use of pipes.
grarpamp, thanks for your work on more advanced ways to look at the information, but right now it is fine with me to be the first to know that my computer is requesting a circuit to somewhere. Gives me half a second to rip out the cable. ;-)
Here's the patch. This should also work for unices that do not produce ESPIPE and for WIN32 that doesn't have unix-like named pipes. <formal>I place this patch in the public domain.</formal>
--- a/src/common/compat.c +++ b/src/common/compat.c @@ -969,7 +969,12 @@ tor_fd_seekend(int fd) #ifdef _WIN32 return _lseek(fd, 0, SEEK_END) < 0 ? -1 : 0; #else - return lseek(fd, 0, SEEK_END) < 0 ? -1 : 0; + int rc = lseek(fd, 0, SEEK_END) < 0 ? -1 : 0; +#ifdef ESPIPE + /* allow for log output to go to a mkfifo named pipe --symlynX */ + if (rc && errno == ESPIPE) rc = 0; +#endif + return rc; #endif }
more advanced ways to look at the information
Yes it's slightly different in that the ticket means to log where requests are set to exit from and when for history.
me to be the first to know that my computer is requesting a circuit to somewhere. Gives me half a second to rip out the cable. ;-)
Though I've not verified other than hitting enter in the urlbar and watching, the controller's 'setevents stream' also appears to log NEW's very close in time to 'Client asked for's, probably in the same function, well before any result is worked up. So there may be two ways for people to do this.
I have the opposite wish case were I would like to have a terminal show me the addresses my tor is connecting to in real-time.
The debug log output isn't very useful for logging the final condition of successful "connection 'requests' in realtime".
As you can see, only the initial 'Client asked for' is really useful per request. That doesn't mean the request actually resulted in a ready circuit.
In the case of normal parallel use, none of the log lines are linked to the parent 'asked for' by any label tag, so it becomes a mashup.
There can be a significant and variable time lag from 'ask for' until a circuit is created and ready to carry user data.
Storing and parsing the required log levels may be wasteful.
So the debug log isn't going to be very useful as far as knowing where your socks/natd/trans/dns port requests went, such as to what exit or last hop to an onion they used. Certainly not for answering anything beyond 'Client asked for'.
You could simply pipe stdout to any line parser. But that precludes other uses of that stream, unless you syslog it first.
So what you probably want is to watch the controller output, even more so once it is enhanced by this ticket:
https://trac.torproject.org/projects/tor/ticket/11179
Example logspam follows...
## first fetch of ip [debug] {APP} connection_ap_handshake_rewrite_and_attach(): Client asked for <ip1>:80 [info] {APP} link_apconn_to_circ(): Looks like completed circuit to <exitfp1> at <exitip1> does allow optimistic data for connection to <ip1> [info] {APP} connection_ap_process_end_not_open(): Address '<ip1>' refused due to 'server out of resources'. Considering retrying. [info] {APP} link_apconn_to_circ(): Looks like completed circuit to <exitfp2> at <exitip2> does allow optimistic data for connection to <ip1> 2 BUILT ...,...,<exitfp2> 3 BUILT ...,...,<exitfp1> 9 SUCCEEDED 2 <ip1>:80 # subsequent [debug] {APP} connection_ap_handshake_rewrite_and_attach(): Client asked for <ip1>:80 [info] {APP} link_apconn_to_circ(): Looks like completed circuit to <exitfp2> at <exitip2> does allow optimistic data for connection to <ip1> 9 SUCCEEDED 2 <ip1>:80
## first fetch of fqdn [debug] {APP} connection_ap_handshake_rewrite_and_attach(): Client asked for <fqdn>:80 [info] {APP} link_apconn_to_circ(): Looks like completed circuit to <exitfp2> at <exitip2> does allow optimistic data for connection to <fqdn> [info] {CONFIG} addressmap_register(): Addressmap: (re)mapped '<fqdn>' to '<ip2>' 2 BUILT ...,...,<exitfp2> 10 SUCCEEDED 2 <ip2>:80 # subsequent [debug] {APP} connection_ap_handshake_rewrite_and_attach(): Client asked for <fqdn>:80 [info] {APP} link_apconn_to_circ(): Looks like completed circuit to <exitfp2> at <exitip2> does allow optimistic data for connection to <fqdn> [info] {APP} addressmap_register(): Temporary addressmap ('<fqdn>' to '<ip2>') not performed, since it's already mapped to '<ip2>' 10 SUCCEEDED 2 <ip2>:80
## first fetch of onion [debug] {APP} connection_ap_handshake_rewrite_and_attach(): Client asked for <ohash>.onion:80 [info] {REND} connection_ap_handshake_rewrite_and_attach(): Got a hidden service request for ID '<ohash>' [info] {REND} connection_ap_handshake_rewrite_and_attach(): Unknown descriptor <ohash>. Fetching. [debug] {REND} rend_client_refetch_v2_renddesc(): Fetching v2 rendezvous descriptor for service <ohash> [info] {REND} directory_get_from_hs_dir(): Sending fetch request for v2 descriptor for service '<ohash>' with descriptor ID '<desc>', auth type 0, and descriptor cookie '[none]' to hidden service directory <dirfp> at <dirip> [debug] {REND} rend_cache_store_v2_desc_as_client(): Successfully stored rend desc '<ohash>', len <len>. [info] {REND} circuit_get_open_circ_or_launch(): Chose <ipfp> at <ipip> as intro point for '<ohash>'. [info] {REND} rend_client_note_connection_attempt_ended(): Connection attempt for <ohash> has ended; cleaning up temporary state. 5 BUILT ...,...,<exitfp0> 11 SUCCEEDED 5 <ohash>.onion:80 # subsequent [debug] {APP} connection_ap_handshake_rewrite_and_attach(): Client asked for <ohash>.onion:80 [info] {REND} connection_ap_handshake_rewrite_and_attach(): Got a hidden service request for ID '<ohash>' [info] {REND} rend_client_note_connection_attempt_ended(): Connection attempt for <ohash> has ended; cleaning up temporary state. 11 SUCCEEDED 5 <ohash>.onion:80
## first fetch of dnsfwd [debug] {APP} connection_ap_handshake_rewrite_and_attach(): Client asked for <dnsfwd>:0 [info] {APP} link_apconn_to_circ(): Looks like completed circuit to <exitfp> at <exitip> does allow optimistic data for connection to <dnsfwd> [info] {CONFIG} addressmap_register(): Addressmap: (re)mapped '<dnsfwd>' to '<dnsrev>' # subsequent [debug] {APP} connection_ap_handshake_rewrite_and_attach(): Client asked for <dnsfwd>:0 [info] {APP} link_apconn_to_circ(): Looks like completed circuit to <exitfp> at <exitip> does allow optimistic data for connection to <dnsfwd> [info] {APP} addressmap_register(): Temporary addressmap ('<dnsfwd>' to '<dnsrev>') not performed, since it's already mapped to '<dnsrev>'
## first fetch of dnsrev [debug] {APP} connection_ap_handshake_rewrite_and_attach(): Client asked for <dnsrev>:0 [info] {APP} link_apconn_to_circ(): Looks like completed circuit to <exitfp> at <exitip> does allow optimistic data for connection to <dnsrev> [info] {CONFIG} addressmap_register(): Addressmap: (re)mapped 'REVERSE[<dnsrev>]' to '<dnsresult>' # subsequent [debug] {APP} connection_ap_handshake_rewrite_and_attach(): Client asked for <dnsrev>:0 [info] {APP} link_apconn_to_circ(): Looks like completed circuit to <exitfp> at <exitip> does allow optimistic data for connection to <dnsrev> [info] {APP} addressmap_register(): Temporary addressmap ('REVERSE[<dnsrev>]' to '<dnsresult>') not performed, since it's already mapped to '<dnsresult>'
-
carlo von lynX -
grarpamp -
Nick Mathewson