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
This commit is contained in:
Neels Hofmeyr 2018-09-10 17:18:28 +02:00
parent ec6fdbb128
commit 3a9ff11e57
4 changed files with 530 additions and 1 deletions

View File

@ -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"

View File

@ -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"

View File

@ -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;
}

View File

@ -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!