From 98290243458f4a6d788e7b43992604c5b9c4a4cb Mon Sep 17 00:00:00 2001 From: midipix Date: Jun 11 2020 08:54:10 +0000 Subject: logging: output the service reply info. --- diff --git a/project/common.mk b/project/common.mk index 0879f14..61ce6f6 100644 --- a/project/common.mk +++ b/project/common.mk @@ -23,7 +23,7 @@ INTERNAL_SRCS = \ src/internal/toksvc_nolibc_impl.c \ src/internal/toksvc_ntaio_impl.c \ src/internal/toksvc_open_impl.c \ - src/log/toks_log_lpc_request.c \ + src/log/toks_log_lpc_message.c \ src/service/toks_service_abort.c \ src/skin/toks_skin_default.c \ diff --git a/src/daemon/toks_daemon_abort.c b/src/daemon/toks_daemon_abort.c index 3668958..e79e1b2 100644 --- a/src/daemon/toks_daemon_abort.c +++ b/src/daemon/toks_daemon_abort.c @@ -10,9 +10,13 @@ #include "toksvc_daemon_impl.h" #include "toksvc_driver_impl.h" +#include "toksvc_log_impl.h" int32_t __stdcall toks_daemon_abort(struct toks_daemon_ctx * dctx) { + toks_log_lpc_request( + dctx,&dctx->reply); + ntapi->zw_reply_port( dctx->hport_daemon, &dctx->reply.header); diff --git a/src/daemon/toks_daemon_loop.c b/src/daemon/toks_daemon_loop.c index b647def..378ecbf 100644 --- a/src/daemon/toks_daemon_loop.c +++ b/src/daemon/toks_daemon_loop.c @@ -112,6 +112,10 @@ int32_t __stdcall toks_daemon_loop(void * ctx) reply->ttyinfo.status = NT_STATUS_LPC_INVALID_CONNECTION_USAGE; } + if (svcvtbl == toks_daemon_vtbl) + toks_log_lpc_reply( + dctx,reply); + ntapi->tt_aligned_block_memset( request,0,sizeof(*request)); diff --git a/src/internal/toksvc_log_impl.h b/src/internal/toksvc_log_impl.h index dcbe78f..12469cd 100644 --- a/src/internal/toksvc_log_impl.h +++ b/src/internal/toksvc_log_impl.h @@ -52,4 +52,8 @@ void toks_log_lpc_request( struct toks_daemon_ctx *, const nt_tty_port_msg *); +void toks_log_lpc_reply( + struct toks_daemon_ctx *, + const nt_tty_port_msg *); + #endif diff --git a/src/log/toks_log_lpc_message.c b/src/log/toks_log_lpc_message.c new file mode 100644 index 0000000..43772bb --- /dev/null +++ b/src/log/toks_log_lpc_message.c @@ -0,0 +1,279 @@ +/*********************************************************/ +/* toksvc: a framework-native token broker service */ +/* Copyright (C) 2020 Z. Gilboa */ +/* Released under GPLv2 and GPLv3; see COPYING.TOKSVC. */ +/*********************************************************/ + +#include +#include + +#include +#include "toksvc_driver_impl.h" +#include "toksvc_daemon_impl.h" +#include "toksvc_log_impl.h" + +#define TOKS_OPCODE_STR(IDX) [TOKS_DAEMON_ ## IDX - TOKS_DAEMON_OPCODE_BASE] + +static const char toks_error_str[] = "#ERROR"; +static const char toks_unknown_str[] = "#UNKNOWN_OPCODE"; + +static const char toks_internal_msg[] = "internal LPC message"; +static const char toks_external_msg[] = "external LPC message"; + +static const char * toks_opcode_str[] = { + TOKS_OPCODE_STR(CONNECT) = "TOKS_DAEMON_CONNECT", + TOKS_OPCODE_STR(DISCONNECT) = "TOKS_DAEMON_DISCONNECT", + TOKS_OPCODE_STR(TTYSIGNAL) = "TOKS_DAEMON_TTYSIGNAL", + TOKS_OPCODE_STR(IPCSIGNAL) = "TOKS_DAEMON_IPCSIGNAL", + TOKS_OPCODE_STR(SIGCHLD) = "TOKS_DAEMON_SIGCHLD", + TOKS_OPCODE_STR(THREADEXIT) = "TOKS_DAEMON_THREADEXIT", + TOKS_OPCODE_STR(ACQUIRE) = "TOKS_DAEMON_ACQUIRE", + TOKS_OPCODE_STR(RELEASE) = "TOKS_DAEMON_RELEASE", + TOKS_OPCODE_STR(CANCEL) = "TOKS_DAEMON_CANCEL", + TOKS_OPCODE_STR(ABORT) = "TOKS_DAEMON_ABORT", +}; + +static const char * toks_lpc_msg_str[] = { + [NT_LPC_NEW_MESSAGE] = "NT_LPC_NEW_MESSAGE", + [NT_LPC_REQUEST] = "NT_LPC_REQUEST", + [NT_LPC_REPLY] = "NT_LPC_REPLY", + [NT_LPC_DATAGRAM] = "NT_LPC_DATAGRAM", + [NT_LPC_LOST_REPLY] = "NT_LPC_LOST_REPLY", + [NT_LPC_PORT_CLOSED] = "NT_LPC_PORT_CLOSED", + [NT_LPC_CLIENT_DIED] = "NT_LPC_CLIENT_DIED", + [NT_LPC_EXCEPTION] = "NT_LPC_EXCEPTION", + [NT_LPC_DEBUG_EVENT] = "NT_LPC_DEBUG_EVENT", + [NT_LPC_ERROR_EVENT] = "NT_LPC_ERROR_EVENT", + [NT_LPC_CONNECTION_REQUEST] = "NT_LPC_CONNECTION_REQUEST", +}; + +static const char * toks_alpc_msg_str[] = { + [NT_ALPC_REQUEST ^ 0x2000] = "NT_ALPC_REQUEST", + [NT_ALPC_CONNECTION_REQUEST ^ 0x2000] = "NT_ALPC_CONNECTION_REQUEST", +}; + +static const char * toks_lpc_msg_type_desc(unsigned msgtype) +{ + if (msgtype <= NT_LPC_CONNECTION_REQUEST) + return toks_lpc_msg_str[msgtype]; + + else if (msgtype == NT_ALPC_REQUEST) + return toks_alpc_msg_str[msgtype ^ 0x2000]; + + else if (msgtype == NT_ALPC_CONNECTION_REQUEST) + return toks_alpc_msg_str[msgtype ^ 0x2000]; + + else + return toks_error_str; +} + +static const char * toks_lpc_msg_source_desc(uintptr_t syspid) +{ + return (syspid == pe_get_current_process_id()) + ? toks_internal_msg + : toks_external_msg; +} + +static const char * toks_lpc_opcode_desc(struct toks_daemon_ctx * dctx) +{ + if ((dctx->opcode >= TOKS_DAEMON_OPCODE_BASE) + && (dctx->opcode < TOKS_DAEMON_OPCODE_CAP)) + return toks_opcode_str[dctx->opcode-TOKS_DAEMON_OPCODE_BASE]; + + return toks_unknown_str; +} + +static void toks_log_lpc_request_desc( + struct toks_daemon_ctx * dctx, + const nt_tty_port_msg * msg, + char * desc) +{ + char * ch = desc; + + ch += ntapi->sprintf( + ch, + " ::: REQUEST INFO ::: " + "msgid=%u, " + "opcode=%s", + msg->ttyinfo.msgid, + toks_lpc_opcode_desc(dctx)); + + if (dctx->opcode == TOKS_DAEMON_ACQUIRE) + if (msg->ipcinfo.ctrlsvc.keys.reserved) + ch += ntapi->sprintf( + ch, + " (tokpid=%d)", + msg->ipcinfo.ctrlsvc.keys.reserved); + + if (msg->ipcinfo.ctrlsvc.keys.key[0]) + ch += ntapi->sprintf( + ch,", refstr=``%s''", + (const char *)msg->ipcinfo.ctrlsvc.keys.key); +} + +static void toks_log_lpc_reply_desc( + struct toks_daemon_ctx * dctx, + const nt_tty_port_msg * msg, + char * desc) +{ + char * ch; + unsigned char * uch; + const unsigned int * keys; + + ch = desc; + + ch += ntapi->sprintf( + ch, + " ::: REPLY INFO ::: " + "status=0x%08x", + msg->ttyinfo.status); + + switch (dctx->opcode) { + case TOKS_DAEMON_ACQUIRE: + keys = (msg->ttyinfo.status == NT_STATUS_SUCCESS) + ? msg->ipcinfo.ipckeys : 0; + break; + + case TOKS_DAEMON_RELEASE: + keys = msg->ipcinfo.ipckeys; + break; + + default: + keys = 0; + } + + if (keys) { + ch += ntapi->sprintf(ch,", token=["); + + uch = (unsigned char *)ch; + + uch[8] = '-'; + uch[17] = '-'; + uch[26] = '-'; + uch[35] = '-'; + uch[44] = '-'; + + ntapi->tt_uint32_to_hex_utf8(keys[0],&uch[0]); + ntapi->tt_uint32_to_hex_utf8(keys[1],&uch[9]); + ntapi->tt_uint32_to_hex_utf8(keys[2],&uch[18]); + ntapi->tt_uint32_to_hex_utf8(keys[3],&uch[27]); + ntapi->tt_uint32_to_hex_utf8(keys[4],&uch[36]); + ntapi->tt_uint32_to_hex_utf8(keys[5],&uch[45]); + + ch += 6*8 + 5; + + *ch++ = ']'; + *ch = 0; + } + + if (dctx->opcode == TOKS_DAEMON_ACQUIRE) { + if (msg->ttyinfo.status == NT_STATUS_SUCCESS) { + (void)0; + + } else if (msg->ttyinfo.status == NT_STATUS_PENDING) { + ch += ntapi->sprintf(ch," (pending, queued)"); + + } else if (msg->ttyinfo.status == NT_STATUS_TIMEOUT) { + if (!dctx->request.ipcinfo.hevent) + ch += ntapi->sprintf(ch," (timeout=0, not queued)"); + else + ch += ntapi->sprintf(ch," (timeout, internal error)"); + } else { + ch += ntapi->sprintf(ch," (error, not queued)"); + } + } +} + +void toks_log_lpc_request( + struct toks_daemon_ctx * dctx, + const nt_tty_port_msg * msg) +{ + struct toks_driver_ctx * drvctx = dctx->driver_ctx; + + TOKS_LOG_LEVEL(drvctx,0); + + nt_cid cid; + char path[2048]; + char desc[1024]; + + cid.process_id = msg->header.client_id.process_id; + cid.thread_id = msg->header.client_id.thread_id; + + toks_log_get_arbitrary_process_name( + &cid,path,sizeof(path)); + + switch (msg->header.msg_type) { + case NT_LPC_REQUEST: + toks_log_lpc_request_desc( + dctx,msg,desc); + break; + + default: + desc[0] = 0; + } + + toks_log_header( + drvctx, + TOKS_LOG_ENTRY_SERVER_INFO, + "%s from %s (syspid %d, systid %d), " + "data_size=%u, msg_size=%u, " + "msg_type=%u (%s), msg_id=%u%s\n", + toks_lpc_msg_source_desc(msg->header.client_id.process_id), + toks_log_basename(path), + cid.process_id, + cid.thread_id, + msg->header.data_size, + msg->header.msg_size, + msg->header.msg_type, + toks_lpc_msg_type_desc(msg->header.msg_type), + msg->header.msg_id, + desc); + + + if (cid.process_id) + toks_log_write( + drvctx, + TOKS_LOG_ENTRY_SUB_LEVEL_2, + "%s.\n",path); +} + +void toks_log_lpc_reply( + struct toks_daemon_ctx * dctx, + const nt_tty_port_msg * msg) +{ + struct toks_driver_ctx * drvctx = dctx->driver_ctx; + + TOKS_LOG_LEVEL(drvctx,0); + + nt_cid cid; + char desc[1024]; + + cid.process_id = msg->header.client_id.process_id; + cid.thread_id = msg->header.client_id.thread_id; + + switch (dctx->request.header.msg_type) { + case NT_LPC_REQUEST: + toks_log_lpc_reply_desc( + dctx,msg,desc); + break; + + default: + desc[0] = 0; + } + + toks_log_header( + drvctx, + TOKS_LOG_ENTRY_SERVER_INFO, + "%s (syspid %d, systid %d), " + "data_size=%u, msg_size=%u, " + "msg_type=%u (%s), msg_id=%u%s\n", + toks_lpc_msg_source_desc(msg->header.client_id.process_id), + cid.process_id, + cid.thread_id, + msg->header.data_size, + msg->header.msg_size, + msg->header.msg_type, + toks_lpc_msg_type_desc(msg->header.msg_type), + msg->header.msg_id, + desc); +} diff --git a/src/log/toks_log_lpc_request.c b/src/log/toks_log_lpc_request.c deleted file mode 100644 index b007056..0000000 --- a/src/log/toks_log_lpc_request.c +++ /dev/null @@ -1,165 +0,0 @@ -/*********************************************************/ -/* toksvc: a framework-native token broker service */ -/* Copyright (C) 2020 Z. Gilboa */ -/* Released under GPLv2 and GPLv3; see COPYING.TOKSVC. */ -/*********************************************************/ - -#include -#include - -#include -#include "toksvc_driver_impl.h" -#include "toksvc_daemon_impl.h" -#include "toksvc_log_impl.h" - -#define TOKS_OPCODE_STR(IDX) [TOKS_DAEMON_ ## IDX - TOKS_DAEMON_OPCODE_BASE] - -static const char toks_error_str[] = "#ERROR"; -static const char toks_unknown_str[] = "#UNKNOWN_OPCODE"; - -static const char toks_internal_msg[] = "internal LPC message"; -static const char toks_external_msg[] = "external LPC message"; - -static const char * toks_opcode_str[] = { - TOKS_OPCODE_STR(CONNECT) = "TOKS_DAEMON_CONNECT", - TOKS_OPCODE_STR(DISCONNECT) = "TOKS_DAEMON_DISCONNECT", - TOKS_OPCODE_STR(TTYSIGNAL) = "TOKS_DAEMON_TTYSIGNAL", - TOKS_OPCODE_STR(IPCSIGNAL) = "TOKS_DAEMON_IPCSIGNAL", - TOKS_OPCODE_STR(SIGCHLD) = "TOKS_DAEMON_SIGCHLD", - TOKS_OPCODE_STR(THREADEXIT) = "TOKS_DAEMON_THREADEXIT", - TOKS_OPCODE_STR(ACQUIRE) = "TOKS_DAEMON_ACQUIRE", - TOKS_OPCODE_STR(RELEASE) = "TOKS_DAEMON_RELEASE", - TOKS_OPCODE_STR(CANCEL) = "TOKS_DAEMON_CANCEL", - TOKS_OPCODE_STR(ABORT) = "TOKS_DAEMON_ABORT", -}; - -static const char * toks_lpc_msg_str[] = { - [NT_LPC_NEW_MESSAGE] = "NT_LPC_NEW_MESSAGE", - [NT_LPC_REQUEST] = "NT_LPC_REQUEST", - [NT_LPC_REPLY] = "NT_LPC_REPLY", - [NT_LPC_DATAGRAM] = "NT_LPC_DATAGRAM", - [NT_LPC_LOST_REPLY] = "NT_LPC_LOST_REPLY", - [NT_LPC_PORT_CLOSED] = "NT_LPC_PORT_CLOSED", - [NT_LPC_CLIENT_DIED] = "NT_LPC_CLIENT_DIED", - [NT_LPC_EXCEPTION] = "NT_LPC_EXCEPTION", - [NT_LPC_DEBUG_EVENT] = "NT_LPC_DEBUG_EVENT", - [NT_LPC_ERROR_EVENT] = "NT_LPC_ERROR_EVENT", - [NT_LPC_CONNECTION_REQUEST] = "NT_LPC_CONNECTION_REQUEST", -}; - -static const char * toks_alpc_msg_str[] = { - [NT_ALPC_REQUEST ^ 0x2000] = "NT_ALPC_REQUEST", - [NT_ALPC_CONNECTION_REQUEST ^ 0x2000] = "NT_ALPC_CONNECTION_REQUEST", -}; - -static const char * toks_lpc_msg_type_desc(unsigned msgtype) -{ - if (msgtype <= NT_LPC_CONNECTION_REQUEST) - return toks_lpc_msg_str[msgtype]; - - else if (msgtype == NT_ALPC_REQUEST) - return toks_alpc_msg_str[msgtype ^ 0x2000]; - - else if (msgtype == NT_ALPC_CONNECTION_REQUEST) - return toks_alpc_msg_str[msgtype ^ 0x2000]; - - else - return toks_error_str; -} - -static const char * toks_lpc_msg_source_desc(uintptr_t syspid) -{ - return (syspid == pe_get_current_process_id()) - ? toks_internal_msg - : toks_external_msg; -} - -static const char * toks_lpc_opcode_desc(struct toks_daemon_ctx * dctx) -{ - if ((dctx->opcode >= TOKS_DAEMON_OPCODE_BASE) - && (dctx->opcode < TOKS_DAEMON_OPCODE_CAP)) - return toks_opcode_str[dctx->opcode-TOKS_DAEMON_OPCODE_BASE]; - - return toks_unknown_str; -} - -static void toks_log_lpc_request_desc( - struct toks_daemon_ctx * dctx, - const nt_tty_port_msg * msg, - char * desc) -{ - char * ch = desc; - - ch += ntapi->sprintf( - ch, - " ::: REQUEST INFO ::: " - "msgid=%u, " - "opcode=%s", - msg->ttyinfo.msgid, - toks_lpc_opcode_desc(dctx)); - - if (dctx->opcode == TOKS_DAEMON_ACQUIRE) - if (msg->ipcinfo.ctrlsvc.keys.reserved) - ch += ntapi->sprintf( - ch, - " (tokpid=%d)", - msg->ipcinfo.ctrlsvc.keys.reserved); - - if (msg->ipcinfo.ctrlsvc.keys.key[0]) - ntapi->sprintf( - ch,", refstr=``%s''", - (const char *)msg->ipcinfo.ctrlsvc.keys.key); -} - -void toks_log_lpc_request( - struct toks_daemon_ctx * dctx, - const nt_tty_port_msg * msg) -{ - struct toks_driver_ctx * drvctx = dctx->driver_ctx; - - TOKS_LOG_LEVEL(drvctx,0); - - nt_cid cid; - char path[2048]; - char desc[1024]; - - cid.process_id = msg->header.client_id.process_id; - cid.thread_id = msg->header.client_id.thread_id; - - toks_log_get_arbitrary_process_name( - &cid,path,sizeof(path)); - - switch (msg->header.msg_type) { - case NT_LPC_REQUEST: - toks_log_lpc_request_desc( - dctx,msg,desc); - break; - - default: - desc[0] = 0; - } - - toks_log_header( - drvctx, - TOKS_LOG_ENTRY_SERVER_INFO, - "%s from %s (syspid %d, systid %d), " - "data_size=%u, msg_size=%u, " - "msg_type=%u (%s), msg_id=%u%s\n", - toks_lpc_msg_source_desc(msg->header.client_id.process_id), - toks_log_basename(path), - cid.process_id, - cid.thread_id, - msg->header.data_size, - msg->header.msg_size, - msg->header.msg_type, - toks_lpc_msg_type_desc(msg->header.msg_type), - msg->header.msg_id, - desc); - - - if (cid.process_id) - toks_log_write( - drvctx, - TOKS_LOG_ENTRY_SUB_LEVEL_2, - "%s.\n",path); -}