Changes to RPC object logging and Node config

- Move config from Python to Node
- Also log responses
- Only log request/response object properties in Node, as logging them
in both Node and Python is redundant
- Error-out if Node listen config is missing
- For convenience, make PeerClient copy setting properties from
ClientManager instead of referencing them

matrix_appservice_kakaotalk/config.py

@@ -117,7 +117,6 @@ class Config(BaseBridgeConfig):
         else:
             copy("rpc.connection.host")
             copy("rpc.connection.port")
-        copy("rpc.logging_keys")
 
     def _get_permissions(self, key: str) -> tuple[bool, bool, bool, str]:
         level = self["bridge.permissions"].get(key, "")

matrix_appservice_kakaotalk/example-config.yaml

@@ -252,11 +252,6 @@ rpc:
         # Only for type: tcp
         host: localhost
         port: 29392
-    # Command arguments to print in logs. Optional.
-    # TODO Support nested arguments, like channel_props.ktid
-    logging_keys:
-    - mxid
-    #- channel_props
 
 # Python logging configuration.
 #

matrix_appservice_kakaotalk/rpc/rpc.py

@@ -86,7 +86,6 @@ class RPCClient:
     _is_connected: CancelableEvent
     _is_disconnected: CancelableEvent
     _connection_lock: asyncio.Lock
-    _logging_keys: list[str]
 
     def __init__(self, config: Config, register_config_key: str) -> None:
         self.config = config
@@ -106,7 +105,6 @@ class RPCClient:
         self._is_disconnected = CancelableEvent(self.loop)
         self._is_disconnected.set()
         self._connection_lock = asyncio.Lock()
-        self._logging_keys = config["rpc.logging_keys"]
 
     async def connect(self) -> None:
         async with self._connection_lock:
@@ -149,8 +147,7 @@ class RPCClient:
         self._read_task = self.loop.create_task(self._try_read_loop())
         await self._raw_request("register",
                                 peer_id=self.config["appservice.address"],
-                                register_config=self.config[self.register_config_key],
-                                logging_keys=self._logging_keys)
+                                register_config=self.config[self.register_config_key])
         self._is_connected.set()
         self._is_disconnected.clear()
 
@@ -250,6 +247,7 @@ class RPCClient:
             self.log.debug(f"Nobody waiting for response to {req_id}")
             return
         if command == "response":
+            self.log.debug("Received response %d", req_id)
             waiter.set_result(req.get("response"))
         elif command == "error":
             waiter.set_exception(RPCError(req.get("error", line)))
@@ -305,10 +303,7 @@ class RPCClient:
         req_id = self._next_req_id
         future = self._response_waiters[req_id] = self.loop.create_future()
         req = {"id": req_id, "command": command, **data}
-        self.log.debug("Request %d: %s", req_id,
-                       ', '.join(
-                           [command] +
-                           [f"{k}: {data[k]}" for k in self._logging_keys if k in data]))
+        self.log.debug("Request %d: %s", req_id, command)
         assert self._writer is not None
         self._writer.write(json.dumps(req).encode("utf-8"))
         self._writer.write(b"\n")

node/README.md

@@ -3,5 +3,8 @@ If `type` is `unix`, `path` is the path where to create the socket, and `force`
 
 If `type` is `tcp`, `port` and `host` are the host/port where to listen.
 
-### Register timeout
+### Register timeout config
 `register_timeout` is the amount of time (in milliseconds) that a connecting peer must send a "register" command after initiating a connection.
+
+### Logging config
+`logging_keys` specifies which properties of RPC request & response objects to print in logs. Optional.

node/example-config-docker.json

@@ -3,5 +3,10 @@
 		"type": "unix",
 		"path": "/data/rpc.sock",
 		"force": true
+	},
+	"register_timeout": 3000,
+	"logging_keys": {
+		"request": ["mxid"],
+		"response": ["status"]
 	}
 }

node/example-config.json

@@ -4,5 +4,9 @@
 		"path": "/var/run/matrix-appservice-kakaotalk/rpc.sock",
 		"force": false
 	},
-	"register_timeout": 3000
+	"register_timeout": 3000,
+	"logging_keys": {
+		"request": ["mxid"],
+		"response": ["status"]
+	}
 }

node/src/client.js

