Go over mgt process's complaining on stderr and syslog and try to

make somewhat more predictable.

Disable syslogging when we're running under varnishtest.

bin/varnishd/common/params.h

@@ -29,6 +29,11 @@
  * This file contains the heritage passed when mgt forks cache
  */
 
+#ifdef COMMON_PARAMS_H
+#error "Multiple includes of common/params.h"
+#endif
+#define COMMON_PARAMS_H
+
 #include <stdint.h>
 
 #include "vre.h"

bin/varnishd/mgt/mgt.h

@@ -123,6 +123,13 @@ struct choice {
 };
 const void *pick(const struct choice *cp, const char *which, const char *kind);
 
+extern const char C_ERR[];	// Things are not as they should be
+extern const char C_INFO[];	// Normal stuff, keep a record for later
+extern const char C_DEBUG[];	// More detail than you'd normally want
+extern const char C_SECURITY[];	// Security issues
+extern const char C_CLI[];	// CLI traffic between master and child
+void MGT_complain(const char *loud, const char *, ...) __v_printflike(2, 3);
+
 /* mgt_param.c */
 void MCF_InitParams(struct cli *);
 void MCF_CollectParams(void);
@@ -169,18 +176,20 @@ extern unsigned mgt_vcc_err_unref;
 extern unsigned mgt_vcc_allow_inline_c;
 extern unsigned mgt_vcc_unsafe_path;
 
-#define REPORT0(pri, fmt)				\
-	do {						\
-		fprintf(stderr, fmt "\n");		\
-		syslog(pri, fmt);			\
-	} while (0)
-
-#define REPORT(pri, fmt, ...)				\
-	do {						\
-		fprintf(stderr, fmt "\n", __VA_ARGS__);	\
-		syslog(pri, fmt, __VA_ARGS__);		\
-	} while (0)
-
 #if defined(PTHREAD_CANCELED) || defined(PTHREAD_MUTEX_DEFAULT)
 #error "Keep pthreads out of in manager process"
 #endif
+
+static inline int
+MGT_FEATURE(enum feature_bits x)
+{
+	return (mgt_param.feature_bits[(unsigned)x>>3] &
+	    (0x80U >> ((unsigned)x & 7)));
+}
+
+static inline int
+MGT_DO_DEBUG(enum debug_bits x)
+{
+	return (mgt_param.debug_bits[(unsigned)x>>3] &
+	    (0x80U >> ((unsigned)x & 7)));
+}

bin/varnishd/mgt/mgt_child.c

@@ -86,20 +86,6 @@ static struct vlu	*child_std_vlu;
 static struct vsb *child_panic = NULL;
 static double mgt_uptime_t0 = 0.;
 
-/* XXX: Doesn't really belong here, but only place we use it */
-static inline int
-MGT_FEATURE(enum feature_bits x)
-{
-	return (mgt_param.feature_bits[(unsigned)x>>3] &
-	    (0x80U >> ((unsigned)x & 7)));
-}
-static inline int
-MGT_DO_DEBUG(enum debug_bits x)
-{
-	return (mgt_param.debug_bits[(unsigned)x>>3] &
-	    (0x80U >> ((unsigned)x & 7)));
-}
-
 static void mgt_reap_child(void);
 
 /*---------------------------------------------------------------------
@@ -133,7 +119,7 @@ mgt_panic_record(pid_t r)
 	VSB_quote(child_panic, heritage.panic_str,
 	    strnlen(heritage.panic_str, heritage.panic_str_len), 0);
 	AZ(VSB_finish(child_panic));
-	REPORT(LOG_ERR, "Child (%jd) %s",
+	MGT_complain(C_ERR, "Child (%jd) %s",
 	    (intmax_t)r, VSB_data(child_panic));
 }
 
@@ -237,7 +223,7 @@ child_line(void *priv, const char *p)
 {
 	(void)priv;
 
-	REPORT(LOG_NOTICE, "Child (%jd) said %s", (intmax_t)child_pid, p);
+	MGT_complain(C_INFO, "Child (%jd) said %s", (intmax_t)child_pid, p);
 	return (0);
 }
 
@@ -320,7 +306,7 @@ mgt_launch_child(struct cli *cli)
 			VCLI_SetResult(cli, CLIS_CANT);
 			return;
 		}
-		REPORT0(LOG_ERR,
+		MGT_complain(C_ERR,
 		    "Child start failed: could not open sockets");
 		return;
 	}
@@ -394,7 +380,7 @@ mgt_launch_child(struct cli *cli)
 		exit(0);
 	}
 	assert(pid > 1);
-	REPORT(LOG_NOTICE, "child (%jd) Started", (intmax_t)pid);
+	MGT_complain(C_DEBUG, "Child (%jd) Started", (intmax_t)pid);
 	VSC_C_mgt->child_start = ++static_VSC_C_mgt.child_start;
 
 	/* Close stuff the child got */
