Blame src/log/toks_log_lpc_message.c

f2a689
/*********************************************************/
f2a689
/*  toksvc: a framework-native token broker service      */
d91fa0
/*  Copyright (C) 2020  SysDeer Technologies, LLC        */
f2a689
/*  Released under GPLv2 and GPLv3; see COPYING.TOKSVC.  */
f2a689
/*********************************************************/
f2a689
f2a689
#include <psxtypes/psxtypes.h>
f2a689
#include <ntapi/nt_tty.h>
f2a689
f2a689
#include <toksvc/toksvc.h>
f2a689
#include "toksvc_driver_impl.h"
9c1f6d
#include "toksvc_daemon_impl.h"
f2a689
#include "toksvc_log_impl.h"
f2a689
cc692f
#define  TOKS_OPCODE_STR(IDX) [TOKS_DAEMON_ ## IDX - TOKS_DAEMON_OPCODE_BASE]
cc692f
295f6b
static const char toks_error_str[]      = "#ERROR";
cc692f
static const char toks_unknown_str[]    = "#UNKNOWN_OPCODE";
295f6b
15d97b
static const char toks_internal_msg[]   = "internal LPC message";
15d97b
static const char toks_external_msg[]   = "external LPC message";
15d97b
cc692f
static const char * toks_opcode_str[]   = {
cc692f
	TOKS_OPCODE_STR(CONNECT)        = "TOKS_DAEMON_CONNECT",
cc692f
	TOKS_OPCODE_STR(DISCONNECT)     = "TOKS_DAEMON_DISCONNECT",
cc692f
	TOKS_OPCODE_STR(TTYSIGNAL)      = "TOKS_DAEMON_TTYSIGNAL",
cc692f
	TOKS_OPCODE_STR(IPCSIGNAL)      = "TOKS_DAEMON_IPCSIGNAL",
cc692f
	TOKS_OPCODE_STR(SIGCHLD)        = "TOKS_DAEMON_SIGCHLD",
cc692f
	TOKS_OPCODE_STR(THREADEXIT)     = "TOKS_DAEMON_THREADEXIT",
d27132
	TOKS_OPCODE_STR(CIDQUERY)       = "TOKS_DAEMON_CIDQUERY",
cc692f
	TOKS_OPCODE_STR(ACQUIRE)        = "TOKS_DAEMON_ACQUIRE",
cc692f
	TOKS_OPCODE_STR(RELEASE)        = "TOKS_DAEMON_RELEASE",
cc692f
	TOKS_OPCODE_STR(CANCEL)         = "TOKS_DAEMON_CANCEL",
cc692f
	TOKS_OPCODE_STR(ABORT)          = "TOKS_DAEMON_ABORT",
e6c547
	TOKS_OPCODE_STR(IOCTL)          = "TOKS_DAEMON_IOCTL",
cc692f
};
cc692f
295f6b
static const char * toks_lpc_msg_str[]  = {
295f6b
	[NT_LPC_NEW_MESSAGE]            = "NT_LPC_NEW_MESSAGE",
295f6b
	[NT_LPC_REQUEST]                = "NT_LPC_REQUEST",
295f6b
	[NT_LPC_REPLY]                  = "NT_LPC_REPLY",
295f6b
	[NT_LPC_DATAGRAM]               = "NT_LPC_DATAGRAM",
295f6b
	[NT_LPC_LOST_REPLY]             = "NT_LPC_LOST_REPLY",
295f6b
	[NT_LPC_PORT_CLOSED]            = "NT_LPC_PORT_CLOSED",
295f6b
	[NT_LPC_CLIENT_DIED]            = "NT_LPC_CLIENT_DIED",
295f6b
	[NT_LPC_EXCEPTION]              = "NT_LPC_EXCEPTION",
295f6b
	[NT_LPC_DEBUG_EVENT]            = "NT_LPC_DEBUG_EVENT",
295f6b
	[NT_LPC_ERROR_EVENT]            = "NT_LPC_ERROR_EVENT",
295f6b
	[NT_LPC_CONNECTION_REQUEST]     = "NT_LPC_CONNECTION_REQUEST",
295f6b
};
295f6b
295f6b
static const char * toks_alpc_msg_str[] = {
295f6b
	[NT_ALPC_REQUEST ^ 0x2000]            = "NT_ALPC_REQUEST",
295f6b
	[NT_ALPC_CONNECTION_REQUEST ^ 0x2000] = "NT_ALPC_CONNECTION_REQUEST",
295f6b
};
295f6b
295f6b
static const char * toks_lpc_msg_type_desc(unsigned msgtype)
295f6b
{
295f6b
	if (msgtype <= NT_LPC_CONNECTION_REQUEST)
295f6b
		return toks_lpc_msg_str[msgtype];
295f6b
295f6b
	else if (msgtype == NT_ALPC_REQUEST)
295f6b
		return toks_alpc_msg_str[msgtype ^ 0x2000];
295f6b
295f6b
	else if (msgtype == NT_ALPC_CONNECTION_REQUEST)
295f6b
		return toks_alpc_msg_str[msgtype ^ 0x2000];
295f6b
295f6b
	else
295f6b
		return toks_error_str;
295f6b
}
295f6b
15d97b
static const char * toks_lpc_msg_source_desc(uintptr_t syspid)
15d97b
{
15d97b
	return (syspid == pe_get_current_process_id())
15d97b
		? toks_internal_msg
15d97b
		: toks_external_msg;
15d97b
}
15d97b
cc692f
static const char * toks_lpc_opcode_desc(struct toks_daemon_ctx * dctx)
cc692f
{
cc692f
	if ((dctx->opcode >= TOKS_DAEMON_OPCODE_BASE)
cc692f
			&& (dctx->opcode < TOKS_DAEMON_OPCODE_CAP))
cc692f
		return toks_opcode_str[dctx->opcode-TOKS_DAEMON_OPCODE_BASE];
cc692f
cc692f
	return toks_unknown_str;
cc692f
}
cc692f
cc692f
static void toks_log_lpc_request_desc(
cc692f
	struct toks_daemon_ctx * dctx,
cc692f
	const nt_tty_port_msg *  msg,
cc692f
	char *                   desc)
