[tor-bugs] #28736 [Core Tor/sbws]: Make info level logs more clear and consistent

[Tor Bug Tracker & Wiki]

#28736: Make info level logs more clear and consistent
---------------------------+-----------------------------------
 Reporter:  juga           |          Owner:  (none)
     Type:  defect         |         Status:  new
 Priority:  Medium         |      Milestone:  sbws: 1.0.x-final
Component:  Core Tor/sbws  |        Version:  sbws: 1.0.2
 Severity:  Normal         |     Resolution:
 Keywords:                 |  Actual Points:
Parent ID:  #28663         |         Points:
 Reviewer:                 |        Sponsor:
---------------------------+-----------------------------------

Old description:

> I think the operator should see, at info level:
> - see one line when it fails (with the nick/fp of both relays and the
> reason)
> - see one line when it doesn't (with the nick/fp of both relays)
> Currently the failures are logged at several po
> ints in the code (and several levels)
> and the messages don't provide the same available information
>
> For instance, every time a relay fails to be measured, all these lines
> are shown:
> 2018-12-05 12:35:12,104 WARNING Thread-5 circuitbuilder.py:83 -
> _build_circuit_impl - Circuit failed to be created: CHANNEL_CLOSED
> 2018-12-05 12:35:12,107 WARNING Thread-5 circuitbuilder.py:83 -
> _build_circuit_impl - EXTENDCIRCUIT returned unexpected response code:
> 551
> 2018-12-05 12:35:12,108 WARNING Thread-5 circuitbuilder.py:83 -
> _build_circuit_impl - EXTENDCIRCUIT returned unexpected response code:
> 551
> 2018-12-05 12:35:12,109 WARNING Thread-5 scanner.py:203 - measure_relay -
> Could not build circuit involving UbuntuCore250
> 2018-12-05 12:36:13,848 WARNING Thread-5 scanner.py:217 - measure_relay -
> When measuring default 565B07B9 the destination seemed to have stopped )
>
> I think this should be only 1 line a level INFO, and the rest at DEBUG
> level
>
> For success measurements, it logs
> 2018-12-05 12:40:13,947 INFO Thread-1 resultdump.py:544 - handle_result -
> Torrr 96EA4E2C finished measurement with ResultSuccess
>
> Instead of ResultSuccess, should say which two relays were measureed.

New description:

 I think the operator should see, at info level:
 - see one line when it fails (with the nick/fp of both relays and the
 reason)
 - see one line when it doesn't (with the nick/fp of both relays)
 Currently the failures are logged at several po
 ints in the code (and several levels)
 and the messages don't provide the same available information

 For instance, every time a relay fails to be measured, all these lines are
 shown:

 {{{
 2018-12-05 12:35:12,104 WARNING Thread-5 circuitbuilder.py:83 -
 _build_circuit_impl - Circuit failed to be created: CHANNEL_CLOSED
 2018-12-05 12:35:12,107 WARNING Thread-5 circuitbuilder.py:83 -
 _build_circuit_impl - EXTENDCIRCUIT returned unexpected response code: 551
 2018-12-05 12:35:12,108 WARNING Thread-5 circuitbuilder.py:83 -
 _build_circuit_impl - EXTENDCIRCUIT returned unexpected response code: 551
 2018-12-05 12:35:12,109 WARNING Thread-5 scanner.py:203 - measure_relay -
 Could not build circuit involving UbuntuCore250
 2018-12-05 12:36:13,848 WARNING Thread-5 scanner.py:217 - measure_relay -
 When measuring default 565B07B9 the destination seemed to have stopped )
 }}}

 I think this should be only 1 line a level INFO, and the rest at DEBUG
 level

 For success measurements, it logs

 {{{
 2018-12-05 12:40:13,947 INFO Thread-1 resultdump.py:544 - handle_result -
 Torrr 96EA4E2C finished measurement with ResultSuccess
 }}}

 Instead of ResultSuccess, should say which two relays were measured.

 Edit: format

--

Comment (by juga):

 Replying to [ticket:28736 juga]:
 > I think the operator should see, at info level:
 > - see one line when it fails (with the nick/fp of both relays and the
 reason)
 > - see one line when it doesn't (with the nick/fp of both relays)
 > Currently the failures are logged at several po
 > ints in the code (and several levels)
 > and the messages don't provide the same available information
 >
 > For instance, every time a relay fails to be measured, all these lines
 are shown:
 > 2018-12-05 12:35:12,104 WARNING Thread-5 circuitbuilder.py:83 -
 _build_circuit_impl - Circuit failed to be created: CHANNEL_CLOSED
 > 2018-12-05 12:35:12,107 WARNING Thread-5 circuitbuilder.py:83 -
 _build_circuit_impl - EXTENDCIRCUIT returned unexpected response code: 551
 > 2018-12-05 12:35:12,108 WARNING Thread-5 circuitbuilder.py:83 -
 _build_circuit_impl - EXTENDCIRCUIT returned unexpected response code: 551
 > 2018-12-05 12:35:12,109 WARNING Thread-5 scanner.py:203 - measure_relay
 - Could not build circuit involving UbuntuCore250
 > 2018-12-05 12:36:13,848 WARNING Thread-5 scanner.py:217 - measure_relay
 - When measuring default 565B07B9 the destination seemed to have stopped )
 >
 > I think this should be only 1 line a level INFO, and the rest at DEBUG
 level
 >
 > For success measurements, it logs
 > 2018-12-05 12:40:13,947 INFO Thread-1 resultdump.py:544 - handle_result
 - Torrr 96EA4E2C finished measurement with ResultSuccess
 >
 > Instead of ResultSuccess, should say which two relays were measureed.

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