fe_test: add test for syslog feature (#5985)

The syslog feature allows to run a program and redirect its output/error
stream to system log. It's triggered passing `syslog_stdout` argument to
`Forkhelpers` functions like `execute_command_get_output`.
To test this feature use a small preload library to redirect syslog
writing.
This allows to test program without changing it.
The log is redirected to `/tmp/xyz` instead of `/dev/log`. The name was
chosen to allow for future static build redirection.
The C program is used only for the test, so the code style take into
account this (specifically it does not try to handle all redirect
situation and all error paths).

Author: robhoes

ocaml/forkexecd/test/dune

@@ -1,11 +1,18 @@
 (executable
  (modes exe)
  (name fe_test)
- (libraries fmt forkexec mtime clock mtime.clock.os uuid xapi-stdext-unix fd-send-recv))
+ (libraries fmt forkexec mtime clock mtime.clock.os uuid xapi-stdext-unix fd-send-recv xapi-log))
+
+; preload library to redirect "/dev/log"
+(rule
+ (targets syslog.so)
+ (deps syslog.c)
+ (action
+  (run %{cc} -O2 -Wall -DPIC -fPIC -s --shared -o %{targets} %{deps} -ldl)))
 
 (rule
  (alias runtest)
  (package xapi-forkexecd)
- (deps fe_test.sh fe_test.exe ../src/fe_main.exe)
+ (deps fe_test.sh fe_test.exe ../src/fe_main.exe syslog.so)
  (action
   (run ./fe_test.sh)))

ocaml/forkexecd/test/fe_test.ml

@@ -238,6 +238,77 @@ let test_internal_failure_error () =
       Printexc.print_backtrace stderr ;
       fail "Failed with unexpected exception: %s" (Printexc.to_string e)
 
+(* Emulate syslog and output lines to returned channel *)
+let syslog_lines sockname =
+  let clean () = try Unix.unlink sockname with _ -> () in
+  clean () ;
+  let sock = Unix.socket ~cloexec:true Unix.PF_UNIX Unix.SOCK_DGRAM 0 in
+  let rd_pipe, wr_pipe = Unix.pipe ~cloexec:true () in
+  Unix.bind sock (Unix.ADDR_UNIX sockname) ;
+  match Unix.fork () with
+  | 0 ->
+      (* child, read from socket and output to pipe *)
+      let term_handler = Sys.Signal_handle (fun _ -> clean () ; exit 0) in
+      Sys.set_signal Sys.sigint term_handler ;
+      Sys.set_signal Sys.sigterm term_handler ;
+      Unix.close rd_pipe ;
+      Unix.dup2 wr_pipe Unix.stdout ;
+      Unix.close wr_pipe ;
+      let buf = Bytes.create 1024 in
+      let rec fwd () =
+        let l = Unix.recv sock buf 0 (Bytes.length buf) [] in
+        if l > 0 then (
+          print_bytes (Bytes.sub buf 0 l) ;
+          print_newline () ;
+          (fwd [@tailcall]) ()
+        )
+      in
+      fwd () ; exit 0
+  | pid ->
+      Unix.close sock ;
+      Unix.close wr_pipe ;
+      (pid, Unix.in_channel_of_descr rd_pipe)
+
+let test_syslog with_stderr =
+  let rec syslog_line ic =
+    let line = input_line ic in
+    (* ignore log lines from daemon *)
+    if String.ends_with ~suffix:"\\x0A" line then
+      syslog_line ic
+    else
+      let re = Str.regexp ": " in
+      match Str.bounded_split re line 3 with
+      | _ :: _ :: final :: _ ->
+          final ^ "\n"
+      | _ ->
+          raise Not_found
+  in
+  let expected_out = "output string" in
+  let expected_err = "error string" in
+  let args = ["echo"; expected_out; expected_err] in
+  let child, ic = syslog_lines "/tmp/xyz" in
+  let out, err =
+    Forkhelpers.execute_command_get_output ~syslog_stdout:Syslog_DefaultKey
+      ~redirect_stderr_to_stdout:with_stderr exe args
+  in
+  expect "" (out ^ "\n") ;
+  if with_stderr then
+    expect "" (err ^ "\n")
+  else
+    expect expected_err err ;
+  Unix.sleepf 0.05 ;
+  Syslog.log Syslog.Daemon Syslog.Err "exe: XXX\n" ;
+  Syslog.log Syslog.Daemon Syslog.Err "exe: YYY\n" ;
+  let out = syslog_line ic in
+  expect expected_out out ;
+  let err = syslog_line ic in
+  let expected = if with_stderr then expected_err else "XXX" in
+  expect expected err ;
+  Unix.kill child Sys.sigint ;
+  Unix.waitpid [] child |> ignore ;
+  close_in ic ;
+  print_endline "Completed syslog test"
+
 let master fds =
   Printf.printf "\nPerforming timeout tests\n%!" ;
   test_delay () ;
@@ -249,6 +320,10 @@ let master fds =
   test_input () ;
   Printf.printf "\nPerforming internal failure test\n%!" ;
   test_internal_failure_error () ;
