pseudo: add prefix for log and make log consistent

The following changes since commit 1e13d1fd22186af5544e7248dc12635cd2f2e08b:

meta-environment: ensure corret TOOLCHAIN_CONFIGSITE_NOCACHE value (2016-09-26 10:05:53 +0100)

are available in the git repository at:

git://git.openembedded.org/openembedded-core-contrib rbt/pseudo
http://cgit.openembedded.org/cgit.cgi/openembedded-core-contrib/log/?h=rbt/pseudo

Robert Yang (1):
pseudo: add prefix for log and make log consistent

 ...er.c-add-prefix-for-log-and-make-log-cons.patch | 83 ++++++++++++++++++++++
 meta/recipes-devtools/pseudo/pseudo_1.8.1.bb       |  1 +
 2 files changed, 84 insertions(+)
 create mode 100644 meta/recipes-devtools/pseudo/files/0001-pseudo_server.c-add-prefix-for-log-and-make-log-cons.patch

2.9.0

The log messages might not be consistent when the same error happens, part of the log messages go to terminial, and part of them go to pseudo.log, and these code use multiprocesses, which makes it very hard to understand, for example:

$ kill -9 `ps aux | grep /usr/bin/pseud | awk '{print $2}'`
$ /path/to/usr/bin/pseudo & /path/to/usr/bin/pseudo

Messages printed to terminal:
Child process exit status 4: lock_held
Messages printed to pseudo.log:
pseudo: lock already held by existing pid 34028.
pseudo: Couldn't obtain lock: Resource temporarily unavailable.

They are messages for one error, so that they should be consistent, this patch fixes the problem, they will go into pseudo.log now.

This patch also adds log prefix "pseudo: " for the message to show where they are from.

---
 ...er.c-add-prefix-for-log-and-make-log-cons.patch | 83 ++++++++++++++++++++++
 meta/recipes-devtools/pseudo/pseudo_1.8.1.bb       |  1 +
 2 files changed, 84 insertions(+)
 create mode 100644 meta/recipes-devtools/pseudo/files/0001-pseudo_server.c-add-prefix-for-log-and-make-log-cons.patch

