[tor-bugs] #1362 [Tor - Tor client]: log does not record at NOTICE level when Tor is really ready
Tor Bug Tracker & Wiki
torproject-admin at torproject.org
Sun Aug 1 21:23:25 UTC 2010
#1362: log does not record at NOTICE level when Tor is really ready
----------------------------+-----------------------------------------------
Reporter: keb | Type: defect
Status: new | Priority: trivial
Milestone: | Component: Tor - Tor client
Version: 0.2.2.10-alpha | Resolution: None
Keywords: | Parent:
----------------------------+-----------------------------------------------
Old description:
> the Notice level Tor log said
>
> Apr 18 00:37:00.072 [Notice] We now have enough directory information to
> build circuits.
>
> but i was getting these errors in IRC:
>
> [00:37] SOCKS Proxy failed to connect to host (error 1).
> [00:37] Proxy traversal failed.
>
> so i turned on Info level logging and
> tried to connect to IRC server again a few times
> with same results as above until the last Tor log line below:
>
> Apr 18 00:38:39.453 [Info] exit circ (length 3): jceaovh(open)
> $B2B00F568DEAA608C9C9A2DFCABD3A2622460743(open)
> $476418056BAEEFFB0354CB7DA0B0D50010264820(open)
> Apr 18 00:38:39.455 [Info] connection_ap_handshake_send_begin():
> Address/port sent, ap socket 22, n_circ_id 47188
> Apr 18 00:38:39.455 [Info] connection_edge_process_inbuf(): data from
> edge while in 'waiting for connect response' state. Leaving it on buffer.
> Apr 18 00:38:46.557 [Info] connection_ap_process_end_not_open(): Edge got
> end (internal error at server) before we're connected. Marking for close.
> Apr 18 00:38:46.559 [Info] exit circ (length 3): jceaovh(open)
> $B2B00F568DEAA608C9C9A2DFCABD3A2622460743(open)
> $476418056BAEEFFB0354CB7DA0B0D50010264820(open)
> Apr 18 00:39:03.432 [Info]
> update_consensus_router_descriptor_downloads(): 0 router descriptors
> downloadable. 0 delayed; 1363 present (0 of those were in old_routers); 0
> would_reject; 1 wouldnt_use; 0 in progress.
> Apr 18 00:39:18.460 [Info] routerlist_remove_old_routers(): We have 1363
> live routers and 0 old router descriptors.
> Apr 18 00:39:18.461 [Info] buf_shrink_freelists(): Cleaning freelist for
> 4096-byte chunks: keeping 9, dropping 8.
> Apr 18 00:39:18.462 [Info] buf_shrink_freelists(): Cleaning freelist for
> 32768-byte chunks: keeping 3, dropping 1.
> Apr 18 00:39:38.583 [Info] command_process_versions_cell(): Negotiated
> version 2 with [scrubbed]:9001; sending NETINFO.
> Apr 18 00:39:38.584 [Info] command_process_netinfo_cell(): Got good
> NETINFO cell from [scrubbed]:9001; OR connection is now open, using
> protocol version 2
>
> immediately after that last message, the IRC connection worked.
> There were no Notice level messages indicating any problem.
> Therefore i suggest promoting that last message, or some cleaned up
> version of it,
> to Notice level so the log shows when Tor is really ready to pass user
> traffic.
>
> [Automatically added by flyspray2trac: Operating System: All]
New description:
the Notice level Tor log said
Apr 18 00:37:00.072 [Notice] We now have enough directory information to
build circuits.
but i was getting these errors in IRC:
[00:37] SOCKS Proxy failed to connect to host (error 1).
[00:37] Proxy traversal failed.
so i turned on Info level logging and
tried to connect to IRC server again a few times
with same results as above until the last Tor log line below:
Apr 18 00:38:39.453 [Info] exit circ (length 3): jceaovh(open)
$B2B00F568DEAA608C9C9A2DFCABD3A2622460743(open)
$476418056BAEEFFB0354CB7DA0B0D50010264820(open)
Apr 18 00:38:39.455 [Info] connection_ap_handshake_send_begin():
Address/port sent, ap socket 22, n_circ_id 47188
Apr 18 00:38:39.455 [Info] connection_edge_process_inbuf(): data from edge
while in 'waiting for connect response' state. Leaving it on buffer.
Apr 18 00:38:46.557 [Info] connection_ap_process_end_not_open(): Edge got
end (internal error at server) before we're connected. Marking for close.
Apr 18 00:38:46.559 [Info] exit circ (length 3): jceaovh(open)
$B2B00F568DEAA608C9C9A2DFCABD3A2622460743(open)
$476418056BAEEFFB0354CB7DA0B0D50010264820(open)
Apr 18 00:39:03.432 [Info] update_consensus_router_descriptor_downloads():
0 router descriptors downloadable. 0 delayed; 1363 present (0 of those
were in old_routers); 0 would_reject; 1 wouldnt_use; 0 in progress.
Apr 18 00:39:18.460 [Info] routerlist_remove_old_routers(): We have 1363
live routers and 0 old router descriptors.
Apr 18 00:39:18.461 [Info] buf_shrink_freelists(): Cleaning freelist for
4096-byte chunks: keeping 9, dropping 8.
Apr 18 00:39:18.462 [Info] buf_shrink_freelists(): Cleaning freelist for
32768-byte chunks: keeping 3, dropping 1.
Apr 18 00:39:38.583 [Info] command_process_versions_cell(): Negotiated
version 2 with [scrubbed]:9001; sending NETINFO.
Apr 18 00:39:38.584 [Info] command_process_netinfo_cell(): Got good
NETINFO cell from [scrubbed]:9001; OR connection is now open, using
protocol version 2
immediately after that last message, the IRC connection worked.
There were no Notice level messages indicating any problem.
Therefore i suggest promoting that last message, or some cleaned up
version of it,
to Notice level so the log shows when Tor is really ready to pass user
traffic.
[Automatically added by flyspray2trac: Operating System: All]
--
Comment(by arma):
This bug is as valid as it ever was, insofar as the behavior hasn't
changed.
I'm not really sure what we should fix though. It works well enough for
me.
Perhaps some of the problem is that on slow connections, since Tor tries
to preemptively build several circuits, it could be busy building its
second and third preemptive circuit when you start trying to use the first
one.
Another part of the mystery is why this person got an end cell with reason
END_STREAM_REASON_INTERNAL after the first connection attempt. What went
wrong at the relay end? Was it a problem with that particular relay?
--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/1362#comment:3>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online
More information about the tor-bugs
mailing list