From 3a9ff11e574fa7ee19b1062b2c90151dbf7f0e27 Mon Sep 17 00:00:00 2001 From: Neels Hofmeyr Date: Mon, 10 Sep 2018 17:18:28 +0200 Subject: 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 --- configure.ac | 15 ++ tests/Makefile.am | 30 +++- tests/logging/logging_vty_test.c | 296 +++++++++++++++++++++++++++++++++++++ tests/logging/logging_vty_test.vty | 190 ++++++++++++++++++++++++ 4 files changed, 530 insertions(+), 1 deletion(-) create mode 100644 tests/logging/logging_vty_test.c create mode 100644 tests/logging/logging_vty_test.vty 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 + * All Rights Reserved + * + * Author: Neels Hofmeyr + * + * 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 + +#include + +#include +#include +#include + +#include +#include +#include +#include + +#include + +#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! -- cgit v1.2.3