new file mode 100644
index 0000000..e9cf3ba
@@ -0,0 +1,83 @@
+From 505ea70ff63da3645243a7f3e4359432b11c3dd9 Mon Sep 17 00:00:00 2001
+From: Robert Yang <[email protected]>
+Date: Tue, 27 Sep 2016 19:39:03 -0700
+Subject: [PATCH] pseudo_server.c: add prefix for log and make log consistent
+
+The log messages might not be consistent when the same error happens,
+part of the log messages go to terminial, and part of them go to
+pseudo.log, and these code use multiprocesses, which makes it very hard
+to understand, for example:
+$ kill -9 `ps aux | grep /usr/bin/pseud | awk '{print $2}'`
+$ /path/to/usr/bin/pseudo & /path/to/usr/bin/pseudo
+
+Messages printed to terminal:
+  Child process exit status 4: lock_held
+Messages printed to pseudo.log:
+  pseudo: lock already held by existing pid 34028.
+  pseudo: Couldn't obtain lock: Resource temporarily unavailable.
+
+They are messages for one error, so that they should be consistent, this
+patch fixes the problem, they will go into pseudo.log now.
+
+This patch also adds log prefix "pseudo: " for the message to show where
+they are from.
+
+Upstream-Status: Pending
+
+Signed-off-by: Robert Yang <[email protected]>
+---
+ pseudo_server.c | 9 ++++++---
+ pseudo_util.c   | 3 +++
+ 2 files changed, 9 insertions(+), 3 deletions(-)
+
+diff --git a/pseudo_server.c b/pseudo_server.c
+index 8731d20..31e7b0a 100644
+--- a/pseudo_server.c
++++ b/pseudo_server.c
+@@ -168,6 +168,12 @@ pseudo_server_start(int daemonize) {
+ 				strerror(errno));
+ 			exit(PSEUDO_EXIT_FORK_FAILED);
+ 		}
++
++		/* log messages will go into pseudo.log from here */
++		fclose(stdin);
++		fclose(stdout);
++		pseudo_debug_logfile(PSEUDO_LOGFILE, 2);
++
+ 		if (child) {
+ 			int status;
+ 			int rc;
+@@ -229,9 +235,6 @@ pseudo_server_start(int daemonize) {
+ 		} else {
+ 			/* detach from parent session */
+ 			setsid();
+-			fclose(stdin);
+-			fclose(stdout);
+-			pseudo_debug_logfile(PSEUDO_LOGFILE, 2);
+ 			/* and then just execute the server code normally.  */
+ 			/* Any logging will presumably go to logfile, but
+ 			 * exit status will make it back to the parent for
+diff --git a/pseudo_util.c b/pseudo_util.c
+index 0c156cf..3948c93 100644
+--- a/pseudo_util.c
++++ b/pseudo_util.c
+@@ -494,6 +494,8 @@ pseudo_diag(char *fmt, ...) {
+ 	va_list ap;
+ 	char debuff[8192];
+ 	int len;
++	/* log prefix */
++	char *pseudo_log_prefix = "pseudo: ";
+ 	/* gcc on Ubuntu 8.10 requires that you examine the return from
+ 	 * write(), and won't let you cast it to void.  Of course, if you
+ 	 * can't print error messages, there's nothing to do.
+@@ -507,6 +509,7 @@ pseudo_diag(char *fmt, ...) {
+ 	if (len > 8192)
+ 		len = 8192;
+ 
++	wrote += write(pseudo_util_debug_fd, pseudo_log_prefix, strlen(pseudo_log_prefix));
+ 	if (debugged_newline && (pseudo_util_debug_flags & PDBGF_PID)) {
+ 		wrote += write(pseudo_util_debug_fd, pid_text, pid_len);
+ 	}
+-- 
+2.9.0
+

index cec2149..fa614cd 100644
@@ -7,6 +7,7 @@ SRC_URI = "http://downloads.yoctoproject.org/releases/pseudo/${BPN}-${PV}.tar.bz
            file://moreretries.patch \
            file://Fix-xattr-performance.patch \
            file://0001-Don-t-send-SIGUSR1-to-init.patch \
+           file://0001-pseudo_server.c-add-prefix-for-log-and-make-log-cons.patch \
            "
 
 SRC_URI[md5sum] = "ee38e4fb62ff88ad067b1a5a3825bac7"

2.9.0

I don't think this produces desireable behavior in the command-line use case; so far as I can tell, this would result in getting no messages at all now.

We definitely don't want to unconditionally prepend "pseudo:" to absolutely all log messages, that'd be gigabytes of data in a lot of cases. Furthermore, pseudo_diag() is sometimes used to produce partial lines. So

	pseudo_diag("foo: ");
	pseudo_diag("bar\n");

would now produce
pseudo: foo: pseudo: bar
which is not desireable. It would make more sense to add the prefix to the specific things you're likely to see during startup, of which there's only a few.

I think the right answer probably involves distinguishing between cases where we're spawning a daemon because a client has requested one, and command-line invocation. This can be partially fixed by moving the pseudo_debug_logfile() call up, and making it conditional on opt_d, but then pseudo should also probably start a daemon directly (without that) rather than relying on the client spawning code when execing something. I can probably fix this soonish.

-s

Hi Peter,

Thanks for the reply, I tested your patch from git repo, it doesn't work, the message goes to the terminal:
Child process exit status 4: lock_held

index 8731d20..7c2db2f 100644
@@ -162,6 +162,9 @@ pseudo_server_start(int daemonize) {
         * SIGUSR1, or until too much time has passed. */
        if (daemonize) {
                int child;
+
+               /* make startup messages go away when invoked-as-daemon */
+               pseudo_debug_logfile(PSEUDO_LOGFILE, 2);
                child = fork();
                if (child == -1) {
                        pseudo_diag("Couldn't fork child process: %s\n",

@@ -231,7 +234,6 @@ pseudo_server_start(int daemonize) {
                        setsid();
                        fclose(stdin);
                        fclose(stdout);
-                       pseudo_debug_logfile(PSEUDO_LOGFILE, 2);
                        /* and then just execute the server code normally.  */
                        /* Any logging will presumably go to logfile, but
                         * exit status will make it back to the parent for

the reproducer is:

$ kill -9 `ps aux | grep /usr/bin/pseud | awk '{print $2}'` ; /buildarea/lyang1/test_gen/tmp/sysroots/x86_64-linux/usr/bin/pseudo & /buildarea/lyang1/test_gen/tmp/sysroots/x86_64-linux/usr/bin/pseudo

And please see my reply inline.

If there are gigabytes log messages, will 8 characters prefix "pseudo: " contributes a lot to that ? And I didn't see many log messages when no errors happen in a normal case (less than 10 lines or 0). "pseudo -x flags" can produce more, but that is for debugging. I prefer adding prefix to all the log messages based on the following reasons:
1) Make the log messages unify.
2) It is good for debugging when log messages print on terminal, just like what we saw this time (Child process exit status 4: lock_held"
3) How to figure out which one should add prefix, and which one should not ? It may cost a lot, but the gain is only for saving 8 characters in a line, is it worth ?

// Robert

Should pseudo_diag() be used in this way ? I think no according to other log utils such as python's logging module.

Huh. I'll have to look more closely, then.

Hmm.

If we've got logging on enough to produce a lot, then it'll be a bit.

And there isn't any reason to prefix *all* the messages. The only reason these mattered is that they show up in the middle of a build without context. If we take away the very small number of messages that were showing up on the console (which should probably be pseudo_debug() messages now anyway), there's no need for the prefixing.

This is not other log utils. This logging utility *specifically* allows for partial lines, and has extra support for them.

I'll have a look at the diagnostics now that we have that nice quick reproducer.

-s

This, it turns out, is a result of a much worse bug which somehow previously evaded detection, and just happened to work by blind luck or coincidence or something.

Which is that pseudo_logfile() was returning, not a file descriptor, but "either 0 or -1", but I was then treating it as a file descriptor.

So actually the messages were going to fd 0, not to fd 2, in this case.

Fixed with a one-line patch:
- return 0;
+ return fd;

(And actually, I think it may make sense to go change those messages from pseudo_diag to pseudo_debug, since they're basically useless unless you're debugging the startup code.)

-s

Thanks, it works for me now, I will send a V2 with your patch sooner.

How about the prefix issues? Which ones should be prefixed do you think please ?

Yocto 2.2 may not need the prefix, but we can treat it as an enhancement for YP 2.3.

// Robert

I don't think anything should be prefixed at this point. The prefix was a suggestion for clarifying those messages which were showing up on the console, but really, they shouldn't have been showing up on the console in the first place.

And really, ideally several of those messages would become less frequent, since they're diagnostics for a circumstance we expect to happen. They should probably be debug messages, not unconditional diagnostics.

-s

Thanks, got it.

Sounds good to me.

// Robert