From 162864eede94e9854d5146939f064fbf775caef1 Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Tue, 24 Mar 2026 11:27:35 +0100 Subject: [PATCH 01/25] server/upsd.c: mainloop(): report chosen/seen socket counts per type (driver, client...) [#3302] Signed-off-by: Jim Klimov --- server/upsd.c | 76 ++++++++++++++++++++++++++++++++++++++++----------- 1 file changed, 60 insertions(+), 16 deletions(-) diff --git a/server/upsd.c b/server/upsd.c index 685ec45514..ef22bb25cf 100644 --- a/server/upsd.c +++ b/server/upsd.c @@ -1547,6 +1547,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 +1573,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 +1617,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 +1632,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 +1660,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 +1675,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 +1693,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; @@ -1871,10 +1890,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 +1931,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 +1942,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 +1956,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 +1988,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 +2002,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 +2025,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 +2039,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 +2060,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 +2080,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; From 79c3de32590303e0881d489f8550426056650317 Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Thu, 26 Mar 2026 15:51:30 +0100 Subject: [PATCH 02/25] server/upsd.c: mainloop(): log how many hits polling returned (POSIX), or that it failed and we would sleep 0.1s [#3302] Signed-off-by: Jim Klimov --- server/upsd.c | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/server/upsd.c b/server/upsd.c index ef22bb25cf..0b6fc13a25 100644 --- a/server/upsd.c +++ b/server/upsd.c @@ -1774,10 +1774,13 @@ 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)) { @@ -2155,7 +2158,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; } @@ -2163,7 +2166,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; } From 4bca811098bb52042666222eb5ecc68294528c5a Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Thu, 26 Mar 2026 16:31:25 +0100 Subject: [PATCH 03/25] server/upsd.c: mainloop(): log incoming connections/data events for POSIX and WIN32, revise logging disconnect events for POSIX [#3302] Signed-off-by: Jim Klimov --- server/upsd.c | 46 ++++++++++++++++++++++++++++++++++++++++------ 1 file changed, 40 insertions(+), 6 deletions(-) diff --git a/server/upsd.c b/server/upsd.c index 0b6fc13a25..d47aa40cbb 100644 --- a/server/upsd.c +++ b/server/upsd.c @@ -1785,16 +1785,18 @@ static void mainloop(void) 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" : "") @@ -1848,6 +1850,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: @@ -2209,6 +2226,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__); @@ -2240,8 +2274,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__); From bebdabf6f7f1683cd6016ce7ec2342f500642fac Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Thu, 26 Mar 2026 15:52:19 +0100 Subject: [PATCH 04/25] server/upsd.c: mainloop(): add a comment for future rework of WIN32 loop [#3302, #3365, #3376] Signed-off-by: Jim Klimov --- server/upsd.c | 3 +++ 1 file changed, 3 insertions(+) diff --git a/server/upsd.c b/server/upsd.c index d47aa40cbb..2866526027 100644 --- a/server/upsd.c +++ b/server/upsd.c @@ -2127,6 +2127,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) { From f51f2ef2005b8145756ac225d74964056ed46eb6 Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Wed, 1 Apr 2026 15:13:40 +0200 Subject: [PATCH 05/25] drivers/upsdrvctl.c: fix broken debug message and update comments Signed-off-by: Jim Klimov --- drivers/upsdrvctl.c | 18 ++++++++++++------ 1 file changed, 12 insertions(+), 6 deletions(-) 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); From 3cfcc400dee22068ef58f84a50bfdd0d3b2a6d87 Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Wed, 25 Mar 2026 18:42:26 +0100 Subject: [PATCH 06/25] drivers/dummy-ups.c: pepper parse_data_file() with debug tracing logs [#3368] Signed-off-by: Jim Klimov --- drivers/dummy-ups.c | 21 ++++++++++++++++++++- 1 file changed, 20 insertions(+), 1 deletion(-) 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; } From b71b4d8c8058d9faa23d36f20498c51ee9e8d0d1 Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Wed, 25 Mar 2026 13:07:06 +0100 Subject: [PATCH 07/25] server/netssl.c: try to get PR_ErrorToName()/PR_ErrorToString() for actionable error messages [#3302, #1711] Signed-off-by: Jim Klimov --- server/netssl.c | 59 +++++++++++++++++++++++++++++++++++++++---------- 1 file changed, 47 insertions(+), 12 deletions(-) diff --git a/server/netssl.c b/server/netssl.c index fb512beb14..a255d7b2ff 100644 --- a/server/netssl.c +++ b/server/netssl.c @@ -228,42 +228,77 @@ 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 buffer[SMALLBUF], 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) { + if ((size_t)err_len < sizeof(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); } 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 : Internal error buffer too small, 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; From 01820e8a36b3a948fe468543471c5cd08a78bb24 Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Thu, 26 Mar 2026 14:59:40 +0100 Subject: [PATCH 08/25] server/netssl.c: nss_error(): only allocate buffer for PR_GetErrorText() when projected err_len>0, and request the right size right away Signed-off-by: Jim Klimov --- server/netssl.c | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/server/netssl.c b/server/netssl.c index a255d7b2ff..8ecbdc2763 100644 --- a/server/netssl.c +++ b/server/netssl.c @@ -232,7 +232,7 @@ static char *nss_password_callback(PK11SlotInfo *slot, PRBool retry, * it with caller-provided text (typically the calling function name). */ static void nss_error(const char* text) { - char buffer[SMALLBUF], err_name_buf[SMALLBUF]; + char err_name_buf[SMALLBUF]; PRErrorCode err_num = PR_GetError(); const char *err_name = PR_ErrorToName(err_num); PRInt32 err_len = PR_GetErrorTextLength(); @@ -248,11 +248,13 @@ static void nss_error(const char* text) } if (err_len > 0) { - if ((size_t)err_len < sizeof(buffer)) { + 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 : Internal error buffer too small, needs %ld bytes", (long)err_num, err_name_buf, 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 { /* The code above may be obsolete or not ubiquitous, try another way */ From d95498187bebe46734e4fe9f2bb71e2223443578 Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Thu, 26 Mar 2026 15:00:14 +0100 Subject: [PATCH 09/25] server/netssl.c: nss_error(): wrap printout lines to help sync with other variants of this code Signed-off-by: Jim Klimov --- server/netssl.c | 25 +++++++++++++++++++++---- 1 file changed, 21 insertions(+), 4 deletions(-) diff --git a/server/netssl.c b/server/netssl.c index 8ecbdc2763..2a0c4e59d1 100644 --- a/server/netssl.c +++ b/server/netssl.c @@ -251,18 +251,35 @@ static void nss_error(const char* text) 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); + 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); + 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); + 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); + upsdebugx(1, "nss_error %ld%s in %s", + (long)err_num, + err_name_buf, + text); } } } From b729192642e1e7ec3d621b1b627630722ebf7e0f Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Thu, 26 Mar 2026 14:35:00 +0100 Subject: [PATCH 10/25] clients/upsclient.c: resync nss_error() implementation with server/netssl.c [#3302, #1711] Signed-off-by: Jim Klimov --- clients/upsclient.c | 59 +++++++++++++++++++++++++++++++++++++++------ 1 file changed, 52 insertions(+), 7 deletions(-) diff --git a/clients/upsclient.c b/clients/upsclient.c index 22f05f95f2..980ddd6494 100644 --- a/clients/upsclient.c +++ b/clients/upsclient.c @@ -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); + } } } From 1c6e550c4463c305edfcdcc0d676972138d09228 Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Thu, 26 Mar 2026 15:00:48 +0100 Subject: [PATCH 11/25] clients/nutclient.cpp: resync nss_error() implementation with server/netssl.c [#3302, #1711] Signed-off-by: Jim Klimov --- clients/nutclient.cpp | 60 ++++++++++++++++++++++++++++++++++++++----- 1 file changed, 53 insertions(+), 7 deletions(-) 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; + } } } From a245b7e0ba98db23716608e484fad5491d247799 Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Tue, 31 Mar 2026 15:53:41 +0200 Subject: [PATCH 12/25] clients/upsclient.c: upscli_strerror(): detail NSS errors more [#3379, #3331] Signed-off-by: Jim Klimov --- clients/upsclient.c | 36 ++++++++++++++++++++++++++++++++---- 1 file changed, 32 insertions(+), 4 deletions(-) diff --git a/clients/upsclient.c b/clients/upsclient.c index 980ddd6494..e3932a9e55 100644 --- a/clients/upsclient.c +++ b/clients/upsclient.c @@ -683,10 +683,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, From d6cf1a6e88eb4859d10de32f0d8d309be007f9e6 Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Thu, 26 Mar 2026 15:27:07 +0100 Subject: [PATCH 13/25] server/conf.c: parse_upsd_conf_args(): debug-log keywords that are recognized, but pertain to another build configuration [#3331] Signed-off-by: Jim Klimov --- server/conf.c | 38 +++++++++++++++++++++++++++++++++++--- 1 file changed, 35 insertions(+), 3 deletions(-) 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]); From 7b22155f36494da3e0015fbe8819f3313cc96f3e Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Tue, 31 Mar 2026 16:06:54 +0200 Subject: [PATCH 14/25] server/netssl.c: net_starttls(): debug-trace calls into NSS, to profile their timing [#3379, #3331] Signed-off-by: Jim Klimov --- server/netssl.c | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/server/netssl.c b/server/netssl.c index 2a0c4e59d1..db7e09d426 100644 --- a/server/netssl.c +++ b/server/netssl.c @@ -407,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; } @@ -535,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"); @@ -542,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"); @@ -549,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"); @@ -562,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"); @@ -569,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"); @@ -576,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"); @@ -583,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"); @@ -593,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"); @@ -603,6 +617,7 @@ 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. */ + upsdebugx(4, "%s: calling SSL_ForceHandshake()", __func__); status = SSL_ForceHandshake(client->ssl); if (status != SECSuccess) { PRErrorCode code = PR_GetError(); From d25a1a203fc379acb138fb590e702f69de7a4250 Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Tue, 31 Mar 2026 16:35:20 +0200 Subject: [PATCH 15/25] server/netssl.c: net_starttls(): update comment about SSL_ForceHandshake() [#3331] Signed-off-by: Jim Klimov --- server/netssl.c | 16 +++++++++++++++- 1 file changed, 15 insertions(+), 1 deletion(-) diff --git a/server/netssl.c b/server/netssl.c index db7e09d426..56c74c04cf 100644 --- a/server/netssl.c +++ b/server/netssl.c @@ -616,7 +616,21 @@ 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) { From bc641322819a9d17a206bc0a7bf598e2362a465c Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Tue, 31 Mar 2026 16:55:33 +0200 Subject: [PATCH 16/25] server/upsd.c: client_disconnect(): sleep a bit if dropping a semi-initialised SSL client [#3331] Signed-off-by: Jim Klimov --- server/upsd.c | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/server/upsd.c b/server/upsd.c index 2866526027..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); From f02ca927f3939664f0e020859c2521ed3a441a01 Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Mon, 30 Mar 2026 17:18:39 +0200 Subject: [PATCH 17/25] drivers/dstate.c: send_to_one(): revise log messages [#3302] Signed-off-by: Jim Klimov --- drivers/dstate.c | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) 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); From 8fef6a5127c2a740e0ed1c37a8c4dbdc96015f0b Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Tue, 31 Mar 2026 13:59:03 +0200 Subject: [PATCH 18/25] clients/upsclient.c: pepper read/write and SSL init operations with debug messages, update comments [#3331] Signed-off-by: Jim Klimov --- clients/upsclient.c | 64 ++++++++++++++++++++++++++++++++++++++------- 1 file changed, 55 insertions(+), 9 deletions(-) diff --git a/clients/upsclient.c b/clients/upsclient.c index e3932a9e55..7287a6997f 100644 --- a/clients/upsclient.c +++ b/clients/upsclient.c @@ -556,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; } @@ -759,10 +761,16 @@ static ssize_t upscli_select_read(const int fd, void *buf, const size_t buflen, ret = select(fd + 1, &fds, NULL, NULL, &tv); if (ret < 1) { + upsdebugx(3, "%s: select() failed: %" PRIiSIZE, __func__, ret); return ret; } - return read(fd, buf, buflen); + ret = read(fd, buf, buflen); + if (ret < 1) { + upsdebugx(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) ) @@ -828,6 +836,7 @@ 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); return -1; } @@ -836,6 +845,7 @@ 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); return -1; } @@ -844,11 +854,18 @@ static ssize_t net_read(UPSCONN_t *ups, char *buf, size_t buflen, const time_t t upslogx(LOG_ERR, "%s: SSL_read timed out after %d retries", __func__, ssl_retries); 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) { @@ -856,19 +873,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; } @@ -896,10 +916,16 @@ static ssize_t upscli_select_write(const int fd, const void *buf, const size_t b ret = select(fd + 1, NULL, &fds, NULL, &tv); if (ret < 1) { + upsdebugx(3, "%s: select() failed: %" PRIiSIZE, __func__, ret); return ret; } - return write(fd, buf, buflen); + ret = write(fd, buf, buflen); + if (ret < 1) { + upsdebugx(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) ) @@ -959,6 +985,7 @@ 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); return -1; } @@ -967,6 +994,7 @@ 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); return -1; } @@ -975,11 +1003,18 @@ static ssize_t net_write(UPSCONN_t *ups, const char *buf, size_t buflen, const t upslogx(LOG_ERR, "%s: SSL_write timed out after %d retries", __func__, ssl_retries); 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) { @@ -987,19 +1022,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; } @@ -1044,18 +1082,22 @@ 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", __func__); return -1; } if (upscli_readline(ups, buf, sizeof(buf)) != 0) { + upsdebugx(3, "%s: STARTTLS not established, failed to read response", __func__); return -1; } if (strncmp(buf, "OK STARTTLS", 11) != 0) { + upsdebugx(3, "%s: STARTTLS not supported, unexpected response: %s", __func__, buf); return 0; /* not supported */ } @@ -1064,18 +1106,18 @@ static int upscli_sslinit(UPSCONN_t *ups, int verifycert) # 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; } @@ -1120,8 +1162,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; } @@ -1190,6 +1232,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 */ @@ -1279,6 +1323,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 */ From 6cf0224a5dde38a20e111232713c2ad0c5b2eb01 Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Tue, 31 Mar 2026 14:04:06 +0200 Subject: [PATCH 19/25] clients/upsclient.c: net_read()/net_write(): set ups->upserror=UPSCLI_ERR_SSLERR when (Open)SSL read/write fails during/despite retry loop [#3331] Signed-off-by: Jim Klimov --- clients/upsclient.c | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/clients/upsclient.c b/clients/upsclient.c index 7287a6997f..eac1f4ef1e 100644 --- a/clients/upsclient.c +++ b/clients/upsclient.c @@ -838,6 +838,7 @@ static ssize_t net_read(UPSCONN_t *ups, char *buf, size_t buflen, const time_t t /* 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++; @@ -847,11 +848,13 @@ 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; } @@ -987,6 +990,7 @@ static ssize_t net_write(UPSCONN_t *ups, const char *buf, size_t buflen, const t /* 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++; @@ -996,11 +1000,13 @@ 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; } From f1ff222b05e7b611b0e27c787e510b614db6de93 Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Tue, 31 Mar 2026 15:55:46 +0200 Subject: [PATCH 20/25] clients/upsclient.c: upscli_select_write()/upscli_select_read(): track and report errno from select/read/write failures more diligently [#3379, #3331] Signed-off-by: Jim Klimov --- clients/upsclient.c | 14 ++++++++++---- 1 file changed, 10 insertions(+), 4 deletions(-) diff --git a/clients/upsclient.c b/clients/upsclient.c index eac1f4ef1e..b836f64973 100644 --- a/clients/upsclient.c +++ b/clients/upsclient.c @@ -755,19 +755,23 @@ 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) { - upsdebugx(3, "%s: select() failed: %" PRIiSIZE, __func__, ret); + upsdebug_with_errno(3, "%s: select() failed: %" PRIiSIZE, __func__, ret); return ret; } + errno = 0; ret = read(fd, buf, buflen); if (ret < 1) { - upsdebugx(3, "%s: read() failed: %" PRIiSIZE, __func__, ret); + upsdebug_with_errno(3, "%s: read() failed: %" PRIiSIZE, __func__, ret); } return ret; @@ -916,16 +920,18 @@ 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) { - upsdebugx(3, "%s: select() failed: %" PRIiSIZE, __func__, ret); + upsdebug_with_errno(3, "%s: select() failed: %" PRIiSIZE, __func__, ret); return ret; } + errno = 0; ret = write(fd, buf, buflen); if (ret < 1) { - upsdebugx(3, "%s: write() failed: %" PRIiSIZE, __func__, ret); + upsdebug_with_errno(3, "%s: write() failed: %" PRIiSIZE, __func__, ret); } return ret; From 09ce833fc2d820791691bf13242a33bea3ad5ae8 Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Tue, 31 Mar 2026 15:59:08 +0200 Subject: [PATCH 21/25] clients/upsclient.c: upscli_sslinit(): track and report upscli_strerror() from read/write failures more diligently, and handle "ERR*" replies with separate logging [#3379, #3331] Signed-off-by: Jim Klimov --- clients/upsclient.c | 13 ++++++++++--- 1 file changed, 10 insertions(+), 3 deletions(-) diff --git a/clients/upsclient.c b/clients/upsclient.c index b836f64973..c556f6556d 100644 --- a/clients/upsclient.c +++ b/clients/upsclient.c @@ -1099,21 +1099,28 @@ static int upscli_sslinit(UPSCONN_t *ups, int verifycert) snprintf(buf, sizeof(buf), "STARTTLS\n"); if (upscli_sendline(ups, buf, strlen(buf)) != 0) { - upsdebugx(3, "%s: STARTTLS not established, failed to send request", __func__); + 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", __func__); + 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 From c7b49a88732782c4e4a57ff61a7cb4caa97c588a Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Tue, 31 Mar 2026 16:00:17 +0200 Subject: [PATCH 22/25] clients/upsclient.c: upscli_sendline_timeout()/upscli_readline_timeout(): report "disconnecting" explicitly [#3379] Signed-off-by: Jim Klimov --- clients/upsclient.c | 2 ++ 1 file changed, 2 insertions(+) diff --git a/clients/upsclient.c b/clients/upsclient.c index c556f6556d..9a82b52903 100644 --- a/clients/upsclient.c +++ b/clients/upsclient.c @@ -1929,6 +1929,7 @@ ssize_t upscli_sendline_timeout(UPSCONN_t *ups, const char *buf, size_t buflen, ret = net_write(ups, buf, buflen, timeout); if (ret < 1) { + upsdebugx(3, "%s: net_write() returned %" PRIiSIZE ", disconnecting", __func__, ret); upscli_disconnect(ups); return -1; } @@ -1972,6 +1973,7 @@ 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) { + upsdebugx(3, "%s: net_read() returned %" PRIiSIZE ", disconnecting", __func__, ret); upscli_disconnect(ups); return -1; } From fc6d27a0cffb316a22e354f3abde03ab3b9252eb Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Wed, 1 Apr 2026 10:01:07 +0200 Subject: [PATCH 23/25] clients/upsclient.c: update comments about "built-in(blocking)" connect timeout default [#2847] Signed-off-by: Jim Klimov --- clients/upsclient.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/clients/upsclient.c b/clients/upsclient.c index 9a82b52903..748f50a761 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; @@ -2316,7 +2316,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 */ From 6e0580b076bd61178a8a480e0b47fe92c6c314d1 Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Tue, 24 Mar 2026 16:12:32 +0100 Subject: [PATCH 24/25] clients/upsclient.c: upscli_disconnect(): after LOGOUT, let the server say OK Goodbye [#3302, #1711] Signed-off-by: Jim Klimov --- clients/upsclient.c | 20 ++++++++++++++++++++ 1 file changed, 20 insertions(+) diff --git a/clients/upsclient.c b/clients/upsclient.c index 748f50a761..8481a096b3 100644 --- a/clients/upsclient.c +++ b/clients/upsclient.c @@ -2147,6 +2147,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; } @@ -2166,6 +2168,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); From b198324f944e3fc88cee0cf64082aca87a9f991a Mon Sep 17 00:00:00 2001 From: Jim Klimov Date: Tue, 31 Mar 2026 17:22:35 +0200 Subject: [PATCH 25/25] Introduce upscli_sendline_timeout_may_disconnect() and upscli_readline_timeout_may_disconnect() [#3302] Signed-off-by: Jim Klimov --- clients/upsclient.c | 30 ++++++++++++++++++++++++------ clients/upsclient.h | 2 ++ docs/man/Makefile.am | 14 ++++++++++++-- docs/man/upscli_readline.txt | 13 ++++++++++--- docs/man/upscli_sendline.txt | 13 ++++++++++--- 5 files changed, 58 insertions(+), 14 deletions(-) diff --git a/clients/upsclient.c b/clients/upsclient.c index 8481a096b3..381b1252d8 100644 --- a/clients/upsclient.c +++ b/clients/upsclient.c @@ -1903,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; @@ -1929,20 +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) { - upsdebugx(3, "%s: net_write() returned %" PRIiSIZE ", disconnecting", __func__, ret); - 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; @@ -1973,8 +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) { - upsdebugx(3, "%s: net_read() returned %" PRIiSIZE ", disconnecting", __func__, ret); - 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; } @@ -1996,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); 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 ------------