Ipfire 171 (test) problems logs in /cgi-bin/logs.cgi/log.dat

pscar13 · 6 October 2022 20:42

Hello,

Since my first test of the core 171 version (ustable published by P Muller on 09/16
ASIX ax88179_178a USB-to-LAN adapter unusable after Core Update 170 - #22 by pmueller),

I had noticed that I no longer saw my pppd logs in RED on the /cgi-bin/logs.cgi/log.dat page

I updated this morning to the C171 test version and I still see the problem

In fact the problem concerns all messages other than “kernel” which contain two spaces after the hostname in the file /var/log/messages
(pppd, unbound, …)

Here is an excerpt from my /var/log/messages

Oct  6 17:48:45 ipfire kernel: Adding 479812k swap on /dev/sda3.  Priority:1 extents:1 across:479812k SSFS
Oct  6 17:48:45 ipfire  unbound: [4151:0] notice: init module 0: validator
Oct  6 17:48:45 ipfire  unbound: [4151:0] notice: init module 1: iterator
Oct  6 17:48:45 ipfire  acpid: starting up with netlink and the input layer
Oct  6 17:48:45 ipfire  acpid: 1 rule loaded
Oct  6 17:48:45 ipfire  acpid: waiting for events: event logging is off
Oct  6 17:48:45 ipfire  unbound: [4151:0] info: start of service (unbound 1.16.3).
Oct  6 17:48:46 ipfire kernel: RTL8211E Gigabit Ethernet r8169-0-200:00: attached PHY driver (mii_bus:phy_addr=r8169-0-200:00, irq=MAC)
Oct  6 17:48:46 ipfire kernel: r8169 0000:02:00.0 green0: Link is Down
Oct  6 17:48:47 ipfire  pppd[4312]: Plugin rp-pppoe.so loaded.
Oct  6 17:48:47 ipfire connectd[4313]: Connectd (start) started with PID 4313
Oct  6 17:48:47 ipfire kernel: PPP generic driver version 2.4.2
Oct  6 17:48:47 ipfire  pppd[4312]: PPPoE plugin from pppd 2.4.9
Oct  6 17:48:47 ipfire  pppd[4312]: pppd 2.4.9 started by root, uid 0
Oct  6 17:48:47 ipfire kernel: NET: Registered PF_PPPOX protocol family
Oct  6 17:48:48 ipfire kernel: ax88179_178a 1-1.1:1.0 blue0: ax88179 - Link status is: 1
Oct  6 17:48:49 ipfire kernel: ax88179_178a 1-1.2:1.0 red0: ax88179 - Link status is: 1
Oct  6 17:48:49 ipfire kernel: r8169 0000:02:00.0 green0: Link is Up - 1Gbps/Full - flow control rx/tx
Oct  6 17:48:49 ipfire  unbound: [4151:0] error: SERVFAIL <checkipv6.synology.com. AAAA IN>: exceeded the maximum number of sends
Oct  6 17:48:49 ipfire  unbound: [4151:0] error: SERVFAIL <checkipv6.synology.com. AAAA IN>: exceeded the maximum number of sends
Oct  6 17:48:50 ipfire  unbound: [4151:0] error: SERVFAIL <_ldap._tcp.dc._msdcs.pscar.dynu.com. SRV IN>: exceeded the maximum number of sends
Oct  6 17:48:50 ipfire  unbound: [4151:0] error: SERVFAIL <www.msftconnecttest.com. A IN>: exceeded the maximum number of sends
Oct  6 17:48:50 ipfire  unbound: [4151:0] error: SERVFAIL <_ldap._tcp.dc._msdcs.pscar.dynu.com. SRV IN>: exceeded the maximum number of sends
Oct  6 17:48:50 ipfire  unbound: [4151:0] error: SERVFAIL <www.msftconnecttest.com. A IN>: exceeded the maximum number of sends
Oct  6 17:48:51 ipfire  unbound: [4151:0] error: SERVFAIL <_ldap._tcp.dc._msdcs.pscar.dynu.com. SRV IN>: exceeded the maximum number of sends
Oct  6 17:48:52 ipfire  pppd[4312]: PPP session is 9473
Oct  6 17:48:52 ipfire  pppd[4312]: Connected to 02:03:3a:04:79:3f via interface red0
Oct  6 17:48:52 ipfire  pppd[4312]: Using interface ppp0
Oct  6 17:48:52 ipfire  pppd[4312]: Connect: ppp0 <--> red0
Oct  6 17:48:52 ipfire root: Could not find a bridged zone for ppp0
Oct  6 17:48:53 ipfire  unbound: [4151:0] error: SERVFAIL <api.onedrive.com. A IN>: exceeded the maximum number of sends
Oct  6 17:48:53 ipfire  unbound: [4151:0] error: SERVFAIL <api.onedrive.com. AAAA IN>: exceeded the maximum number of sends
Oct  6 17:48:53 ipfire  unbound: [4151:0] error: SERVFAIL <api.onedrive.com. A IN>: exceeded the maximum number of sends
Oct  6 17:48:53 ipfire  unbound: [4151:0] error: SERVFAIL <api.onedrive.com. AAAA IN>: exceeded the maximum number of sends
Oct  6 17:48:53 ipfire  pppd[4312]: CHAP authentication succeeded: CHAP authentication success, unit 947
Oct  6 17:48:53 ipfire  pppd[4312]: CHAP authentication succeeded
Oct  6 17:48:53 ipfire  pppd[4312]: peer from calling number 02:03:3A:04:79:3F authorized
Oct  6 17:48:53 ipfire  pppd[4312]: local  IP address xxxxxxxxxxxx
Oct  6 17:48:53 ipfire  pppd[4312]: remote IP address xxxxxxxxxxxx
Oct  6 17:48:53 ipfire  pppd[4312]: primary   DNS address xxxxxxxxxxxx
Oct  6 17:48:53 ipfire  pppd[4312]: secondary DNS address xxxxxxxxxxxx
Oct  6 17:48:55 ipfire  vnstatd[4034]: Interface "ppp0" enabled.
Oct  6 17:48:56 ipfire  unbound: [4151:0] info: generate keytag query _ta-4a5c-4f66. NULL IN
Oct  6 17:48:57 ipfire connectd[4313]: System is online. Exiting.
Oct  6 17:48:57 ipfire  saslauthd[5262]: detach_tty      : master pid is: 5262
Oct  6 17:48:57 ipfire  saslauthd[5262]: ipc_init        : listening on socket: /var/run/saslauthd/mux
Oct  6 17:49:00 ipfire  vnstatd[4034]: Removing interface "ifb0" from database as it is disabled and has seen no data.
Oct  6 17:49:00 ipfire  vnstatd[4034]: Interface "ifb0" no longer in database, stopping monitoring.
Oct  6 17:49:00 ipfire  vnstatd[4034]: Monitoring (7): wlan0 (1000 Mbit) red0 (1000 Mbit) ppp0 (1000 Mbit) orange0 (1000 Mbit) imq0 (1000 Mbit) green0 (1000 Mbit) blue0 (1000 Mbit) 
Oct  6 17:49:02 ipfire kernel: DROP_HOSTILE IN=ppp0 OUT= MAC= SRC=89.248.165.118 DST=xx.xx.xx.xx LEN=40 TOS=0x00 PREC=0x00 TTL=246 ID=25580 PROTO=TCP SPT=45563 DPT=3376 WINDOW=1024 RES=0x00 SYN URGP=0 
Oct  6 17:49:03 ipfire kernel: IPv4: martian source 169.254.255.255 from 169.254.190.133, on dev green0
Oct  6 17:49:03 ipfire kernel: ll header: 00000000: ff ff ff ff ff ff 98 48 27 db 79 58 08 00
Oct  6 17:49:03 ipfire kernel: IPv4: martian source 169.254.255.255 from 169.254.190.133, on dev green0
Oct  6 17:49:03 ipfire kernel: ll header: 00000000: ff ff ff ff ff ff 98 48 27 db 79 58 08 00
Oct  6 17:49:04 ipfire kernel: IPv4: martian source 169.254.255.255 from 169.254.190.133, on dev green0
Oct  6 17:49:04 ipfire kernel: ll header: 00000000: ff ff ff ff ff ff 98 48 27 db 79 58 08 00
Oct  6 17:49:04 ipfire kernel: IPv4: martian source 169.254.255.255 from 169.254.190.133, on dev green0
Oct  6 17:49:04 ipfire kernel: ll header: 00000000: ff ff ff ff ff ff 98 48 27 db 79 58 08 00
Oct  6 17:49:05 ipfire  ntpdate[5306]: adjust time server 46.243.26.34 offset +0.001889 sec
Oct  6 17:49:05 ipfire ipfire: NTP synchronisation
Oct  6 17:49:06 ipfire  ntpd[5846]: ntpd 4.2.8p15@1.3728-o Tue Sep 13 13:05:10 UTC 2022 (1): Starting
Oct  6 17:49:06 ipfire  ntpd[5846]: Command line: /usr/bin/ntpd -Ap /var/run/ntpd.pid
Oct  6 17:49:06 ipfire  ntpd[5846]: ----------------------------------------------------
Oct  6 17:49:06 ipfire  ntpd[5846]: ntp-4 is maintained by Network Time Foundation,
Oct  6 17:49:06 ipfire  ntpd[5846]: Inc. (NTF), a non-profit 501(c)(3) public-benefit
Oct  6 17:49:06 ipfire  ntpd[5846]: corporation.  Support and training for ntp-4 are
Oct  6 17:49:06 ipfire  ntpd[5846]: available at https://www.nwtime.org/support
Oct  6 17:49:06 ipfire  ntpd[5846]: ----------------------------------------------------
Oct  6 17:49:06 ipfire  ntpd[5849]: proto: precision = 0.168 usec (-22)
Oct  6 17:49:06 ipfire  ntpd[5849]: basedate set to 2022-09-01
Oct  6 17:49:06 ipfire  ntpd[5849]: gps base set to 2022-09-04 (week 2226)
Oct  6 17:49:06 ipfire  ntpd[5849]: Listen and drop on 0 v6wildcard [::]:123
Oct  6 17:49:06 ipfire  ntpd[5849]: Listen and drop on 1 v4wildcard 0.0.0.0:123
Oct  6 17:49:06 ipfire  ntpd[5849]: Listen normally on 2 lo 127.0.0.1:123
Oct  6 17:49:06 ipfire  ntpd[5849]: Listen normally on 3 green0 192.168.10.1:123
Oct  6 17:49:06 ipfire  ntpd[5849]: Listen normally on 4 blue0 192.168.20.1:123
Oct  6 17:49:06 ipfire  ntpd[5849]: Listen normally on 5 ppp0 90.37.65.57:123
Oct  6 17:49:06 ipfire  ntpd[5849]: Listening on routing socket on fd #22 for interface updates
Oct  6 17:49:06 ipfire  ntpd[5849]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
Oct  6 17:49:06 ipfire  ntpd[5849]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
Oct  6 17:49:06 ipfire kernel: IPv4: martian source 169.254.255.255 from 169.254.190.133, on dev green0
Oct  6 17:49:06 ipfire kernel: ll header: 00000000: ff ff ff ff ff ff 98 48 27 db 79 58 08 00
Oct  6 17:49:06 ipfire kernel: IPv4: martian source 169.254.255.255 from 169.254.190.133, on dev green0
Oct  6 17:49:06 ipfire kernel: ll header: 00000000: ff ff ff ff ff ff 98 48 27 db 79 58 08 00
Oct  6 17:49:06 ipfire  collectd[5925]: cpufreq plugin: Found 2 CPUs
Oct  6 17:49:06 ipfire  collectd[5925]: Initialization complete, entering read-loop.
Oct  6 17:49:06 ipfire  dhcpd: Wrote 0 deleted host decls to leases file.
Oct  6 17:49:06 ipfire  dhcpd: Wrote 0 new dynamic host decls to leases file.
Oct  6 17:49:06 ipfire  dhcpd: Wrote 6 leases to leases file.
Oct  6 17:49:06 ipfire  dhcpd: Server starting service.
Oct  6 17:49:07 ipfire  sshd[6029]: Server listening on 0.0.0.0 port 222.
Oct  6 17:49:07 ipfire kernel: IPv4: martian source 169.254.255.255 from 169.254.190.133, on dev green0
Oct  6 17:49:07 ipfire kernel: ll header: 00000000: ff ff ff ff ff ff 98 48 27 db 79 58 08 00
Oct  6 17:49:07 ipfire  dhcpd: DHCPDISCOVER from 98:48:27:db:79:58 via green0
Oct  6 17:49:07 ipfire  dhcpd: DHCPOFFER on 192.168.10.37 to 98:48:27:db:79:58 via green0
Oct  6 17:49:07 ipfire  dhcpd: DHCPREQUEST for 192.168.10.37 (192.168.10.1) from 98:48:27:db:79:58 via green0
Oct  6 17:49:07 ipfire  dhcpd: DHCPACK on 192.168.10.37 to 98:48:27:db:79:58 via green0
Oct  6 17:49:07 ipfire  suricata: This is Suricata version 6.0.8 RELEASE running in SYSTEM mode
Oct  6 17:49:07 ipfire  suricata: CPUs/cores online: 2
Oct  6 17:49:07 ipfire  suricata: HTTP memcap: 268435456
Oct  6 17:49:07 ipfire  suricata: Enabling fail-open on queue
Oct  6 17:49:07 ipfire  suricata: NFQ running in REPEAT mode with mark 2147483648/2147483648
Oct  6 17:49:08 ipfire  suricata: dropped the caps for main thread
Oct  6 17:49:08 ipfire  suricata: fast output device (regular) initialized: fast.log
Oct  6 17:49:08 ipfire  suricata: Packets will start being processed before signatures are active.
Oct  6 17:49:08 ipfire  suricata: binding this thread 0 to queue '0'
Oct  6 17:49:08 ipfire  suricata: setting queue length to 4096
Oct  6 17:49:08 ipfire  suricata: setting nfnl bufsize to 6144000
Oct  6 17:49:08 ipfire  suricata: fail-open mode should be set on queue
Oct  6 17:49:08 ipfire  suricata: binding this thread 1 to queue '1'
Oct  6 17:49:08 ipfire  suricata: setting queue length to 4096
Oct  6 17:49:08 ipfire  suricata: setting nfnl bufsize to 6144000
Oct  6 17:49:08 ipfire  suricata: fail-open mode should be set on queue
Oct  6 17:49:08 ipfire  dhcpd: DHCPDISCOVER from 6c:f7:84:99:ab:14 via green0
Oct  6 17:49:08 ipfire  dhcpd: DHCPOFFER on 192.168.10.14 to 6c:f7:84:99:ab:14 via green0
Oct  6 17:49:08 ipfire  suricata: all 2 packet processing threads, 2 management threads initialized, engine started.
Oct  6 17:49:08 ipfire  suricata: rule reload starting
Oct  6 17:49:08 ipfire  suricata: Including configuration file /var/ipfire/suricata/suricata-homenet.yaml.
Oct  6 17:49:08 ipfire  suricata: Including configuration file /var/ipfire/suricata/suricata-dns-servers.yaml.
Oct  6 17:49:08 ipfire  suricata: Including configuration file /var/ipfire/suricata/suricata-http-ports.yaml.
Oct  6 17:49:08 ipfire  suricata: Including configuration file /var/ipfire/suricata/suricata-used-rulesfiles.yaml.
Oct  6 17:49:08 ipfire  dhcpd: DHCPREQUEST for 192.168.10.14 (192.168.10.1) from 6c:f7:84:99:ab:14 via green0
Oct  6 17:49:08 ipfire  dhcpd: DHCPACK on 192.168.10.14 to 6c:f7:84:99:ab:14 via green0
Oct  6 17:49:08 ipfire  ntpd[5849]: Listen normally on 6 red0 192.168.1.2:123
Oct  6 17:49:08 ipfire  ntpd[5849]: new interface(s) found: waking up resolver
Oct  6 17:49:08 ipfire kernel: u32 classifier
Oct  6 17:49:08 ipfire kernel:     Performance counters on
Oct  6 17:49:08 ipfire kernel:     input device check on
Oct  6 17:49:08 ipfire kernel:     Actions configured
Oct  6 17:49:09 ipfire kernel: GACT probability on
Oct  6 17:49:09 ipfire kernel: Mirror/redirect action on
Oct  6 17:49:09 ipfire root: Could not find a bridged zone for imq0
Oct  6 17:49:09 ipfire root: Could not find a bridged zone for ifb0
Oct  6 17:49:09 ipfire root: Could not find a bridged zone for ifb1
Oct  6 17:49:10 ipfire  unbound: [4151:0] info: service stopped (unbound 1.16.3).
Oct  6 17:49:10 ipfire  unbound: [4151:0] info: server stats for thread 0: 62 queries, 18 answers from cache, 44 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Oct  6 17:49:10 ipfire  unbound: [4151:0] info: server stats for thread 0: requestlist max 5 avg 0.909091 exceeded 0 jostled 0
Oct  6 17:49:10 ipfire  unbound: [4151:0] info: average recursion processing time 0.168150 sec
Oct  6 17:49:10 ipfire  unbound: [4151:0] info: histogram of recursion processing times
Oct  6 17:49:10 ipfire  unbound: [4151:0] info: [25%]=0.00351086 median[50%]=0.0917504 [75%]=0.314573
Oct  6 17:49:10 ipfire  unbound: [4151:0] info: lower(secs) upper(secs) recursions
Oct  6 17:49:10 ipfire  unbound: [4151:0] info:    0.001024    0.002048 6
Oct  6 17:49:10 ipfire  unbound: [4151:0] info:    0.002048    0.004096 7
Oct  6 17:49:10 ipfire  unbound: [4151:0] info:    0.008192    0.016384 1
Oct  6 17:49:10 ipfire  unbound: [4151:0] info:    0.016384    0.032768 2
Oct  6 17:49:10 ipfire  unbound: [4151:0] info:    0.032768    0.065536 4
Oct  6 17:49:10 ipfire  unbound: [4151:0] info:    0.065536    0.131072 5
Oct  6 17:49:10 ipfire  unbound: [4151:0] info:    0.131072    0.262144 6
Oct  6 17:49:10 ipfire  unbound: [4151:0] info:    0.262144    0.524288 10
Oct  6 17:49:10 ipfire  unbound: [4151:0] info:    0.524288    1.000000 3
Oct  6 17:49:10 ipfire  unbound: [4151:0] notice: Restart of unbound 1.16.3.
Oct  6 17:49:10 ipfire  unbound: [4151:0] notice: init module 0: validator
Oct  6 17:49:10 ipfire  unbound: [4151:0] notice: init module 1: iterator
Oct  6 17:49:10 ipfire  unbound: [4151:0] info: start of service (unbound 1.16.3).
Oct  6 17:49:10 ipfire  unbound: [4151:0] info: generate keytag query _ta-4a5c-4f66. NULL IN
Oct  6 17:49:10 ipfire  vnstatd[4034]: Interface "imq0" enabled.
Oct  6 17:49:10 ipfire  vnstatd[4034]: Interface "ifb0" added with 1000 Mbit bandwidth limit.
Oct  6 17:49:10 ipfire  vnstatd[4034]: Interface "ifb1" added with 1000 Mbit bandwidth limit.
Oct  6 17:49:10 ipfire  vnstatd[4034]: Monitoring (9): ifb1 (1000 Mbit) ifb0 (1000 Mbit) wlan0 (1000 Mbit) red0 (1000 Mbit) ppp0 (1000 Mbit) orange0 (1000 Mbit) imq0 (1000 Mbit) green0 (1000 Mbit) blue0 (1000 Mbit)

bonnietwin · 6 October 2022 20:59

I confirm the same thing when I look for DNS unbound. Interestingly if you select All for the date rather than a specific day then it does show the logs.

Definitely something has changed in the logs between CU170 and CU171 Testing.

Can you please raise a bug for this and include CU171 Testing in the Title.

Your IPFire People email address and password credentials apply also for the IPFire Bugzilla

https://wiki.ipfire.org/devel/bugzilla
https://bugzilla.ipfire.org/

cbrown · 7 October 2022 11:14

Echoing your confirm @bonnietwin. Something has changed with the System Logs page. Most Settings:->Section: selections that showed data on CU170 now show no logs.

bonnietwin · 7 October 2022 14:26

I have raised this as a bug in the IPFire bugzilla.

https://bugzilla.ipfire.org/show_bug.cgi?id=12949

pscar13 · 8 October 2022 10:43

While waiting for the fix, I patched the file /srv/web/ipfire/cgi-bin/logs.cgi/log.dat to see the logs correctly

--- log.dat	Wed Oct  5 13:57:43 2022
+++ log.dat	Sat Oct  8 08:05:58 2022
@@ -229,3 +229,3 @@
 		my $line = $_;
-	 	if ($line =~ /^${monthstr} ${daystr} ..:..:.. [\w\-]+ ${section}(.*)/) {
+	 	if ($line =~ /^${monthstr} ${daystr} ..:..:.. [\w\-]+ \s?${section}(.*)/) {
 		    # when standard viewing, just keep in memory the correct slice
@@ -274,3 +274,3 @@
 	{
-		/^... (..) (..:..:..) [\w\-]+ ${section}(.*)$/;
+		/^... (..) (..:..:..) [\w\-]+ \s?${section}(.*)$/;
 		my $day =  $1;
@@ -397,3 +397,3 @@
 {
-	/^... (..) (..:..:..) [\w\-]+ ${section}(.*)$/;
+	/^... (..) (..:..:..) [\w\-]+ \s?${section}(.*)$/;
 	my $day =  $1;

xperimental · 8 October 2022 11:29

There is already a patch mentioned in the bugzilla topic: git.ipfire.org Git - thirdparty/glibc.git/commitdiff

bbitsch · 8 October 2022 12:01

@pscar13 :This can should be a temporary patch only.
The deleted regular expressions are there the right ones. Your edits accept the false lines also.
But the code generating these false lines should be corrected. This is in progress, see the link cited by Terry.

pscar13 · 8 October 2022 12:04

Thanks,
I had seen well, but I do not have the possibility, nor desire for the moment to modify the glibc sources and to rebuild my system completely.
The patch of the proposed file is easier and immediate while waiting for the corrected stable version (I hope so)

bonnietwin · 10 October 2022 16:39

The nightly build Latest was carried out today with the patched glibc.

I have just tested it out on my vm testbed and confirm that it is working as expected.

cbrown · 10 October 2022 18:48

Hi @bonnietwin
When I look at: Index of /master/latest/x86_64
it shows latest entry in changelog.txt as: Tue Oct 4 13:32:47 2022 +0000
So, I guess I would not get the the fix by simply doing upgrade to Testing.
Am I correct?
-cab

bonnietwin · 10 October 2022 19:09

The entries in the Changelog are dated from when those patches were created. If you look at the second entry in that Changelog it has the glibc fix white space in syslog messages patch.

The Changelog.txt file was updated at 14:10 on 10th Oct.

Based on that I took my CU171 Testing vm and moved the mine file back to 170 and then re-ran the upgrade from 170 to 171 Testing, rebooted and everything created in the log after that no longer has the additional space. So yes, it is in the latest CU171 Testing.

Of course, the logs from the intervening period will stay with the additional space but if you do an upgrade on a CU170 system then all the logs will have the correct spacing.

cbrown · 10 October 2022 19:33

I see where the fix is referenced in: /master/2022-10-10 09:33:06 +0000-437fb4d7
But I do not see the fix in: /master/latest/x86_64
Perhaps all is good other than the missing contents in changelog.txt

Edit: I did the upgrade to Testing, and do have master/437fb4d7

bonnietwin · 10 October 2022 19:42

I just clicked on your master/latest link and this is the second entry in the list.

commit 692d18285f59f78cfea96b5e2d9f21bed01360ba
Author: Michael Tremer michael.tremer@ipfire.org
Date: Fri Oct 7 16:24:15 2022 +0000

glibc: Fix added whitespace in syslog messages

Fixes: #12949
Signed-off-by: Michael Tremer michael.tremer@ipfire.org

cbrown · 10 October 2022 19:47

Wow, I’ve got some weird browser cache thing going on. When I download the changelog.txt, It does indeed show the fix and looks fine. When I browse the link, it shows nothing past Oct 4
-cab

Edit: Yes, that was it. I completely closed out of FireFox. When I came back, the changelog.txt looks perfectly fine – as expected

bonnietwin · 10 October 2022 19:52

Glad you figured out what was happening.