@@ -425,6 +425,9 @@ export default class PeerClient {
 	 */
 	constructor(manager, socket, connID) {
 		this.manager = manager
+		this.registerTimeout = manager.registerTimeout
+		this.loggingKeys = manager.loggingKeys
+
 		this.socket = socket
 		this.connID = connID
 
@@ -433,8 +436,6 @@ export default class PeerClient {
 		this.maxCommandID = 0
 		this.peerID = ""
 		this.deviceName = "KakaoTalk Bridge"
-		/** @type {[string]} */
-		this.loggingKeys = []
 		/** @type {Map<string, UserClient>} */
 		this.userClients = new Map()
 	}
@@ -465,10 +466,10 @@ export default class PeerClient {
 
 		setTimeout(() => {
 			if (!this.peerID && !this.stopped) {
-				this.log(`Didn't receive register request within ${this.manager.registerTimeout/1000} seconds, terminating`)
+				this.log(`Didn't receive register request within ${this.registerTimeout/1000} seconds, terminating`)
 				this.stop("Register request timeout")
 			}
-		}, this.manager.registerTimeout)
+		}, this.registerTimeout)
 	}
 
 	async stop(error = null) {
@@ -1194,12 +1195,10 @@ export default class PeerClient {
 	 * @param {string} req.peer_id
 	 * @param {Object} req.register_config
 	 * @param {string} req.register_config.device_name
-	 * @param {?[string]} req.logging_keys
 	 */
 	handleRegister = async (req) => {
 		this.peerID = req.peer_id
 		this.deviceName = req.register_config.device_name || this.deviceName
-		this.loggingKeys = req.logging_keys || this.loggingKeys
 		this.log(`Registered socket ${this.connID} -> ${this.peerID}`)
 		if (this.manager.clients.has(this.peerID)) {
 			const oldClient = this.manager.clients.get(this.peerID)
@@ -1230,12 +1229,7 @@ export default class PeerClient {
 			this.log("Ignoring old request", req.id)
 			return
 		}
-		this.log(
-			`Request ${req.id}:`,
-			[req.command].concat(
-				this.loggingKeys.filter(k => k in req).map(k => `${k}: ${JSON.stringify(req[k], this.#writeReplacer)}`))
-			.join(', ')
-		)
+		this.log(`Request ${req.id}:`, this.#logObj(req, req.command, this.loggingKeys.request))
 		this.maxCommandID = req.id
 		let handler
 		if (!this.peerID) {
@@ -1306,17 +1300,40 @@ export default class PeerClient {
 				resp.command = "error"
 				if (err instanceof ProtocolError) {
 					resp.error = err.message
+					this.error(`Response ${resp.id}: ${err.message}`)
 				} else {
 					resp.error = err.toString()
-					this.log(`Error handling request ${resp.id} ${err.stack}`)
+					this.error(`Response ${resp.id}: ${err.stack}`)
 				}
 			}
 		}
-		// TODO Check if session is broken. If it is, close the PeerClient
+		if (resp.response) {
+			const success = resp.response.success !== false
+			const logger = (success ? this.log : this.error).bind(this)
+			logger(
+				`Response ${resp.id}:`,
+				this.#logObj(
+					resp.response,
+					success ? "success" : "failure",
+					this.loggingKeys.response
+				)
+			)
+		}
 		await this.write(resp)
 	}
 
-	#writeReplacer = function(key, value) {
+	/**
+	 * @param {object} obj
+	 * @param {string} desc
+	 * @param {[string]} keys
+	 */
+	#logObj(obj, desc, keys) {
+		return [desc].concat(
+			keys.filter(key => key in obj).map(key => `${key}: ${JSON.stringify(obj[key], this.#writeReplacer)}`)
+		).join(', ')
+	}
+
+	#writeReplacer(key, value) {
 		if (value instanceof Long) {
 			return value.toString()
 		} else {
@@ -1324,7 +1341,7 @@ export default class PeerClient {
 		}
 	}
 
-	#readReviver = function(key, value) {
+	#readReviver(key, value) {
 		if (value instanceof Object) {
 			// TODO Use a type map if there will be many possible types
 			if (value.__type__ == "Long") {

node/src/clientmanager.js

@@ -20,11 +20,33 @@ import path from "path"
 import PeerClient from "./client.js"
 import { promisify } from "./util.js"
 
+/**
+ * @typedef {object} ListenConfig
+ * @property {string} type
+ * @property {string} path
+ * @property {boolean} force
+ */
+
+/**
+ * @typedef {object} LoggingKeys
+ * @property {[string]} request
+ * @property {[string]} response
+ */
+
 
 export default class ClientManager {
-	constructor(listenConfig, registerTimeout) {
+	/**
+	 * @param {ListenConfig} listenConfig
+	 * @param {number} registerTimeout
+	 * @param {?LoggingKeys} loggingKeys
+	 */
+	constructor(listenConfig, registerTimeout, loggingKeys) {
+		if (!listenConfig) {
+			throw new Error("Listen config missing")
+		}
 		this.listenConfig = listenConfig
 		this.registerTimeout = registerTimeout || 3000
+		this.loggingKeys = loggingKeys || {request: [], response: []}
 		this.server = net.createServer(this.acceptConnection)
 		this.connections = []
 		this.clients = new Map()
@@ -43,7 +65,7 @@ export default class ClientManager {
 		} else {
 			const connID = this.connIDSequence++
 			this.connections[connID] = sock
-			new PeerClient(this, sock, connID).start()
+			new PeerClient(this, sock, connID, this.loggingKeys).start()
 		}
 	}
 

node/src/main.js

@@ -32,7 +32,11 @@ const configPath = args["--config"] || "config.json"
 console.log("[Main] Reading config from", configPath)
 const config = JSON.parse(fs.readFileSync(configPath).toString())
 
-const manager = new ClientManager(config.listen, config.register_timeout)
+const manager = new ClientManager(
+	config.listen,
+	config.register_timeout,
+	config.logging_keys
+)
 
 function stop() {
 	manager.stop().then(() => {