logging vty: add VTY transcript test

I am setting out to refactor various details about logging. To show the effect,
I am first adding this new test to illustrate the exact effects on the various
osmo programs.

Add logging_vty_test.c as a standalone program that simply defines a few
logging categories and opens a telnet vty to play with.

Add logging_vty_test.vty, as an osmo_verify_transcript_vty.py test script.

Add --enable-external-tests to configure.ac, to enable running
logging_vty_test.vty during 'make check'.

Also allow running 'make vty-test' without the need to first configure with
--enable-external-tests (a flexibility I've missed many times over in the other
osmo source trees).

Add a Makefile.am stub for external CTRL tests, basically a copy-paste from
osmo-msc.git. I doubt that libosmocore will get python driven CTRL interface
testing any time soon, but if so we will know to not run it concurrently.

Change-Id: I948e832a33131f8eab98651d6010ceb0ccbc9a9c

4 files changed, 530 insertions, 1 deletions

diff --git a/configure.ac b/configure.ac
index dd5f15bc..bc3358a0 100644
--- a/configure.ac
+++ b/configure.ac
@@ -296,6 +296,21 @@ then
 	CPPFLAGS="$CPPFLAGS $WERROR_FLAGS"
 fi
 
+AC_ARG_ENABLE([external_tests],
+		AC_HELP_STRING([--enable-external-tests],
+				[Include the VTY/CTRL tests in make check [default=no]]),
+		[enable_ext_tests="$enableval"],[enable_ext_tests="no"])
+if test "x$enable_ext_tests" = "xyes" ; then
+	AM_PATH_PYTHON
+	AC_CHECK_PROG(OSMOTESTEXT_CHECK,osmo_verify_transcript_vty.py,yes)
+	 if test "x$OSMOTESTEXT_CHECK" != "xyes" ; then
+		AC_MSG_ERROR([Please install git://osmocom.org/python/osmo-python-tests to run the VTY/CTRL tests.])
+	fi
+fi
+AC_MSG_CHECKING([whether to enable VTY/CTRL tests])
+AC_MSG_RESULT([$enable_ext_tests])
+AM_CONDITIONAL(ENABLE_EXT_TESTS, test "x$enable_ext_tests" = "xyes")
+
 CFLAGS="$CFLAGS -DBUILDING_LIBOSMOCORE -Wall"
 CPPFLAGS="$CPPFLAGS -DBUILDING_LIBOSMOCORE -Wall"
 
diff --git a/tests/Makefile.am b/tests/Makefile.am
index 5d07695a..18d4bb4a 100644
--- a/tests/Makefile.am
+++ b/tests/Makefile.am
@@ -24,7 +24,9 @@ check_PROGRAMS = timer/timer_test sms/sms_test ussd/ussd_test		\
 		 abis/abis_test endian/endian_test sercomm/sercomm_test	\
 		 prbs/prbs_test gsm23003/gsm23003_test 			\
 		 codec/codec_ecu_fr_test timer/clk_override_test	\
-		 oap/oap_client_test
+		 oap/oap_client_test					\
+		 logging/logging_vty_test				\
+		 $(NULL)
 
 if ENABLE_MSGFILE
 check_PROGRAMS += msgfile/msgfile_test
@@ -148,6 +150,9 @@ gb_gprs_ns_test_LDADD = $(LDADD) $(top_builddir)/src/gb/libosmogb.la $(LIBRARY_D
 
 logging_logging_test_SOURCES = logging/logging_test.c
 
+logging_logging_vty_test_SOURCES = logging/logging_vty_test.c
+logging_logging_vty_test_LDADD = $(LDADD) $(top_builddir)/src/vty/libosmovty.la
+
 fr_fr_test_SOURCES = fr/fr_test.c
 fr_fr_test_LDADD = $(LDADD) $(top_builddir)/src/gb/libosmogb.la $(LIBRARY_DLSYM) \
 		   $(top_builddir)/src/vty/libosmovty.la \
@@ -280,6 +285,7 @@ TESTSUITE = $(srcdir)/testsuite
 check-local: atconfig $(TESTSUITE)
 	cat /proc/cpuinfo
 	$(SHELL) '$(TESTSUITE)' $(TESTSUITEFLAGS)
+	$(MAKE) $(AM_MAKEFLAGS) ext-tests
 
 installcheck-local: atconfig $(TESTSUITE)
 	$(SHELL) '$(TESTSUITE)' AUTOTEST_PATH='$(bindir)' \
@@ -298,3 +304,25 @@ $(TESTSUITE): $(srcdir)/testsuite.at $(srcdir)/package.m4
 conv/gsm0503_test_vectors.c: $(top_srcdir)/utils/conv_gen.py $(top_srcdir)/utils/conv_codes_gsm.py
 	$(AM_V_GEN)python $(top_srcdir)/utils/conv_gen.py gen_vectors gsm \
 		--target-path $(builddir)/conv
+
+if ENABLE_EXT_TESTS
+ext-tests:
+# don't run vty and ctrl tests concurrently so that the ports don't conflict
+	$(MAKE) vty-test
+	$(MAKE) ctrl-test
+else
+ext-tests:
+	echo "Not running python-based external tests (determined at configure-time)"
+endif
+
+# To update the VTY script from current application behavior,
+# pass -u to osmo_verify_transcript_vty.py by doing:
+#   make vty-test U=-u
+vty-test:
+	osmo_verify_transcript_vty.py -v \
+		-p 42042 \
+		-r "$(top_builddir)/tests/logging/logging_vty_test" \
+		$(U) $(srcdir)/logging/*.vty
+
+ctrl-test:
+	echo "No CTRL tests exist currently"
diff --git a/tests/logging/logging_vty_test.c b/tests/logging/logging_vty_test.c
new file mode 100644
index 00000000..806a460c
--- /dev/null
+++ b/tests/logging/logging_vty_test.c
@@ -0,0 +1,296 @@
+/* test program with a vty interface to test logging behavior */
+/*
+ * (C) 2018 by sysmocom - s.f.m.c. GmbH <info@sysmocom.de>
+ * All Rights Reserved
+ *
+ * Author: Neels Hofmeyr <neels@hofmeyr.de>
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License along
+ * with this program; if not, write to the Free Software Foundation, Inc.,
+ * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ */
+
+#define _GNU_SOURCE
+#include <getopt.h>
+
+#include <signal.h>
+
+#include <osmocom/core/logging.h>
+#include <osmocom/core/utils.h>
+#include <osmocom/core/application.h>
+
+#include <osmocom/vty/command.h>
+#include <osmocom/vty/logging.h>
+#include <osmocom/vty/misc.h>
+#include <osmocom/vty/telnet_interface.h>
+
+#include <stdlib.h>
+
+#include "config.h"
+
+void *root_ctx = NULL;
+
+enum {
+	DAA,
+	DBB,
+	DCCC,
+	DDDDD,
+	DEEE,
+};
+
+DEFUN(log_sweep, log_sweep_cmd,
+      "log-sweep [CATEGORY]",
+      "Log once for all categories on all levels\n")
+{
+	int only_category = argc ? log_parse_category(argv[0]) : -1;
+
+	if (argc && only_category < 0) {
+		vty_out(vty, "%% Error: unknown category: %s%s", argv[0], VTY_NEWLINE);
+		return CMD_WARNING;
+	}
+
+#define LOG_LEVEL(CAT, LEVEL) \
+	if (only_category < 0 || only_category == CAT) \
+		LOGP(CAT, LEVEL, "Log message for " #CAT " on level " #LEVEL "\n")
+
+#define LOG_ALL_LEVELS(CAT) \
+	LOG_LEVEL(CAT, LOGL_DEBUG); \
+	LOG_LEVEL(CAT, LOGL_INFO); \
+	LOG_LEVEL(CAT, LOGL_NOTICE); \
+	LOG_LEVEL(CAT, LOGL_ERROR); \
+	LOG_LEVEL(CAT, LOGL_FATAL)
+
+	LOG_ALL_LEVELS(DAA);
+	LOG_ALL_LEVELS(DBB);
+	LOG_ALL_LEVELS(DCCC);
+	LOG_ALL_LEVELS(DDDDD);
+	LOG_ALL_LEVELS(DEEE);
+
+	vty_out(vty, "%s", VTY_NEWLINE);
+
+	return CMD_SUCCESS;
+}
+
+static void vty_commands_init()
+{
+	install_element_ve(&log_sweep_cmd);
+}
+
+static const struct log_info_cat default_categories[] = {
+	[DAA] = {
+		.name = "DAA",
+		.description = "Antropomorphic Armadillos (AA)",
+		.color = "\033[1;31m",
+		.enabled = 1, .loglevel = LOGL_DEBUG,
+	},
+	[DBB] = {
+		.name = "DBB",
+		.description = "Bidirectional Breadspread (BB)",
+		.color = "\033[1;32m",
+		.enabled = 1, .loglevel = LOGL_INFO,
+	},
+	[DCCC] = {
+		.name = "DCCC",
+		.description = "Chaos Communication Congress (CCC)",
+		.color = "\033[1;33m",
+		.enabled = 1, .loglevel = LOGL_NOTICE,
+	},
+	[DDDDD] = {
+		.name = "DDDDD",
+		.description = "Dehydrated Dribbling Duck Dunkers (DDDD)",
+		.color = "\033[1;34m",
+		.enabled = 1, .loglevel = LOGL_ERROR,
+	},
+	[DEEE] = {
+		.name = "DEEE",
+		.description = "Exhaustive Entropy Extraction (EEE)",
+		.color = "\033[1;35m",
+		.enabled = 1, .loglevel = LOGL_FATAL,
+	},
+};
+
+const struct log_info log_info = {
+	.cat = default_categories,
+	.num_cat = ARRAY_SIZE(default_categories),
+};
+
+static void print_help()
+{
+	printf( "options:\n"
+		"  -h	--help		this text\n"
+		"  -d	--debug MASK	Enable debugging (e.g. -d DRSL:DOML:DLAPDM)\n"
+		"  -D	--daemonize	For the process into a background daemon\n"
+		"  -c	--config-file	Specify the filename of the config file\n"
+		"  -s	--disable-color	Don't use colors in stderr log output\n"
+		"  -T	--timestamp	Prefix every log line with a timestamp\n"
+		"  -V	--version	Print version information and exit\n"
+		"  -e	--log-level	Set a global log-level\n"
+		);
+}
+
+static struct {
+	const char *config_file;
+	int daemonize;
+} cmdline_config = {};
+
+static void handle_options(int argc, char **argv)
+{
+	while (1) {
+		int option_idx = 0, c;
+		static const struct option long_options[] = {
+			{ "help", 0, 0, 'h' },
+			{ "debug", 1, 0, 'd' },
+			{ "daemonize", 0, 0, 'D' },
+			{ "config-file", 1, 0, 'c' },
+			{ "disable-color", 0, 0, 's' },
+			{ "timestamp", 0, 0, 'T' },
+			{ "version", 0, 0, 'V' },
+			{ "log-level", 1, 0, 'e' },
+			{}
+		};
+
+		c = getopt_long(argc, argv, "hc:d:Dc:sTVe:",
+				long_options, &option_idx);
+		if (c == -1)
+			break;
+
+		switch (c) {
+		case 'h':
+			print_help();
+			exit(0);
+		case 's':
+			log_set_use_color(osmo_stderr_target, 0);
+			break;
+		case 'd':
+			log_parse_category_mask(osmo_stderr_target, optarg);
+			break;
+		case 'D':
+			cmdline_config.daemonize = 1;
+			break;
+		case 'c':
+			cmdline_config.config_file = optarg;
+			break;
+		case 'T':
+			log_set_print_timestamp(osmo_stderr_target, 1);
+			break;
+		case 'e':
+			log_set_log_level(osmo_stderr_target, atoi(optarg));
+			break;
+		case 'V':
+			print_version(1);
+			exit(0);
+			break;
+		default:
+			/* catch unknown options *as well as* missing arguments. */
+			fprintf(stderr, "Error in command line options. Exiting.\n");
+			exit(-1);
+		}
+	}
+}
+
+static int quit = 0;
+
+static void signal_handler(int signal)
+{
+	fprintf(stdout, "signal %u received\n", signal);
+
+	switch (signal) {
+	case SIGINT:
+	case SIGTERM:
+		quit++;
+		break;
+	case SIGABRT:
+		osmo_generate_backtrace();
+		/* in case of abort, we want to obtain a talloc report
+		 * and then return to the caller, who will abort the process */
+	case SIGUSR1:
+		talloc_report(tall_vty_ctx, stderr);
+		talloc_report_full(root_ctx, stderr);
+		break;
+	case SIGUSR2:
+		talloc_report_full(tall_vty_ctx, stderr);
+		break;
+	default:
+		break;
+	}
+}
+
+static struct vty_app_info vty_info = {
+	.name		= "logging_vty_test",
+	.version	= PACKAGE_VERSION,
+};
+
+int main(int argc, char **argv)
+{
+	int rc;
+
+	root_ctx = talloc_named_const(NULL, 0, "logging_vty_test");
+
+	vty_info.tall_ctx = root_ctx;
+	vty_init(&vty_info);
+
+	osmo_init_logging2(root_ctx, &log_info);
+
+	vty_commands_init();
+
+	handle_options(argc, argv);
+
+	logging_vty_add_cmds(&log_info);
+	osmo_talloc_vty_add_cmds();
+
+	log_set_print_category(osmo_stderr_target, 1);
+	log_set_print_category_hex(osmo_stderr_target, 0);
+	log_set_print_level(osmo_stderr_target, 1);
+	log_set_print_filename2(osmo_stderr_target, LOG_FILENAME_NONE);
+
+	if (cmdline_config.config_file) {
+		rc = vty_read_config_file(cmdline_config.config_file, NULL);
+		if (rc < 0) {
+			LOGP(DLGLOBAL, LOGL_FATAL, "Failed to parse the config file: '%s'\n",
+			     cmdline_config.config_file);
+			return 1;
+		}
+	}
+
+	rc = telnet_init_dynif(root_ctx, NULL, vty_get_bind_addr(), 42042);
+	if (rc < 0)
+		return 2;
+
+	signal(SIGINT, &signal_handler);
+	signal(SIGTERM, &signal_handler);
+	signal(SIGABRT, &signal_handler);
+	signal(SIGUSR1, &signal_handler);
+	signal(SIGUSR2, &signal_handler);
+	osmo_init_ignore_signals();
+
+	if (cmdline_config.daemonize) {
+		rc = osmo_daemonize();
+		if (rc < 0) {
+			perror("Error during daemonize");
+			return 6;
+		}
+	}
+
+	while (!quit) {
+		log_reset_context();
+		osmo_select_main(0);
+	}
+
+	log_fini();
+
+	talloc_free(root_ctx);
+	talloc_free(tall_vty_ctx);
+
+	return 0;
+}
diff --git a/tests/logging/logging_vty_test.vty b/tests/logging/logging_vty_test.vty
new file mode 100644
index 00000000..c57b70f8
--- /dev/null
+++ b/tests/logging/logging_vty_test.vty
@@ -0,0 +1,190 @@
+logging_vty_test> enable
+
+logging_vty_test# ! Note that 'logging level all everything' is still printed!
+logging_vty_test# show running-config
+...
+log stderr
+...
+  logging level all everything
+  logging level aa debug
+  logging level bb info
+  logging level ccc notice
+  logging level dddd error
+  logging level eee fatal
+...
+
+logging_vty_test# configure terminal
+logging_vty_test(config)# no log stderr
+logging_vty_test(config)# exit
+
+logging_vty_test# logging enable
+logging_vty_test# logging filter all 1
+logging_vty_test# logging print category-hex 0
+logging_vty_test# logging print category 1
+logging_vty_test# logging print level 1
+logging_vty_test# logging color 0
+logging_vty_test# logging print file 0
+
+
+logging_vty_test# list
+... !logging
+  logging enable
+  logging disable
+  logging filter all (0|1)
+  logging color (0|1)
+  logging timestamp (0|1)
+  logging print extended-timestamp (0|1)
+  logging print category (0|1)
+  logging print category-hex (0|1)
+  logging print level (0|1)
+  logging print file (0|1|basename) [last]
+  logging set-log-mask MASK
+  logging level (all|aa|bb|ccc|dddd|eee|lglobal|llapd|linp|lmux|lmi|lmib|lsms|lctrl|lgtp|lstats|lgsup|loap|lss7|lsccp|lsua|lm3ua|lmgcp|ljibuf) (everything|debug|info|notice|error|fatal)
+  show logging vty
+... !logging
+
+logging_vty_test# logging ?
+  enable        Enables logging to this vty
+  disable       Disables logging to this vty
+  filter        Filter log messages
+  color         Configure color-printing for log messages
+  timestamp     Configure log message timestamping
+  print         Log output settings
+  set-log-mask  Set the logmask of this logging target
+  level         Set the log level for a specified category
+
+logging_vty_test# logging level ?
+  all      Global setting for all subsystems
+  aa       Antropomorphic Armadillos (AA)
+  bb       Bidirectional Breadspread (BB)
+  ccc      Chaos Communication Congress (CCC)
+  dddd     Dehydrated Dribbling Duck Dunkers (DDDD)
+  eee      Exhaustive Entropy Extraction (EEE)
+  lglobal  Library-internal global log family
+...
+
+logging_vty_test# logging level aa ?
+  everything  Don't use. It doesn't log anything
+  debug       Log debug messages and higher levels
+  info        Log informational messages and higher levels
+  notice      Log noticeable messages and higher levels
+  error       Log error messages and higher levels
+  fatal       Log only fatal messages
+
+logging_vty_test# logging level all ?
+  everything  Don't use. It doesn't log anything
+  debug       Log debug messages and higher levels
+  info        Log informational messages and higher levels
+  notice      Log noticeable messages and higher levels
+  error       Log error messages and higher levels
+  fatal       Log only fatal messages
+
+
+logging_vty_test# log-sweep
+DAA DEBUG Log message for DAA on level LOGL_DEBUG
+DAA INFO Log message for DAA on level LOGL_INFO
+DAA NOTICE Log message for DAA on level LOGL_NOTICE
+DAA ERROR Log message for DAA on level LOGL_ERROR
+DAA FATAL Log message for DAA on level LOGL_FATAL
+DBB INFO Log message for DBB on level LOGL_INFO
+DBB NOTICE Log message for DBB on level LOGL_NOTICE
+DBB ERROR Log message for DBB on level LOGL_ERROR
+DBB FATAL Log message for DBB on level LOGL_FATAL
+DCCC NOTICE Log message for DCCC on level LOGL_NOTICE
+DCCC ERROR Log message for DCCC on level LOGL_ERROR
+DCCC FATAL Log message for DCCC on level LOGL_FATAL
+DDDDD ERROR Log message for DDDDD on level LOGL_ERROR
+DDDDD FATAL Log message for DDDDD on level LOGL_FATAL
+DEEE FATAL Log message for DEEE on level LOGL_FATAL
+
+logging_vty_test# logging level all fatal
+logging_vty_test# log-sweep
+DAA FATAL Log message for DAA on level LOGL_FATAL
+DBB FATAL Log message for DBB on level LOGL_FATAL
+DCCC FATAL Log message for DCCC on level LOGL_FATAL
+DDDDD FATAL Log message for DDDDD on level LOGL_FATAL
+DEEE FATAL Log message for DEEE on level LOGL_FATAL
+
+logging_vty_test# logging level all error
+logging_vty_test# log-sweep
+DAA ERROR Log message for DAA on level LOGL_ERROR
+DAA FATAL Log message for DAA on level LOGL_FATAL
+DBB ERROR Log message for DBB on level LOGL_ERROR
+DBB FATAL Log message for DBB on level LOGL_FATAL
+DCCC ERROR Log message for DCCC on level LOGL_ERROR
+DCCC FATAL Log message for DCCC on level LOGL_FATAL
+DDDDD ERROR Log message for DDDDD on level LOGL_ERROR
+DDDDD FATAL Log message for DDDDD on level LOGL_FATAL
+DEEE ERROR Log message for DEEE on level LOGL_ERROR
+DEEE FATAL Log message for DEEE on level LOGL_FATAL
+
+logging_vty_test# logging level all notice
+logging_vty_test# log-sweep
+DAA NOTICE Log message for DAA on level LOGL_NOTICE
+DAA ERROR Log message for DAA on level LOGL_ERROR
+DAA FATAL Log message for DAA on level LOGL_FATAL
+DBB NOTICE Log message for DBB on level LOGL_NOTICE
+DBB ERROR Log message for DBB on level LOGL_ERROR
+DBB FATAL Log message for DBB on level LOGL_FATAL
+DCCC NOTICE Log message for DCCC on level LOGL_NOTICE
+DCCC ERROR Log message for DCCC on level LOGL_ERROR
+DCCC FATAL Log message for DCCC on level LOGL_FATAL
+DDDDD NOTICE Log message for DDDDD on level LOGL_NOTICE
+DDDDD ERROR Log message for DDDDD on level LOGL_ERROR
+DDDDD FATAL Log message for DDDDD on level LOGL_FATAL
+DEEE NOTICE Log message for DEEE on level LOGL_NOTICE
+DEEE ERROR Log message for DEEE on level LOGL_ERROR
+DEEE FATAL Log message for DEEE on level LOGL_FATAL
+
+logging_vty_test# logging level all debug
+logging_vty_test# log-sweep
+DAA DEBUG Log message for DAA on level LOGL_DEBUG
+DAA INFO Log message for DAA on level LOGL_INFO
+DAA NOTICE Log message for DAA on level LOGL_NOTICE
+DAA ERROR Log message for DAA on level LOGL_ERROR
+DAA FATAL Log message for DAA on level LOGL_FATAL
+DBB DEBUG Log message for DBB on level LOGL_DEBUG
+DBB INFO Log message for DBB on level LOGL_INFO
+DBB NOTICE Log message for DBB on level LOGL_NOTICE
+DBB ERROR Log message for DBB on level LOGL_ERROR
+DBB FATAL Log message for DBB on level LOGL_FATAL
+DCCC DEBUG Log message for DCCC on level LOGL_DEBUG
+DCCC INFO Log message for DCCC on level LOGL_INFO
+DCCC NOTICE Log message for DCCC on level LOGL_NOTICE
+DCCC ERROR Log message for DCCC on level LOGL_ERROR
+DCCC FATAL Log message for DCCC on level LOGL_FATAL
+DDDDD DEBUG Log message for DDDDD on level LOGL_DEBUG
+DDDDD INFO Log message for DDDDD on level LOGL_INFO
+DDDDD NOTICE Log message for DDDDD on level LOGL_NOTICE
+DDDDD ERROR Log message for DDDDD on level LOGL_ERROR
+DDDDD FATAL Log message for DDDDD on level LOGL_FATAL
+DEEE DEBUG Log message for DEEE on level LOGL_DEBUG
+DEEE INFO Log message for DEEE on level LOGL_INFO
+DEEE NOTICE Log message for DEEE on level LOGL_NOTICE
+DEEE ERROR Log message for DEEE on level LOGL_ERROR
+DEEE FATAL Log message for DEEE on level LOGL_FATAL
+
+logging_vty_test# ! 'logging level all' overrides everything, be it stronger or weaker
+logging_vty_test# logging level all notice
+logging_vty_test# logging level eee debug
+logging_vty_test# log-sweep eee
+DEEE NOTICE Log message for DEEE on level LOGL_NOTICE
+DEEE ERROR Log message for DEEE on level LOGL_ERROR
+DEEE FATAL Log message for DEEE on level LOGL_FATAL
+
+logging_vty_test# logging level all notice
+logging_vty_test# logging level eee fatal
+logging_vty_test# log-sweep eee
+DEEE NOTICE Log message for DEEE on level LOGL_NOTICE
+DEEE ERROR Log message for DEEE on level LOGL_ERROR
+DEEE FATAL Log message for DEEE on level LOGL_FATAL
+
+logging_vty_test# ! Old 'logging level all everything' has no effect
+logging_vty_test# logging level all everything
+% Ignoring deprecated logging level everything
+logging_vty_test# log-sweep eee
+DEEE NOTICE Log message for DEEE on level LOGL_NOTICE
+DEEE ERROR Log message for DEEE on level LOGL_ERROR
+DEEE FATAL Log message for DEEE on level LOGL_FATAL
+
+logging_vty_test# ! There is currently no way to remove the 'logging level all' level!