Artix Linux Forum

This messages shows always on start of tty1. I'm really trying to find why this doesn't works properly. A refresh install probably will fix it, but I don't want do this. Any suggestion?

Related:
+ https://forum.artixlinux.org/index.php/topic,56.0.html
+ https://github.com/OpenRC/openrc/issues/216

I see that error a lot, I don't think a fresh install will help. So far as I can tell it is harmless though and the temporary log file in tmp hasn't been created on the first pass through that section of code somehow, but on the next run it has been created so you only get one error message. It could be timing related too, not everybody might see it. I did something to mess up /tmp being mounted once and those errors filled the screen, the boot hung, CPU went to 100% as the fans came on full - now that was a real error  ;)

It is m suspicion too, that this may be timing or a hardware specific thing.
I am affected by this since i moved to a nvme drive from old hdd.

Disabling rc logging does make the error message go away! Actually I've just got used to seeing that red spot and ignore it...
This is one guess what might be happening, but I don't know for sure. There might be some odd issue with multiple streams on the same file too. I think the tmp file systems exist and are OK when the error happens though.

	if ((log = fopen(TMPLOG, "ae")))     <<<<<< it might get created here but there would be no error if it wasn't
			write_time(log, "started");
		else {
                             free(logbuf);

.....

		if (logbuf) {                   <<<<<<<< if logbuf was empty on the first run through TMPLOG would not get created here by "ae"
			if ((log = fopen(TMPLOG, "ae"))) {
				write_time(log, "started");
				write_log(fileno(log), logbuf, logbuf_len);
			}
			free(logbuf);
              }

........

		if ((plog = fopen(logfile, "ae"))) {                                 <<<<<< that is the log in /var/log
			if ((log = fopen(TMPLOG, "re"))) {                      <<<<<< r is just read, not create
				while ((bytes = fread(buffer, sizeof(*buffer), BUFSIZ, log)) > 0) {
					if (fwrite(buffer, sizeof(*buffer), bytes, plog) < bytes) {
						log_error = 1;
						eerror("Error: write(%s) failed: %s", logfile, strerror(errno));
						break;
					}
				}
				fclose(log);
			} else {
				log_error = 1;
				eerror("Error: fopen(%s) failed: %s", TMPLOG, strerror(errno));           <<<<<<<< that is the error message
			}

			fclose(plog);
		} else {
			/*
			 * logfile or its basedir may be read-only during sysinit and
			 * shutdown so skip the error in this case
			 */
			if (errno != EROFS && ((strcmp(level, RC_LEVEL_SHUTDOWN) != 0) && (strcmp(level, RC_LEVEL_SYSINIT) != 0))) {
				log_error = 1;
				eerror("Error: fopen(%s) failed: %s", logfile, strerror(errno));              <<<<<< not the error as it is "logfile" /var/log
			}
}

I was seeing this as well because i use startx instead of login manager.
Ive stopped seeing now though.

It's something about going into the default runlevel I think, the file exists on the first fopen but then cannot be opened for reading:
* Error: fopen(/run/openrc/rc.log) failed: No such file or directory ae1=1 ae2=0 ae3=1 level=default

diff -ura orig-openrc-0.40.3/src/rc/rc-logger.c new-openrc-0.40.3/src/rc/rc-logger.c
--- orig-openrc-0.40.3/src/rc/rc-logger.c	2018-12-21 18:24:18.000000000 +0000
+++ new-openrc-0.40.3/src/rc/rc-logger.c	2019-02-18 17:58:34.099205658 +0000
@@ -148,6 +148,11 @@
 	const char *logfile;
 	int log_error = 0;
 
+	int fopae1 = 0;
+	int fopae2 = 0;
+	int fopae3 = 0;
+
+
 	if (!rc_conf_yesno("rc_logger"))
 		return;
 
@@ -184,13 +189,15 @@
 		signal_pipe[1] = -1;
 
 		runlevel = level;
-		if ((log = fopen(TMPLOG, "ae")))
+		if ((log = fopen(TMPLOG, "ae"))) {
 			write_time(log, "started");
-		else {
+			fopae1 = 1;
+		} else {
 			free(logbuf);
 			logbuf_size = BUFSIZ * 10;
 			logbuf = xmalloc(sizeof (char) * logbuf_size);
 			logbuf_len = 0;
+			fopae1 = 9;
 		}
 
 		fd[0].fd = signal_pipe[0];
@@ -237,6 +244,9 @@
 			if ((log = fopen(TMPLOG, "ae"))) {
 				write_time(log, "started");
 				write_log(fileno(log), logbuf, logbuf_len);
+				fopae2 = 1;
+			} else {
+					fopae2 = 9;
 			}
 			free(logbuf);
 		}
@@ -255,6 +265,7 @@
 		}
 
 		if ((plog = fopen(logfile, "ae"))) {
+			fopae3 = 1;
 			if ((log = fopen(TMPLOG, "re"))) {
 				while ((bytes = fread(buffer, sizeof(*buffer), BUFSIZ, log)) > 0) {
 					if (fwrite(buffer, sizeof(*buffer), bytes, plog) < bytes) {
@@ -266,7 +277,7 @@
 				fclose(log);
 			} else {
 				log_error = 1;
-				eerror("Error: fopen(%s) failed: %s", TMPLOG, strerror(errno));
+				eerror("Error: fopen(%s) failed: %s ae1=%d ae2=%d ae3=%d level=%s", TMPLOG, strerror(errno), fopae1, fopae2, fopae3, level);
 			}
 
 			fclose(plog);

A boot recorded, with auditd started in sysinit, although it will hang the boot sometimes in there using the default init script with no needs defined

audit rules defined:
-a always,exit -F arch=b32 -F path=/run/openrc/rc.log -S all -F key=runtmplog
-a always,exit -F arch=b64 -F path=/run/openrc/rc.log -S all -F key=runtmplog
-a always,exit -F arch=b32 -F path=/run/openrc/rc.log -S all -F success=0 -F key=runtmplogfail
-a always,exit -F arch=b64 -F path=/run/openrc/rc.log -S all -F success=0 -F key=runtmplogfail

$ sudo ausearch -k runtmplog |ag -A 3 syscall
type=CONFIG_CHANGE msg=audit(1550846349.143:233):  auid=4294967295 ses=4294967295 op=remove_rule key="runtmplog" list=4 res=1
type=SYSCALL msg=audit(1550846347.109:221): arch=c000003e syscall=257 success=yes exit=4 a0=ffffff9c a1=56474e512a17 a2=80441 a3=1b6 items=2 ppid=2572 pid=2573
auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="openrc" exe="/usr/bin/openrc" key="runtmplog"
----
time->Fri Feb 22 14:40:12 2019
type=CONFIG_CHANGE msg=audit(1550846412.856:11):  auid=4294967295 ses=4294967295 op=add_rule key="runtmplog" list=4 res=1
type=SYSCALL msg=audit(1550846413.356:64): arch=c000003e syscall=257 success=yes exit=4 a0=ffffff9c a1=55f168b61a17 a2=80441 a3=1b6 items=2 ppid=675 pid=677
auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="openrc" exe="/usr/bin/openrc" key="runtmplog"
----
time->Fri Feb 22 14:40:13 2019
type=PROCTITLE msg=audit(1550846413.636:67): proctitle=6F70656E72630064656661756C74
type=SYSCALL msg=audit(1550846413.636:67): arch=c000003e syscall=257 success=yes exit=4 a0=ffffff9c a1=55841e4bca17 a2=80441 a3=1b6 items=2 ppid=954 pid=955
auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="openrc" exe="/usr/bin/openrc" key="runtmplog"
----
time->Fri Feb 22 14:40:17 2019
type=PROCTITLE msg=audit(1550846417.000:72): proctitle=6F70656E726300626F6F74
type=SYSCALL msg=audit(1550846417.000:72): arch=c000003e syscall=257 success=yes exit=7 a0=ffffff9c a1=55f168b61a17 a2=80000 a3=0 items=1 ppid=675 pid=677 auid=4294967295
uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="openrc" exe="/usr/bin/openrc" key="runtmplog"
----
time->Fri Feb 22 14:40:17 2019
type=CONFIG_CHANGE msg=audit(1550846417.100:73): auid=4294967295 ses=4294967295 op=updated_rules path="/run/openrc/rc.log" key="runtmplogfail" list=4 res=1
type=SYSCALL msg=audit(1550846417.100:77): arch=c000003e syscall=87 success=yes exit=0 a0=55f168b61a17 a1=7ffcee992fb9 a2=55f16a6b1c50 a3=2074612064657472 items=2
ppid=675 pid=677 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="openrc" exe="/usr/bin/openrc" key="runtmplog"

$ sudo ausearch -k runtmplogfail |ag -A 3 syscall

--- nothing ---

So openrc presumably causes the trouble as it deletes the log with syscall 87 as it enters the default runlevel.
But here is a weird thing - so where is the failed open that creates the error message? There are some earlier open's, syscall 257. But no failures are logged!!!
Perhaps audit can't monitor a non existent file though, so when it is deleted it is no longer logged?

^ I think it is possibly a bug upstream, im not getting it anymore but my rc.log still says below.

https://www.archlinux.org/packages/extra/x86_64/syslog-ng/

 * Checking your configfile (/etc/syslog-ng/syslog-ng.conf) ...
2328 [2019-02-22T21:01:29.495778] WARNING: Configuration file format is too old, syslog-ng is running in compatibility mod$
2329  [ ok ]
2330  * Starting syslog-ng ...
2331 [2019-02-22T21:01:30.265561] WARNING: Configuration file format is too old, syslog-ng is running in compatibility mod$
2332 [2019-02-22T21:01:30.350609] WARNING: With use-dns(no), dns-cache() will be forced to 'no' too!;

I checked failed syscalls in the whole directory:
-a always,exit -F arch=b32 -F dir=/run/openrc/ -S all -F success=0 -F key=runtmpfail
-a always,exit -F arch=b64 -F dir=/run/openrc/ -S all -F success=0 -F key=runtmpfail

And although there were a lot of results, they were all syscalls 83 84 87 133 which are mkdir rmdir unlink and mknod. But now my guess is that when fopen gets called on the non-existent file, at some point the OS checks to see if the file exists and returns the error message rather than actually doing the open syscall and that failing.

It certainly seems like an 'upstream' issue though  ::)
It was interesting finding out a bit more about why the error message appears though.
(It appears because the 'tmplog' /run/openrc/rc.log gets deleted by openrc when you go from the boot runlevel into the default runlevel, and rclogger is partway through a section of code and has not realized this yet)

"WARNING: Configuration file format is too old" - I had something like that, and I think I updated a version number in the conf file or perhaps swapped it for a pacnew one, but it is something to do with the conf file in /etc anyway.

I just tested out audit logging on some failed fopen "re" attempts in both the /run/ tmpfs amnd on the regular fs. It doesn't log the failed opens on a non existent file, so that's normal behaviour for audit. There was something else that points to the fopen "not happening" in this case - I noticed in the rc-logger.c code it tests the assignment, not the returned result, and avoids a compiler warning by using an extra set of brackets. But this still gives the correct logical result, which shows that if fopen fails in this instance it doesn't actually assign anything to the FILE*.
So that seems to answer the side issue about the lack of failed syscalls in the audit logs.

#include <stdio.h>
#include <errno.h>
#include <string.h>
#include <unistd.h>

int main () {
  FILE *f1 = 0;

  errno = 0;
  f1 = 0;
  f1 = fopen("/run/openrc/abcxyz/somefile1", "re");
  if (f1 != 0) puts ("fopen /run/openrc/abcxyz/somefile1 worked");
  else printf ("Error: fopen (\"/run/openrc/abcxyz/somefile1\", \"re\") failed: %s\n", strerror(errno));
  errno = 0;
  f1 = 0;
  f1 = fopen ("/opt/aaa/somefile2", "re");
  if (f1 != 0) puts ("fopen /opt/aaa/somefile2 worked");
  else printf ("Error: fopen (\"/opt/aaa/somefile2\", \"re\") failed: %s\n", strerror(errno));
  errno = 0;
  f1 = 0;
  if ((f1 = fopen ("/run/openrc/abcxyz/somefile3", "re"))) puts ("fopen /run/openrc/abcxyz/somefile3 worked");
  else printf ("Error: fopen (\"/run/openrc/abcxyz/somefile3\", \"re\") failed: %s\n", strerror(errno));
  errno = 0;
  f1 = 0;
  if ((f1 = fopen ("/opt/aaa/somefile4", "re"))) puts ("fopen /opt/aaa/somefile4 worked");
  else printf ("Error: fopen (\"/opt/aaa/somefile4\", \"re\") failed: %s\n", strerror(errno));
  errno = 0;
  f1 = 0;
  if ((f1 = fopen ("/run/openrc/abcxyz/somefile5", "ae"))) puts ("fopen /run/openrc/abcxyz/somefile5 worked");
  else printf ("Error: fopen (\"/run/openrc/abcxyz/somefile5\", \"ae\") failed: %s\n", strerror(errno));
  errno = 0;
  f1 = 0;
  if ((f1 = fopen ("/opt/aaa/somefile6", "ae"))) puts ("fopen /opt/aaa/somefile6 worked");
  else printf ("Error: fopen (\"/opt/aaa/somefile6\", \"ae\") failed: %s\n", strerror(errno));
  unlink ("/run/openrc/abcxyz/somefile5");
  unlink ("/opt/aaa/somefile6");
  return 0;
}


audit rules:

-a always,exit -F arch=b32 -F dir=/run/openrc/abcxyz/ -S all -F key=ntestfail
-a always,exit -F arch=b64 -F dir=/run/openrc/abcxyz/ -S all -F key=ntestfail
-a always,exit -F arch=b32 -F dir=/opt/aaa -S all -F key=ntestfail
-a always,exit -F arch=b64 -F dir=/opt/aaa -S all -F key=ntestfail

(audit did not log any failed opens, only the successful ones)

If anyone tried this you need to make  the directories /run/openrc/abcxyz and /opt/aaa first.
Because the run one will be deleted on reboot you should get rid of the audit rules if they were defined in audit.rules before then too,
or it will probably cause an error on the next boot btw. It doesn't really do anything useful except test out that idea anyway.

Could you please share your findings openrc upstream ticket (https://github.com/OpenRC/openrc/issues/216)?
It'd be a much more suitable place to cure the issue.