Foreman-proxy writing into deleted log file

Support
1

Problem:
I have just noticed that foreman-proxy is writing into a deleted file:

# lsof | fgrep -e DEL -e deleted
...
smart-pro   2346                  foreman-proxy    9w      REG              253,0      9162   83889316 /var/log/foreman-proxy/proxy.log-20220809 (deleted)
smart-pro   2346   3789 diagnosti foreman-proxy    9w      REG              253,0      9162   83889316 /var/log/foreman-proxy/proxy.log-20220809 (deleted)
smart-pro   2346   4733 diagnosti foreman-proxy    9w      REG              253,0      9162   83889316 /var/log/foreman-proxy/proxy.log-20220809 (deleted)
smart-pro   2346   4736 diagnosti foreman-proxy    9w      REG              253,0      9162   83889316 /var/log/foreman-proxy/proxy.log-20220809 (deleted)
...

The original file /var/log/foreman-proxy/proxy.log has been rotated by logrotate, i.e. moved and then compressed. There is a logrotate configuration for the proxy:

# cat /etc/logrotate.d/foreman-proxy 
/var/log/foreman-proxy/migrate_settings.log
/var/log/foreman-proxy/proxy.log
{
  missingok
  notifempty
  create 0644 foreman-proxy foreman-proxy
  sharedscripts
  rotate 5
  compress
        daily
  postrotate
    /bin/systemctl kill --signal=SIGUSR1 foreman-proxy >/dev/null 2>&1 || true
  endscript
}

But it seems SIGUSR1 doesn’t do what it should here…

Expected outcome:
foreman-proxy closing the old file and opening a new file.

Foreman and Proxy versions:
foreman-proxy-3.3.0-1.el8.noarch

Distribution and version:
AlmaLinux 8.6

2

Is nobody else noticing this?

3

Just noticed again:

smart-pro    994                  foreman-proxy   11w      REG              253,0      9170   21028310 /var/log/foreman-proxy/proxy.log-20221028 (deleted)
smart-pro    994   1610 diagnosti foreman-proxy   11w      REG              253,0      9170   21028310 /var/log/foreman-proxy/proxy.log-20221028 (deleted)
smart-pro    994   1742 diagnosti foreman-proxy   11w      REG              253,0      9170   21028310 /var/log/foreman-proxy/proxy.log-20221028 (deleted)
smart-pro    994  77951 diagnosti foreman-proxy   11w      REG              253,0      9170   21028310 /var/log/foreman-proxy/proxy.log-20221028 (deleted)

We use logrotate and there is a logrotate configuration:

# cat /etc/logrotate.d/foreman-proxy 
/var/log/foreman-proxy/migrate_settings.log
/var/log/foreman-proxy/proxy.log
{
  missingok
  notifempty
  create 0644 foreman-proxy foreman-proxy
  sharedscripts
  rotate 5
  compress
        daily
  postrotate
    /bin/systemctl kill --signal=SIGUSR1 foreman-proxy >/dev/null 2>&1 || true
  endscript
}

However, the USR1 signal isn’t doing what it’s supposed to do:

# /bin/systemctl kill --signal=SIGUSR1 foreman-proxy
# lsof | fgrep -e DEL -e deleted
...
smart-pro    994                  foreman-proxy   11w      REG              253,0      9170   21028310 /var/log/foreman-proxy/proxy.log-20221028 (deleted)
smart-pro    994   1610 diagnosti foreman-proxy   11w      REG              253,0      9170   21028310 /var/log/foreman-proxy/proxy.log-20221028 (deleted)
smart-pro    994   1742 diagnosti foreman-proxy   11w      REG              253,0      9170   21028310 /var/log/foreman-proxy/proxy.log-20221028 (deleted)
smart-pro    994  77951 diagnosti foreman-proxy   11w      REG              253,0      9170   21028310 /var/log/foreman-proxy/proxy.log-20221028 (deleted)
4

Continuing here from Logrotate of Smart-Proxy kills REX SSH sessions - #5 by gvde to not derail the topic there further.

I am absolutely sure it’s working. I have just run lsof | fgrep -e DEL -e deleted | grep pro, I get no results.
When I intentionally make foreman-proxy log an error (by querying the DHCP API for an invalid subnet), I can see the error beeing logged to /var/log/foreman-proxy/proxy.log. I can also see the logentries from yesterday’s test in the rotated file /var/log/foreman-proxy/proxy.log-20221222.gz. As already mentioned, this in 3.2:

# rpm -q foreman-proxy
foreman-proxy-3.2.1-1.el7.noarch

In our EL8 test environment, I can see the same behaviour with 3.2. No open deleted files by foreman-proxy, and logs being correctly written to the new file after rotation:

# rpm -q foreman-proxy
foreman-proxy-3.2.1-1.el8.noarch
5

Same here, it “just works”.

If I am reading smart-proxy/decorator.rb at befb442f443cf345c8c92d83ad0a159f261137f5 · theforeman/smart-proxy · GitHub correctly, the roll-over happens the moment a new message is logged, and not immediately on SIGUSR1. Can you check that the file actually has entries after it has been rotated?

6

Really? O.K. That is really unexpected to me. I occasionally scan for open deleted files (e.g. after updates, to see what needs to be restarted) and an open deleted log file usually means, the process didn’t get the correct signal. Obviously, then I see the exact same symptoms: process has deleted rotated logfile open and the logfile itself has size zero.

I now sent a /version to the foreman-proxy via API as that’s logged and you are correct. The message goes into proxy.log:

# cat /var/log/foreman-proxy/proxy.log
2022-12-22T10:33:58  [I] Logging file reopened via USR1 signal
2022-12-22T10:33:59 6c797e3f [I] Started GET /version 
2022-12-22T10:33:59 6c797e3f [I] Finished GET /version with 200 (0.5 ms)

O.K. It works. But I find this most confusing. The symptoms I see until then cannot be distinguished to the case when it didn’t catch the signal and is actually writing into the deleted file. And the timestamp to the Logging file reopened via USR1 signal is also misleading as the signal came at a completely different time.

So my question is: isn’t it possible to close the old file on USR1? It’s pointless to keep it open and close it only on the next message written. This would at least get rid off those confusing symptoms.

7

I guess it would be nicer, yeah. But my knowledge around logging is very limited.

If you look at the commits that touched this functionality:

it was intentionally implemented like this, which hints at “not (easily) possible”?

8

Too bad. At least the logs aren’t large so it doesn’t matter so much if the open deleted file still allocates disk space until the next message is logged…