+  Printf.printf "\nPerforming syslog tests\n%!" ;
+  test_syslog true ;
+  test_syslog false ;
+
   let combinations = shuffle (all_combinations fds) in
   Printf.printf "Starting %d tests\n%!" (List.length combinations) ;
   let i = ref 0 in

ocaml/forkexecd/test/fe_test.sh

@@ -8,7 +8,7 @@ export FE_TEST=1
 SOCKET=${XDG_RUNTIME_DIR}/xapi/forker/main
 rm -f "$SOCKET"
 
-../src/fe_main.exe &
+LD_PRELOAD="$PWD/syslog.so" ../src/fe_main.exe &
 MAIN=$!
 cleanup () {
     kill $MAIN
@@ -17,4 +17,4 @@ trap cleanup EXIT INT
 for _ in $(seq 1 10); do
     test -S ${SOCKET} || sleep 1
 done
-echo "" | ./fe_test.exe 16
+echo "" | LD_PRELOAD="$PWD/syslog.so" ./fe_test.exe 16

ocaml/forkexecd/test/syslog.c

@@ -0,0 +1,121 @@
+#define _GNU_SOURCE
+#define _DEFAULT_SOURCE
+#include <stdarg.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <stdbool.h>
+#include <time.h>
+#include <alloca.h>
+#include <unistd.h>
+#include <dlfcn.h>
+#include <syslog.h>
+#include <sys/types.h>
+#include <sys/socket.h>
+#include <sys/un.h>
+
+#define START(name) \
+	static typeof(name) *old_func = NULL; \
+	if (!old_func) \
+		old_func = (typeof(name) *) dlsym(RTLD_NEXT, #name);
+
+int connect(int sockfd, const struct sockaddr *addr, socklen_t addrlen)
+{
+	static const char dev_log[] = "/dev/log";
+	START(connect);
+
+	struct sockaddr_un *un = (struct sockaddr_un *) addr;
+	if (!addr || addr->sa_family != AF_UNIX
+	    || memcmp(un->sun_path, dev_log, sizeof(dev_log)) != 0)
+		return old_func(sockfd, addr, addrlen);
+
+	struct sockaddr_un new_addr;
+	new_addr.sun_family = AF_UNIX;
+	strcpy(new_addr.sun_path, "/tmp/xyz");
+	return old_func(sockfd, (struct sockaddr *) &new_addr, sizeof(new_addr));
+}
+
+static const char *month_name(int month)
+{
+	static const char names[12][4] = {
+		"Jan",
+		"Feb",
+		"Mar",
+		"Apr",
+		"May",
+		"Jun",
+		"Jul",
+		"Aug",
+		"Sep",
+		"Oct",
+		"Nov",
+		"Dec",
+	};
+	if (month >= 0 && month < 12)
+		return names[month];
+
+	return "Xxx";
+}
+
+static void vsyslog_internal(int priority, const char *format, va_list ap)
+{
+	// format is "<13>Jul  9 07:19:01 hostname: message"
+	time_t now = time(NULL);
+	struct tm tm, *p;
+	p = gmtime_r(&now, &tm);
+
+	if (LOG_FAC(priority) == 0)
+		priority |= LOG_USER;
+
+	char buffer[1024];
+	char *buf = buffer;
+	const int prefix_len = sprintf(buffer, "<%d> %s % 2d %02d:%02d:%02d %s: ", priority, month_name(p->tm_mon),
+		p->tm_mday, p->tm_hour, p->tm_min, p->tm_sec, "dummy");
+
+	int left = (int) sizeof(buffer) - prefix_len;
+	int l = vsnprintf(buffer + prefix_len, left, format, ap);
+	if (l >= left) {
+		buf = malloc(prefix_len + l + 1);
+		if (!buf)
+			return;
+		memcpy(buf, buffer, prefix_len);
+		l = vsnprintf(buf + prefix_len, l + 1, format, ap);
+	}
+
+	int sock = socket(AF_UNIX, SOCK_DGRAM | SOCK_CLOEXEC, 0);
+	if (sock >= 0) {
+		struct sockaddr_un addr;
+		addr.sun_family = AF_UNIX;
+		strcpy(addr.sun_path, "/tmp/xyz");
+		sendto(sock, buf, prefix_len + l, MSG_NOSIGNAL, &addr, sizeof(addr));
+
+		close(sock);
+	}
+	if (buf != buffer)
+		free(buf);
+}
+
+void syslog(int priority, const char *format, ...)
+{
+	va_list ap;
+	va_start(ap, format);
+	vsyslog_internal(priority, format, ap);
+	va_end(ap);
+}
+
+void vsyslog(int priority, const char *format, va_list ap)
+{
+	vsyslog_internal(priority, format, ap);
+}
+
+void __syslog_chk(int priority, int flags, const char *format, ...)
+{
+	va_list ap;
+	va_start(ap, format);
+	vsyslog_internal(priority, format, ap);
+	va_end(ap);
+}
+
+void __vsyslog_chk(int priority, int flags, const char *format, va_list ap)
+{
+	vsyslog_internal(priority, format, ap);
+}