cc692f
{
cc692f
	char * ch = desc;
cc692f
cc692f
	ch += ntapi->sprintf(
cc692f
		ch,
cc692f
		" ::: REQUEST INFO ::: "
34069c
		"opcode=%s, "
34069c
		"opdata=%u (0x%08x)",
34069c
		toks_lpc_opcode_desc(dctx),
34069c
		msg->ttyinfo.opdata,
34069c
		msg->ttyinfo.opdata);
cc692f
cc692f
	if (dctx->opcode == TOKS_DAEMON_ACQUIRE)
8b933d
		if (msg->syncinfo.ipcsvc.keys.reserved)
cc692f
			ch += ntapi->sprintf(
cc692f
				ch,
cc692f
				" (tokpid=%d)",
8b933d
				msg->syncinfo.ipcsvc.keys.reserved);
cc692f
8b933d
	if (msg->syncinfo.ipcsvc.keys.key[0])
982902
		ch += ntapi->sprintf(
cc692f
			ch,", refstr=``%s''",
8b933d
			(const char *)msg->syncinfo.ipcsvc.keys.key);
cc692f
}
cc692f
982902
static void toks_log_lpc_reply_desc(
982902
	struct toks_daemon_ctx * dctx,
982902
	const nt_tty_port_msg *  msg,
982902
	char *                   desc)
982902
{
982902
	char *                ch;
982902
	unsigned char *       uch;
982902
	const unsigned int  * keys;
982902
982902
	ch = desc;
982902
982902
	ch += ntapi->sprintf(
982902
		ch,
982902
		" ::: REPLY INFO ::: "
982902
		"status=0x%08x",
982902
		msg->ttyinfo.status);
982902
982902
	switch (dctx->opcode) {
982902
		case TOKS_DAEMON_ACQUIRE:
982902
			keys = (msg->ttyinfo.status == NT_STATUS_SUCCESS)
8b933d
				? msg->syncinfo.ipckeys : 0;
982902
			break;
982902
982902
		case TOKS_DAEMON_RELEASE:
8b933d
			keys = msg->syncinfo.ipckeys;
982902
			break;
982902
982902
		default:
982902
			keys = 0;
982902
	}
982902
982902
	if (keys) {
982902
		ch += ntapi->sprintf(ch,", token=[");
982902
982902
		uch = (unsigned char *)ch;
982902
982902
		uch[8]  = '-';
982902
		uch[17] = '-';
982902
		uch[26] = '-';
982902
		uch[35] = '-';
982902
		uch[44] = '-';
982902
982902
		ntapi->tt_uint32_to_hex_utf8(keys[0],&uch[0]);
982902
		ntapi->tt_uint32_to_hex_utf8(keys[1],&uch[9]);
982902
		ntapi->tt_uint32_to_hex_utf8(keys[2],&uch[18]);
982902
		ntapi->tt_uint32_to_hex_utf8(keys[3],&uch[27]);
982902
		ntapi->tt_uint32_to_hex_utf8(keys[4],&uch[36]);
982902
		ntapi->tt_uint32_to_hex_utf8(keys[5],&uch[45]);
982902
982902
		ch += 6*8 + 5;
982902
982902
		*ch++ = ']';
982902
		*ch   = 0;
982902
	}
982902
982902
	if (dctx->opcode == TOKS_DAEMON_ACQUIRE) {
982902
		if (msg->ttyinfo.status == NT_STATUS_SUCCESS) {
982902
			(void)0;
982902
982902
		} else if (msg->ttyinfo.status == NT_STATUS_PENDING) {
982902
			ch += ntapi->sprintf(ch," (pending, queued)");
982902
982902
		} else if (msg->ttyinfo.status == NT_STATUS_TIMEOUT) {
8b933d
			if (!dctx->request.syncinfo.hevent)
982902
				ch += ntapi->sprintf(ch," (timeout=0, not queued)");
982902
			else
982902
				ch += ntapi->sprintf(ch," (timeout, internal error)");
982902
		} else {
982902
			ch += ntapi->sprintf(ch," (error, not queued)");
982902
		}
982902
	}
982902
}
982902
f2a689
void toks_log_lpc_request(
9c1f6d
	struct toks_daemon_ctx * dctx,
f2a689
	const nt_tty_port_msg *  msg)
