drivers/dummy-ups.c: pepper parse_data_file() with debug tracing logs [#3368]

Signed-off-by: Jim Klimov <jimklimov+nut@gmail.com>

Author: jimklimov

drivers/dstate.c

@@ -196,11 +196,11 @@ static TYPE_FD sock_open(const char *fn)
 
 	fd = CreateNamedPipe(
 			fn,			/* pipe name */
-			PIPE_ACCESS_DUPLEX |	/* read/write access */
-			FILE_FLAG_OVERLAPPED,	/* async IO */
-			PIPE_TYPE_BYTE |
-			PIPE_READMODE_BYTE |
-			PIPE_WAIT,
+			PIPE_ACCESS_DUPLEX	/* read/write access */
+			| FILE_FLAG_OVERLAPPED,	/* async IO */
+			PIPE_TYPE_BYTE
+			| PIPE_READMODE_BYTE
+			| PIPE_WAIT,
 			PIPE_UNLIMITED_INSTANCES,	/* max. instances */
 			ST_SOCK_BUF_LEN,	/* output buffer size */
 			ST_SOCK_BUF_LEN,	/* input buffer size */
@@ -236,11 +236,20 @@ static TYPE_FD sock_open(const char *fn)
 static void sock_disconnect(conn_t *conn)
 {
 #ifndef WIN32
+	if (VALID_FD(conn->fd)) {
+		upsdebugx(4, "%s: flushing socket %d", __func__, (int)conn->fd);
+		fflush(conn->fd);
+	}
 	upsdebugx(3, "%s: disconnecting socket %d", __func__, (int)conn->fd);
 	close(conn->fd);
 #else	/* WIN32 */
 	/* FIXME NUT_WIN32_INCOMPLETE not sure if this is the right way to close a connection */
 	if (conn->read_overlapped.hEvent != INVALID_HANDLE_VALUE) {
+		if (VALID_FD(conn->fd)) {
+			upsdebugx(4, "%s: flushing named pipe handle %p", __func__, conn->fd);
+			FlushFileBuffers(conn->fd);
+		}
+		upsdebugx(4, "%s: closing not-invalid named pipe handle %p", __func__, conn->fd);
 		CloseHandle(conn->read_overlapped.hEvent);
 		conn->read_overlapped.hEvent = INVALID_HANDLE_VALUE;
 	}
@@ -326,6 +335,7 @@ static void send_to_all(const char *fmt, ...)
 		if( result == 0 ) {
 			upsdebugx(2, "%s: write failed on handle %p, disconnecting", __func__, conn->fd);
 			sock_disconnect(conn);
+			conn = NULL;
 			continue;
 		}
 		else  {
@@ -346,6 +356,7 @@ static void send_to_all(const char *fmt, ...)
 			upsdebugx(6, "%s: failed write: %s", __func__, buf);
 
 			sock_disconnect(conn);
+			conn = NULL;
 
 			/* TOTHINK: Maybe fallback elsewhere in other cases? */
 			if (ret < 0 && errno == EAGAIN && do_synchronous == -1) {
@@ -471,6 +482,7 @@ static int send_to_one(conn_t *conn, const char *fmt, ...)
 #endif	/* WIN32 */
 		upsdebugx(6, "%s: failed write: %s", __func__, buf);
 		sock_disconnect(conn);
+		conn = NULL;
 
 		/* TOTHINK: Maybe fallback elsewhere in other cases? */
 		if (ret < 0 && errno == EAGAIN && do_synchronous == -1) {
@@ -996,6 +1008,7 @@ static void sock_read(conn_t *conn)
 
 		default:
 			sock_disconnect(conn);
+			conn = NULL;
 			return;
 		}
 	}
@@ -1028,6 +1041,7 @@ static void sock_read(conn_t *conn)
 		if (is_closed) {
 			upsdebugx(1, "%s: it seems the other side has closed the connection", __func__);
 			sock_disconnect(conn);
+			conn = NULL;
 			return;
 		}
 	} else {
@@ -1041,6 +1055,7 @@ static void sock_read(conn_t *conn)
 	if( res == 0 ) {
 		upslogx(LOG_INFO, "Read error : %d",(int)GetLastError());
 		sock_disconnect(conn);
+		conn = NULL;
 		return;
 	}
 	ret = bytesRead;
@@ -1115,6 +1130,7 @@ static void sock_close(void)
 	for (conn = connhead; conn; conn = cnext) {
 		cnext = conn->next;
 		sock_disconnect(conn);
+		conn = NULL;
 	}
 
 	connhead = NULL;
@@ -1249,6 +1265,7 @@ int dstate_poll_fds(struct timeval timeout, TYPE_FD arg_extrafd)
 
 		if (conn->closing) {
 			sock_disconnect(conn);
+			conn = NULL;
 		}
 	}
 
@@ -1338,6 +1355,7 @@ int dstate_poll_fds(struct timeval timeout, TYPE_FD arg_extrafd)
 
 		if (conn->closing) {
 			sock_disconnect(conn);
+			conn = NULL;
 		}
 	}
 

drivers/dummy-ups.c

@@ -786,24 +786,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 */
 	}
 
@@ -812,6 +823,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))
@@ -822,6 +834,10 @@ static int parse_data_file(TYPE_FD arg_upsfd)
 		}
 
 		/* Check if we have something to process */
+		upsdebugx(4, "%s: %s:%d: numargs:%d token:%s",
+			__func__, fn, ctx->linenum, ctx->numargs,
+			(ctx->numargs < 1 ? "<null>" : ctx->arglist[0])
+			);
 		if (ctx->numargs < 1)
 			continue;
 
@@ -920,9 +936,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;
 }