@@ -432,7 +418,8 @@ mgt_launch_child(struct cli *cli)
 	mgt_cli_start_child(child_cli_in, child_cli_out);
 	child_pid = pid;
 	if (mgt_push_vcls_and_start(&u, &p)) {
-		REPORT(LOG_ERR, "Pushing vcls failed:\n%s", p);
+		MGT_complain(C_ERR, "Child (%jd) Pushing vcls failed:\n%s",
+		    (intmax_t)child_pid, p);
 		free(p);
 		child_state = CH_RUNNING;
 		mgt_stop_child();
@@ -502,7 +489,8 @@ mgt_reap_child(void)
 	/* Compose obituary */
 	vsb = VSB_new_auto();
 	XXXAN(vsb);
-	VSB_printf(vsb, "Child (%ld) %s", (long)r, status ? "died" : "ended");
+	VSB_printf(vsb, "Child (%jd) %s", (intmax_t)r,
+	    status ? "died" : "ended");
 	if (WIFEXITED(status) && WEXITSTATUS(status)) {
 		VSB_printf(vsb, " status=%d", WEXITSTATUS(status));
 		exit_status |= 0x20;
@@ -524,7 +512,7 @@ mgt_reap_child(void)
 	}
 #endif
 	AZ(VSB_finish(vsb));
-	REPORT(LOG_INFO, "%s", VSB_data(vsb));
+	MGT_complain(status ? C_ERR : C_INFO, "%s", VSB_data(vsb));
 	VSB_delete(vsb);
 
 	/* Dispose of shared memory but evacuate panic messages first */
@@ -548,7 +536,7 @@ mgt_reap_child(void)
 
 	child_pid = -1;
 
-	REPORT0(LOG_DEBUG, "Child cleanup complete");
+	MGT_complain(C_DEBUG, "Child cleanup complete");
 
 	if (child_state == CH_DIED && mgt_param.auto_restart)
 		mgt_launch_child(NULL);
@@ -576,7 +564,7 @@ MGT_Child_Cli_Fail(void)
 		return;
 	if (child_pid < 0)
 		return;
-	REPORT(LOG_ERR, "Child (%jd) not responding to CLI, killing it.",
+	MGT_complain(C_ERR, "Child (%jd) not responding to CLI, killing it.",
 	    (intmax_t)child_pid);
 	if (MGT_FEATURE(FEATURE_NO_COREDUMP))
 		(void)kill(child_pid, SIGKILL);
@@ -599,7 +587,7 @@ mgt_stop_child(void)
 
 	child_state = CH_STOPPING;
 
-	REPORT0(LOG_DEBUG, "Stopping Child");
+	MGT_complain(C_DEBUG, "Stopping Child");
 
 	mgt_reap_child();
 }
@@ -646,7 +634,7 @@ mgt_sigint(const struct vev *e, int what)
 
 	(void)e;
 	(void)what;
-	REPORT0(LOG_ERR, "Manager got SIGINT");
+	MGT_complain(C_ERR, "Manager got SIGINT");
 	(void)fflush(stdout);
 	if (child_pid >= 0)
 		mgt_stop_child();
@@ -716,7 +704,7 @@ MGT_Run(void)
 	AZ(sigaction(SIGHUP, &sac, NULL));
 
 	if (!d_flag && !mgt_has_vcl())
-		REPORT0(LOG_ERR, "No VCL loaded yet");
+		MGT_complain(C_ERR, "No VCL loaded yet");
 	else if (!d_flag) {
 		mgt_launch_child(NULL);
 		if (child_state != CH_RUNNING) {
@@ -730,7 +718,7 @@ MGT_Run(void)
 
 	i = vev_schedule(mgt_evb);
 	if (i != 0)
-		REPORT(LOG_ERR, "vev_schedule() = %d", i);
+		MGT_complain(C_ERR, "vev_schedule() = %d", i);
 
-	REPORT0(LOG_ERR, "manager dies");
+	MGT_complain(C_INFO, "manager dies");
 }

bin/varnishd/mgt/mgt_cli.c

@@ -41,7 +41,6 @@
 #include <stdio.h>
 #include <stdlib.h>
 #include <string.h>
-#include <syslog.h>
 #include <unistd.h>
 
 #include "mgt/mgt.h"
@@ -58,10 +57,6 @@
 
 #include "mgt_cli.h"
 
-#ifndef LOG_AUTHPRIV
-#  define LOG_AUTHPRIV	0
-#endif
-
 static int		cli_i = -1, cli_o = -1;
 static struct VCLS	*cls;
 static const char	*secret_file;
@@ -301,7 +296,7 @@ mcf_auth(struct cli *cli, const char *const *av, void *priv)
 	VCLI_AuthResponse(fd, cli->challenge, buf);
 	AZ(close(fd));
 	if (strcasecmp(buf, av[2])) {
-		syslog(LOG_WARNING|LOG_AUTHPRIV,
+		MGT_complain(C_SECURITY,
 		    "CLI Authentication failure from %s", cli->ident);
 		VCLI_SetResult(cli, CLIS_CLOSE);
 		return;
@@ -321,21 +316,20 @@ static struct cli_proto cli_auth[] = {
 };
 
 /*--------------------------------------------------------------------*/
+
 static void
 mgt_cli_cb_before(const struct cli *cli)
 {
 
-	if (mgt_param.syslog_cli_traffic)
-		syslog(LOG_NOTICE, "CLI %s Rd %s", cli->ident, cli->cmd);
+	MGT_complain(C_CLI, "CLI %s Rd %s", cli->ident, cli->cmd);
 }
 
 static void
 mgt_cli_cb_after(const struct cli *cli)
 {
 
-	if (mgt_param.syslog_cli_traffic)
-		syslog(LOG_NOTICE, "CLI %s Wr %03u %s",
-		    cli->ident, cli->result, VSB_data(cli->sb));
+	MGT_complain(C_CLI, "CLI %s Wr %03u %s",
+	    cli->ident, cli->result, VSB_data(cli->sb));
 }
 
 /*--------------------------------------------------------------------*/
@@ -610,7 +604,7 @@ Marg_connect(const struct vev *e, int what)
 
 	M_fd = VTCP_connected(M_fd);
 	if (M_fd < 0) {
-		syslog(LOG_INFO, "Could not connect to CLI-master: %m");
+		MGT_complain(C_INFO, "Could not connect to CLI-master: %m");
 		ma = VTAILQ_FIRST(&m_addr_list);
 		AN(ma);
 		VTAILQ_REMOVE(&m_addr_list, ma, list);

bin/varnishd/mgt/mgt_jail_solaris.c

@@ -210,7 +210,6 @@
 #include <stdio.h>
 #include <stdlib.h>
 #include <string.h>
-#include <syslog.h>
 #include <unistd.h>
 
 #include "mgt/mgt.h"
@@ -390,7 +389,7 @@ vjs_setup(enum jail_gen_e jge)
 	priv_set_t *priv_all;
 
 	if (! (priv_all = priv_allocset())) {
-		REPORT(LOG_ERR,
+		MGT_complain(C_SECURITY,
 		    "Solaris Jail warning: "
 		    " vjs_setup - priv_allocset failed: errno=%d (%s)",
 		    errno, strerror(errno));
@@ -423,7 +422,7 @@ vjs_privsep(enum jail_gen_e jge)
 		if (getuid() != mgt_param.uid)
 			XXXAZ(setuid(mgt_param.uid));
 	} else {
-		REPORT(LOG_INFO,
+		MGT_complain(C_SECURITY,
 		    "Privilege %s missing, will not change uid/gid",
 		    PRIV_PROC_SETID);
 	}
@@ -454,7 +453,7 @@ vjs_waive(enum jail_gen_e jge)
 	    !(inheritable = priv_allocset()) ||
 	    !(permitted = priv_allocset()) ||
 	    !(limited = priv_allocset())) {
-		REPORT(LOG_ERR,
+		MGT_complain(C_SECURITY,
 		    "Solaris Jail warning: "
 		    " vjs_waive - priv_allocset failed: errno=%d (%s)",
 		    errno, strerror(errno));

bin/varnishd/mgt/mgt_jail_unix.c

@@ -43,7 +43,6 @@
 #include "mgt/mgt.h"
 
 #ifdef __linux__
-#include <syslog.h>
 #include <sys/prctl.h>
 #endif
 
@@ -231,7 +230,7 @@ vju_subproc(enum jail_subproc_e jse)
 	 * reenable them again.
 	 */
 	if (prctl(PR_SET_DUMPABLE, 1) != 0) {
-		REPORT0(LOG_INFO,
+		MGT_complain(C_INFO,
 		    "Could not set dumpable bit.  Core dumps turned off\n");
 	}
 #endif

bin/varnishd/mgt/mgt_main.c

@@ -37,6 +37,7 @@
 #include <errno.h>
 #include <fcntl.h>
 #include <stdio.h>
+#include <stdarg.h>
 #include <stdlib.h>
 #include <string.h>
 #include <syslog.h>
@@ -120,6 +121,57 @@ build_vident(void)
 	}
 }
 
+/*--------------------------------------------------------------------
+ * 'Ello, I wish to register a complaint...
+ */
+
+#ifndef LOG_AUTHPRIV
+#  define LOG_AUTHPRIV 0
+#endif
+
+const char C_ERR[] = "Error:";
+const char C_INFO[] = "Info:";
+const char C_DEBUG[] = "Debug:";
+const char C_SECURITY[] = "Security:";
+const char C_CLI[] = "Cli:";
+
+void
+MGT_complain(const char *loud, const char *fmt, ...)
+{
+	va_list ap;
+	struct vsb *vsb;
+	int sf;
+
+	if (loud == C_CLI && !mgt_param.syslog_cli_traffic)
+		return;
+	vsb = VSB_new_auto();
+	AN(vsb);
+	va_start(ap, fmt);
+	VSB_vprintf(vsb, fmt, ap);
+	va_end(ap);
+	AZ(VSB_finish(vsb));
+
+	if (loud == C_ERR)
+		sf = LOG_ERR;
+	else if (loud == C_INFO)
+		sf = LOG_INFO;
+	else if (loud == C_DEBUG)
+		sf = LOG_DEBUG;
+	else if (loud == C_SECURITY)
+		sf = LOG_WARNING | LOG_AUTHPRIV;
+	else if (loud == C_CLI)
+		sf = LOG_INFO;
+	else
+		WRONG("Wrong complaint loudness");
+
+	if (loud != C_CLI)
+		fprintf(stderr, "%s %s\n", loud, VSB_data(vsb));
+
+	if (!MGT_DO_DEBUG(DBG_VTC_MODE))
+		syslog(sf, "%s", VSB_data(vsb));
+	VSB_delete(vsb);
+}
+
 /*--------------------------------------------------------------------*/
 
 const void *
@@ -755,9 +807,7 @@ main(int argc, char * const *argv)
 
 	assert(pfh == NULL || !VPF_Write(pfh));
 
-	if (d_flag)
-		fprintf(stderr, "Platform: %s\n", VSB_data(vident) + 1);
-	syslog(LOG_NOTICE, "Platform: %s\n", VSB_data(vident) + 1);
+	MGT_complain(C_DEBUG, "Platform: %s\n", VSB_data(vident) + 1);
 
 	mgt_pid = getpid();	/* daemon() changed this */
 

bin/varnishd/mgt/mgt_sandbox.c

@@ -54,7 +54,6 @@
 #include <grp.h>
 #include <stdio.h>
 #include <stdlib.h>
-#include <syslog.h>
 #include <string.h>
 #include <unistd.h>
 
@@ -236,7 +235,7 @@ mgt_sandbox_unix(enum sandbox_e who)
 	 * reenable them again.
 	 */
 	if (prctl(PR_SET_DUMPABLE, 1) != 0) {
-		REPORT0(LOG_INFO,
+		MGT_complain(C_INFO,
 		    "Could not set dumpable bit.  Core dumps turned off\n");
 	}
 #endif
@@ -277,10 +276,10 @@ mgt_sandbox_init(void)
 	subs = VSUB_run(sb, run_sandbox_test, NULL, "SANDBOX-test", 10);
 	VSB_delete(sb);
 	if (subs) {
-		REPORT0(LOG_INFO, "Warning: init of platform-specific sandbox "
-		    "failed - sandboxing disabled");
-		REPORT0(LOG_INFO, "Warning: Varnish might run with elevated "
-		    "privileges");
+		MGT_complain(C_SECURITY,
+		    "Platform-specific sandbox failed - sandboxing disabled");
+		MGT_complain(C_SECURITY,
+		    "Varnish runs with elevated privileges");
 		mgt_sandbox = mgt_sandbox_null;
 	}