Opened 6 years ago

Last modified 2 years ago

#9860 needs_revision defect

junk log messages every time SETCONF changes the set of ORPorts

Reported by: zwol Owned by:
Priority: Very Low Milestone: Tor: unspecified
Component: Core Tor/Tor Version: Tor: 0.2.4.17-rc
Severity: Normal Keywords: tor-client, tor-relay, easy, deferrable, logging, usability torrc
Cc: Actual Points:
Parent ID: Points: small/medium
Reviewer: Sponsor:

Description

Every time you use SETCONF (from a controller) to change the set of ORPorts, Tor emits log messages like this:

Sep 30 23:45:59.000 [notice] Opening OR listener on 0.0.0.0:9022
Sep 30 23:45:59.000 [notice] Tor 0.2.4.17-rc-dev (git-00fb525+ace95c5+0e691f1) opening log file.
Sep 30 23:46:00.000 [notice] Your Tor server's identity key fingerprint is 'tbbscraperentry 73EFD4FE8D5D2466ECBDCFAC11894A72A322FD3C'
Sep 30 23:47:42.000 [notice] Opening OR listener on 0.0.0.0:9023
Sep 30 23:47:42.000 [notice] Tor 0.2.4.17-rc-dev (git-00fb525+ace95c5+0e691f1) opening log file.
Sep 30 23:47:42.000 [notice] Your Tor server's identity key fingerprint is 'tbbscraperentry 73EFD4FE8D5D2466ECBDCFAC11894A72A322FD3C'
Sep 30 23:50:40.000 [notice] Closing no-longer-configured OR listener on 0.0.0.0:9008
Sep 30 23:50:40.000 [notice] Tor 0.2.4.17-rc-dev (git-00fb525+ace95c5+0e691f1) opening log file.
Sep 30 23:50:40.000 [notice] Closing old OR listener on 0.0.0.0:9008
Sep 30 23:50:40.000 [notice] Your Tor server's identity key fingerprint is 'tbbscraperentry 73EFD4FE8D5D2466ECBDCFAC11894A72A322FD3C'
Sep 30 23:50:45.000 [notice] Closing no-longer-configured OR listener on 0.0.0.0:9012
Sep 30 23:50:45.000 [notice] Tor 0.2.4.17-rc-dev (git-00fb525+ace95c5+0e691f1) opening log file.
Sep 30 23:50:45.000 [notice] Closing old OR listener on 0.0.0.0:9012
Sep 30 23:50:45.000 [notice] Your Tor server's identity key fingerprint is 'tbbscraperentry 73EFD4FE8D5D2466ECBDCFAC11894A72A322FD3C'

The "opening log file" and "Your Tor server's identity key fingerprint is" lines should not be printed for every configuration change. And I'm not sure why it tells me it's closing a listener twice.

Child Tickets

Attachments (3)

0001-Trying-to-avoid-junk-log-messsages.patch (2.1 KB) - added by rl1987 6 years ago.
0002-Preventing-junk-log-messages-when-ORPort-changes.patch (2.5 KB) - added by rl1987 6 years ago.
0003-Silence-GCC-warning.patch (841 bytes) - added by rl1987 6 years ago.

Download all attachments as: .zip

Change History (31)

comment:1 Changed 6 years ago by zwol

Component: - Select a componentTor
Version: Tor: 0.2.4.17-rc

comment:2 Changed 6 years ago by nickm

Keywords: tor-client tor-relay easy deferrable added
Milestone: Tor: 0.2.4.x-final

The identity fingerprint message comes from init_keys() in src/or/router.c; it would be fine to make that happen only once using a static boolean.

We should demote one of the "closing listener" messages to info.

The simplest workaround for the "opening log" one would be to only do the log-reopening dance in options_act_reversible if the log options have really changed.

comment:3 in reply to:  2 Changed 6 years ago by rl1987

Replying to nickm:

The simplest workaround for the "opening log" one would be to only do the log-reopening dance in options_act_reversible if the log options have really changed.

How do we know if the options have changed? We can't use tor_memcmp() to compare or_options_t structs since memory alignment of fields may differ even if individual field values are equal. Is there another way?

comment:4 Changed 6 years ago by rl1987

Status: newneeds_information

comment:5 Changed 6 years ago by nickm

Status: needs_informationnew

You'd compare the specific options, either with the generic "config_is_same()" function:

   config_is_same(&options_format, options, old_options, "Log")

or with a type-specific comparison, as in:

   config_lines_eq(options->Logs, old_options->Logs)

comment:6 Changed 6 years ago by rl1987

