log: only print timestamps when verbosity increased

While timestamps can be handy, they clutter output for normal users.
Let's print them only when verbosity (-v) is increased from default.
Currently, default is 2 (-vv) so for timestamps one should use -vvv
or -v3.

Alternatively, we could introduce a separate --timestamps option.
Personally, I find it more handy for timestamps to be tied to log level.
Signed-off-by: Kir Kolyshkin <kir@openvz.org>
Signed-off-by: Pavel Emelyanov <xemul@parallels.com>

Documentation/criu.txt

@@ -112,7 +112,7 @@ OPTIONS
     The following levels are available:
         * *-v1*, *-v*    - only messages and errors;
         * *-v2*, *-vv*   - also warnings (default level);
-        * *-v3*, *-vvv*  - also information messages;
+        * *-v3*, *-vvv*  - also information messages and timestamps;
         * *-v4*, *-vvvv* - lots of debug.
 
 *--log-pid*::

crtools.c

@@ -443,7 +443,7 @@ usage:
 "  -v[NUM]               set logging level (higher level means more output):\n"
 "                          -v1|-v    - only errors and messages\n"
 "                          -v2|-vv   - also warnings (default level)\n"
-"                          -v3|-vvv  - also information messages\n"
+"                          -v3|-vvv  - also information messages and timestamps\n"
 "                          -v4|-vvvv - lots of debug\n"
 "\n"
 "* Memory dumping options:\n"

log.c

@@ -19,6 +19,8 @@
 #include "servicefd.h"
 
 #define DEFAULT_LOGFD		STDERR_FILENO
+/* Enable timestamps if verbosity is increased from default */
+#define LOG_TIMESTAMP		(DEFAULT_LOGLEVEL + 1)
 
 static unsigned int current_loglevel = DEFAULT_LOGLEVEL;
 
@@ -61,12 +63,21 @@ int log_get_fd(void)
 	return fd < 0 ? DEFAULT_LOGFD : fd;
 }
 
+static void reset_buf_off(void)
+{
+	if (current_loglevel >= LOG_TIMESTAMP)
+		/* reserve space for a timestamp */
+		buf_off = TS_BUF_OFF;
+	else
+		buf_off = 0;
+}
+
 int log_init(const char *output)
 {
 	int new_logfd, fd;
 
 	gettimeofday(&start, NULL);
-	buf_off = TS_BUF_OFF;
+	reset_buf_off();
 
 	if (output) {
 		new_logfd = open(output, O_CREAT|O_TRUNC|O_WRONLY|O_APPEND, 0600);
@@ -102,8 +113,7 @@ int log_init_by_pid(void)
 	 * reset buf_off as this fn is called on each fork while
 	 * restoring process tree
 	 */
-
-	buf_off = TS_BUF_OFF;
+	reset_buf_off();
 
 	if (!opts.log_file_per_pid) {
 		buf_off += snprintf(buffer + buf_off, PAGE_SIZE - buf_off, "%6d: ", getpid());
@@ -147,7 +157,8 @@ static void __print_on_level(unsigned int loglevel, const char *format, va_list
 		if (loglevel > current_loglevel)
 			return;
 		fd = log_get_fd();
-		print_ts();
+		if (current_loglevel >= LOG_TIMESTAMP)
+			print_ts();
 	}
 
 	size  = vsnprintf(buffer + buf_off, PAGE_SIZE - buf_off, format, params);