Opened 4 years ago

Last modified 21 months ago

#13386 new defect

"opening new log file" line goes to err-logfile despite being at loglevel notice

Reported by: toralf Owned by:
Priority: Low Milestone: Tor: unspecified
Component: Core Tor/Tor Version:
Severity: Normal Keywords: needs-design logging opening-file
Cc: atagar Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

Although I might image the rationale behind it, it is still confusing, that lines like

[notice] Tor 0.2.5.8-rc (git-a64f3ab3ee5c433c) opening log file.

are in the err log file for a torrc config like this :

# logging
#
Log notice file /var/log/tor/notice.log
Log warn file /var/log/tor/warn.log
Log err file /var/log/tor/err.log

Either the prefix "[notice]" should be changed to "[err]" or probably scrubbed away completely.

Child Tickets

Change History (6)

comment:1 Changed 4 years ago by nickm

Milestone: Tor: unspecified

comment:2 Changed 2 years ago by arma

Cc: atagar added
Severity: Normal
Summary: [notice] goes to err-logfile"opening new log file" line goes to err-logfile despite being at loglevel notice

To be clear, I think it is just that first log entry that goes there, since we want to tag the log file with what Tor version we are, and generate a line so people can know the log file is working. I think later [notice] lines don't end up in the error-level log file.

Calling that line an [err] doesn't make much sense to me, since errs are supposed to be things that prevented the Tor process from continuing.

And changing the format of log lines, e.g. by not putting a severity on this one, will confuse anything that tries to parse the log lines.

I guess I could see us changing that first line from

Nov 08 20:15:13.065 [notice] Tor 0.3.0.0-alpha-dev (git-25f53955f6d4fd85) opening new log file.

to something like

# Opening new log file at Nov 08 20:15:13.065. Tor 0.3.0.0-alpha-dev (git-25f53955f6d4fd85).

Damian, you're one of the people who tries to parse lines from the log files. What would you want here?

comment:3 Changed 2 years ago by atagar

Hi Roger. If the concern is that a 'notice' entry goes to the err log then why not fix this by sending it to the notice log instead? Is there a reason to change the line content?

comment:4 Changed 2 years ago by arma

No, it is not that a notice log line goes to the wrong log file. It is a special log line added to a newly made log file so it won't be empty.

See my above comment again. Then look at
https://gitweb.torproject.org/tor.git/tree/src/common/log.c?id=tor-0.2.8.9#n235

comment:5 Changed 2 years ago by atagar

I'm not a fan of changing the log line format but I'm not coming up with a better option. Making these lines special is a minor headache for parsers and things like the following...

% cut -d ' ' -f 4 ~/.tor/log | sort | uniq -c | sort -nr
  20803 [warn]
  13692 [notice]
   7832 [debug]
    135 [info]
     33 [err]
      2 /lib/i386-linux-gnu/libcrypto.so.1.0.0(OPENSSL_cleanse+0x32)[0xb723a5b2]
      2 
      1 tor(+0x14826e)[0xb760b26e]
      1 died:

From the above we evidently already have multi-line log entries so kinda already crossed that bridge...

Jul 09 08:28:28.000 [notice] No circuits are opened. Relaxed timeout for circuit 4708 (a Testing circuit 3-hop circuit in state doing handshakes with channel state open) to 60000ms. However, it appears the circuit has timed out anyway. 2 guards are live. [23 similar message(s) suppressed in last 3600 seconds]

============================================================ T= 1468078946
Tor 0.2.9.0-alpha-dev (git-44ea3dc3311564a9) died: Caught signal 11
tor(+0x14826e)[0xb760b26e]
/lib/i386-linux-gnu/libcrypto.so.1.0.0(OPENSSL_cleanse+0x32)[0xb723a5b2]
/lib/i386-linux-gnu/libcrypto.so.1.0.0(OPENSSL_cleanse+0x32)[0xb723a5b2]

Options that have come up thus far seem to be...

  • Drop these lines. This is a no-go because we need some sentinel to indicate when logging starts for a new tor instance.
  • Change these lines to [err] (or whatever the log has). This doesn't make sense. For instance, if I have "Log bw file /var/log/tor/bw.log" would we log these as bandwidth events?
  • Use special lines as suggested above. Not great, but livable.
  • Leave this unfixed, sending the notice to all log files.

Other ideas welcome but of the above either the special lines or leaving this unfixed have my vote. As sucky as these are the other options are even worse.

comment:6 Changed 21 months ago by nickm

Keywords: needs-design logging opening-file added
Note: See TracTickets for help on using tickets.