rpc: Report back first error message on failure

When running criu in swrk mode the client typically wants to know
the reason of failure. Right now criu reports back NOTHING but the
fact that dump/restore/etc fails. We've tried to address this by
introducing the cr-errno engine, but it doesn't seem to be informative
enough and is hard to maintain -- adding new errno-s is boring :(

I propose to report back the first message with ERROR level upon
failrure as __typically__ the very first error message indicates
that proceeding is impossible and criu rolls back (generating more
error messages, so it's crucial to know the very first one).

If we ever meet the situation that the first pr_err/pr_perror doesn't
cause criu to exit, this printing should be fixed to be pr_warn.
Signed-off-by: Pavel Emelyanov <xemul@virtuozzo.com>
Acked-by: Andrei Vagin <avagin@virtuozzo.com>

criu/cr-service.c

@@ -114,6 +114,7 @@ static void set_resp_err(CriuResp *resp)
 {
 	resp->cr_errno = get_cr_errno();
 	resp->has_cr_errno = resp->cr_errno ? true : false;
+	resp->cr_errmsg = log_first_err();
 }
 
 static void send_criu_err(int sk, char *msg)
@@ -284,6 +285,11 @@ static int setup_opts_from_req(int sk, CriuOpts *req)
 		goto err;
 	}
 
+	if (log_keep_err()) {
+		pr_perror("Can't tune log");
+		goto err;
+	}
+
 	/* checking flags from client */
 	if (req->has_leave_running && req->leave_running)
 		opts.final_state = TASK_ALIVE;

criu/include/log.h

@@ -9,6 +9,8 @@ extern int log_init(const char *output);
 extern void log_fini(void);
 extern int log_init_by_pid(void);
 extern void log_closedir(void);
+extern int log_keep_err(void);
+extern char *log_first_err(void);
 
 extern void log_set_fd(int fd);
 extern int log_get_fd(void);

criu/log.c

@@ -17,6 +17,9 @@
 #include "util.h"
 #include "cr_options.h"
 #include "servicefd.h"
+#include "rst-malloc.h"
+#include "lock.h"
+#include "string.h"
 
 #define DEFAULT_LOGFD		STDERR_FILENO
 /* Enable timestamps if verbosity is increased from default */
@@ -72,6 +75,49 @@ static void reset_buf_off(void)
 		buf_off = 0;
 }
 
+/*
+ * Keeping the very first error messsage for RPC to report back.
+ */
+struct str_and_lock {
+	mutex_t l;
+	char s[1024];
+};
+
+static struct str_and_lock *first_err;
+
+int log_keep_err(void)
+{
+	first_err = shmalloc(sizeof(struct str_and_lock));
+	if (first_err == NULL)
+		return -1;
+
+	mutex_init(&first_err->l);
+	first_err->s[0] = '\0';
+	return 0;
+}
+
+static void log_note_err(char *msg)
+{
+	if (first_err && first_err->s[0] == '\0') {
+		/*
+		 * In any action other than restore this locking is
+		 * actually not required, but ... it's error path
+		 * anyway, so it doesn't make much sence to try hard
+		 * and optimize this out.
+		 */
+		mutex_lock(&first_err->l);
+		if (first_err->s[0] == '\0')
+			strlcpy(first_err->s, msg, sizeof(first_err->s));
+		mutex_unlock(&first_err->l);
+	}
+}
+
+char *log_first_err(void)
+{
+	BUG_ON(!first_err);
+	return first_err->s[0] == '\0' ? NULL : first_err->s;
+}
+
 int log_init(const char *output)
 {
 	int new_logfd, fd;
@@ -178,6 +224,9 @@ static void __print_on_level(unsigned int loglevel, const char *format, va_list
 		off += ret;
 	}
 	errno =  __errno;
+
+	if (loglevel == LOG_ERROR)
+		log_note_err(buffer + buf_off);
 }
 
 void print_on_level(unsigned int loglevel, const char *format, ...)

images/rpc.proto

@@ -187,4 +187,5 @@ message criu_resp {
 
 	optional int32			cr_errno	= 7;
 	optional criu_features		features	= 8;
+	optional string			cr_errmsg	= 9;
 }