f2a689
{
9c1f6d
	struct toks_driver_ctx * drvctx = dctx->driver_ctx;
9c1f6d
6c4b3b
	TOKS_LOG_LEVEL(drvctx,2);
f2a689
f2a689
	nt_cid cid;
f2a689
	char   path[2048];
cc692f
	char   desc[1024];
f2a689
f2a689
	cid.process_id = msg->header.client_id.process_id;
f2a689
	cid.thread_id  = msg->header.client_id.thread_id;
f2a689
f2a689
	toks_log_get_arbitrary_process_name(
f2a689
		&cid,path,sizeof(path));
f2a689
cc692f
	switch (msg->header.msg_type) {
cc692f
		case NT_LPC_REQUEST:
cc692f
			toks_log_lpc_request_desc(
cc692f
				dctx,msg,desc);
cc692f
			break;
cc692f
cc692f
		default:
cc692f
			desc[0] = 0;
cc692f
	}
cc692f
f2a689
	toks_log_header(
9c1f6d
		drvctx,
f2a689
		TOKS_LOG_ENTRY_SERVER_INFO,
15d97b
		"%s from %s (syspid %d, systid %d), "
f2a689
		"data_size=%u, msg_size=%u, "
cc692f
		"msg_type=%u (%s), msg_id=%u%s\n",
15d97b
		toks_lpc_msg_source_desc(msg->header.client_id.process_id),
f2a689
		toks_log_basename(path),
f2a689
		cid.process_id,
f2a689
		cid.thread_id,
f2a689
		msg->header.data_size,
f2a689
		msg->header.msg_size,
f2a689
		msg->header.msg_type,
295f6b
		toks_lpc_msg_type_desc(msg->header.msg_type),
cc692f
		msg->header.msg_id,
cc692f
		desc);
cc692f
f2a689
f2a689
	if (cid.process_id)
f2a689
		toks_log_write(
9c1f6d
			drvctx,
f2a689
			TOKS_LOG_ENTRY_SUB_LEVEL_2,
f2a689
			"%s.\n",path);
f2a689
}
982902
6c4b3b
static void toks_log_lpc_reply_impl(
982902
	struct toks_daemon_ctx * dctx,
982902
	const nt_tty_port_msg *  msg)
982902
{
982902
	struct toks_driver_ctx * drvctx = dctx->driver_ctx;
982902
6c4b3b
	TOKS_LOG_LEVEL(drvctx,2);
982902
982902
	nt_cid cid;
982902
	char   desc[1024];
982902
982902
	cid.process_id = msg->header.client_id.process_id;
982902
	cid.thread_id  = msg->header.client_id.thread_id;
982902
982902
	switch (dctx->request.header.msg_type) {
982902
		case NT_LPC_REQUEST:
982902
			toks_log_lpc_reply_desc(
982902
				dctx,msg,desc);
982902
			break;
982902
982902
		default:
982902
			desc[0] = 0;
982902
	}
982902
982902
	toks_log_header(
982902
		drvctx,
982902
		TOKS_LOG_ENTRY_SERVER_INFO,
982902
		"%s (syspid %d, systid %d), "
982902
		"data_size=%u, msg_size=%u, "
982902
		"msg_type=%u (%s), msg_id=%u%s\n",
982902
		toks_lpc_msg_source_desc(msg->header.client_id.process_id),
982902
		cid.process_id,
982902
		cid.thread_id,
982902
		msg->header.data_size,
982902
		msg->header.msg_size,
982902
		msg->header.msg_type,
982902
		toks_lpc_msg_type_desc(msg->header.msg_type),
982902
		msg->header.msg_id,
982902
		desc);
6c4b3b
}
6c4b3b
6c4b3b
void toks_log_lpc_reply(
6c4b3b
	struct toks_daemon_ctx * dctx,
6c4b3b
	const nt_tty_port_msg *  msg)
6c4b3b
{
6c4b3b
	struct toks_driver_ctx * drvctx = dctx->driver_ctx;
6c4b3b
	int                      opdata = msg->ttyinfo.opdata;
6c4b3b
6c4b3b
	TOKS_LOG_LEVEL(drvctx,1);
6c4b3b
6c4b3b
	toks_log_lpc_reply_impl(dctx,msg);
bb0371
bb0371
	if (dctx->opcode == TOKS_DAEMON_IOCTL) {
bb0371
		if (opdata == TOKS_IOCTL_SET_TOKEN_COUNT)
bb0371
			toks_log_service_info(dctx);
bb0371
	}
982902
}