[Author Prev][Author Next][Thread Prev][Thread Next][Author Index][Thread Index]

Re: [tor-bugs] #1362 [Tor - Tor client]: log does not record at NOTICE level when Tor is really ready

To: undisclosed-recipients:;
Subject: Re: [tor-bugs] #1362 [Tor - Tor client]: log does not record at NOTICE level when Tor is really ready
From: "Tor Bug Tracker & Wiki" <torproject-admin@xxxxxxxxxxxxxx>
Date: Sun, 01 Aug 2010 21:23:25 -0000
Auto-submitted: auto-generated
Delivered-to: archiver@xxxxxxxx
Delivery-date: Sun, 01 Aug 2010 17:23:35 -0400
In-reply-to: <043.cff6101e27db3be64b74e89ae50b8142@xxxxxxxxxxxxxx>
List-archive: <http://lists.torproject.org/pipermail/tor-bugs>
List-help: <mailto:tor-bugs-request@lists.torproject.org?subject=help>
List-id: Tor bugs reporting list for trac <tor-bugs.lists.torproject.org>
List-post: <mailto:tor-bugs@lists.torproject.org>
List-subscribe: <https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs>, <mailto:tor-bugs-request@lists.torproject.org?subject=subscribe>
List-unsubscribe: <https://lists.torproject.org/cgi-bin/mailman/options/tor-bugs>, <mailto:tor-bugs-request@lists.torproject.org?subject=unsubscribe>
References: <043.cff6101e27db3be64b74e89ae50b8142@xxxxxxxxxxxxxx>
Reply-to: tor-assistants@xxxxxxxxxxxxxx
Sender: tor-bugs-bounces@xxxxxxxxxxxxxxxxxxxx

#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
_______________________________________________
tor-bugs mailing list
tor-bugs@xxxxxxxxxxxxxxxxxxxx
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Prev by Author: Re: [tor-bugs] #1362 [Tor - Tor client]: log does not record at NOTICE level when Tor is really ready
Next by Author: Re: [tor-bugs] #1351 [Tor - Relay]: tor stopped publishing descriptor
Previous by thread: Re: [tor-bugs] #1362 [Tor - Tor client]: log does not record at NOTICE level when Tor is really ready
Next by thread: Re: [tor-bugs] #1741 [Tor - Tor client]: Hidden Service Servers complain about ancient circs
Index(es):
- Author
- Thread