[SOLVED] Circular logging seems to be not working

[JasMan]

Hi,
I've noticed that some logs like those from NTP and Unbound showes only old entrys. I guess the circular logging is not working for those logs.

The log files under /var/log/ for this services have reached the configured maximum file size (System: Settings: Logging: Log File Size (Bytes), 20.000.000 Bytes on my OPNsense) and therefore, I guess, logging has stopped.

I haven't found any known issue about that. Maybe I've forgot only a setting or something like this.
The circular logging for the system log looks fine. The file has reached the maximum size too, but new logs are shown and the old ones dissapear.

Any idea?

Thank you.
Jas Man

[Drinyth]

No real ideas on how to solve the issue or where things got changed, but I checked both my NTP and unbound logs in /var/log just now and both of mine are showing up as circular log files? Strange.

[JasMan]

Hey,
Thank you for your reply.

How do you see that both files are circular log files? Have they reached the max file size and you still see new logs entries in the log?

On my OPNsense the logging works as long as the file has not reached his max file size. When the max file size has reached, no new entries are logged anymore.
When I restart e.g. the Unbound service then, new log entrys are logged again for some time. But sometime logging stops again.

Jas Man

EDIT: I just saw that OPNsense reserves the space for the log files. That means the files have always the maximum size. Now I guess logging stops when the file is full.

[franco]

I'm late to the party and have a question before looking further:

How do you measure that logs have stopped logging?


Cheers,
Franco

[JasMan]

I've set the logging of Unbound to level 2, which logs every forwarded DNS request to the external DNS server.

Sometime the last entries that are shown in the WebGUI are from e.g. yesterday or the day before. The logfiles last modified date shows the same date as the last entry in the WebGUI.

[JasMan]

I've just noticed that the OpenVPN clients are not able to resolve any internal and external DNS names when Unbound stopped logging. I'm not sure if both problems occure at the same time, but I guess that it do. The other clients in the LAN and Guest LAN are not affected by this issue.

After I increase the Unbound log level to 5, the log file filled up faster of course. I rebooted the appliance today at 12:00p.m. after I've installed all available upates. Four minutes later the logging in Unbound stopped. According to the time stamp of the log files, the gateways.log and the lighttp.log stopped at the same time:

Code: [Select]

root@JasWall:/var/log # ls -l -T *.log
-rw-r-----  1 root  wheel      6153 Jun 23 23:16:43 2018 acme.sh.log
-rw-------  1 root  wheel  25000000 Sep 24 20:48:18 2018 configd.log
-rw-------  1 root  wheel  25000000 Sep 24 20:45:10 2018 dhcpd.log
-rw-------  1 root  wheel    511488 Jul 27 22:35:16 2018 dnsmasq.log
-rw-------  1 root  wheel  25000000 Sep 24 20:45:52 2018 filter.log
-rw-------  1 root  wheel   6398208 Sep 24 20:51:07 2018 flowd.log
-rw-------  1 root  wheel  25000000 Sep 24 12:04:16 2018 gateways.log
-rw-------  1 root  wheel  25000000 Sep 24 20:48:49 2018 ipsec.log
-rw-r--r--  1 root  wheel  25000000 Sep 23 13:21:32 2018 l2tps.log
-rw-------  1 root  wheel  25000000 Sep 24 12:04:16 2018 lighttpd.log
-rw-r--r--  1 root  wheel  25000000 Sep 23 13:21:32 2018 mail.log
-rw-------  1 root  wheel  25000000 Sep 24 12:04:54 2018 ntpd.log
-rw-------  1 root  wheel  25000000 Sep 24 20:43:05 2018 openvpn.log
-rw-r--r--  1 root  wheel  25000000 Sep 23 13:21:32 2018 poes.log
-rw-------  1 root  wheel  25000000 Sep 24 12:11:00 2018 portalauth.log
-rw-------  1 root  wheel  25000000 Sep 23 13:21:33 2018 ppps.log
-rw-r--r--  1 root  wheel  25000000 Sep 23 13:21:33 2018 pptps.log
-rw-r--r--  1 root  wheel  25000000 Sep 23 13:21:33 2018 relayd.log
-rw-------  1 root  wheel  25000000 Sep 24 12:04:16 2018 resolver.log
-rw-------  1 root  wheel  25000000 Sep 23 13:21:33 2018 routing.log
-rw-------  1 root  wheel  25000000 Sep 24 18:01:01 2018 suricata.log
-rw-------  1 root  wheel  25000000 Sep 24 20:49:52 2018 system.log
-rw-r--r--  1 root  wheel      1510 Sep 24 20:49:31 2018 utx.log
-rw-------  1 root  wheel  25000000 Sep 23 13:21:33 2018 vpn.log
-rw-------  1 root  wheel  25000000 Sep 23 13:21:33 2018 wireless.log


[JasMan]

After my last post yesterday I've changed the log level of Unbound to 0 to log as less as possible and I restarted the service.
Until now there is only one log entry that the service was started. I'm pretty sure it's because the low log level and not because the logging is hanging again. Also DNS for the OpenVPN clients works since yesterday.

The lighttp.log is still very silent. No new entries since yesterday, 12:04p.m.. Hangs? Normal?

I'm sure that this behaviour was not in 17.x. I would have noticed that.
@Franco: Should I open an bug report? Or do you had already the time to take a look into?
Thanks in advance.

[JasMan]

I've set the logging of Unbound to level 2, which logs every forwarded DNS request to the external DNS server.

Sometime the last entries that are shown in the WebGUI are from e.g. yesterday or the day before. The logfiles last modified date shows the same date as the last entry in the WebGUI.

I did some more tests. I think the problem is not the circular logging, rather the Unbound server in combined with OpenVPN. I've disabled the OpenVPN service and now the logging of Unbound works fine since yesterday.

Could it have to do with my other issue which I've already posted here: https://forum.opnsense.org/index.php?topic=9161.msg41092#msg41092

Jas Man

[franco]

Discussion continues in https://github.com/opnsense/core/issues/2791