I have attempted to fix this bug in a way you described, but "Opening OR listener" messages are originating from code in connection.c and probably should be addressed in some other way.

comment:7 Changed 6 years ago by rl1987

Status: newneeds_review

comment:8 Changed 6 years ago by nickm

Hm. This has potential, but there's a problem. "Logs" is not the only option that affects logging. There's also LogTimeGranularity, RunAsDaemon, and LogMessageDomains. Changes in those ones might not warrant closing and re-opening all the logs, but they _do_ mean that the other part of options_init_logs() will need to get called.

comment:9 Changed 6 years ago by rl1987

Do we need to get rid of "Opening OR listener" message? It doesn't seem be redundant here, since it informs the user that OR port did actually change.

comment:10 Changed 6 years ago by zwol

No, that one, and one of the two "Closing OR listener..." messages, should stay.

comment:11 Changed 6 years ago by rl1987

If we have log_notice() in retry_all_listeners(), we are getting this behaviour:

Oct 26 16:46:48.000 [notice] New control connection opened.
Oct 26 16:47:02.000 [notice] Opening OR listener on 0.0.0.0:9053
Oct 26 16:47:02.000 [notice] Closing no-longer-configured OR listener on 127.0.0.1:9090
Oct 26 16:47:02.000 [notice] Closing no-longer-configured OR listener on 0.0.0.0:9001
Oct 26 16:47:09.000 [notice] Opening OR listener on 0.0.0.0:9054
Oct 26 16:47:09.000 [notice] Closing no-longer-configured OR listener on 0.0.0.0:9053
Oct 26 16:47:09.000 [notice] Closing no-longer-configured OR listener on 127.0.0.1:9090
Oct 26 16:47:09.000 [notice] Closing no-longer-configured OR listener on 0.0.0.0:9001
Oct 26 16:47:25.000 [notice] Closing no-longer-configured OR listener on 0.0.0.0:9053
Oct 26 16:47:25.000 [notice] Closing no-longer-configured OR listener on 127.0.0.1:9090
Oct 26 16:47:25.000 [notice] Closing no-longer-configured OR listener on 0.0.0.0:9001

Is this acceptable? Does that indicate problems with listener closing logic?

comment:12 Changed 6 years ago by nickm

At least one of the "Closing no-longer-configured FOO" and "Closing old FOO" should turn into an info.

comment:13 Changed 6 years ago by arma

This is just a log thing? And we're still trying to sort out how we want it to behave and whether we've gotten our patch right? That makes it a good candidate for 0.2.5 rather than 0.2.4.

comment:14 Changed 6 years ago by nickm

Milestone: Tor: 0.2.4.x-finalTor: 0.2.5.x-final
Status: needs_reviewneeds_revision

Changed 6 years ago by rl1987

comment:15 Changed 6 years ago by nickm

Milestone: Tor: 0.2.5.x-finalTor: 0.2.6.x-final

Moving nearly all needs_revision tickets into 0.2.6, as now untimely for 0.2.5.

comment:16 Changed 5 years ago by nickm

Status: needs_revisionneeds_review

comment:17 Changed 5 years ago by nickm

Status: needs_reviewneeds_revision

comment:18 Changed 5 years ago by nickm

Milestone: Tor: 0.2.6.x-finalTor: 0.2.7.x-final

comment:19 Changed 4 years ago by nickm

Keywords: 027-triaged-1-out added

Marking triaged-out items from first round of 0.2.7 triage.

comment:20 Changed 4 years ago by nickm

Milestone: Tor: 0.2.7.x-finalTor: 0.2.???

Move *most* 0.2.7-triaged-1-out needs_revision items into 0.2.???. Keep a few based on my sense of the sensible.

comment:21 Changed 4 years ago by nickm

Points: small/medium
Severity: Normal

comment:22 Changed 3 years ago by teor

Milestone: Tor: 0.2.???Tor: 0.3.???

Milestone renamed

comment:23 Changed 3 years ago by nickm

Keywords: tor-03-unspecified-201612 added
Milestone: Tor: 0.3.???Tor: unspecified

Finally admitting that 0.3.??? was a euphemism for Tor: unspecified all along.

comment:24 Changed 2 years ago by nickm

Keywords: tor-03-unspecified-201612 removed

Remove an old triaging keyword.

comment:25 Changed 2 years ago by nickm

Keywords: 027-triaged-in added

comment:26 Changed 2 years ago by nickm

Keywords: 027-triaged-in removed

comment:27 Changed 2 years ago by nickm

Keywords: 027-triaged-1-out removed

comment:28 Changed 2 years ago by nickm

Keywords: logging usability torrc added
Note: See TracTickets for help on using tickets.