log rotation for /var/log/tor/debug.log did not close handle to old file after compression

so / ran full after a week or so. I found the culprits with: find /proc/*/fd -ls | grep '(deleted)'

Version: tor 0.4.2.7-1~d8.jessie+1

Config:

Standard torrc with one Hidden service, using an HTTPSProxy and notice+debug logging enabled:

Log notice file /var/log/tor/notices.log Log debug file /var/log/tor/debug.log

Trac:
Username: MaKoTor

changed milestone to %Tor: unspecified in legacy/trac

Trac:
Parent Ticket: legacy/trac#33087 (moved)

added 044-deferred in Legacy / Trac backport in Legacy / Trac component::core tor/tor in Legacy / Trac logs in Legacy / Trac milestone::Tor: unspecified in Legacy / Trac parent::33087 in Legacy / Trac priority::medium in Legacy / Trac reporter::MaKoTor in Legacy / Trac severity::normal in Legacy / Trac status::new in Legacy / Trac type::defect in Legacy / Trac labels

After rebooting the machine ~1.5 days ago, it starts happening again:

$ sudo find /proc/*/fd -ls | grep  '(deleted)'
 11271    0 l-wx------   1 debian-tor debian-tor       64 Apr  8 14:12 /proc/509/fd/9 -> /var/log/tor/debug.log.1\ (deleted)
 11272    0 l-wx------   1 debian-tor debian-tor       64 Apr  8 14:12 /proc/509/fd/10 -> /var/log/tor/notices.log.1\ (deleted)

I will enable similar log configurations on other hosts with other linux flavors and start tracking down if the problem is related to /etc/logrotate.d/tor , tor itself or if it is a one-off on the currently affected machine.

Trac:
Username: MaKoTor

Does your logrotate plan hup tor afterwards? If you hup tor, it should release its old handles on the log files.

That said, Debian jessie is pretty much dead. I would suggest moving to a supported Debian and seeing if your issue gets resolved.

Confirmed the behavior on two Ubuntu 16.04 and 18.04 as well, so far affected afaik:

0.4.2.7-1xenial+1 0.4.2.7-1bionic+1 0.4.2.7-1~d8.jessie+1

The /etc/logrotate.d/tor in all these packages does not explicitly HUP, instead it:

 postrotate
                if invoke-rc.d tor status > /dev/null; then
                        invoke-rc.d tor reload > /dev/null
                fi

Running "sudo service tor reload" manually does reload the config, but does not close the file handles, and produces, among others, this log line:

Apr 14 08:49:19.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.

This line is also in all the compressed log files as well - so hup is performed but doesn't help.

Thanks, ama, for the hup pointer - I now started to look into: ./src/lib/log/log.c ./src/app/main/main.c:do_hup(void) but the log (file) interactions are quite complex (too complex?)

I guess I will try to locate some life systems with older tor versions to get a "binary search" going - I assume this is a recent "regression", or nobody ever noticed?

btw, http://dccbbv6cooddgcrq.onion/tor.git also doesn't respond (it's advertised in the footer of https://gitweb.torproject.org/tor.git). Sorry, Off-topic.

Trac:
Username: MaKoTor

Found versions which seem NOT AFFECTED:

0.2.9.14-1ubuntu116.04.3 0.4.1.5-1xenial+1 0.4.3.4-rc built from git

Since 0.4.2.7-1~xenial+1 IS affected (see above), a change somewhere between

0.4.1.5 and 0.4.2.7

is most likely the culprit, and it seems to be fixed again in

tor-0.4.3.4-rc

./src/lib/log/log.c seems to be under heavy development right now.

It's also now proven it's not log-rotation specific, instead, 0.4.2.7 seems to open two handles for each log file, and only closes one of them HUP.

Trac:
Username: MaKoTor

Nice find!

Next step is to do a 'git bisect' to figure out which commit introduced the bug.

Do you know how to do one of those, and/or would you like to use this as a learning opportunity, and/or is that something somebody else should pick up?

Check out legacy/trac#33087 (moved) ("bugfix on 0.4.1.6") for one possibility.

Yes, bisecting just confirmed, it's 8a23393e which fixes it onwards.

So the question is... developing a patch for 0.4.2.7 ?

Trac:
Username: MaKoTor

Good stuff. That commit is part of legacy/trac#33087 (moved) (which aimed to resolve bugs in legacy/trac#31594 (moved)), and legacy/trac#33087 (moved) went into 0.4.3 and is awaiting backport to 0.4.1 and 0.4.2.

Also interesting: 0.4.1 (0.4.1.5-1~xenial+1 at least) was not affected (yet), any risk backporting might have unintended consequences on that one?

How could I test the outstanding backport(s) to confirm?

Trac:
Username: MaKoTor

Trac:
Parent: N/A to legacy/trac#33087 (moved)

Trac:
Keywords: N/A deleted, backport logs added
Milestone: N/A to Tor: 0.4.4.x-final

Bulk-remove tickets from 0.4.4. Add the 044-deferred label to them.

Trac:
Milestone: Tor: 0.4.4.x-final to Tor: unspecified
Keywords: backport logs deleted, logs, 044-deferred, backport added

mentioned in issue legacy/trac#33087 (moved)

moved from legacy/trac#33850 (moved)

added Bug label and removed 1 deleted label

added Deferred label and removed 1 deleted label

This seems to be a real bug that got bisected. We should try to fix it.

changed milestone to %Tor: 0.4.5.x-freeze

changed milestone to %Tor: 0.4.5.x-stable

I think from the above that this bug is another result of #33087 (closed), which was fixed in 0.4.2, though commit 8a23393e looks like it didn't go in until 0.4.3.4-rc.

In any case it was fixing a bug that went into 0.4.1. And now each of 0.4.1 and 0.4.2 and 0.4.3.3-alpha are obsolete.

So I think this bug is resolved.

Closing as resolved: This is fixed in 0.4.3, and 0.4.2 and 0.4.1 are no longer supported.

closed