diff --git a/.gitignore b/.gitignore index 8d027bcec9..26991a7786 100644 --- a/.gitignore +++ b/.gitignore @@ -53,6 +53,7 @@ Makefile.in *.adoc*.tmp *.txt*.tmp /cppcheck*.xml +/.ci*.txt* /.ci*.log /.ci*.log.* .dirstamp diff --git a/NEWS.adoc b/NEWS.adoc index fb6ba84db1..1ced95eb5a 100644 --- a/NEWS.adoc +++ b/NEWS.adoc @@ -139,6 +139,10 @@ as part of https://github.com/networkupstools/nut/issues/1410 solution. of UID/GID (everywhere), which makes troubleshooting harder (e.g. lack of access to config files or USB device nodes). Now we have it [#1694] + - A `NUT_DEBUG_PID` envvar (presence) support was added to add current + process ID to tags with debug-level identifiers. This may be useful + when many NUT daemons write to the same console or log file. [#2118] + - huawei-ups2000 is now known to support more devices, noted in docs and for auto-detection [#1448, #1684] diff --git a/UPGRADING.adoc b/UPGRADING.adoc index 9e0e989a01..6cdfd2bae5 100644 --- a/UPGRADING.adoc +++ b/UPGRADING.adoc @@ -128,6 +128,11 @@ Changes from 2.8.0 to 2.8.1 and exposed in `libnutscan.so` builds in particular - API version for the public library was bumped [#317] +- A `NUT_DEBUG_PID` envvar (presence) support was added to add current + process ID to tags with debug-level identifiers. This may be useful + when many NUT daemons write to the same console or log file, such as + in containers/plugins for Home Assistant, storage appliances, etc. [#2118] + - `configure` script, reference init-script and packaging templates updated to eradicate `@PIDPATH@/nut` ambiguity in favor of `@ALTPIDPATH@` for the unprivileged processes vs. `@PIDPATH@` for those running as root [#1719] diff --git a/common/common.c b/common/common.c index c12587ae1d..7633a3defa 100644 --- a/common/common.c +++ b/common/common.c @@ -1519,6 +1519,7 @@ void s_upsdebug_with_errno(int level, const char *fmt, ...) { va_list va; char fmt2[LARGEBUF]; + static int NUT_DEBUG_PID = -1; /* Note: Thanks to macro wrapping, we do not quite need this * test now, but we still need the "level" value to report @@ -1534,7 +1535,18 @@ void s_upsdebug_with_errno(int level, const char *fmt, ...) * can help limit this debug stream quicker, than experimentally picking ;) */ if (level > 0) { int ret; - ret = snprintf(fmt2, sizeof(fmt2), "[D%d] %s", level, fmt); + + if (NUT_DEBUG_PID < 0) { + NUT_DEBUG_PID = (getenv("NUT_DEBUG_PID") != NULL); + } + + if (NUT_DEBUG_PID) { + /* Note that we re-request PID every time as it can + * change during the run-time (forking etc.) */ + ret = snprintf(fmt2, sizeof(fmt2), "[D%d:%" PRIiMAX "] %s", level, (intmax_t)getpid(), fmt); + } else { + ret = snprintf(fmt2, sizeof(fmt2), "[D%d] %s", level, fmt); + } if ((ret < 0) || (ret >= (int) sizeof(fmt2))) { syslog(LOG_WARNING, "upsdebug_with_errno: snprintf needed more than %d bytes", LARGEBUF); @@ -1564,6 +1576,7 @@ void s_upsdebugx(int level, const char *fmt, ...) { va_list va; char fmt2[LARGEBUF]; + static int NUT_DEBUG_PID = -1; if (nut_debug_level < level) return; @@ -1571,7 +1584,19 @@ void s_upsdebugx(int level, const char *fmt, ...) /* See comments above in upsdebug_with_errno() - they apply here too. */ if (level > 0) { int ret; - ret = snprintf(fmt2, sizeof(fmt2), "[D%d] %s", level, fmt); + + if (NUT_DEBUG_PID < 0) { + NUT_DEBUG_PID = (getenv("NUT_DEBUG_PID") != NULL); + } + + if (NUT_DEBUG_PID) { + /* Note that we re-request PID every time as it can + * change during the run-time (forking etc.) */ + ret = snprintf(fmt2, sizeof(fmt2), "[D%d:%" PRIiMAX "] %s", level, (intmax_t)getpid(), fmt); + } else { + ret = snprintf(fmt2, sizeof(fmt2), "[D%d] %s", level, fmt); + } + if ((ret < 0) || (ret >= (int) sizeof(fmt2))) { syslog(LOG_WARNING, "upsdebugx: snprintf needed more than %d bytes", LARGEBUF); diff --git a/drivers/dummy-ups.c b/drivers/dummy-ups.c index 3b4be2436c..e14149a4a7 100644 --- a/drivers/dummy-ups.c +++ b/drivers/dummy-ups.c @@ -2,6 +2,7 @@ Copyright (C) 2005 - 2015 Arnaud Quette + 2014 - 2023 Jim Klimov 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 @@ -47,7 +48,7 @@ #include "dummy-ups.h" #define DRIVER_NAME "Device simulation and repeater driver" -#define DRIVER_VERSION "0.16" +#define DRIVER_VERSION "0.17" /* driver description structure */ upsdrv_info_t upsdrv_info = @@ -98,7 +99,7 @@ static struct stat datafile_stat; static int setvar(const char *varname, const char *val); static int instcmd(const char *cmdname, const char *extra); -static int parse_data_file(TYPE_FD upsfd); +static int parse_data_file(TYPE_FD arg_upsfd); static dummy_info_t *find_info(const char *varname); static int is_valid_data(const char* varname); static int is_valid_value(const char* varname, const char *value); @@ -207,6 +208,36 @@ void upsdrv_initinfo(void) dstate_addcmd("load.off"); } +static int prepare_filepath(char *fn, size_t buflen) +{ + /* Note: device_path is a global variable, + * the "port=..." value parsed in main.c */ + if (device_path[0] == '/' +#ifdef WIN32 + || device_path[1] == ':' /* "C:\..." */ +#endif + ) { + /* absolute path */ + return snprintf(fn, buflen, "%s", device_path); + } else if (device_path[0] == '.') { + /* "./" or "../" e.g. via CLI, relative to current working + * directory of the driver process... at this moment */ + if (getcwd(fn, buflen)) { + return snprintf(fn + strlen(fn), buflen - strlen(fn), "/%s", device_path); + } else { + return snprintf(fn, buflen, "%s", device_path); + } + } else { + /* assumed to be a filename in NUT config file path + * (possibly under, with direct use of dirname without dots) + * Note that we do not fiddle with file-path separator, + * modern Windows (at least via MinGW/MSYS2) supports + * the POSIX slash. + */ + return snprintf(fn, buflen, "%s/%s", confpath(), device_path); + } +} + void upsdrv_updateinfo(void) { upsdebugx(1, "upsdrv_updateinfo..."); @@ -227,26 +258,18 @@ void upsdrv_updateinfo(void) struct stat fs; char fn[SMALLBUF]; - if (device_path[0] == '/' -#ifdef WIN32 - || device_path[1] == ':' /* "C:\..." */ -#endif - ) - snprintf(fn, sizeof(fn), "%s", device_path); - else if (device_path[0] == '.') { - /* "./" or "../" e.g. via CLI */ - if (getcwd(fn, sizeof(fn))) { - snprintf(fn + strlen(fn), sizeof(fn) - strlen(fn), "/%s", device_path); - } else - snprintf(fn, sizeof(fn), "%s", device_path); - } else - snprintf(fn, sizeof(fn), "%s/%s", confpath(), device_path); + prepare_filepath(fn, sizeof(fn)); /* Determine if file modification timestamp has changed * since last use (so we would want to re-read it) */ #ifndef WIN32 - /* Either successful stat is OK to fill the "fs" struct */ - if (0 != fstat (upsfd, &fs) && 0 != stat (fn, &fs)) + /* Either successful stat (zero return) is OK to + * fill the "fs" struct. Note that currently + * "upsfd" is a no-op for files, they are re-opened + * and re-parsed every time so callers can modify + * the data without complications. + */ + if ( (INVALID_FD(upsfd) || 0 != fstat (upsfd, &fs)) && 0 != stat (fn, &fs)) #else /* Consider GetFileAttributesEx() for WIN32_FILE_ATTRIBUTE_DATA? * https://stackoverflow.com/questions/8991192/check-the-file-size-without-opening-file-in-c/8991228#8991228 @@ -254,15 +277,16 @@ void upsdrv_updateinfo(void) if (0 != stat (fn, &fs)) #endif { - upsdebugx(2, "Can't open %s currently", fn); + upsdebugx(2, "%s: MODE_DUMMY_ONCE: Can't stat %s currently", __func__, fn); /* retry ASAP until we get a file */ memset(&datafile_stat, 0, sizeof(struct stat)); next_update = 1; } else { if (datafile_stat.st_mtime != fs.st_mtime) { upsdebugx(2, - "upsdrv_updateinfo: input file was already read once " - "to the end, but changed later - re-reading: %s", fn); + "%s: MODE_DUMMY_ONCE: input file was already read once " + "to the end, but changed later - re-reading: %s", + __func__, fn); /* updated file => retry ASAP */ next_update = 1; datafile_stat = fs; @@ -271,7 +295,7 @@ void upsdrv_updateinfo(void) } if (ctx == NULL && next_update == -1) { - upsdebugx(2, "upsdrv_updateinfo: NO-OP: input file was already read once to the end"); + upsdebugx(2, "%s: MODE_DUMMY_ONCE: NO-OP: input file was already read once to the end", __func__); dstate_dataok(); } else { /* initial parsing interrupted by e.g. TIMER line */ @@ -474,33 +498,25 @@ void upsdrv_initups(void) #endif } - if (device_path[0] == '/' -#ifdef WIN32 - || device_path[1] == ':' /* "C:\..." */ -#endif - ) - snprintf(fn, sizeof(fn), "%s", device_path); - else if (device_path[0] == '.') { - /* "./" or "../" e.g. via CLI */ - if (getcwd(fn, sizeof(fn))) { - snprintf(fn + strlen(fn), sizeof(fn) - strlen(fn), "/%s", device_path); - } else - snprintf(fn, sizeof(fn), "%s", device_path); - } else - snprintf(fn, sizeof(fn), "%s/%s", confpath(), device_path); + prepare_filepath(fn, sizeof(fn)); /* Update file modification timestamp (and other data) */ #ifndef WIN32 - /* Either successful stat is OK to fill the "datafile_stat" struct */ - if (0 != fstat (upsfd, &datafile_stat) && 0 != stat (device_path, &datafile_stat)) + /* Either successful stat (zero return) is OK to fill the + * "datafile_stat" struct. Note that currently "upsfd" is + * a no-op for files, they are re-opened and re-parsed + * every time so callers can modify the data without + * complications. + */ + if ( (INVALID_FD(upsfd) || 0 != fstat (upsfd, &datafile_stat)) && 0 != stat (fn, &datafile_stat)) #else /* Consider GetFileAttributesEx() for WIN32_FILE_ATTRIBUTE_DATA? * https://stackoverflow.com/questions/8991192/check-the-file-size-without-opening-file-in-c/8991228#8991228 */ - if (0 != stat (device_path, &datafile_stat)) + if (0 != stat (fn, &datafile_stat)) #endif { - upsdebugx(2, "Can't open %s (%s) currently", device_path, fn); + upsdebugx(2, "%s: Can't stat %s (%s) currently", __func__, device_path, fn); } else { upsdebugx(2, "Located %s for device simulation data: %s", device_path, fn); } @@ -642,7 +658,7 @@ static dummy_info_t *find_info(const char *varname) return item; } - upsdebugx(2, "find_info: unknown variable: %s\n", varname); + upsdebugx(2, "find_info: unknown variable: %s", varname); return NULL; } @@ -719,21 +735,7 @@ static int parse_data_file(TYPE_FD arg_upsfd) { ctx = (PCONF_CTX_t *)xmalloc(sizeof(PCONF_CTX_t)); - if (device_path[0] == '/' -#ifdef WIN32 - || device_path[1] == ':' /* "C:\..." */ -#endif - ) - snprintf(fn, sizeof(fn), "%s", device_path); - else if (device_path[0] == '.') { - /* "./" or "../" e.g. via CLI */ - if (getcwd(fn, sizeof(fn))) { - snprintf(fn + strlen(fn), sizeof(fn) - strlen(fn), "/%s", device_path); - } else - snprintf(fn, sizeof(fn), "%s", device_path); - } else - snprintf(fn, sizeof(fn), "%s/%s", confpath(), device_path); - + prepare_filepath(fn, sizeof(fn)); pconf_init(ctx, upsconf_err); if (!pconf_file_begin(ctx, fn)) diff --git a/tests/NIT/nit.sh b/tests/NIT/nit.sh index 4b132224ba..9cee5082a7 100755 --- a/tests/NIT/nit.sh +++ b/tests/NIT/nit.sh @@ -34,6 +34,9 @@ export TZ LANG LC_ALL NUT_QUIET_INIT_SSL="true" export NUT_QUIET_INIT_SSL +NUT_DEBUG_PID="true" +export NUT_DEBUG_PID + log_separator() { echo "" >&2 echo "================================" >&2 @@ -548,11 +551,11 @@ testcase_upsd_no_configs_at_all() { log_info "[testcase_upsd_no_configs_at_all] Test UPSD without configs at all" upsd -F if [ "$?" = 0 ]; then - log_error "upsd should fail without configs" + log_error "[testcase_upsd_no_configs_at_all] upsd should fail without configs" FAILED="`expr $FAILED + 1`" FAILED_FUNCS="$FAILED_FUNCS testcase_upsd_no_configs_at_all" else - log_info "OK, upsd failed to start in wrong conditions" + log_info "[testcase_upsd_no_configs_at_all] PASSED: upsd failed to start in wrong conditions" PASSED="`expr $PASSED + 1`" fi } @@ -563,11 +566,11 @@ testcase_upsd_no_configs_driver_file() { generatecfg_upsd_trivial upsd -F if [ "$?" = 0 ]; then - log_error "upsd should fail without driver config file" + log_error "[testcase_upsd_no_configs_driver_file] upsd should fail without driver config file" FAILED="`expr $FAILED + 1`" FAILED_FUNCS="$FAILED_FUNCS testcase_upsd_no_configs_driver_file" else - log_info "OK, upsd failed to start in wrong conditions" + log_info "[testcase_upsd_no_configs_driver_file] PASSED: upsd failed to start in wrong conditions" PASSED="`expr $PASSED + 1`" fi } @@ -579,11 +582,11 @@ testcase_upsd_no_configs_in_driver_file() { generatecfg_ups_trivial upsd -F if [ "$?" = 0 ]; then - log_error "upsd should fail without drivers defined in config file" + log_error "[testcase_upsd_no_configs_in_driver_file] upsd should fail without drivers defined in config file" FAILED="`expr $FAILED + 1`" FAILED_FUNCS="$FAILED_FUNCS testcase_upsd_no_configs_in_driver_file" else - log_info "OK, upsd failed to start in wrong conditions" + log_info "[testcase_upsd_no_configs_in_driver_file] PASSED: upsd failed to start in wrong conditions" PASSED="`expr $PASSED + 1`" fi } @@ -599,7 +602,7 @@ testcase_upsd_allow_no_device() { fi upsd -F & PID_UPSD="$!" - log_debug "Tried to start UPSD as PID $PID_UPSD" + log_debug "[testcase_upsd_allow_no_device] Tried to start UPSD as PID $PID_UPSD" sleep 2 COUNTDOWN=60 @@ -613,57 +616,65 @@ testcase_upsd_allow_no_device() { if [ "$COUNTDOWN" -le 50 ] ; then # Should not get to this, except on very laggy systems maybe - log_warn "Had to wait a few retries for the UPSD process to appear" + log_warn "[testcase_upsd_allow_no_device] Had to wait a few retries for the UPSD process to appear" fi + res_testcase_upsd_allow_no_device=0 if [ "$COUNTDOWN" -gt 0 ] \ && isPidAlive "$PID_UPSD" \ ; then - log_info "OK, upsd is running" + log_info "[testcase_upsd_allow_no_device] OK, upsd is running" PASSED="`expr $PASSED + 1`" log_separator - log_info "Query listing from UPSD by UPSC (no devices configured yet) to test that UPSD responds to UPSC" + log_info "[testcase_upsd_allow_no_device] Query listing from UPSD by UPSC (no devices configured yet) to test that UPSD responds to UPSC" if runcmd upsc -l localhost:$NUT_PORT ; then : else # Note: avoid exact matching for stderr, because it can have Init SSL messages etc. if echo "$CMDERR" | grep "Error: Server disconnected" >/dev/null ; then - log_warn "Retry once to rule out laggy systems" + log_warn "[testcase_upsd_allow_no_device] Retry once to rule out laggy systems" sleep 3 runcmd upsc -l localhost:$NUT_PORT fi if echo "$CMDERR" | grep "Error: Server disconnected" >/dev/null ; then - log_warn "Retry once more to rule out very laggy systems" + log_warn "[testcase_upsd_allow_no_device] Retry once more to rule out very laggy systems" sleep 15 runcmd upsc -l localhost:$NUT_PORT fi - [ "$CMDRES" = 0 ] || die "upsd does not respond on port ${NUT_PORT} ($?): $CMDOUT" + [ "$CMDRES" = 0 ] || die "[testcase_upsd_allow_no_device] upsd does not respond on port ${NUT_PORT} ($?): $CMDOUT" fi if [ -n "$CMDOUT" ] ; then - log_error "got reply for upsc listing when none was expected: $CMDOUT" + log_error "[testcase_upsd_allow_no_device] got reply for upsc listing when none was expected: $CMDOUT" FAILED="`expr $FAILED + 1`" FAILED_FUNCS="$FAILED_FUNCS testcase_upsd_allow_no_device" + res_testcase_upsd_allow_no_device=1 else - log_info "OK, empty response as expected" + log_info "[testcase_upsd_allow_no_device] OK, empty response as expected" PASSED="`expr $PASSED + 1`" fi else - log_error "upsd was expected to be running although no devices are defined; is ups.conf populated?" + log_error "[testcase_upsd_allow_no_device] upsd was expected to be running although no devices are defined; is ups.conf populated?" ls -la "$NUT_CONFPATH/" || true FAILED="`expr $FAILED + 1`" FAILED_FUNCS="$FAILED_FUNCS testcase_upsd_allow_no_device" + res_testcase_upsd_allow_no_device=1 report_NUT_PORT - - UPSD_RES=0 - kill -15 $PID_UPSD - wait $PID_UPSD || UPSD_RES=$? - log_error "upsd exit-code was: $UPSD_RES" - return $UPSD_RES fi + log_info "[testcase_upsd_allow_no_device] stopping upsd: $PID_UPSD" + UPSD_RES=0 kill -15 $PID_UPSD - wait $PID_UPSD + wait $PID_UPSD || UPSD_RES=$? + if [ "$res_testcase_upsd_allow_no_device" = 0 ] ; then + log_info "[testcase_upsd_allow_no_device] upsd exit-code was: $UPSD_RES" + else + log_error "[testcase_upsd_allow_no_device] upsd exit-code was: $UPSD_RES" + fi + if [ "$UPSD_RES" != 0 ]; then + return $UPSD_RES + fi + return $res_testcase_upsd_allow_no_device } testgroup_upsd_invalid_configs() { @@ -727,19 +738,34 @@ sandbox_start_drivers() { #upsdrvctl -F start dummy & dummy-ups -a dummy -F & PID_DUMMYUPS="$!" + log_debug "Tried to start dummy-ups driver for 'dummy' as PID $PID_DUMMYUPS" if [ x"${TOP_SRCDIR}" != x ]; then dummy-ups -a UPS1 -F & PID_DUMMYUPS1="$!" + log_debug "Tried to start dummy-ups driver for 'UPS1' as PID $PID_DUMMYUPS1" dummy-ups -a UPS2 -F & PID_DUMMYUPS2="$!" + log_debug "Tried to start dummy-ups driver for 'UPS2' as PID $PID_DUMMYUPS2" fi sleep 5 if shouldDebug ; then - (ps -ef || ps -xawwu) 2>/dev/null | grep -E '(ups|nut|dummy)' || true + (ps -ef || ps -xawwu) 2>/dev/null | grep -E '(ups|nut|dummy|'"`basename "$0"`"')' | grep -vE '(ssh|startups|grep)' || true + fi + + if isPidAlive "$PID_DUMMYUPS" \ + && { [ x"${TOP_SRCDIR}" != x ] && isPidAlive "$PID_DUMMYUPS1" && isPidAlive "$PID_DUMMYUPS2" \ + || [ x"${TOP_SRCDIR}" = x ] ; } \ + ; then + # All drivers expected for this environment are already running + log_info "Starting dummy-ups driver(s) for sandbox - all expected processes are running" + return 0 + else + log_error "Starting dummy-ups driver(s) for sandbox - finished, but something seems to not be running" + return 1 fi } @@ -757,34 +783,46 @@ UPS2" EXPECTED_UPSLIST="`echo "$EXPECTED_UPSLIST" | tr -d '\r'`" fi - log_info "Query listing from UPSD by UPSC (driver not running yet)" - runcmd upsc -l localhost:$NUT_PORT || die "upsd does not respond on port ${NUT_PORT} ($?): $CMDOUT" + log_info "[testcase_sandbox_start_upsd_alone] Query listing from UPSD by UPSC (driver not running yet)" + res_testcase_sandbox_start_upsd_alone=0 + runcmd upsc -l localhost:$NUT_PORT || die "[testcase_sandbox_start_upsd_alone] upsd does not respond on port ${NUT_PORT} ($?): $CMDOUT" # For windows runners (printf can do wonders, so strip CR if any): if [ x"${TOP_SRCDIR}" != x ]; then CMDOUT="`echo "$CMDOUT" | tr -d '\r'`" fi if [ x"$CMDOUT" != x"$EXPECTED_UPSLIST" ] ; then - log_error "got this reply for upsc listing when '$EXPECTED_UPSLIST' was expected: '$CMDOUT'" + log_error "[testcase_sandbox_start_upsd_alone] got this reply for upsc listing when '$EXPECTED_UPSLIST' was expected: '$CMDOUT'" FAILED="`expr $FAILED + 1`" FAILED_FUNCS="$FAILED_FUNCS testcase_sandbox_start_upsd_alone" + res_testcase_sandbox_start_upsd_alone=1 else PASSED="`expr $PASSED + 1`" fi - log_info "Query driver state from UPSD by UPSC (driver not running yet)" + log_info "[testcase_sandbox_start_upsd_alone] Query driver state from UPSD by UPSC (driver not running yet)" runcmd upsc dummy@localhost:$NUT_PORT && { log_error "upsc was supposed to answer with error exit code: $CMDOUT" FAILED="`expr $FAILED + 1`" FAILED_FUNCS="$FAILED_FUNCS testcase_sandbox_start_upsd_alone" + res_testcase_sandbox_start_upsd_alone=1 } # Note: avoid exact matching for stderr, because it can have Init SSL messages etc. if echo "$CMDERR" | grep 'Error: Driver not connected' >/dev/null ; then PASSED="`expr $PASSED + 1`" else - log_error "got some other reply for upsc query when 'Error: Driver not connected' was expected on stderr: '$CMDOUT'" + log_error "[testcase_sandbox_start_upsd_alone] got some other reply for upsc query when 'Error: Driver not connected' was expected on stderr: '$CMDOUT'" FAILED="`expr $FAILED + 1`" FAILED_FUNCS="$FAILED_FUNCS testcase_sandbox_start_upsd_alone" + res_testcase_sandbox_start_upsd_alone=1 fi + + if [ "$res_testcase_sandbox_start_upsd_alone" = 0 ]; then + log_info "[testcase_sandbox_start_upsd_alone] PASSED: got just the failures expected for data server alone (driver not running yet)" + else + log_error "[testcase_sandbox_start_upsd_alone] got some unexpected failures, see above" + fi + + return $res_testcase_sandbox_start_upsd_alone } testcase_sandbox_start_upsd_after_drivers() { @@ -795,33 +833,35 @@ testcase_sandbox_start_upsd_after_drivers() { upsd -F & PID_UPSD="$!" - log_debug "Tried to start UPSD as PID $PID_UPSD" + log_debug "[testcase_sandbox_start_upsd_after_drivers] Tried to start UPSD as PID $PID_UPSD" sandbox_start_drivers sandbox_start_upsd sleep 5 - COUNTDOWN=60 + COUNTDOWN=90 while [ "$COUNTDOWN" -gt 0 ]; do # For query errors or known wait, keep looping runcmd upsc dummy@localhost:$NUT_PORT \ && case "$CMDOUT" in - "ups.status: WAIT") ;; + *"ups.status: WAIT"*) ;; *) log_info "Got output:" ; echo "$CMDOUT" ; break ;; esac sleep 1 COUNTDOWN="`expr $COUNTDOWN - 1`" done - if [ "$COUNTDOWN" -le 50 ] ; then - log_warn "Had to wait a few retries for the dummy driver to connect" + if [ "$COUNTDOWN" -le 88 ] ; then + log_warn "[testcase_sandbox_start_upsd_after_drivers] Had to wait a few retries for the dummy driver to connect" fi if [ "$COUNTDOWN" -le 1 ] ; then report_NUT_PORT - die "upsd does not respond on port ${NUT_PORT} ($?)" + die "[testcase_sandbox_start_upsd_after_drivers] upsd does not respond on port ${NUT_PORT} ($?)" fi + + log_info "[testcase_sandbox_start_upsd_after_drivers] PASSED: upsd responds on port ${NUT_PORT}" } testcase_sandbox_start_drivers_after_upsd() { @@ -830,75 +870,84 @@ testcase_sandbox_start_drivers_after_upsd() { sandbox_start_drivers log_info "[testcase_sandbox_start_drivers_after_upsd] Query driver state from UPSD by UPSC after driver startup" - COUNTDOWN=60 + # Timing issues: upsd starts, we wait 10 sec, drivers start and init, + # at 20 sec upsd does not see them yet, at 30 sec the sockets connect + # but info does not come yet => may be "driver stale", finally at + # 40+(drv)/50+(upsd) sec a DUMPALL is processed (regular 30-sec loop?) - + # so tightly near a minute until we have sturdy replies. + COUNTDOWN=90 while [ "$COUNTDOWN" -gt 0 ]; do - # For query errors or known wait, keep looping + # For query errors or known wait, keep looping. May get: + # driver.state: updateinfo + # ups.status: WAIT runcmd upsc dummy@localhost:$NUT_PORT \ && case "$CMDOUT" in - "ups.status: WAIT") ;; - *) log_info "Got output:" ; echo "$CMDOUT" ; break ;; + *"ups.status: WAIT"*) ;; + *) log_info "[testcase_sandbox_start_drivers_after_upsd] Got output:" ; echo "$CMDOUT" ; break ;; esac sleep 1 COUNTDOWN="`expr $COUNTDOWN - 1`" done - if [ "$COUNTDOWN" -le 58 ] ; then - log_warn "Had to wait a few retries for the dummy driver to connect" + if [ "$COUNTDOWN" -le 88 ] ; then + log_warn "[testcase_sandbox_start_drivers_after_upsd] Had to wait a few retries for the dummy driver to connect" fi if [ "$COUNTDOWN" -le 1 ] ; then # Should not get to this, except on very laggy systems maybe - log_error "Query failed, retrying with UPSD started after drivers" + log_error "[testcase_sandbox_start_drivers_after_upsd] Query failed, retrying with UPSD started after drivers" testcase_sandbox_start_upsd_after_drivers fi if [ x"${TOP_SRCDIR}" != x ]; then - log_info "Wait for dummy UPSes with larger data sets to initialize" + log_info "[testcase_sandbox_start_drivers_after_upsd] Wait for dummy UPSes with larger data sets to initialize" for U in UPS1 UPS2 ; do - COUNTDOWN=60 + COUNTDOWN=90 # TODO: Convert to runcmd()? OUT="" while [ x"$OUT" = x"ups.status: WAIT" ] ; do OUT="`upsc $U@localhost:$NUT_PORT ups.status`" || break - [ x"$OUT" = x"ups.status: WAIT" ] || { log_info "Got output:"; echo "$OUT"; break; } + [ x"$OUT" = x"ups.status: WAIT" ] || { log_info "[testcase_sandbox_start_drivers_after_upsd] Got output:"; echo "$OUT"; break; } sleep 1 COUNTDOWN="`expr $COUNTDOWN - 1`" # Systemic error, e.g. could not create socket file? - [ "$COUNTDOWN" -lt 1 ] && die "Dummy driver did not start or respond in time" + [ "$COUNTDOWN" -lt 1 ] && die "[testcase_sandbox_start_drivers_after_upsd] Dummy driver did not start or respond in time" done - if [ "$COUNTDOWN" -le 58 ] ; then - log_warn "Had to wait a few retries for the $U driver to connect" + if [ "$COUNTDOWN" -le 88 ] ; then + log_warn "[testcase_sandbox_start_drivers_after_upsd] Had to wait a few retries for the $U driver to connect" fi done fi - log_info "Expected drivers are now responding via UPSD" + log_info "[testcase_sandbox_start_drivers_after_upsd] PASSED: Expected drivers are now responding via UPSD" } testcase_sandbox_upsc_query_model() { log_info "[testcase_sandbox_upsc_query_model] Query model from dummy device" - runcmd upsc dummy@localhost:$NUT_PORT device.model || die "upsd does not respond on port ${NUT_PORT} ($?): $CMDOUT" + runcmd upsc dummy@localhost:$NUT_PORT device.model || die "[testcase_sandbox_upsc_query_model] upsd does not respond on port ${NUT_PORT} ($?): $CMDOUT" if [ x"$CMDOUT" != x"Dummy UPS" ] ; then - log_error "got this reply for upsc query when 'Dummy UPS' was expected: $CMDOUT" + log_error "[testcase_sandbox_upsc_query_model] got this reply for upsc query when 'Dummy UPS' was expected: $CMDOUT" FAILED="`expr $FAILED + 1`" FAILED_FUNCS="$FAILED_FUNCS testcase_sandbox_upsc_query_model" else PASSED="`expr $PASSED + 1`" + log_info "[testcase_sandbox_upsc_query_model] PASSED: got expected model from dummy device: $CMDOUT" fi } testcase_sandbox_upsc_query_bogus() { log_info "[testcase_sandbox_upsc_query_bogus] Query driver state from UPSD by UPSC for bogus info" runcmd upsc dummy@localhost:$NUT_PORT ups.bogus.value && { - log_error "upsc was supposed to answer with error exit code: $CMDOUT" + log_error "[testcase_sandbox_upsc_query_bogus] upsc was supposed to answer with error exit code: $CMDOUT" FAILED="`expr $FAILED + 1`" FAILED_FUNCS="$FAILED_FUNCS testcase_sandbox_upsc_query_bogus" } # Note: avoid exact matching for stderr, because it can have Init SSL messages etc. if echo "$CMDERR" | grep 'Error: Variable not supported by UPS' >/dev/null ; then PASSED="`expr $PASSED + 1`" + log_info "[testcase_sandbox_upsc_query_bogus] PASSED: got expected reply to bogus query" else - log_error "got some other reply for upsc query when 'Error: Variable not supported by UPS' was expected on stderr: '$CMDOUT'" + log_error "[testcase_sandbox_upsc_query_bogus] got some other reply for upsc query when 'Error: Variable not supported by UPS' was expected on stderr: stderr:'$CMDERR' / stdout:'$CMDOUT'" FAILED="`expr $FAILED + 1`" FAILED_FUNCS="$FAILED_FUNCS testcase_sandbox_upsc_query_bogus" fi @@ -909,23 +958,23 @@ testcase_sandbox_upsc_query_timer() { log_info "[testcase_sandbox_upsc_query_timer] Test that dummy-ups TIMER action changes the reported state" # Driver is set up to flip ups.status every 5 sec, so check every 3 # TODO: Any need to convert to runcmd()? - OUT1="`upsc dummy@localhost:$NUT_PORT ups.status`" || die "upsd does not respond on port ${NUT_PORT} ($?): $OUT1" ; sleep 3 - OUT2="`upsc dummy@localhost:$NUT_PORT ups.status`" || die "upsd does not respond on port ${NUT_PORT} ($?): $OUT2" + OUT1="`upsc dummy@localhost:$NUT_PORT ups.status`" || die "[testcase_sandbox_upsc_query_timer] upsd does not respond on port ${NUT_PORT} ($?): $OUT1" ; sleep 3 + OUT2="`upsc dummy@localhost:$NUT_PORT ups.status`" || die "[testcase_sandbox_upsc_query_timer] upsd does not respond on port ${NUT_PORT} ($?): $OUT2" OUT3="" OUT4="" if [ x"$OUT1" = x"$OUT2" ]; then sleep 3 - OUT3="`upsc dummy@localhost:$NUT_PORT ups.status`" || die "upsd does not respond on port ${NUT_PORT} ($?): $OUT3" + OUT3="`upsc dummy@localhost:$NUT_PORT ups.status`" || die "[testcase_sandbox_upsc_query_timer] upsd does not respond on port ${NUT_PORT} ($?): $OUT3" if [ x"$OUT2" = x"$OUT3" ]; then sleep 3 - OUT4="`upsc dummy@localhost:$NUT_PORT ups.status`" || die "upsd does not respond on port ${NUT_PORT} ($?): $OUT4" + OUT4="`upsc dummy@localhost:$NUT_PORT ups.status`" || die "[testcase_sandbox_upsc_query_timer] upsd does not respond on port ${NUT_PORT} ($?): $OUT4" fi fi if echo "$OUT1$OUT2$OUT3$OUT4" | grep "OB" && echo "$OUT1$OUT2$OUT3$OUT4" | grep "OL" ; then - log_info "OK, ups.status flips over time" + log_info "[testcase_sandbox_upsc_query_timer] PASSED: ups.status flips over time" PASSED="`expr $PASSED + 1`" else - log_error "ups.status did not flip over time" + log_error "[testcase_sandbox_upsc_query_timer] ups.status did not flip over time" FAILED="`expr $FAILED + 1`" FAILED_FUNCS="$FAILED_FUNCS testcase_sandbox_upsc_query_timer" fi @@ -953,10 +1002,10 @@ testcase_sandbox_python_without_credentials() { unset NUT_PASS || true "${TOP_BUILDDIR}/scripts/python/module/test_nutclient.py" ) ; then - log_info "OK, PyNUT did not complain" + log_info "[testcase_sandbox_python_without_credentials] PASSED: PyNUT did not complain" PASSED="`expr $PASSED + 1`" else - log_error "PyNUT complained, check above" + log_error "[testcase_sandbox_python_without_credentials] PyNUT complained, check above" FAILED="`expr $FAILED + 1`" FAILED_FUNCS="$FAILED_FUNCS testcase_sandbox_python_without_credentials" fi @@ -976,10 +1025,10 @@ testcase_sandbox_python_with_credentials() { export NUT_USER NUT_PASS "${TOP_BUILDDIR}/scripts/python/module/test_nutclient.py" ) ; then - log_info "OK, PyNUT did not complain" + log_info "[testcase_sandbox_python_with_credentials] PASSED: PyNUT did not complain" PASSED="`expr $PASSED + 1`" else - log_error "PyNUT complained, check above" + log_error "[testcase_sandbox_python_with_credentials] PyNUT complained, check above" FAILED="`expr $FAILED + 1`" FAILED_FUNCS="$FAILED_FUNCS testcase_sandbox_python_with_credentials" fi @@ -996,10 +1045,10 @@ testcase_sandbox_python_with_upsmon_credentials() { export NUT_USER NUT_PASS "${TOP_BUILDDIR}/scripts/python/module/test_nutclient.py" ) ; then - log_info "OK, PyNUT did not complain" + log_info "[testcase_sandbox_python_with_upsmon_credentials] PASSED: PyNUT did not complain" PASSED="`expr $PASSED + 1`" else - log_error "PyNUT complained, check above" + log_error "[testcase_sandbox_python_with_upsmon_credentials] PyNUT complained, check above" FAILED="`expr $FAILED + 1`" FAILED_FUNCS="$FAILED_FUNCS testcase_sandbox_python_with_upsmon_credentials" fi @@ -1034,10 +1083,10 @@ testcase_sandbox_cppnit_without_creds() { unset NUT_PASS || true "${TOP_BUILDDIR}/tests/cppnit" ) ; then - log_info "OK, cppnit did not complain" + log_info "[testcase_sandbox_cppnit_without_creds] PASSED: cppnit did not complain" PASSED="`expr $PASSED + 1`" else - log_error "cppnit complained, check above" + log_error "[testcase_sandbox_cppnit_without_creds] cppnit complained, check above" FAILED="`expr $FAILED + 1`" FAILED_FUNCS="$FAILED_FUNCS testcase_sandbox_cppnit_without_creds" fi @@ -1062,10 +1111,10 @@ testcase_sandbox_cppnit_simple_admin() { export NUT_USER NUT_PASS NUT_SETVAR_DEVICE "${TOP_BUILDDIR}/tests/cppnit" ) ; then - log_info "OK, cppnit did not complain" + log_info "[testcase_sandbox_cppnit_simple_admin] PASSED: cppnit did not complain" PASSED="`expr $PASSED + 1`" else - log_error "cppnit complained, check above" + log_error "[testcase_sandbox_cppnit_simple_admin] cppnit complained, check above" FAILED="`expr $FAILED + 1`" FAILED_FUNCS="$FAILED_FUNCS testcase_sandbox_cppnit_simple_admin" fi @@ -1084,10 +1133,10 @@ testcase_sandbox_cppnit_upsmon_primary() { export NUT_USER NUT_PASS NUT_PRIMARY_DEVICE "${TOP_BUILDDIR}/tests/cppnit" ) ; then - log_info "OK, cppnit did not complain" + log_info "[testcase_sandbox_cppnit_upsmon_primary] PASSED: cppnit did not complain" PASSED="`expr $PASSED + 1`" else - log_error "cppnit complained, check above" + log_error "[testcase_sandbox_cppnit_upsmon_primary] cppnit complained, check above" FAILED="`expr $FAILED + 1`" FAILED_FUNCS="$FAILED_FUNCS testcase_sandbox_cppnit_upsmon_primary" fi @@ -1106,10 +1155,10 @@ testcase_sandbox_cppnit_upsmon_master() { export NUT_USER NUT_PASS NUT_PRIMARY_DEVICE "${TOP_BUILDDIR}/tests/cppnit" ) ; then - log_info "OK, cppnit did not complain" + log_info "[testcase_sandbox_cppnit_upsmon_master] PASSED: cppnit did not complain" PASSED="`expr $PASSED + 1`" else - log_error "cppnit complained, check above" + log_error "[testcase_sandbox_cppnit_upsmon_master] cppnit complained, check above" FAILED="`expr $FAILED + 1`" FAILED_FUNCS="$FAILED_FUNCS testcase_sandbox_cppnit_upsmon_master" fi @@ -1142,7 +1191,7 @@ testcase_sandbox_nutscanner_list() { log_separator log_info "[testcase_sandbox_nutscanner_list] Call libupsclient test suite: nut-scanner on localhost:${NUT_PORT}" - log_info "Preparing LD_LIBRARY_PATH='${LD_LIBRARY_PATH_CLIENT}'" + log_info "[testcase_sandbox_nutscanner_list] Preparing LD_LIBRARY_PATH='${LD_LIBRARY_PATH_CLIENT}'" # Note: for some reason `LD_LIBRARY_PATH=... runcmd ...` loses it :\ LD_LIBRARY_PATH="${LD_LIBRARY_PATH_CLIENT}" @@ -1156,6 +1205,10 @@ testcase_sandbox_nutscanner_list() { LD_LIBRARY_PATH="${LD_LIBRARY_PATH_ORIG}" export LD_LIBRARY_PATH + log_info "[testcase_sandbox_nutscanner_list] findings from nut-scanner:" + echo "$CMDOUT" + log_info "[testcase_sandbox_nutscanner_list] inspecting these findings from nut-scanner..." + # Note: the reported "driver" string is not too helpful as a "nutclient". # In practice this could be a "dummy-ups" repeater or "clone" driver, # or some of the config elements needed for upsmon (lacking creds/role) @@ -1166,29 +1219,47 @@ testcase_sandbox_nutscanner_list() { || return if [ "${NUT_PORT}" = 3493 ] || [ x"$NUT_PORT" = x ]; then - echo "Note: not testing for suffixed port number" >&2 + log_info "[testcase_sandbox_nutscanner_list] Note: not testing for suffixed port number" >&2 else echo "$CMDOUT" | grep -E 'dummy@.*'":${NUT_PORT}" \ - || return + || { + log_error "[testcase_sandbox_nutscanner_list] dummy@... not found" >&2 + return 1 + } fi if [ x"${TOP_SRCDIR}" = x ]; then - echo "Note: only testing one dummy device" >&2 + log_info "[testcase_sandbox_nutscanner_list] Note: only testing one dummy device" >&2 else echo "$CMDOUT" | grep -E '^\[nutdev2\]$' \ && echo "$CMDOUT" | grep 'port = "UPS1@' \ && echo "$CMDOUT" | grep -E '^\[nutdev3\]$' \ && echo "$CMDOUT" | grep 'port = "UPS2@' \ - || return + || { + log_error "[testcase_sandbox_nutscanner_list] something about UPS1/UPS2 not found" >&2 + return 1 + } fi - ) ; then - log_info "OK, nut-scanner found all expected devices" + + if [ x"${TOP_SRCDIR}" = x ]; then + PORTS_WANT=1 + else + PORTS_WANT=3 + fi + PORTS_SEEN="`echo "$CMDOUT" | grep -Ec 'port *='`" + + if [ "$PORTS_WANT" != "$PORTS_SEEN" ]; then + log_error "[testcase_sandbox_nutscanner_list] Too many 'port=' lines: want $PORTS_WANT != seen $PORTS_SEEN" >&2 + return 1 + fi + ) >/dev/null ; then + log_info "[testcase_sandbox_nutscanner_list] PASSED: nut-scanner found all expected devices" PASSED="`expr $PASSED + 1`" else if ( echo "$CMDERR" | grep -E "Cannot load NUT library.*libupsclient.*found.*NUT search disabled" ) ; then - log_warn "SKIP: ${TOP_BUILDDIR}/tools/nut-scanner/nut-scanner: $CMDERR" + log_warn "[testcase_sandbox_nutscanner_list] SKIP: ${TOP_BUILDDIR}/tools/nut-scanner/nut-scanner: $CMDERR" else - log_error "nut-scanner complained or did not return all expected data, check above" + log_error "[testcase_sandbox_nutscanner_list] nut-scanner complained or did not return all expected data, check above" FAILED="`expr $FAILED + 1`" FAILED_FUNCS="$FAILED_FUNCS testcase_sandbox_nutscanner_list" fi @@ -1215,6 +1286,7 @@ testgroup_sandbox() { testcases_sandbox_cppnit testcases_sandbox_nutscanner + log_separator sandbox_forget_configs } @@ -1222,6 +1294,8 @@ testgroup_sandbox_python() { # Arrange for quick test iterations testcase_sandbox_start_drivers_after_upsd testcases_sandbox_python + + log_separator sandbox_forget_configs } @@ -1229,6 +1303,8 @@ testgroup_sandbox_cppnit() { # Arrange for quick test iterations testcase_sandbox_start_drivers_after_upsd testcases_sandbox_cppnit + + log_separator sandbox_forget_configs } @@ -1236,6 +1312,8 @@ testgroup_sandbox_cppnit_simple_admin() { # Arrange for quick test iterations testcase_sandbox_start_drivers_after_upsd testcase_sandbox_cppnit_simple_admin + + log_separator sandbox_forget_configs } @@ -1243,6 +1321,8 @@ testgroup_sandbox_nutscanner() { # Arrange for quick test iterations testcase_sandbox_start_drivers_after_upsd testcases_sandbox_nutscanner + + log_separator sandbox_forget_configs }