diff --git a/clients/nutclient.cpp b/clients/nutclient.cpp index 821c296d12..0dd0cb8897 100644 --- a/clients/nutclient.cpp +++ b/clients/nutclient.cpp @@ -332,14 +332,60 @@ SSL_CTX* Socket::_ssl_ctx = nullptr; # endif /* WITH_OPENSSL */ # ifdef WITH_NSS -static void nss_error(const char* funcname) -{ - char buffer[256]; - PRInt32 length = PR_GetErrorText(buffer); - if (length > 0 && length < 256) { - std::cerr << "nss_error " << static_cast(PR_GetError()) << " in " << funcname << " : " << buffer << std::endl; +/** Detail the currently raised NSS error code if possible, and debug-log + * it with caller-provided text (typically the calling function name). */ +static void nss_error(const char* text) +{ + std::string err_name_buf; + PRErrorCode err_num = PR_GetError(); + const char *err_name = PR_ErrorToName(err_num); + PRInt32 err_len = PR_GetErrorTextLength(); + + if (err_name) { + err_name_buf << " (" << err_name << ")"; + } + + if (err_len > 0) { + char *buffer = (char *)calloc(err_len + 1, sizeof(char)); + if (buffer) { + PR_GetErrorText(buffer); + std::cerr << "nss_error " + << static_cast(err_num) + << err_name_buf + << " in " << text + << " : " + << buffer + << std::endl; + free(buffer); + } else { + std::cerr << "nss_error " + << static_cast(err_num) + << err_name_buf + << " in " << text + << " : " + << "Failed to allocate internal error buffer " + << "for detailed error text, needs " + << static_cast(err_len) << " bytes" + << std::endl; + } } else { - std::cerr << "nss_error " << static_cast(PR_GetError()) << " in " << funcname << std::endl; + /* The code above may be obsolete or not ubiquitous, try another way */ + const char *err_text = PR_ErrorToString(err_num, PR_LANGUAGE_I_DEFAULT); + if (err_text && *err_text) { + std::cerr << "nss_error " + << static_cast(err_num) + << err_name_buf + << " in " << text + << " : " + << err_text + << std::endl; + } else { + std::cerr << "nss_error " + << static_cast(err_num) + << err_name_buf + << " in " << text + << std::endl; + } } } diff --git a/clients/upsclient.c b/clients/upsclient.c index 22f05f95f2..381b1252d8 100644 --- a/clients/upsclient.c +++ b/clients/upsclient.c @@ -164,7 +164,7 @@ static HOST_CERT_t* upscli_find_host_cert(const char* hostname); /* Flag for SSL init */ static int upscli_initialized = 0; -/* 0 means no timeout in upscli_connect() */ +/* 0 means no timeout in upscli_connect(), aka built-in(blocking) default */ static struct timeval upscli_default_connect_timeout = {0, 0}; static int upscli_default_connect_timeout_initialized = 0; @@ -240,14 +240,59 @@ static char *nss_password_callback(PK11SlotInfo *slot, PRBool retry, return nsscertpasswd ? PL_strdup(nsscertpasswd) : NULL; } -static void nss_error(const char* funcname) +/** Detail the currently raised NSS error code if possible, and debug-log + * it with caller-provided text (typically the calling function name). */ +static void nss_error(const char* text) { - char buffer[SMALLBUF]; - PRInt32 length = PR_GetErrorText(buffer); - if (length > 0 && length < SMALLBUF) { - upsdebugx(1, "nss_error %ld in %s : %s", (long)PR_GetError(), funcname, buffer); - }else{ - upsdebugx(1, "nss_error %ld in %s", (long)PR_GetError(), funcname); + char err_name_buf[SMALLBUF]; + PRErrorCode err_num = PR_GetError(); + const char *err_name = PR_ErrorToName(err_num); + PRInt32 err_len = PR_GetErrorTextLength(); + + if (err_name) { + size_t len = snprintf(err_name_buf, sizeof(err_name_buf), " (%s)", err_name); + if (len > sizeof(err_name_buf) - 2) { + err_name_buf[sizeof(err_name_buf) - 2] = ')'; + err_name_buf[sizeof(err_name_buf) - 1] = '\0'; + } + } else { + err_name_buf[0] = '\0'; + } + + if (err_len > 0) { + char *buffer = (char *)calloc(err_len + 1, sizeof(char)); + if (buffer) { + PR_GetErrorText(buffer); + upsdebugx(1, "nss_error %ld%s in %s : %s", + (long)err_num, + err_name_buf, + text, + buffer); + free(buffer); + } else { + upsdebugx(1, "nss_error %ld%s in %s : " + "Failed to allocate internal error buffer " + "for detailed error text, needs %ld bytes", + (long)err_num, + err_name_buf, + text, + (long)err_len); + } + } else { + /* The code above may be obsolete or not ubiquitous, try another way */ + const char *err_text = PR_ErrorToString(err_num, PR_LANGUAGE_I_DEFAULT); + if (err_text && *err_text) { + upsdebugx(1, "nss_error %ld%s in %s : %s", + (long)err_num, + err_name_buf, + text, + err_text); + } else { + upsdebugx(1, "nss_error %ld%s in %s", + (long)err_num, + err_name_buf, + text); + } } } @@ -511,6 +556,8 @@ int upscli_init(int certverify, const char *certpath, #endif /* WITH_OPENSSL | WITH_NSS */ upscli_initialized = 1; + + upsdebugx(1, "%s: completed", __func__); return 1; } @@ -638,10 +685,38 @@ const char *upscli_strerror(UPSCONN_t *ups) upscli_errlist[ups->upserror].str, "%s", errbuf); } else { - snprintf(ups->errbuf, UPSCLI_ERRBUF_LEN, - "SSL error #%ld, message too %s to be displayed", - (long)PR_GetError(), - PR_GetErrorTextLength() > 0 ? "long" : "short"); + /* Retry with other metods before giving up, see nss_error() */ + char err_name_buf[SMALLBUF]; + PRErrorCode err_num = PR_GetError(); + const char *err_name = PR_ErrorToName(err_num), + *err_text = PR_ErrorToString(err_num, PR_LANGUAGE_I_DEFAULT); + + if (err_name) { + size_t len = snprintf(err_name_buf, sizeof(err_name_buf), " (%s)", err_name); + if (len > sizeof(err_name_buf) - 2) { + err_name_buf[sizeof(err_name_buf) - 2] = ')'; + err_name_buf[sizeof(err_name_buf) - 1] = '\0'; + } + } else { + err_name_buf[0] = '\0'; + } + + if (err_text && *err_text + && strlen(err_text) + strlen(upscli_errlist[ups->upserror].str) < UPSCLI_ERRBUF_LEN + ) { + snprintf_dynamic( + ups->errbuf, UPSCLI_ERRBUF_LEN, + upscli_errlist[ups->upserror].str, + "%s", err_text); + if (err_name && strlen(err_name_buf) + strlen(ups->errbuf) < UPSCLI_ERRBUF_LEN) { + strncat(ups->errbuf, err_name_buf, UPSCLI_ERRBUF_LEN - strlen(ups->errbuf) - 1); + } + } else { + snprintf(ups->errbuf, UPSCLI_ERRBUF_LEN, + "SSL error #%ld, message too %s to be displayed", + (long)PR_GetError(), + PR_GetErrorTextLength() > 0 ? "long" : "short"); + } } #else snprintf(ups->errbuf, UPSCLI_ERRBUF_LEN, @@ -680,16 +755,26 @@ static ssize_t upscli_select_read(const int fd, void *buf, const size_t buflen, FD_ZERO(&fds); FD_SET(fd, &fds); + upsdebugx(6, "%s: will wait on select() for up to %" PRIuMAX ".%" PRIuMAX " seconds", + __func__, (uintmax_t)d_sec, (uintmax_t)d_usec); tv.tv_sec = d_sec; tv.tv_usec = d_usec; + errno = 0; ret = select(fd + 1, &fds, NULL, NULL, &tv); if (ret < 1) { + upsdebug_with_errno(3, "%s: select() failed: %" PRIiSIZE, __func__, ret); return ret; } - return read(fd, buf, buflen); + errno = 0; + ret = read(fd, buf, buflen); + if (ret < 1) { + upsdebug_with_errno(3, "%s: read() failed: %" PRIiSIZE, __func__, ret); + } + + return ret; } #if (defined HAVE_PRAGMA_GCC_DIAGNOSTIC_PUSH_POP_BESIDEFUNC) && ( (defined HAVE_PRAGMA_GCC_DIAGNOSTIC_IGNORED_TYPE_LIMITS_BESIDEFUNC) || (defined HAVE_PRAGMA_GCC_DIAGNOSTIC_IGNORED_TAUTOLOGICAL_CONSTANT_OUT_OF_RANGE_COMPARE_BESIDEFUNC) ) @@ -755,7 +840,9 @@ static ssize_t net_read(UPSCONN_t *ups, char *buf, size_t buflen, const time_t t NULL, &tv) < 0 ) { /* select failure is fatal enough to stop retrying */ + upsdebugx(3, "%s: SSL_read and subsequent select() failed", __func__); ssl_error(ups->ssl, (ssize_t)iret); + ups->upserror = UPSCLI_ERR_SSLERR; return -1; } ssl_retries++; @@ -763,19 +850,29 @@ static ssize_t net_read(UPSCONN_t *ups, char *buf, size_t buflen, const time_t t } /* Other errors are fatal */ + upsdebugx(3, "%s: SSL_read failed: %" PRIiSIZE, __func__, (ssize_t)iret); ssl_error(ups->ssl, (ssize_t)iret); + ups->upserror = UPSCLI_ERR_SSLERR; return -1; } if (ssl_retries >= SSL_IO_MAX_RETRIES) { upslogx(LOG_ERR, "%s: SSL_read timed out after %d retries", __func__, ssl_retries); + ups->upserror = UPSCLI_ERR_SSLERR; return -1; } + + if (ret < 1) { + upsdebugx(3, "%s: SSL_read failed: %" PRIiSIZE, __func__, ret); + } # elif defined(WITH_NSS) /* WITH_OPENSSL */ /* PR_* routines deal in PRInt32 type * We might need to window our I/O if we exceed 2GB :) */ assert(buflen <= PR_INT32_MAX); ret = PR_Read(ups->ssl, buf, (PRInt32)buflen); + if (ret < 1) { + upsdebugx(3, "%s: PR_read failed: %" PRIiSIZE, __func__, ret); + } # endif /* WITH_OPENSSL | WITH_NSS*/ if (ret < 1) { @@ -783,19 +880,22 @@ static ssize_t net_read(UPSCONN_t *ups, char *buf, size_t buflen, const time_t t } return ret; - } + } /* end of: if (ups->ssl) */ #endif /* WITH_SSL */ + /* Plaintext read */ ret = upscli_select_read(ups->fd, buf, buflen, timeout, 0); /* error reading data, server disconnected? */ if (ret < 0) { + upsdebugx(3, "%s: upscli_select_read failed: %" PRIiSIZE, __func__, ret); ups->upserror = UPSCLI_ERR_READ; ups->syserrno = errno; } /* no data available, server disconnected? */ if (ret == 0) { + upsdebugx(3, "%s: upscli_select_read failed (disconnected?): %" PRIiSIZE, __func__, ret); ups->upserror = UPSCLI_ERR_SRVDISC; } @@ -820,13 +920,21 @@ static ssize_t upscli_select_write(const int fd, const void *buf, const size_t b tv.tv_sec = d_sec; tv.tv_usec = d_usec; + errno = 0; ret = select(fd + 1, NULL, &fds, NULL, &tv); if (ret < 1) { + upsdebug_with_errno(3, "%s: select() failed: %" PRIiSIZE, __func__, ret); return ret; } - return write(fd, buf, buflen); + errno = 0; + ret = write(fd, buf, buflen); + if (ret < 1) { + upsdebug_with_errno(3, "%s: write() failed: %" PRIiSIZE, __func__, ret); + } + + return ret; } #if (defined HAVE_PRAGMA_GCC_DIAGNOSTIC_PUSH_POP_BESIDEFUNC) && ( (defined HAVE_PRAGMA_GCC_DIAGNOSTIC_IGNORED_TYPE_LIMITS_BESIDEFUNC) || (defined HAVE_PRAGMA_GCC_DIAGNOSTIC_IGNORED_TAUTOLOGICAL_CONSTANT_OUT_OF_RANGE_COMPARE_BESIDEFUNC) ) @@ -886,7 +994,9 @@ static ssize_t net_write(UPSCONN_t *ups, const char *buf, size_t buflen, const t NULL, &tv) < 0 ) { /* select failure is fatal enough to stop retrying */ + upsdebugx(3, "%s: SSL_write and subsequent select() failed", __func__); ssl_error(ups->ssl, (ssize_t)iret); + ups->upserror = UPSCLI_ERR_SSLERR; return -1; } ssl_retries++; @@ -894,19 +1004,29 @@ static ssize_t net_write(UPSCONN_t *ups, const char *buf, size_t buflen, const t } /* Other errors (including iret=0) are fatal */ + upsdebugx(3, "%s: SSL_write failed: %" PRIiSIZE, __func__, (ssize_t)iret); ssl_error(ups->ssl, (ssize_t)iret); + ups->upserror = UPSCLI_ERR_SSLERR; return -1; } if (ssl_retries >= SSL_IO_MAX_RETRIES) { upslogx(LOG_ERR, "%s: SSL_write timed out after %d retries", __func__, ssl_retries); + ups->upserror = UPSCLI_ERR_SSLERR; return -1; } + + if (ret < 1) { + upsdebugx(3, "%s: SSL_write failed: %" PRIiSIZE, __func__, ret); + } # elif defined(WITH_NSS) /* WITH_OPENSSL */ /* PR_* routines deal in PRInt32 type * We might need to window our I/O if we exceed 2GB :) */ assert(buflen <= PR_INT32_MAX); ret = PR_Write(ups->ssl, buf, (PRInt32)buflen); + if (ret < 1) { + upsdebugx(3, "%s: PR_write failed: %" PRIiSIZE, __func__, ret); + } # endif /* WITH_OPENSSL | WITH_NSS */ if (ret < 1) { @@ -914,19 +1034,22 @@ static ssize_t net_write(UPSCONN_t *ups, const char *buf, size_t buflen, const t } return ret; - } + } /* end of: if (ups->ssl) */ #endif /* WITH_SSL */ + /* Plaintext write */ ret = upscli_select_write(ups->fd, buf, buflen, timeout, 0); /* error writing data, server disconnected? */ if (ret < 0) { + upsdebugx(3, "%s: upscli_select_write failed: %" PRIiSIZE, __func__, ret); ups->upserror = UPSCLI_ERR_WRITE; ups->syserrno = errno; } /* not ready for writing, server disconnected? */ if (ret == 0) { + upsdebugx(3, "%s: upscli_select_write failed (disconnected?): %" PRIiSIZE, __func__, ret); ups->upserror = UPSCLI_ERR_SRVDISC; } @@ -971,38 +1094,49 @@ static int upscli_sslinit(UPSCONN_t *ups, int verifycert) upscli_init(0, NULL, NULL, NULL); } + upsdebugx(3, "%s: Trying to STARTTLS", __func__); /* see if upsd even talks SSL/TLS */ snprintf(buf, sizeof(buf), "STARTTLS\n"); if (upscli_sendline(ups, buf, strlen(buf)) != 0) { + upsdebugx(3, "%s: STARTTLS not established, failed to send request: %s", + __func__, upscli_strerror(ups)); return -1; } if (upscli_readline(ups, buf, sizeof(buf)) != 0) { + upsdebugx(3, "%s: STARTTLS not established, failed to read response: %s", + __func__, upscli_strerror(ups)); return -1; } + if (strncmp(buf, "ERR ", 4) == 0) { + upsdebugx(3, "%s: STARTTLS not supported or init error: %s", __func__, buf); + return 0; /* not supported */ + } + if (strncmp(buf, "OK STARTTLS", 11) != 0) { + upsdebugx(3, "%s: STARTTLS not supported, unexpected response: %s", __func__, buf); return 0; /* not supported */ } - /* upsd is happy, so let's crank up the client */ + /* upsd is happy and said OK, so let's crank up the client */ # ifdef WITH_OPENSSL if (!ssl_ctx) { - upsdebugx(3, "SSL context is not available"); + upsdebugx(3, "%s: SSL context is not available", __func__); return 0; } ups->ssl = SSL_new(ssl_ctx); if (!ups->ssl) { - upsdebugx(3, "Can not create SSL socket"); + upsdebugx(3, "%s: Can not create SSL socket", __func__); return 0; } if (SSL_set_fd(ups->ssl, ups->fd) != 1) { - upsdebugx(3, "Can not bind file descriptor to SSL socket"); + upsdebugx(3, "%s: Can not bind file descriptor to SSL socket", __func__); return -1; } @@ -1047,8 +1181,8 @@ static int upscli_sslinit(UPSCONN_t *ups, int verifycert) res = SSL_connect(ups->ssl); if (res == 1) { - upsdebugx(3, "SSL connected (%s)", - SSL_get_version(ups->ssl)); + upsdebugx(3, "%s: SSL connected (%s)", + __func__, SSL_get_version(ups->ssl)); break; } @@ -1117,6 +1251,8 @@ static int upscli_sslinit(UPSCONN_t *ups, int verifycert) } } + upsdebugx(3, "%s: Succeeded to STARTTLS (OpenSSL)", __func__); + return 1; # elif defined(WITH_NSS) /* WITH_OPENSSL */ @@ -1206,6 +1342,8 @@ static int upscli_sslinit(UPSCONN_t *ups, int verifycert) return -1; } + upsdebugx(3, "%s: Succeeded to STARTTLS (NSS)", __func__); + return 1; # endif /* WITH_OPENSSL | WITH_NSS */ @@ -1765,7 +1903,7 @@ int upscli_list_next(UPSCONN_t *ups, size_t numq, const char **query, return 1; } -ssize_t upscli_sendline_timeout(UPSCONN_t *ups, const char *buf, size_t buflen, const time_t timeout) +ssize_t upscli_sendline_timeout_may_disconnect(UPSCONN_t *ups, const char *buf, size_t buflen, const time_t timeout, int may_disconnect) { ssize_t ret; @@ -1791,19 +1929,29 @@ ssize_t upscli_sendline_timeout(UPSCONN_t *ups, const char *buf, size_t buflen, ret = net_write(ups, buf, buflen, timeout); if (ret < 1) { - upscli_disconnect(ups); + if (may_disconnect) { + upsdebugx(3, "%s: net_write() returned %" PRIiSIZE ", disconnecting", __func__, ret); + upscli_disconnect(ups); + } else { + upsdebugx(3, "%s: net_write() returned %" PRIiSIZE ", keeping connection open as caller wants it", __func__, ret); + } return -1; } return 0; } +ssize_t upscli_sendline_timeout(UPSCONN_t *ups, const char *buf, size_t buflen, const time_t timeout) +{ + return upscli_sendline_timeout_may_disconnect(ups, buf, buflen, timeout, 1); +} + ssize_t upscli_sendline(UPSCONN_t *ups, const char *buf, size_t buflen) { return upscli_sendline_timeout(ups, buf, buflen, 0); } -ssize_t upscli_readline_timeout(UPSCONN_t *ups, char *buf, size_t buflen, const time_t timeout) +ssize_t upscli_readline_timeout_may_disconnect(UPSCONN_t *ups, char *buf, size_t buflen, const time_t timeout, int may_disconnect) { ssize_t ret; size_t recv; @@ -1834,7 +1982,12 @@ ssize_t upscli_readline_timeout(UPSCONN_t *ups, char *buf, size_t buflen, const ret = net_read(ups, ups->readbuf, sizeof(ups->readbuf), timeout); if (ret < 1) { - upscli_disconnect(ups); + if (may_disconnect) { + upsdebugx(3, "%s: net_read() returned %" PRIiSIZE ", disconnecting", __func__, ret); + upscli_disconnect(ups); + } else { + upsdebugx(3, "%s: net_read() returned %" PRIiSIZE ", keeping connection open as caller wants it", __func__, ret); + } return -1; } @@ -1856,6 +2009,11 @@ ssize_t upscli_readline_timeout(UPSCONN_t *ups, char *buf, size_t buflen, const return 0; } +ssize_t upscli_readline_timeout(UPSCONN_t *ups, char *buf, size_t buflen, const time_t timeout) +{ + return upscli_readline_timeout_may_disconnect(ups, buf, buflen, timeout, 1); +} + ssize_t upscli_readline(UPSCONN_t *ups, char *buf, size_t buflen) { return upscli_readline_timeout(ups, buf, buflen, DEFAULT_NETWORK_TIMEOUT); @@ -2007,6 +2165,8 @@ int upscli_splitaddr(const char *buf, char **hostname, uint16_t *port) int upscli_disconnect(UPSCONN_t *ups) { + char tmp[UPSCLI_NETBUF_LEN]; + if (!ups) { return -1; } @@ -2026,6 +2186,24 @@ int upscli_disconnect(UPSCONN_t *ups) net_write(ups, "LOGOUT\n", 7, 0); + /* Give it a bit of time to gracefully close connections, + * drain the buffer and avoid noise in logs of upsd like: + * write() failed for 127.0.0.1: Transport endpoint is not connected + */ + memset(tmp, 0, sizeof(tmp)); + if (net_read(ups, tmp, sizeof(tmp), DEFAULT_NETWORK_TIMEOUT) > 0) { + if (!strcmp(tmp, "OK Goodbye\n")) { + /* There may be trailing garbage from the buffer after the newline, not sure why */ + upsdebugx(1, "%s: We logged out, and server said '%s' nicely, as expected", __func__, tmp); + } else if (!strncmp(tmp, "OK", 2)) { + upsdebugx(1, "%s: We logged out, and server said '%s' nicely, good enough", __func__, tmp); + } else { + upsdebugx(1, "%s: We logged out, and server said '%s', not OK but oh well", __func__, tmp); + } + } else { + upsdebugx(1, "%s: We logged out, and server did not reply in a short time frame", __func__); + } + #ifdef WITH_OPENSSL if (ups->ssl) { SSL_shutdown(ups->ssl); @@ -2176,7 +2354,7 @@ void upscli_get_default_connect_timeout(struct timeval *ptv) { } int upscli_init_default_connect_timeout(const char *cli_secs, const char *config_secs, const char *default_secs) { - const char *envvar_secs, *cause = "built-in"; + const char *envvar_secs, *cause = "built-in(blocking)"; int failed = 0, applied = 0; /* First the very default: blocking connections as we always had */ diff --git a/clients/upsclient.h b/clients/upsclient.h index 84889fbeb7..e84c28c5f0 100644 --- a/clients/upsclient.h +++ b/clients/upsclient.h @@ -152,9 +152,11 @@ int upscli_list_start(UPSCONN_t *ups, size_t numq, const char **query); int upscli_list_next(UPSCONN_t *ups, size_t numq, const char **query, size_t *numa, char ***answer); +ssize_t upscli_sendline_timeout_may_disconnect(UPSCONN_t *ups, const char *buf, size_t buflen, const time_t timeout, int may_disconnect); ssize_t upscli_sendline_timeout(UPSCONN_t *ups, const char *buf, size_t buflen, const time_t timeout); ssize_t upscli_sendline(UPSCONN_t *ups, const char *buf, size_t buflen); +ssize_t upscli_readline_timeout_may_disconnect(UPSCONN_t *ups, char *buf, size_t buflen, const time_t timeout, int may_disconnect); ssize_t upscli_readline_timeout(UPSCONN_t *ups, char *buf, size_t buflen, const time_t timeout); ssize_t upscli_readline(UPSCONN_t *ups, char *buf, size_t buflen); diff --git a/docs/man/Makefile.am b/docs/man/Makefile.am index 8f48835884..7541919b04 100644 --- a/docs/man/Makefile.am +++ b/docs/man/Makefile.am @@ -733,9 +733,11 @@ INST_MAN_DEV_API_PAGES = \ upscli_list_start.$(MAN_SECTION_API) \ upscli_readline.$(MAN_SECTION_API) \ upscli_readline_timeout.$(MAN_SECTION_API) \ + upscli_readline_timeout_may_disconnect.$(MAN_SECTION_API) \ upscli_report_build_details.$(MAN_SECTION_API) \ upscli_sendline.$(MAN_SECTION_API) \ upscli_sendline_timeout.$(MAN_SECTION_API) \ + upscli_sendline_timeout_may_disconnect.$(MAN_SECTION_API) \ upscli_splitaddr.$(MAN_SECTION_API) \ upscli_splitname.$(MAN_SECTION_API) \ upscli_ssl.$(MAN_SECTION_API) \ @@ -795,9 +797,15 @@ INST_MAN_DEV_API_PAGES = \ upscli_readline_timeout.$(MAN_SECTION_API): upscli_readline.$(MAN_SECTION_API) touch $@ +upscli_readline_timeout_may_disconnect.$(MAN_SECTION_API): upscli_readline.$(MAN_SECTION_API) + touch $@ + upscli_sendline_timeout.$(MAN_SECTION_API): upscli_sendline.$(MAN_SECTION_API) touch $@ +upscli_sendline_timeout_may_disconnect.$(MAN_SECTION_API): upscli_sendline.$(MAN_SECTION_API) + touch $@ + upscli_tryconnect.$(MAN_SECTION_API): upscli_connect.$(MAN_SECTION_API) touch $@ @@ -922,7 +930,9 @@ HTML_DEV_MANS = $(INST_HTML_DEV_MANS) # Anyway it would be the same man-like page for several functions HTML_DEV_MANS_FICTION = \ upscli_readline_timeout.html \ + upscli_readline_timeout_may_disconnect.html \ upscli_sendline_timeout.html \ + upscli_sendline_timeout_may_disconnect.html \ upscli_tryconnect.html \ nutscan_scan_ip_range_snmp.html \ nutscan_scan_ip_range_xml_http.html \ @@ -930,10 +940,10 @@ HTML_DEV_MANS_FICTION = \ nutscan_scan_ip_range_ipmi.html \ nutscan_add_commented_option_to_device.html -upscli_readline_timeout.html: upscli_readline.html +upscli_readline_timeout.html upscli_readline_timeout_may_disconnect.html: upscli_readline.html test -n '$?' -a -s '$@' && rm -f $@ && ln -s $? $@ -upscli_sendline_timeout.html: upscli_sendline.html +upscli_sendline_timeout.html upscli_sendline_timeout_may_disconnect.html: upscli_sendline.html test -n '$?' -a -s '$@' && rm -f $@ && ln -s $? $@ upscli_tryconnect.html: upscli_connect.html diff --git a/docs/man/upscli_readline.txt b/docs/man/upscli_readline.txt index f6cf5b4398..579471072a 100644 --- a/docs/man/upscli_readline.txt +++ b/docs/man/upscli_readline.txt @@ -4,7 +4,8 @@ UPSCLI_READLINE(3) NAME ---- -upscli_readline, upscli_readline_timeout - Read a single response from a UPS +upscli_readline, upscli_readline_timeout, +upscli_readline_timeout_may_disconnect - Read a single response from a UPS SYNOPSIS -------- @@ -17,6 +18,10 @@ SYNOPSIS int upscli_readline_timeout(UPSCONN_t *ups, char *buf, size_t buflen, const time_t timeout); + + int upscli_readline_timeout_may_disconnect(UPSCONN_t *ups, + char *buf, size_t buflen, const time_t timeout, + int may_disconnect); ------ DESCRIPTION @@ -31,10 +36,12 @@ Some parsing of the string occurs during reception. In particular, ERR messages from linkman:upsd[8] are detected and will cause this function to return '-1'. -The difference between the two functions is that *upscli_readline_timeout()* +The difference between the three functions is that *upscli_readline_timeout()* lets the caller decide the amount of time ('timeout' seconds) after which it should give up and return, whereas *upscli_readline()* does not offer this -freedom, and uses NUT default network timeout (5 seconds). +freedom, and uses NUT default network timeout (5 seconds). Both of these +disconnect upon errors. The *upscli_readline_timeout_may_disconnect()* +further allows to enable or disable such disconnections. RETURN VALUE ------------ diff --git a/docs/man/upscli_sendline.txt b/docs/man/upscli_sendline.txt index f2f70f0034..1732edaf5b 100644 --- a/docs/man/upscli_sendline.txt +++ b/docs/man/upscli_sendline.txt @@ -4,7 +4,8 @@ UPSCLI_SENDLINE(3) NAME ---- -upscli_sendline, upscli_sendline_timeout - Send a single command to a UPS +upscli_sendline, upscli_sendline_timeout, +upscli_sendline_timeout_may_disconnect - Send a single command to a UPS SYNOPSIS -------- @@ -17,6 +18,10 @@ SYNOPSIS int upscli_sendline_timeout(UPSCONN_t *ups, const char *buf, size_t buflen, const time_t timeout); + + int upscli_sendline_timeout_may_disconnect(UPSCONN_t *ups, + const char *buf, size_t buflen, const time_t timeout, + int may_disconnect); ------ DESCRIPTION @@ -29,10 +34,12 @@ of size 'buflen' to the server. The data in 'buf' must be a fully formatted protocol command as no parsing of the buffer occurs within this function. -The difference between the two functions is that *upscli_sendline_timeout()* +The difference between the three functions is that *upscli_sendline_timeout()* lets the caller decide the amount of time ('timeout' seconds) after which it should give up and return, whereas *upscli_sendline()* does not offer this -freedom, and uses an immediate timeout (0 second). +freedom, and uses an immediate timeout (0 second). Both of these disconnect +upon errors. The *upscli_sendline_timeout_may_disconnect()* further allows +to enable or disable such disconnections. RETURN VALUE ------------ diff --git a/drivers/dstate.c b/drivers/dstate.c index d1cf9ba1bc..f8ea29356d 100644 --- a/drivers/dstate.c +++ b/drivers/dstate.c @@ -4,7 +4,7 @@ 2003 Russell Kroll 2008 Arjen de Korte 2012-2017 Arnaud Quette - 2020-2025 Jim Klimov + 2020-2026 Jim Klimov 2025 desertwitch This program is free software; you can redistribute it and/or modify @@ -396,7 +396,8 @@ static int send_to_one(conn_t *conn, const char *fmt, ...) #endif va_end(ap); - upsdebugx(2, "%s: sending %.*s", __func__, (int)strcspn(buf, "\n"), buf); + upsdebugx(2, "%s: sending (got %" PRIiSIZE " from vsnprintf): %.*s", + __func__, ret, (int)strcspn(buf, "\n"), buf); if (ret < 1) { upsdebugx(2, "%s: nothing to write", __func__); return 1; @@ -462,11 +463,11 @@ static int send_to_one(conn_t *conn, const char *fmt, ...) if ((ret < 1) || (ret != (ssize_t)buflen)) { #ifndef WIN32 upsdebug_with_errno(0, "WARNING: %s: write %" PRIuSIZE " bytes to " - "socket %d failed (ret=%" PRIiSIZE "), disconnecting.", + "socket %d failed (ret=%" PRIiSIZE "), disconnecting", __func__, buflen, (int)conn->fd, ret); #else /* WIN32 */ upsdebug_with_errno(0, "WARNING: %s: write %" PRIuSIZE " bytes to " - "handle %p failed (ret=%" PRIiSIZE "), disconnecting.", + "handle %p failed (ret=%" PRIiSIZE "), disconnecting", __func__, buflen, conn->fd, ret); #endif /* WIN32 */ upsdebugx(6, "%s: failed write: %s", __func__, buf); diff --git a/drivers/dummy-ups.c b/drivers/dummy-ups.c index ab359d987c..e618f89cfd 100644 --- a/drivers/dummy-ups.c +++ b/drivers/dummy-ups.c @@ -813,24 +813,35 @@ static int parse_data_file(TYPE_FD arg_upsfd) if (now < next_update) { - upsdebugx(1, "leaving (paused)..."); + upsdebugx(1, "%s: leaving (paused)...", __func__); return 1; } /* initialise everything, to loop back at the beginning of the file */ if (ctx == NULL) { + upsdebugx(2, "%s: (re-)initialize PCONF context", __func__); ctx = (PCONF_CTX_t *)xmalloc(sizeof(PCONF_CTX_t)); + if (!ctx) { + upsdebugx(1, "%s: failed to malloc()", __func__); + return 1; + } + upsdebugx(5, "%s: call prepare_filepath()", __func__); prepare_filepath(fn, sizeof(fn)); + + upsdebugx(5, "%s: got '%s', call pconf_init()", __func__, fn); pconf_init(ctx, upsconf_err); + upsdebugx(5, "%s: call pconf_file_begin()", __func__); if (!pconf_file_begin(ctx, fn)) fatalx(EXIT_FAILURE, "Can't open dummy-ups definition file %s: %s", fn, ctx->errmsg); /* we need this for parsing alarm instructions later */ + upsdebugx(5, "%s: call status_init()", __func__); status_init(); /* in case no ups.status does it */ + upsdebugx(5, "%s: call alarm_init()", __func__); alarm_init(); /* reset alarms at start of parsing */ } @@ -839,6 +850,7 @@ static int parse_data_file(TYPE_FD arg_upsfd) next_update = -1; /* Now start or continue parsing... */ + upsdebugx(3, "%s: proceed parsing PCONF context", __func__); while (pconf_file_next(ctx)) { if (pconf_parse_error(ctx)) @@ -849,6 +861,10 @@ static int parse_data_file(TYPE_FD arg_upsfd) } /* Check if we have something to process */ + upsdebugx(4, "%s: %s:%d: numargs:%" PRIuSIZE " token:%s", + __func__, fn, ctx->linenum, ctx->numargs, + (ctx->numargs < 1 ? "" : ctx->arglist[0]) + ); if (ctx->numargs < 1) continue; @@ -947,9 +963,12 @@ static int parse_data_file(TYPE_FD arg_upsfd) /* Cleanup parseconf if there is no pending action */ if (next_update == -1) { + upsdebugx(3, "%s: clean up PCONF context: no pending action", __func__); pconf_finish(ctx); free(ctx); ctx=NULL; } + + upsdebugx(3, "%s: leaving (finished)", __func__); return 1; } diff --git a/drivers/upsdrvctl.c b/drivers/upsdrvctl.c index 42e20ac19e..74f077a8c4 100644 --- a/drivers/upsdrvctl.c +++ b/drivers/upsdrvctl.c @@ -3,7 +3,7 @@ Copyright (C) 2001 Russell Kroll 2005 - 2017 Arnaud Quette - 2017 - 2025 Jim Klimov + 2017 - 2026 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 @@ -900,10 +900,12 @@ static void forkexec(char *const argv[], const ups_t *ups) } } + /* Block until alarm */ waitret = waitpid(pid, &wstat, 0); alarm(0); + /* Bump timeout or error counts if appropriate */ if (waitret == -1) { upslogx(LOG_WARNING, "Startup timer elapsed, continuing..."); exec_timeout++; @@ -933,7 +935,7 @@ static void forkexec(char *const argv[], const ups_t *ups) } return; - } + } /* end of pid != 0 (fork parent) part */ if (getproctag()) { char tag[SMALLBUF]; @@ -942,7 +944,7 @@ static void forkexec(char *const argv[], const ups_t *ups) } else { setproctag("child"); } - } + } /* forked, maybe */ /* child or foreground mode (no fork, e.g. single driver operation) * execute the specified binary and args into current process @@ -1009,8 +1011,10 @@ static void forkexec(char *const argv[], const ups_t *ups) } /* Wait a bit then look at driver process. - * Unlike under Linux, Windows spawn drivers directly. If the driver is alive, all is OK. - * An optimization can probably be implemented to prevent waiting so much time when all is OK. + * Unlike under Linux, Windows spawn drivers directly. + * If the driver is alive, all is OK. + * An optimization can probably be implemented + * to prevent waiting so much time when all is OK. */ /* Use the local maxstartdelay, if available */ @@ -1996,7 +2000,7 @@ int main(int argc, char **argv) if (waitret == tmp->pid) { upsdebugx(1, "Driver [%s] PID %" PRIdMAX " initially exceeded " - "maxstartdelay %d sec but has finished by now", + "maxstartdelay %d sec but has finished starting by now", tmp->upsname, (intmax_t)tmp->pid, (tmp->maxstartdelay!=-1?tmp->maxstartdelay:maxstartdelay)); tmp->exceeded_timeout = 0; @@ -2158,6 +2162,8 @@ int main(int argc, char **argv) reset_signal_flag(); upsdebugx(1, "upsdrvctl: handling signal: finished"); } +#else /* WIN32 */ + /* TOTHINK: Is there something we can do on the platform? */ #endif /* !WIN32 */ sleep(1); diff --git a/server/conf.c b/server/conf.c index 89a804b7b4..a54a357578 100644 --- a/server/conf.c +++ b/server/conf.c @@ -272,14 +272,29 @@ static int parse_upsd_conf_args(size_t numargs, char **arg) certfile = xstrdup(arg[1]); return 1; } + + if (!strcmp(arg[0], "CERTREQUEST") || !strcmp(arg[0], "CERTPATH") || !strcmp(arg[0], "CERTIDENT")) { + upsdebugx(1, "%s is not supported in this SSL build: --without-nss", arg[0]); + return 0; + } + #elif (defined WITH_NSS) /* WITH_OPENSSL */ + /* CERTPATH */ if (!strcmp(arg[0], "CERTPATH")) { free(certfile); certfile = xstrdup(arg[1]); return 1; } -#ifdef WITH_CLIENT_CERTIFICATE_VALIDATION + + if (!strcmp(arg[0], "CERTFILE")) { + upsdebugx(1, "%s is not supported in this SSL build: --without-openssl", arg[0]); + return 0; + } + + /* See below for NSS handling of `CERTIDENT ` with 2 arguments */ + +# ifdef WITH_CLIENT_CERTIFICATE_VALIDATION /* CERTREQUEST (0 | 1 | 2) */ if (!strcmp(arg[0], "CERTREQUEST")) { if (isdigit((size_t)arg[1][0])) { @@ -303,8 +318,24 @@ static int parse_upsd_conf_args(size_t numargs, char **arg) return 0; } } -#endif /* WITH_CLIENT_CERTIFICATE_VALIDATION */ -#endif /* WITH_OPENSSL | WITH_NSS */ +# else /* WITH_NSS && !WITH_CLIENT_CERTIFICATE_VALIDATION */ + if (!strcmp(arg[0], "CERTREQUEST")) { + upslogx(LOG_ERR, "CERTREQUEST is not supported in this SSL build: --with-nss --without-ssl-client-validation"); + return 0; + } +# endif /* WITH_CLIENT_CERTIFICATE_VALIDATION */ + +#else /* Neither WITH_OPENSSL nor WITH_NSS: */ + + if (!strcmp(arg[0], "CERTREQUEST") || !strcmp(arg[0], "CERTPATH") + || !strcmp(arg[0], "CERTIDENT") || !strcmp(arg[0], "CERTFILE") + || !strcmp(arg[0], "DISABLE_WEAK_SSL") + ) { + upsdebugx(1, "%s is not supported in this non-SSL build", arg[0]); + return 0; + } + +#endif /* WITH_OPENSSL | WITH_NSS */ #if defined(WITH_OPENSSL) || defined(WITH_NSS) /* DISABLE_WEAK_SSL */ @@ -350,6 +381,7 @@ static int parse_upsd_conf_args(size_t numargs, char **arg) #ifdef WITH_NSS /* CERTIDENT */ + /* Note: warning logs about rejection of the keyword for non-NSS builds is handled above */ if (!strcmp(arg[0], "CERTIDENT")) { free(certname); certname = xstrdup(arg[1]); diff --git a/server/netssl.c b/server/netssl.c index fb512beb14..56c74c04cf 100644 --- a/server/netssl.c +++ b/server/netssl.c @@ -228,42 +228,96 @@ static char *nss_password_callback(PK11SlotInfo *slot, PRBool retry, return certpasswd ? PL_strdup(certpasswd) : NULL; } +/** Detail the currently raised NSS error code if possible, and debug-log + * it with caller-provided text (typically the calling function name). */ static void nss_error(const char* text) { - char buffer[SMALLBUF]; + char err_name_buf[SMALLBUF]; PRErrorCode err_num = PR_GetError(); + const char *err_name = PR_ErrorToName(err_num); PRInt32 err_len = PR_GetErrorTextLength(); + if (err_name) { + size_t len = snprintf(err_name_buf, sizeof(err_name_buf), " (%s)", err_name); + if (len > sizeof(err_name_buf) - 2) { + err_name_buf[sizeof(err_name_buf) - 2] = ')'; + err_name_buf[sizeof(err_name_buf) - 1] = '\0'; + } + } else { + err_name_buf[0] = '\0'; + } + if (err_len > 0) { - if (err_len < SMALLBUF) { + char *buffer = (char *)calloc(err_len + 1, sizeof(char)); + if (buffer) { PR_GetErrorText(buffer); - upsdebugx(1, "nss_error %ld in %s : %s", (long)err_num, text, buffer); + upsdebugx(1, "nss_error %ld%s in %s : %s", + (long)err_num, + err_name_buf, + text, + buffer); + free(buffer); } else { - upsdebugx(1, "nss_error %ld in %s : Internal error buffer too small, needs %ld bytes", (long)err_num, text, (long)err_len); + upsdebugx(1, "nss_error %ld%s in %s : " + "Failed to allocate internal error buffer " + "for detailed error text, needs %ld bytes", + (long)err_num, + err_name_buf, + text, + (long)err_len); } } else { - upsdebugx(1, "nss_error %ld in %s", (long)PR_GetError(), text); + /* The code above may be obsolete or not ubiquitous, try another way */ + const char *err_text = PR_ErrorToString(err_num, PR_LANGUAGE_I_DEFAULT); + if (err_text && *err_text) { + upsdebugx(1, "nss_error %ld%s in %s : %s", + (long)err_num, + err_name_buf, + text, + err_text); + } else { + upsdebugx(1, "nss_error %ld%s in %s", + (long)err_num, + err_name_buf, + text); + } } } static int ssl_error(PRFileDesc *ssl, ssize_t ret) { - char buffer[256]; + char buffer[256], err_name_buf[SMALLBUF]; PRErrorCode err_num = PR_GetError(); + const char *err_name = PR_ErrorToName(err_num); PRInt32 err_len = PR_GetErrorTextLength(); - PRInt32 length; NUT_UNUSED_VARIABLE(ssl); NUT_UNUSED_VARIABLE(ret); + if (err_name) { + size_t len = snprintf(err_name_buf, sizeof(err_name_buf), " (%s)", err_name); + if (len > sizeof(err_name_buf) - 2) { + err_name_buf[sizeof(err_name_buf) - 2] = ')'; + err_name_buf[sizeof(err_name_buf) - 1] = '\0'; + } + } else { + err_name_buf[0] = '\0'; + } + if (err_len > 0) { - if (err_len < SMALLBUF) { - length = PR_GetErrorText(buffer); - upsdebugx(1, "ssl_error %ld : %*s", (long)err_num, length, buffer); + if ((size_t)err_len < sizeof(buffer)) { + PRInt32 length = PR_GetErrorText(buffer); + upsdebugx(1, "ssl_error %ld%s : %*s", (long)err_num, err_name_buf, length, buffer); } else { - upsdebugx(1, "ssl_error %ld : Internal error buffer too small, needs %ld bytes", (long)err_num, (long)err_len); + upsdebugx(1, "ssl_error %ld%s : Internal error buffer too small, needs %ld bytes", (long)err_num, err_name_buf, (long)err_len); } } else { - upsdebugx(1, "ssl_error %ld", (long)err_num); + /* The code above may be obsolete or not ubiquitous, try another way */ + const char *err_text = PR_ErrorToString(err_num, PR_LANGUAGE_I_DEFAULT); + if (err_text && *err_text) { + upsdebugx(1, "ssl_error %ld%s : %s", (long)err_num, err_name_buf, err_text); + } else { + upsdebugx(1, "ssl_error %ld%s", (long)err_num, err_name_buf); + } } return -1; @@ -353,7 +407,13 @@ void net_starttls(nut_ctype_t *client, size_t numarg, const char **arg) return; } + /* Note that after this message, the client assumes that communications + * are encrypted (no more plaintext, even if we wanted to report that + * some further SSL setup failed, e.g. due to untrusted certificates + * as seen during handshake). + */ if (!sendback(client, "OK STARTTLS\n")) { + upsdebug_with_errno(2, "%s: could not confirm the beginning of SSL ritual to prospective SSL client", __func__); return; } @@ -481,6 +541,7 @@ void net_starttls(nut_ctype_t *client, size_t numarg, const char **arg) # elif defined(WITH_NSS) /* not WITH_OPENSSL */ + upsdebugx(4, "%s: calling PR_ImportTCPSocket()", __func__); socket = PR_ImportTCPSocket(client->sock_fd); if (socket == NULL) { upslogx(LOG_ERR, "Can not initialize SSL connection"); @@ -488,6 +549,7 @@ void net_starttls(nut_ctype_t *client, size_t numarg, const char **arg) return; } + upsdebugx(4, "%s: calling SSL_ImportFD()", __func__); client->ssl = SSL_ImportFD(NULL, socket); if (client->ssl == NULL) { upslogx(LOG_ERR, "Can not initialize SSL connection"); @@ -495,6 +557,7 @@ void net_starttls(nut_ctype_t *client, size_t numarg, const char **arg) return; } + upsdebugx(4, "%s: calling SSL_SetPKCS11PinArg()", __func__); if (SSL_SetPKCS11PinArg(client->ssl, client) == -1) { upslogx(LOG_ERR, "Can not initialize SSL connection"); nss_error("net_starttls / SSL_SetPKCS11PinArg"); @@ -508,6 +571,7 @@ void net_starttls(nut_ctype_t *client, size_t numarg, const char **arg) /* Note cast to SSLAuthCertificate to prevent warning due to * bad function prototype in NSS. */ + upsdebugx(4, "%s: calling SSL_AuthCertificateHook()", __func__); status = SSL_AuthCertificateHook(client->ssl, (SSLAuthCertificate)AuthCertificate, CERT_GetDefaultCertDB()); if (status != SECSuccess) { upslogx(LOG_ERR, "Can not initialize SSL connection"); @@ -515,6 +579,7 @@ void net_starttls(nut_ctype_t *client, size_t numarg, const char **arg) return; } + upsdebugx(4, "%s: calling SSL_BadCertHook()", __func__); status = SSL_BadCertHook(client->ssl, (SSLBadCertHandler)BadCertHandler, client); if (status != SECSuccess) { upslogx(LOG_ERR, "Can not initialize SSL connection"); @@ -522,6 +587,7 @@ void net_starttls(nut_ctype_t *client, size_t numarg, const char **arg) return; } + upsdebugx(4, "%s: calling SSL_HandshakeCallback()", __func__); status = SSL_HandshakeCallback(client->ssl, (SSLHandshakeCallback)HandshakeCallback, client); if (status != SECSuccess) { upslogx(LOG_ERR, "Can not initialize SSL connection"); @@ -529,6 +595,7 @@ void net_starttls(nut_ctype_t *client, size_t numarg, const char **arg) return; } + upsdebugx(4, "%s: calling SSL_ConfigSecureServer()", __func__); status = SSL_ConfigSecureServer(client->ssl, cert, privKey, NSS_FindCertKEAType(cert)); if (status != SECSuccess) { upslogx(LOG_ERR, "Can not initialize SSL connection"); @@ -539,6 +606,7 @@ void net_starttls(nut_ctype_t *client, size_t numarg, const char **arg) #pragma GCC diagnostic pop #endif + upsdebugx(4, "%s: calling SSL_ResetHandshake()", __func__); status = SSL_ResetHandshake(client->ssl, PR_TRUE); if (status != SECSuccess) { upslogx(LOG_ERR, "Can not initialize SSL connection"); @@ -548,7 +616,22 @@ void net_starttls(nut_ctype_t *client, size_t numarg, const char **arg) /* Note: this call can generate memory leaks not resolvable * by any release function. - * Probably SSL session key object allocation. */ + * Probably SSL session key object allocation. + * + * It also seems to block indefinitely (tested a minute), + * until it decides that the handshake succeeded or failed. + * A malicious or broken client could DoS the server here. + * TOTHINK: Maybe we want to set an alarm and time-limit + * this attempt? + * TOTHINK: Process such connections or generally dialogs + * in threads? + * + * In case of certificate expectation mismatches, it can + * also block the server until the caller closes the socket + * (we rely on the client continuing the crypto-dialog + * after receiving OK STARTTLS posted above) :-\ + */ + upsdebugx(4, "%s: calling SSL_ForceHandshake()", __func__); status = SSL_ForceHandshake(client->ssl); if (status != SECSuccess) { PRErrorCode code = PR_GetError(); diff --git a/server/upsd.c b/server/upsd.c index 685ec45514..d830fcd62d 100644 --- a/server/upsd.c +++ b/server/upsd.c @@ -599,6 +599,11 @@ static void client_disconnect(nut_ctype_t *client) return; } + if (client->ssl && !client->ssl_connected) { + upsdebugx(3, "%s: semi-initialised SSL on a client, sleep a bit to flush the buffers with possible error messages", __func__); + usleep(10000); + } + upsdebugx(2, "Disconnect from %s", client->addr); shutdown(client->sock_fd, 2); @@ -1547,6 +1552,7 @@ static void mainloop(void) size_t chunk = 0; #endif /* WIN32 */ + size_t nfds_tmp_type_all, nfds_tmp_chosen; /* Report socket counts per type (driver, client...) */ size_t nfds_wanted = 0, /* Connections we looked at (some may be invalid) */ nfds_considered = 0; /* Connections we wanted to poll (but might be over maxconn limit) */ nfds_t nfds = 0; @@ -1572,8 +1578,11 @@ static void mainloop(void) #ifndef WIN32 /* scan through driver sockets */ + nfds_tmp_type_all = 0; + nfds_tmp_chosen = 0; for (ups = firstups; ups; ups = ups->next) { nfds_considered++; + nfds_tmp_type_all++; /* see if we need to (re)connect to the socket */ if (INVALID_FD(ups->sock_fd)) { @@ -1613,8 +1622,11 @@ static void mainloop(void) continue; } - upsdebugx(4, "%s: adding FD handler #%" PRIuMAX " for DRIVER [%s, FD %d]", - __func__, (uintmax_t)nfds, ups->name, ups->sock_fd); + nfds_tmp_chosen++; + upsdebugx(4, "%s: adding FD handler #%" PRIuMAX " for DRIVER (%" PRIuMAX "/%" PRIuMAX ") [%s, FD %d]", + __func__, (uintmax_t)nfds, + (uintmax_t)nfds_tmp_chosen, (uintmax_t)nfds_tmp_type_all, + ups->name, ups->sock_fd); fds[nfds].fd = ups->sock_fd; fds[nfds].events = POLLIN; @@ -1625,9 +1637,12 @@ static void mainloop(void) } /* scan through client sockets */ + nfds_tmp_type_all = 0; + nfds_tmp_chosen = 0; for (client = firstclient; client; client = cnext) { cnext = client->next; nfds_considered++; + nfds_tmp_type_all++; if (difftime(now, client->last_heard) > 60) { /* shed clients after 1 minute of inactivity */ @@ -1650,8 +1665,11 @@ static void mainloop(void) continue; } - upsdebugx(4, "%s: adding FD handler #%" PRIuMAX " for CLIENT [%s => %s, FD %d]", - __func__, (uintmax_t)nfds, client->addr, client->loginups, client->sock_fd); + nfds_tmp_chosen++; + upsdebugx(4, "%s: adding FD handler #%" PRIuMAX " for CLIENT (%" PRIuMAX "/%" PRIuMAX ") [%s => %s, FD %d]", + __func__, (uintmax_t)nfds, + (uintmax_t)nfds_tmp_chosen, (uintmax_t)nfds_tmp_type_all, + client->addr, client->loginups, client->sock_fd); fds[nfds].fd = client->sock_fd; fds[nfds].events = POLLIN; @@ -1662,8 +1680,11 @@ static void mainloop(void) } /* scan through server sockets */ + nfds_tmp_type_all = 0; + nfds_tmp_chosen = 0; for (server = firstaddr; server; server = server->next) { nfds_considered++; + nfds_tmp_type_all++; if (INVALID_FD_SOCK(server->sock_fd)) { upsdebugx(5, "%s: skip invalid SERVER listener [%s:%s, FD %d]: socket not bound", __func__, server->addr, server->port, server->sock_fd); @@ -1677,8 +1698,11 @@ static void mainloop(void) continue; } - upsdebugx(4, "%s: adding FD handler #%" PRIuMAX " for SERVER listener [%s:%s, FD %d]", - __func__, (uintmax_t)nfds, server->addr, server->port, server->sock_fd); + nfds_tmp_chosen++; + upsdebugx(4, "%s: adding FD handler #%" PRIuMAX " for SERVER listener (%" PRIuMAX "/%" PRIuMAX ") [%s:%s, FD %d]", + __func__, (uintmax_t)nfds, + (uintmax_t)nfds_tmp_chosen, (uintmax_t)nfds_tmp_type_all, + server->addr, server->port, server->sock_fd); fds[nfds].fd = server->sock_fd; fds[nfds].events = POLLIN; @@ -1755,24 +1779,29 @@ static void mainloop(void) if (ret < 0) { upslog_with_errno(LOG_ERR, "%s", __func__); + /* Sleep to avoid insane looping: */ + upsdebugx(2, "%s: polling failed: code %d; sleeping 0.1 sec and retrying the loop", __func__, ret); usleep(100000); /* 0.1 sec */ return; } + upsdebugx(2, "%s: polling returned %d hits", __func__, ret); for (i = 0; i < nfds; i++) { if (fds[i].revents & (POLLHUP|POLLERR|POLLNVAL)) { - upsdebug_with_errno(3, "%s: Disconnect %s%s due to%s%s%s", + upsdebug_with_errno(3, "%s: Disconnect %s [%s%sFD %d] due to%s%s%s", __func__, - (handler[i].type==DRIVER ? "driver " : - (handler[i].type==CLIENT ? "client " : - (handler[i].type==SERVER ? "server" : + (handler[i].type==DRIVER ? "DRIVER" : + (handler[i].type==CLIENT ? "CLIENT" : + (handler[i].type==SERVER ? "SERVER" : ""))), (handler[i].type==DRIVER ? ((upstype_t *)handler[i].data)->name : (handler[i].type==CLIENT ? ((nut_ctype_t *)handler[i].data)->addr : (handler[i].type==SERVER ? "" : ""))), + (handler[i].type==DRIVER || handler[i].type==CLIENT ? ", " : ""), + fds[i].fd, (fds[i].revents & POLLHUP ? " POLLHUP" : ""), (fds[i].revents & POLLERR ? " POLLERR" : ""), (fds[i].revents & POLLNVAL ? " POLLNVAL" : "") @@ -1826,6 +1855,21 @@ static void mainloop(void) if (fds[i].revents & POLLIN) { + upsdebugx(3, "%s: Incoming %s from %s [%s%sFD %d]", + __func__, + (handler[i].type==SERVER ? "connection" : "data"), + (handler[i].type==DRIVER ? "DRIVER" : + (handler[i].type==CLIENT ? "CLIENT" : + (handler[i].type==SERVER ? "SERVER" : + ""))), + (handler[i].type==DRIVER ? ((upstype_t *)handler[i].data)->name : + (handler[i].type==CLIENT ? ((nut_ctype_t *)handler[i].data)->addr : + (handler[i].type==SERVER ? "" : + ""))), + (handler[i].type==DRIVER || handler[i].type==CLIENT ? ", " : ""), + fds[i].fd + ); + switch(handler[i].type) { case DRIVER: @@ -1871,10 +1915,15 @@ static void mainloop(void) continue; } } + #else /* WIN32 */ + /* scan through driver sockets */ + nfds_tmp_type_all = 0; + nfds_tmp_chosen = 0; for (ups = firstups; ups; ups = ups->next) { nfds_considered++; + nfds_tmp_type_all++; /* see if we need to (re)connect to the socket */ if (INVALID_FD(ups->sock_fd)) { @@ -1907,7 +1956,7 @@ static void mainloop(void) } if (INVALID_FD(ups->read_overlapped.hEvent)) { - upsdebugx(5, "%s: skip DRIVER [%s, handle %p: event loop not bound", __func__, ups->name, ups->sock_fd); + upsdebugx(5, "%s: skip DRIVER [%s, handle %p]: event loop not bound", __func__, ups->name, ups->sock_fd); continue; } @@ -1918,8 +1967,11 @@ static void mainloop(void) continue; } - upsdebugx(4, "%s: adding FD handler #%" PRIuMAX " for DRIVER [%s, handle %p]", - __func__, (uintmax_t)nfds, ups->name, ups->sock_fd); + nfds_tmp_chosen++; + upsdebugx(4, "%s: adding FD handler #%" PRIuMAX " for DRIVER (%" PRIuMAX "/%" PRIuMAX ") [%s, handle %p]", + __func__, (uintmax_t)nfds, + (uintmax_t)nfds_tmp_chosen, (uintmax_t)nfds_tmp_type_all, + ups->name, ups->sock_fd); fds[nfds] = ups->read_overlapped.hEvent; handler[nfds].type = DRIVER; @@ -1929,9 +1981,12 @@ static void mainloop(void) } /* scan through client sockets */ + nfds_tmp_type_all = 0; + nfds_tmp_chosen = 0; for (client = firstclient; client; client = cnext) { cnext = client->next; nfds_considered++; + nfds_tmp_type_all++; if (difftime(now, client->last_heard) > 60) { /* shed clients after 1 minute of inactivity */ @@ -1958,8 +2013,11 @@ static void mainloop(void) continue; } - upsdebugx(4, "%s: adding FD handler #%" PRIuMAX " for CLIENT [%s => %s, FD %" PRIuMAX "]", - __func__, (uintmax_t)nfds, client->addr, client->loginups, (uintmax_t)client->sock_fd); + nfds_tmp_chosen++; + upsdebugx(4, "%s: adding FD handler #%" PRIuMAX " for CLIENT (%" PRIuMAX "/%" PRIuMAX ") [%s => %s, FD %" PRIuMAX "]", + __func__, (uintmax_t)nfds, + (uintmax_t)nfds_tmp_chosen, (uintmax_t)nfds_tmp_type_all, + client->addr, client->loginups, (uintmax_t)client->sock_fd); fds[nfds] = client->Event; handler[nfds].type = CLIENT; @@ -1969,8 +2027,11 @@ static void mainloop(void) } /* scan through server sockets */ + nfds_tmp_type_all = 0; + nfds_tmp_chosen = 0; for (server = firstaddr; server; server = server->next) { nfds_considered++; + nfds_tmp_type_all++; if (INVALID_FD_SOCK(server->sock_fd)) { upsdebugx(5, "%s: skip invalid SERVER listener [%s:%s, FD %" PRIuMAX "]: socket not bound", __func__, server->addr, server->port, (uintmax_t)server->sock_fd); @@ -1989,8 +2050,11 @@ static void mainloop(void) continue; } - upsdebugx(4, "%s: adding FD handler #%" PRIuMAX " for SERVER listener [%s:%s, FD %" PRIuMAX "]", - __func__, (uintmax_t)nfds, server->addr, server->port, (uintmax_t)server->sock_fd); + nfds_tmp_chosen++; + upsdebugx(4, "%s: adding FD handler #%" PRIuMAX " for SERVER listener (%" PRIuMAX "/%" PRIuMAX ") [%s:%s, FD %" PRIuMAX "]", + __func__, (uintmax_t)nfds, + (uintmax_t)nfds_tmp_chosen, (uintmax_t)nfds_tmp_type_all, + server->addr, server->port, (uintmax_t)server->sock_fd); fds[nfds] = server->Event; handler[nfds].type = SERVER; @@ -2000,8 +2064,11 @@ static void mainloop(void) } /* Wait on the read IO on named pipe */ + nfds_tmp_type_all = 0; + nfds_tmp_chosen = 0; for (conn = pipe_connhead; conn; conn = conn->next) { nfds_considered++; + nfds_tmp_type_all++; /* FIXME: derive name from conn->handle to report it. * See GetFileInformationByHandleEx() in API @@ -2018,8 +2085,10 @@ static void mainloop(void) continue; } - upsdebugx(4, "%s: adding FD handler #%" PRIuMAX " for NAMED PIPE", - __func__, (uintmax_t)nfds); + nfds_tmp_chosen++; + upsdebugx(4, "%s: adding FD handler #%" PRIuMAX " for NAMED PIPE (%" PRIuMAX "/%" PRIuMAX ")", + __func__, (uintmax_t)nfds, + (uintmax_t)nfds_tmp_chosen, (uintmax_t)nfds_tmp_type_all); fds[nfds] = conn->overlapped.hEvent; handler[nfds].type = NAMED_PIPE; handler[nfds].data = (void *)conn; @@ -2036,7 +2105,7 @@ static void mainloop(void) /* ignore listeners that we are unable to handle */ upsdebugx(5, "%s: skip handler for new NAMED PIPE connections: too many handled already", __func__); } else { - upsdebugx(4, "%s: adding FD handler #%" PRIuMAX " for new NAMED PIPE connection", + upsdebugx(4, "%s: adding FD handler #%" PRIuMAX " for new NAMED PIPE connection (1/1)", __func__, (uintmax_t)nfds); fds[nfds] = pipe_connection_overlapped.hEvent; handler[nfds].type = NAMED_PIPE; @@ -2063,6 +2132,9 @@ static void mainloop(void) /* https://docs.microsoft.com/en-us/windows/win32/api/synchapi/nf-synchapi-waitformultipleobjects * We handle whoever lights up first, one per loop cycle. + * Maybe later we will prepare and walk an array of eager + * handles, like we do in POSIX builds: + * https://github.com/networkupstools/nut/issues/3376 */ chunk = 0; if (nfds <= sysmaxconn) { @@ -2111,7 +2183,7 @@ static void mainloop(void) upsdebugx(6, "%s: wait for filedescriptors done: %" PRIu64, __func__, ret); if (ret == WAIT_TIMEOUT) { - upsdebugx(2, "%s: no data available", __func__); + upsdebugx(2, "%s: wait timed out: no data available", __func__); return; } @@ -2119,7 +2191,8 @@ static void mainloop(void) DWORD err = GetLastError(); err = err; /* remove compile time warning */ upslog_with_errno(LOG_ERR, "%s", __func__); - upsdebugx(2, "%s: wait failed: code 0x%" PRIx64, __func__, err); + /* Sleep to avoid insane looping: */ + upsdebugx(2, "%s: wait failed: code 0x%" PRIx64 "; sleeping 0.1 sec and retrying the loop", __func__, err); Sleep(100); /* 0.1 sec */ return; } @@ -2161,6 +2234,23 @@ static void mainloop(void) upsdebugx(6, "%s: requesting handler[%" PRIu64 "]", __func__, ret); upsdebugx(6, "%s: handler.type=%d handler.data=%p", __func__, handler[ret].type, handler[ret].data); + upsdebugx(3, "%s: Incoming %s from %s [%s%sarray entry %" PRIuMAX "]", + __func__, + (handler[ret].type==SERVER || (handler[ret].type==NAMED_PIPE && fds[ret] == pipe_connection_overlapped.hEvent) ? "connection" : "data"), + (handler[ret].type==DRIVER ? "DRIVER" : + (handler[ret].type==CLIENT ? "CLIENT" : + (handler[ret].type==SERVER ? "SERVER" : + (handler[ret].type==NAMED_PIPE ? "NAMED_PIPE" : + "")))), + (handler[ret].type==DRIVER ? ((upstype_t *)handler[ret].data)->name : + (handler[ret].type==CLIENT ? ((nut_ctype_t *)handler[ret].data)->addr : + (handler[ret].type==SERVER ? "" : + (handler[ret].type==NAMED_PIPE ? "" : + "")))), + (handler[ret].type==DRIVER || handler[ret].type==CLIENT ? ", " : ""), + (uintmax_t)ret + ); + switch(handler[ret].type) { case DRIVER: upsdebugx(4, "%s: calling sstate_readline() for DRIVER", __func__); @@ -2192,8 +2282,8 @@ static void mainloop(void) set_reload_flag(1); } else { - upslogx(LOG_ERR,"Unknown signal" - ); + upsdebugx(1, "Unknown signal via NAMED_PIPE: '%s'", NUT_STRARG(conn->buf)); + upslogx(LOG_ERR, "Unknown signal"); } upsdebugx(4, "%s: calling pipe_disconnect() for NAMED_PIPE", __func__);