fair/matrix-puppeteer-line
fair
/
matrix-puppeteer-line
3
0
Fork 3
Code Issues 26 Pull Requests 2 Projects Releases Wiki Activity

Separate the logging #27

Open
lecris wants to merge 6 commits from lecris/matrix-puppeteer-line:logger into testing
pull from: lecris/matrix-puppeteer-line:logger
merge into: fair:testing
Conversation 1 Commits 6 Files Changed 7 +286 -267
7 changed files with 286 additions and 267 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
puppet/package.json
View File

@ -21,7 +21,9 @@
"arg": "^4.1.3",
"chrono-node": "^2.1.7",
"systemd-daemon": "^1.1.2",
"puppeteer": "9.1.1"
"puppeteer": "9.1.1",
"loglevel": "^1.7.1",
"loglevel-plugin-prefix": "^0.8.4"
},
"devDependencies": {
"babel-eslint": "^10.1.0",

16
puppet/src/api.js
View File

@ -16,6 +16,7 @@
import net from "net"
import fs from "fs"
import path from "path"
import logger from "loglevel";
import Client from "./client.js"
import { promisify } from "./util.js"
@ -29,10 +30,7 @@ export default class PuppetAPI {
this.clients = new Map()
this.connIDSequence = 0
this.stopped = false
}
log(...text) {
console.log("[API]", ...text)
this.log = logger.getLogger("API")
}
acceptConnection = sock => {
@ -57,16 +55,16 @@ export default class PuppetAPI {
} catch (err) {}
await promisify(cb => this.server.listen(socketPath, cb))
await fs.promises.chmod(socketPath, 0o700)
this.log("Now listening at", socketPath)
this.log.info("Now listening at", socketPath)
}
async startTCP(port, host) {
await promisify(cb => this.server.listen(port, host, cb))
this.log(`Now listening at ${host || ""}:${port}`)
this.log.info(`Now listening at ${host || ""}:${port}`)
}
async start() {
this.log("Starting server")
this.log.info("Starting server")
if (this.listenConfig.type === "unix") {
await this.startUnix(this.listenConfig.path)
@ -84,14 +82,14 @@ export default class PuppetAPI {
socket.end()
socket.destroy()
}
this.log("Stopping server")
this.log.info("Stopping server")
await promisify(cb => this.server.close(cb))
if (this.listenConfig.type === "unix") {
try {
await fs.promises.unlink(this.listenConfig.path)
} catch (err) {}
}
this.log("Stopping puppets")
this.log.info("Stopping puppets")
for (const puppet of this.puppets.values()) {
await puppet.stop()
}

69
puppet/src/client.js
View File

@ -15,6 +15,7 @@
// along with this program. If not, see <https://www.gnu.org/licenses/>.
import MessagesPuppeteer from "./puppet.js"
import {emitLines, promisify} from "./util.js"
import logger from "loglevel";
export default class Client {
/**
@ -28,31 +29,27 @@ export default class Client {
this.manager = manager
this.socket = socket
this.connID = connID
this.userID = userID
this.puppet = puppet
this.stopped = false
this.notificationID = 0
this.maxCommandID = 0
}
log(...text) {
if (this.userID) {
console.log(`[API/${this.userID}/${this.connID}]`, ...text)
} else {
console.log(`[API/${this.connID}]`, ...text)
this.set_userID(userID)
if (!this.userID) {
this.log = logger.getLogger(`API/${this.connID}`)
this.log.setLevel(logger.getLogger("API").getLevel())
}
}
error(...text) {
set_userID(ID) {
this.userID = ID
if (this.userID) {
console.error(`[API/${this.userID}/${this.connID}]`, ...text)
} else {
console.error(`[API/${this.connID}]`, ...text)
this.log = logger.getLogger(`API/${this.userID}/${this.connID}`)
this.log.setLevel(logger.getLogger(`API/${this.connID}`).getLevel())
}
}
start() {
this.log("Received connection", this.connID)
this.log.info("Received connection", this.connID)
emitLines(this.socket)
this.socket.on("line", line => this.handleLine(line)
.catch(err => this.log("Error handling line:", err)))
@ -60,7 +57,7 @@ export default class Client {
setTimeout(() => {
if (!this.userID && !this.stopped) {
this.log("Didn't receive register request within 3 seconds, terminating")
this.log.warn("Didn't receive register request within 3 seconds, terminating")
this.stop("Register request timeout")
}
}, 3000)
@ -75,7 +72,7 @@ export default class Client {
await this._write({id: --this.notificationID, command: "quit", error})
await promisify(cb => this.socket.end(cb))
} catch (err) {
this.error("Failed to end connection:", err)
this.log.error("Failed to end connection:", err)
this.socket.destroy(err)
}
}
@ -85,7 +82,7 @@ export default class Client {
if (this.userID && this.manager.clients.get(this.userID) === this) {
this.manager.clients.delete(this.userID)
}
this.log(`Connection closed (user: ${this.userID})`)
this.log.info(`Connection closed (user: ${this.userID})`)
}
/**
@ -99,7 +96,7 @@ export default class Client {
}
sendMessage(message) {
this.log(`Sending message ${message.id || "with no ID"} to client`)
this.log.debug(`Sending message ${message.id || "with no ID"} to client`)
return this._write({
id: --this.notificationID,
command: "message",
@ -109,7 +106,7 @@ export default class Client {
}
sendReceipt(receipt) {
this.log(`Sending read receipt (${receipt.count || "DM"}) of msg ${receipt.id} for chat ${receipt.chat_id}`)
this.log.debug(`Sending read receipt (${receipt.count || "DM"}) of msg ${receipt.id} for chat ${receipt.chat_id}`)
return this._write({
id: --this.notificationID,
command: "receipt",
@ -118,7 +115,7 @@ export default class Client {
}
sendQRCode(url) {
this.log(`Sending QR ${url} to client`)
this.log.debug(`Sending QR ${url} to client`)
return this._write({
id: --this.notificationID,
command: "qr",
@ -127,7 +124,7 @@ export default class Client {
}
sendPIN(pin) {
this.log(`Sending PIN ${pin} to client`)
this.log.debug(`Sending PIN ${pin} to client`)
return this._write({
id: --this.notificationID,
command: "pin",
@ -136,7 +133,7 @@ export default class Client {
}
sendLoginSuccess() {
this.log("Sending login success to client")
this.log.debug("Sending login success to client")
return this._write({
id: --this.notificationID,
command: "login_success",
@ -144,7 +141,7 @@ export default class Client {
}
sendLoginFailure(reason) {
this.log(`Sending login failure to client${reason ? `: "${reason}"` : ""}`)
this.log.debug(`Sending login failure to client${reason ? `: "${reason}"` : ""}`)
return this._write({
id: --this.notificationID,
command: "login_failure",
@ -153,7 +150,7 @@ export default class Client {
}
sendLoggedOut() {
this.log("Sending logout notice to client")
this.log.debug("Sending logout notice to client")
return this._write({
id: --this.notificationID,
command: "logged_out",
@ -163,7 +160,7 @@ export default class Client {
handleStart = async (req) => {
let started = false
if (this.puppet === null) {
this.log("Opening new puppeteer for", this.userID)
this.log.info("Opening new puppeteer for", this.userID)
this.puppet = new MessagesPuppeteer(this.userID, this.ownID, this.sendPlaceholders, this)
this.manager.puppets.set(this.userID, this.puppet)
await this.puppet.start(!!req.debug)
@ -181,7 +178,7 @@ export default class Client {
if (this.puppet === null) {
return {stopped: false}
}
this.log("Closing puppeteer for", this.userID)
this.log.info("Closing puppeteer for", this.userID)
this.manager.puppets.delete(this.userID)
await this.puppet.stop()
this.puppet = null
@ -193,14 +190,14 @@ export default class Client {
}
handleRegister = async (req) => {
this.userID = req.user_id
this.set_userID(req.user_id)
this.ownID = req.own_id
this.sendPlaceholders = req.ephemeral_events
this.log(`Registered socket ${this.connID} -> ${this.userID}${!this.sendPlaceholders ? "" : " (with placeholder message support)"}`)
this.log.info(`Registered socket ${this.connID} -> ${this.userID}${!this.sendPlaceholders ? "" : " (with placeholder message support)"}`)
if (this.manager.clients.has(this.userID)) {
const oldClient = this.manager.clients.get(this.userID)
this.manager.clients.set(this.userID, this)
this.log(`Terminating previous socket ${oldClient.connID} for ${this.userID}`)
this.log.info(`Terminating previous socket ${oldClient.connID} for ${this.userID}`)
await oldClient.stop("Socket replaced by new connection")
} else {
this.manager.clients.set(this.userID, this)
@ -214,36 +211,36 @@ export default class Client {
async handleLine(line) {
if (this.stopped) {
this.log("Ignoring line, client is stopped")
this.log.info("Ignoring line, client is stopped")
return
}
let req
try {
req = JSON.parse(line)
} catch (err) {
this.log("Non-JSON request:", line)
this.log.error("Non-JSON request:", line)
return
}
if (!req.command || !req.id) {
this.log("Invalid request:", line)
this.log.error("Invalid request:", line)
return
}
if (req.id <= this.maxCommandID) {
this.log("Ignoring old request", req.id)
this.log.warn("Ignoring old request", req.id)
return
}
if (req.command != "is_connected") {
this.log("Received request", req.id, "with command", req.command)
this.log.info("Received request", req.id, "with command", req.command)
}
this.maxCommandID = req.id
let handler
if (!this.userID) {
if (req.command !== "register") {
this.log("First request wasn't a register request, terminating")
this.log.info("First request wasn't a register request, terminating")
await this.stop("Invalid first request")
return
} else if (!req.user_id) {
this.log("Register request didn't contain user ID, terminating")
this.log.info("Register request didn't contain user ID, terminating")
await this.stop("Invalid register request")
return
}
@ -277,7 +274,7 @@ export default class Client {
} catch (err) {
resp.command = "error"
resp.error = err.toString()
this.log("Error handling request", req.id, err)
this.log.error("Error handling request", req.id, err)
}
await this._write(resp)
}

13
puppet/src/main.js
View File

@ -16,6 +16,8 @@
import process from "process"
import fs from "fs"
import sd from "systemd-daemon"
import logger from "loglevel"
import loggerprefix from "loglevel-plugin-prefix"
import arg from "arg"
@ -42,6 +44,17 @@ MessagesPuppeteer.extensionDir = config.extension_dir || MessagesPuppeteer.exten
MessagesPuppeteer.cycleDelay = config.cycle_delay || MessagesPuppeteer.cycleDelay
MessagesPuppeteer.useXdotool = config.use_xdotool || MessagesPuppeteer.useXdotool
MessagesPuppeteer.jiggleDelay = config.jiggle_delay || MessagesPuppeteer.jiggleDelay
let clog = config.logger
let clogpup = clog ? clog.puppeteer : undefined
logger.setLevel(clog ? clog.default_level || 3 : 3)
logger.getLogger("Puppeteer").setLevel(clogpup ? clogpup.level || logger.getLevel() : logger.getLevel())
logger.getLogger("Puppeteer_details").setLevel(clogpup ? clogpup.details || 3 : 3)
logger.getLogger("Puppeteer_spammer").setLevel(clogpup ? clogpup.spammer || 3 : 3)
logger.getLogger("TaskQueue").setLevel(clog ? clog.task_queue || 3 : 3)
logger.getLogger("API").setLevel(clog ? clog.api || 3 : 3)
// Register and specify the logger format. Others will inherit
loggerprefix.reg(logger)
loggerprefix.apply(logger, {template: '[%n] %l:'});
const api = new PuppetAPI(config.listen)

224
puppet/src/puppet.js
View File

@ -19,6 +19,7 @@ import { exec, execSync } from "child_process"
import puppeteer from "puppeteer"
import chrono from "chrono-node"
import logger from "loglevel"
import TaskQueue from "./taskqueue.js"
import {sleep} from "./util.js"
@ -59,14 +60,17 @@ export default class MessagesPuppeteer {
this.jiggleTimerID = null
this.taskQueue = new TaskQueue(this.id)
this.client = client
}
log(...text) {
console.log(`[Puppeteer/${this.id}]`, ...text)
}
error(...text) {
console.error(`[Puppeteer/${this.id}]`, ...text)
// Distinct logger object with same format as previous method
// General logger for overall process
this.log = logger.getLogger(`Puppeteer/${this.id}`)
// Detailed logger for active run (event based)
this.dlog = logger.getLogger(`Puppeteer/${this.id}: Details`)
// Seperate logger for more spammy messages (timer based)
this.spammer = logger.getLogger(`Puppeteer/${this.id}: Spam`)
// Inherit config rules
this.log.setLevel(logger.getLogger("Puppeteer").getLevel())
this.dlog.setLevel(logger.getLogger("Puppeteer_details").getLevel())
this.spammer.setLevel(logger.getLogger("Puppeteer_spammer").getLevel())
}
/**
@ -74,9 +78,9 @@ export default class MessagesPuppeteer {
* This must be called before doing anything else.
*/
async start() {
this.log("Launching browser")
this.log.info("Launching browser")
const args = [
let args = [
`--disable-extensions-except=${MessagesPuppeteer.extensionDir}`,
`--load-extension=${MessagesPuppeteer.extensionDir}`,
`--window-size=${MessagesPuppeteer.viewport.width},${MessagesPuppeteer.viewport.height + 120}`,
@ -94,7 +98,7 @@ export default class MessagesPuppeteer {
devtools: MessagesPuppeteer.devtools,
timeout: 0,
})
this.log("Opening new tab")
this.log.info("Opening new tab")
const pages = await this.browser.pages()
if (pages.length > 0) {
this.page = pages[0]
@ -103,29 +107,29 @@ export default class MessagesPuppeteer {
}
{
this.log("Finding extension UUID")
this.log.info("Finding extension UUID")
await this.page.goto("chrome://system")
const selector = "#extensions-value"
await this.page.waitForSelector(selector, 0)
const lineDetails = await this.page.$eval(selector, e => e.innerText)
const uuid = lineDetails.match(/(.*) : LINE : version/)[1]
this.log(`Found extension UUID ${uuid}`)
this.log.info(`Found extension UUID ${uuid}`)
MessagesPuppeteer.url = `chrome-extension://${uuid}/index.html`
}
this.blankPage = await this.browser.newPage()
if (MessagesPuppeteer.useXdotool) {
this.log("Finding window ID")
this.log.info("Finding window ID")
const buffer = execSync("xdotool search 'about:blank'")
this.windowID = Number.parseInt(buffer)
this.log(`Found window ID ${this.windowID}`)
this.log.info(`Found window ID ${this.windowID}`)
}
this.log(`Opening ${MessagesPuppeteer.url}`)
this.log.info(`Opening ${MessagesPuppeteer.url}`)
await this.page.setBypassCSP(true) // Needed to load content scripts
await this._preparePage(true)
this.log("Exposing functions")
this.log.info("Exposing functions")
await this.page.exposeFunction("__mautrixReceiveQR", this._receiveQRChange.bind(this))
await this.page.exposeFunction("__mautrixSendEmailCredentials", this._sendEmailCredentials.bind(this))
await this.page.exposeFunction("__mautrixReceivePIN", this._receivePIN.bind(this))
@ -145,7 +149,7 @@ export default class MessagesPuppeteer {
this.loginRunning = false
this.loginCancelled = false
this.taskQueue.start()
this.log("Startup complete")
this.log.info("Startup complete")
}
async _preparePage(navigateTo) {
@ -155,7 +159,7 @@ export default class MessagesPuppeteer {
} else {
await this.page.reload()
}
this.log("Injecting content script")
this.log.info("Injecting content script")
await this.page.addScriptTag({path: "./src/contentscript.js", type: "module"})
}
@ -164,7 +168,7 @@ export default class MessagesPuppeteer {
try {
await promiser()
} catch (e) {
this.error(`Error while interacting with page: ${e}`)
this.log.error(`Error while interacting with page: ${e}`)
throw e
} finally {
await this.blankPage.bringToFront()
@ -180,7 +184,7 @@ export default class MessagesPuppeteer {
if (numTries && --numTries == 0) {
throw e
} else if (failMessage) {
this.log(failMessage)
this.log.error(failMessage)
}
}
}
@ -212,7 +216,7 @@ export default class MessagesPuppeteer {
switch (login_type) {
case "qr": {
this.log("Running QR login")
this.dlog.info("Running QR login")
const qrButton = await this.page.waitForSelector("#login_qr_btn")
await qrButton.click()
@ -228,7 +232,7 @@ export default class MessagesPuppeteer {
break
}
case "email": {
this.log("Running email login")
this.dlog.info("Running email login")
if (!login_data) {
this._sendLoginFailure("No login credentials provided for email login")
return
@ -255,7 +259,7 @@ export default class MessagesPuppeteer {
await this.page.evaluate(
element => window.__mautrixController.addPINAppearObserver(element), loginContentArea)
this.log("Waiting for login response")
this.dlog.info("Waiting for login response")
let doneWaiting = false
let loginSuccess = false
const cancelableResolve = (promiseFn) => {
@ -289,7 +293,7 @@ export default class MessagesPuppeteer {
].map(promiseFn => cancelableResolve(promiseFn)))
if (!this.loginCancelled) {
this.log("Removing observers")
this.dlog.info("Removing observers")
// TODO __mautrixController is undefined when cancelling, why?
await this.page.evaluate(ownID => window.__mautrixController.setOwnID(ownID), this.ownID)
await this.page.evaluate(() => window.__mautrixController.removeQRChangeObserver())
@ -309,7 +313,7 @@ export default class MessagesPuppeteer {
}
this._sendLoginSuccess()
this.log("Waiting for sync")
this.dlog.info("Waiting for sync")
try {
await this.page.waitForFunction(
messageSyncElement => {
@ -322,15 +326,15 @@ export default class MessagesPuppeteer {
messageSyncElement)
} catch (err) {
//this._sendLoginFailure(`Failed to sync: ${err}`)
this.log("LINE's sync took too long, assume it's fine and carry on...")
this.dlog.warn("LINE's sync took too long, assume it's fine and carry on...")
} finally {
const syncText = await messageSyncElement.evaluate(e => e.innerText)
this.log(`Final sync text is: "${syncText}"`)
this.dlog.info(`Final sync text is: "${syncText}"`)
}
this.loginRunning = false
await this.blankPage.bringToFront()
this.log("Login complete")
this.dlog.info("Login complete")
}
/**
@ -366,7 +370,7 @@ export default class MessagesPuppeteer {
if (this.browser) {
await this.browser.close()
}
this.log("Everything stopped")
this.log.info("Everything stopped")
}
/**
@ -512,14 +516,14 @@ export default class MessagesPuppeteer {
for (const [chatID, messageID] of Object.entries(msgIDs)) {
this.mostRecentMessages.set(chatID, messageID)
}
this.log("Updated most recent message ID map:")
this.log(JSON.stringify(msgIDs))
this.dlog.info("Updated most recent message ID map:")
this.dlog.debug(JSON.stringify(msgIDs))
for (const [chatID, messageID] of Object.entries(ownMsgIDs)) {
this.mostRecentOwnMessages.set(chatID, messageID)
}
this.log("Updated most recent own message ID map:")
this.log(JSON.stringify(ownMsgIDs))
this.dlog.info("Updated most recent own message ID map:")
this.dlog.debug(JSON.stringify(ownMsgIDs))
this.mostRecentReceipts.clear()
for (const [chatID, receipts] of Object.entries(rctIDs)) {
@ -528,11 +532,11 @@ export default class MessagesPuppeteer {
receiptMap.set(+count, receiptID)
}
}
this.log("Updated most recent receipt ID map")
this.dlog.info("Updated most recent receipt ID map")
for (const [chatID, receiptMap] of this.mostRecentReceipts) {
this.log(`${chatID}:`)
this.dlog.debug(`${chatID}:`)
for (const [count, receiptID] of receiptMap) {
this.log(`Read by ${count}: ${receiptID}`)
this.dlog.debug(`Read by ${count}: ${receiptID}`)
}
}
}
@ -562,7 +566,7 @@ export default class MessagesPuppeteer {
}
async _cycleChatUnsafe() {
this.log("Cycling chats")
this.dlog.info("Cycling chats")
const initialID = this.cycleTimerID
const currentChatID = await this.page.evaluate(() => window.__mautrixController.getCurrentChatID())
@ -601,13 +605,13 @@ export default class MessagesPuppeteer {
}
chatIDToSync = chatListItem.id
this.log(`Viewing chat ${chatIDToSync} to check for new read receipts`)
this.dlog.debug(`Viewing chat ${chatIDToSync} to check for new read receipts`)
await this._syncChat(chatIDToSync)
break
}
if (!chatIDToSync) {
this.log("Found no chats in need of read receipt updates")
this.dlog.debug("Found no chats in need of read receipt updates")
}
if (this.cycleTimerID == initialID) {
@ -624,15 +628,15 @@ export default class MessagesPuppeteer {
}
_jiggleMouse() {
this.log("Jiggling mouse")
this.spammer.info("Jiggling mouse")
const initialID = this.jiggleTimerID
exec(`xdotool mousemove --sync --window ${this.windowID} 0 0`, {},
(error, stdout, stderr) => {
if (error) {
this.log(`Error while jiggling mouse: ${error}`)
this.spammer.error(`Error while jiggling mouse: ${error}`)
} else {
this.log("Jiggled mouse")
this.spammer.debug("Jiggled mouse")
}
if (this.jiggleTimerID == initialID) {
@ -644,7 +648,7 @@ export default class MessagesPuppeteer {
async startObserving() {
// TODO Highly consider syncing anything that was missed since stopObserving...
const chatID = await this.page.evaluate(() => window.__mautrixController.getCurrentChatID())
this.log(`Adding observers for ${chatID || "empty chat"}, and global timers`)
this.dlog.info(`Adding observers for ${chatID || "empty chat"}, and global timers`)
await this.page.evaluate(
() => window.__mautrixController.addChatListObserver())
if (chatID) {
@ -662,7 +666,7 @@ export default class MessagesPuppeteer {
}
async stopObserving() {
this.log("Removing observers and timers")
this.dlog.info("Removing observers and timers")
await this.page.evaluate(
() => window.__mautrixController.removeChatListObserver())
await this.page.evaluate(
@ -687,12 +691,12 @@ export default class MessagesPuppeteer {
// Best to use this on startup when no chat is viewed.
let ownProfile
await this._interactWithPage(async () => {
this.log("Opening settings view")
this.dlog.info("Opening settings view")
await this.page.click("button.mdGHD01SettingBtn")
await this.page.waitForSelector("#context_menu li#settings", {visible: true}).then(e => e.click())
await this.page.waitForSelector("#settings_contents", {visible: true})
this.log("Getting own profile info")
this.dlog.info("Getting own profile info")
ownProfile = {
id: this.ownID,
name: await this.page.$eval("#settings_basic_name_input", e => e.innerText),
@ -727,7 +731,7 @@ export default class MessagesPuppeteer {
async _switchChat(chatID, forceView = false) {
// TODO Allow passing in an element directly
this.log(`Switching to chat ${chatID}`)
this.dlog.info(`Switching to chat ${chatID}`)
let chatItem = await this.page.$(this._chatItemSelector(chatID))
let chatName
@ -745,23 +749,23 @@ export default class MessagesPuppeteer {
if (!!chatItem && await this.page.evaluate(isCorrectChatVisible, chatName)) {
if (!forceView) {
this.log("Already viewing chat, no need to switch")
this.dlog.debug("Already viewing chat, no need to switch")
} else {
await this._interactWithPage(async () => {
this.log("Already viewing chat, but got request to view it")
this.dlog.debug("Already viewing chat, but got request to view it")
this.page.waitForTimeout(500)
})
}
} else {
this.log("Ensuring msg list observer is removed")
this.dlog.info("Ensuring msg list observer is removed")
const hadMsgListObserver = await this.page.evaluate(
() => window.__mautrixController.removeMsgListObserver())
this.log(hadMsgListObserver ? "Observer was already removed" : "Removed observer")
this.dlog.info(hadMsgListObserver ? "Observer was already removed" : "Removed observer")
let switchedTabs = false
let needRealClick = false
if (!chatItem) {
this.log(`Chat ${chatID} not in recents list`)
this.dlog.info(`Chat ${chatID} not in recents list`)
if (chatID.charAt(0) != "u") {
needRealClick = true
@ -790,7 +794,7 @@ export default class MessagesPuppeteer {
await this._retryUntilSuccess(3, "Clicking chat item didn't work...try again",
async () => {
this.log("Clicking chat item")
this.dlog.info("Clicking chat item")
if (!needRealClick) {
await chatItem.evaluate(e => e.click())
} else {
@ -798,7 +802,7 @@ export default class MessagesPuppeteer {
await chatItem.click()
})
}
this.log(`Waiting for chat header title to be "${chatName}"`)
this.dlog.debug(`Waiting for chat header title to be "${chatName}"`)
await this.page.waitForFunction(
isCorrectChatVisible,
{polling: "mutation", timeout: 1000},
@ -810,7 +814,7 @@ export default class MessagesPuppeteer {
await this._interactWithPage(async () => {
// Always show the chat details sidebar, as this makes life easier
this.log("Waiting for detail area to be auto-hidden upon entering chat")
this.dlog.debug("Waiting for detail area to be auto-hidden upon entering chat")
await this.page.waitForFunction(
detailArea => detailArea.childElementCount == 0,
{},
@ -818,30 +822,30 @@ export default class MessagesPuppeteer {
await this._retryUntilSuccess(3, "Clicking chat header didn't work...try again",
async () => {
this.log("Clicking chat header to show detail area")
this.dlog.debug("Clicking chat header to show detail area")
await this.page.click("#_chat_header_area > .mdRGT04Link")
this.log("Waiting for detail area")
this.dlog.debug("Waiting for detail area")
await this.page.waitForSelector("#_chat_detail_area > .mdRGT02Info", {timeout: 1000})
})
})
this.log("Waiting for any item to appear in chat")
this.dlog.debug("Waiting for any item to appear in chat")
try {
await this.page.waitForSelector("#_chat_room_msg_list div", {timeout: 2000})
this.log("Waiting for chat to stabilize")
this.dlog.debug("Waiting for chat to stabilize")
await this.page.evaluate(() => window.__mautrixController.waitForMessageListStability())
} catch (e) {
this.log("No messages in chat found. Maybe no messages were ever sent yet?")
this.dlog.warn("No messages in chat found. Maybe no messages were ever sent yet?")
}
if (hadMsgListObserver) {
this.log("Restoring msg list observer")
this.dlog.debug("Restoring msg list observer")
await this.page.evaluate(
(mostRecentMessage) => window.__mautrixController.addMsgListObserver(mostRecentMessage),
this.mostRecentMessages.get(chatID))
} else {
this.log("Not restoring msg list observer, as there never was one")
this.dlog.debug("Not restoring msg list observer, as there never was one")
}
}
}
@ -872,7 +876,7 @@ export default class MessagesPuppeteer {
(element, chatID) => window.__mautrixController.parseFriendsListItem(element, chatID),
chatID)
this.log(`Found NEW direct chat with ${chatID}`)
this.dlog.info(`Found NEW direct chat with ${chatID}`)
return {
participants: [friendsListInfo],
id: chatID,
@ -893,7 +897,7 @@ export default class MessagesPuppeteer {
let participants
if (!isDirect) {
this.log("Found multi-user chat, so viewing it to get participants")
this.dlog.info("Found multi-user chat, so viewing it to get participants")
// TODO This will mark the chat as "read"!
await this._switchChat(chatID, forceView)
const participantList = await this.page.$("#_chat_detail_area > .mdRGT02Info ul.mdRGT13Ul")
@ -902,9 +906,9 @@ export default class MessagesPuppeteer {
participants = await participantList.evaluate(
element => window.__mautrixController.parseParticipantList(element))
} else {
this.log(`Found direct chat with ${chatID}`)
this.dlog.info(`Found direct chat with ${chatID}`)
if (forceView) {
this.log("Viewing chat on request")
this.dlog.info("Viewing chat on request")
await this._switchChat(chatID, forceView)
}
//const chatDetailArea = await this.page.waitForSelector("#_chat_detail_area > .mdRGT02Info")
@ -916,9 +920,9 @@ export default class MessagesPuppeteer {
}]
}
this.log("Found participants:")
this.dlog.info("Found participants:")
for (const participant of participants) {
this.log(JSON.stringify(participant))
this.dlog.debug(JSON.stringify(participant))
}
return {participants, ...chatListInfo}
}
@ -965,16 +969,16 @@ export default class MessagesPuppeteer {
try {
this._interactWithPage(async () => {
this.log(`About to ask for file chooser in ${chatID}`)
this.dlog.info(`About to ask for file chooser in ${chatID}`)
const [fileChooser] = await Promise.all([
this.page.waitForFileChooser(),
this.page.click("#_chat_room_plus_btn")
])
this.log(`About to upload ${filePath}`)
this.dlog.info(`About to upload ${filePath}`)
await fileChooser.accept([filePath])
})
} catch (e) {
this.log(`Failed to upload file to ${chatID}`)
this.dlog.error(`Failed to upload file to ${chatID}`)
return -1
}
@ -983,16 +987,16 @@ export default class MessagesPuppeteer {
async _waitForSentMessage(chatID) {
try {
this.log("Waiting for message to be sent")
this.dlog.debug("Waiting for message to be sent")
const id = await this.page.evaluate(
() => window.__mautrixController.waitForOwnMessage())
this.log(`Successfully sent message ${id} to ${chatID}`)
this.dlog.debug(`Successfully sent message ${id} to ${chatID}`)
this.mostRecentMessages.set(chatID, id)
this.mostRecentOwnMessages.set(chatID, id)
return id
} catch (e) {
// TODO Catch if something other than a timeout
this.error(`Timed out sending message to ${chatID}`)
this.dlog.error(`Timed out sending message to ${chatID}`)
// TODO Figure out why e is undefined...
//this.error(e)
return -1
@ -1006,19 +1010,19 @@ export default class MessagesPuppeteer {
if (this.client) {
for (const message of messages) {
this.client.sendMessage(message).catch(err =>
this.error("Failed to send message", message.id, "to client:", err))
this.dlog.error("Failed to send message", message.id, "to client:", err))
}
} else {
this.log("No client connected, not sending messages")
this.dlog.info("No client connected, not sending messages")
}
}
async _getMessagesUnsafe(chatID) {
// TODO Consider making a wrapper for pausing/resuming the msg list observers
this.log("Ensuring msg list observer is removed")
this.dlog.info("Ensuring msg list observer is removed")
const hadMsgListObserver = await this.page.evaluate(
() => window.__mautrixController.removeMsgListObserver())
this.log(hadMsgListObserver ? "Observer was already removed" : "Removed observer")
this.dlog.info(hadMsgListObserver ? "Observer was already removed" : "Removed observer")
// TODO Handle unloaded messages. Maybe scroll up
// TODO This will mark the chat as "read"!
@ -1065,12 +1069,12 @@ export default class MessagesPuppeteer {
if (hadMsgListObserver) {
this.log("Restoring msg list observer")
this.dlog.info("Restoring msg list observer")
await this.page.evaluate(
mostRecentMessage => window.__mautrixController.addMsgListObserver(mostRecentMessage),
this.mostRecentMessages.get(chatID))
} else {
this.log("Not restoring msg list observer, as there never was one")
this.dlog.info("Not restoring msg list observer, as there never was one")
}
return {
@ -1089,7 +1093,7 @@ export default class MessagesPuppeteer {
const newLastID = filteredMessages[filteredMessages.length - 1].id
this.mostRecentMessages.set(chatID, newLastID)
const range = newFirstID === newLastID ? newFirstID : `${newFirstID}-${newLastID}`
this.log(`Loaded ${messages.length} messages in ${chatID}, got ${filteredMessages.length} newer than ${minID} (${range})`)
this.dlog.info(`Loaded ${messages.length} messages in ${chatID}, got ${filteredMessages.length} newer than ${minID} (${range})`)
for (const message of filteredMessages) {
message.chat_id = chatID
}
@ -1130,14 +1134,14 @@ export default class MessagesPuppeteer {
async _processChatListChangeUnsafe(chatListInfo) {
const chatID = chatListInfo.id
this.updatedChats.delete(chatID)
this.log("Processing change to", chatID)
this.dlog.info("Processing change to", chatID)
// TODO Also process name/icon changes
const prevNumNotifications = this.numChatNotifications.get(chatID) || 0
const diffNumNotifications = chatListInfo.notificationCount - prevNumNotifications
if (chatListInfo.notificationCount == 0 && diffNumNotifications < 0) {
this.log("Notifications dropped--must have read messages from another LINE client, skip")
this.dlog.info("Notifications dropped--must have read messages from another LINE client, skip")
this.numChatNotifications.set(chatID, 0)
return
}
@ -1181,25 +1185,25 @@ export default class MessagesPuppeteer {
const {messages, receipts} = await this._getMessagesUnsafe(chatID)
if (messages.length == 0) {
this.log("No new messages found in", chatID)
this.dlog.info("No new messages found in", chatID)
} else {
this._receiveMessages(chatID, messages, true)
}
if (receipts.length == 0) {
this.log("No new receipts found in", chatID)
this.dlog.info("No new receipts found in", chatID)
} else {
this._receiveReceiptMulti(chatID, receipts, true)
}
}
_receiveChatListChanges(changes) {
this.log(`Received chat list changes: ${changes.map(item => item.id)}`)
this.dlog.info(`Received chat list changes: ${changes.map(item => item.id)}`)
for (const item of changes) {
if (!this.updatedChats.has(item.id)) {
this.updatedChats.add(item.id)
this.taskQueue.push(() => this._processChatListChangeUnsafe(item))
.catch(err => this.error("Error handling chat list changes:", err))
.catch(err => this.dlog.error("Error handling chat list changes:", err))
}
}
}
@ -1208,17 +1212,17 @@ export default class MessagesPuppeteer {
const receiptMap = this._getReceiptMap(chat_id)
const prevReceiptID = (receiptMap.get(1) || 0)
if (receipt_id <= prevReceiptID) {
this.log(`Received OUTDATED read receipt ${receipt_id} (older than ${prevReceiptID}) for chat ${chat_id}`)
this.dlog.info(`Received OUTDATED read receipt ${receipt_id} (older than ${prevReceiptID}) for chat ${chat_id}`)
return
}
receiptMap.set(1, receipt_id)
this.log(`Received read receipt ${receipt_id} (since ${prevReceiptID}) for chat ${chat_id}`)
this.dlog.info(`Received read receipt ${receipt_id} (since ${prevReceiptID}) for chat ${chat_id}`)
if (this.client) {
this.client.sendReceipt({chat_id: chat_id, id: receipt_id})
.catch(err => this.error("Error handling read receipt:", err))
.catch(err => this.dlog.error("Error handling read receipt:", err))
} else {
this.log("No client connected, not sending receipts")
this.dlog.info("No client connected, not sending receipts")
}
}
@ -1236,29 +1240,29 @@ export default class MessagesPuppeteer {
}
})
if (receipts.length == 0) {
this.log(`Received ALL OUTDATED bulk read receipts for chat ${chat_id}:`, receipts)
this.dlog.info(`Received ALL OUTDATED bulk read receipts for chat ${chat_id}:`, receipts)
return
}
this._trimReceiptMap(receiptMap)
}
this.log(`Received bulk read receipts for chat ${chat_id}:`, receipts)
this.dlog.info(`Received bulk read receipts for chat ${chat_id}:`, receipts)
if (this.client) {
for (const receipt of receipts) {
receipt.chat_id = chat_id
try {
await this.client.sendReceipt(receipt)
} catch (err) {
this.error("Error handling read receipt:", err)
this.dlog.error("Error handling read receipt:", err)
}
}
} else {
this.log("No client connected, not sending receipts")
this.dlog.info("No client connected, not sending receipts")
}
}
async _sendEmailCredentials() {
this.log("Inputting login credentials")
this.dlog.info("Inputting login credentials")
await this._enterText(await this.page.$("#line_login_email"), this.login_email)
await this._enterText(await this.page.$("#line_login_pwd"), this.login_password)
await this.page.click("button#login_btn")
@ -1267,51 +1271,51 @@ export default class MessagesPuppeteer {
_receiveQRChange(url) {
if (this.client) {
this.client.sendQRCode(url).catch(err =>
this.error("Failed to send new QR to client:", err))
this.dlog.error("Failed to send new QR to client:", err))
} else {
this.log("No client connected, not sending new QR")
this.dlog.warn("No client connected, not sending new QR")
}
}
_receivePIN(pin) {
if (this.client) {
this.client.sendPIN(pin).catch(err =>
this.error("Failed to send new PIN to client:", err))
this.dlog.error("Failed to send new PIN to client:", err))
} else {
this.log("No client connected, not sending new PIN")
this.dlog.warn("No client connected, not sending new PIN")
}
}
_sendLoginSuccess() {
this.error("Login success")
this.dlog.info("Login success")
if (this.client) {
this.client.sendLoginSuccess().catch(err =>
this.error("Failed to send login success to client:", err))
this.dlog.error("Failed to send login success to client:", err))
} else {
this.log("No client connected, not sending login success")
this.dlog.warn("No client connected, not sending login success")
}
}
_sendLoginFailure(reason) {
this.loginRunning = false
this.error(`Login failure: ${reason ? reason : "cancelled"}`)
this.dlog.error(`Login failure: ${reason ? reason : "cancelled"}`)
if (this.client) {
this.client.sendLoginFailure(reason).catch(err =>
this.error("Failed to send login failure to client:", err))
this.dlog.error("Failed to send login failure to client:", err))
} else {
this.log("No client connected, not sending login failure")
this.dlog.warn("No client connected, not sending login failure")
}
}
_onLoggedOut() {
this.log("Got logged out!")
this.dlog.info("Got logged out!")
this.stopObserving()
this.page.bringToFront()
if (this.client) {
this.client.sendLoggedOut().catch(err =>
this.error("Failed to send logout notice to client:", err))
this.dlog.error("Failed to send logout notice to client:", err))
} else {
this.log("No client connected, not sending logout notice")
this.dlog.warn("No client connected, not sending logout notice")
}
}
}

21
puppet/src/taskqueue.js
View File

@ -13,6 +13,7 @@
//
// You should have received a copy of the GNU Affero General Public License
// along with this program. If not, see <https://www.gnu.org/licenses/>.
import logger from "loglevel"
export default class TaskQueue {
constructor(id) {
@ -20,21 +21,15 @@ export default class TaskQueue {
this._tasks = []
this.running = false
this._wakeup = null
}
log(...text) {
console.log(`[TaskQueue/${this.id}]`, ...text)
}
error(...text) {
console.error(`[TaskQueue/${this.id}]`, ...text)
this.log = logger.getLogger(`TaskQueue/${this.id}`)
this.log.setLevel(logger.getLogger("TaskQueue").getLevel())
}
async _run() {
this.log("Started processing tasks")
this.log.info("Started processing tasks")
while (this.running) {
if (this._tasks.length === 0) {
this.log("Sleeping until a new task is received")
this.log.debug("Sleeping until a new task is received")
await new Promise(resolve => this._wakeup = () => {
resolve()
this._wakeup = null
@ -42,12 +37,12 @@ export default class TaskQueue {
if (!this.running) {
break
}
this.log("Continuing processing tasks")
this.log.debug("Continuing processing tasks")
}
const { task, resolve, reject } = this._tasks.shift()
await task().then(resolve, reject)
}
this.log("Stopped processing tasks")
this.log.info("Stopped processing tasks")
}
/**
@ -79,7 +74,7 @@ export default class TaskQueue {
return
}
this.running = true
this._run().catch(err => this.error("Fatal error processing tasks:", err))
this._run().catch(err => this.log.error("Fatal error processing tasks:", err))
}
/**

10
puppet/yarn.lock
View File

@ -932,6 +932,16 @@ lodash@^4.17.14, lodash@^4.17.19:
resolved "https://registry.yarnpkg.com/lodash/-/lodash-4.17.20.tgz#b44a9b6297bcb698f1c51a3545a2b3b368d59c52"
integrity sha512-PlhdFcillOINfeV7Ni6oF1TAEayyZBoZ8bcshTHqOYJYlrqzRK5hagpagky5o4HfCzzd1TRkXPMFq6cKk9rGmA==
loglevel-plugin-prefix@^0.8.4:
version "0.8.4"
resolved "https://registry.yarnpkg.com/loglevel-plugin-prefix/-/loglevel-plugin-prefix-0.8.4.tgz#2fe0e05f1a820317d98d8c123e634c1bd84ff644"
integrity sha512-WpG9CcFAOjz/FtNht+QJeGpvVl/cdR6P0z6OcXSkr8wFJOsV2GRj2j10JLfjuA4aYkcKCNIEqRGCyTife9R8/g==
loglevel@^1.7.1:
version "1.7.1"
resolved "https://registry.yarnpkg.com/loglevel/-/loglevel-1.7.1.tgz#005fde2f5e6e47068f935ff28573e125ef72f197"
integrity sha512-Hesni4s5UkWkwCGJMQGAh71PaLUmKFM60dHvq0zi/vDhhrzuk+4GgNbTXJ12YYQJn6ZKBDNIjYcuQGKudvqrIw==
minimatch@^3.0.4:
version "3.0.4"
resolved "https://registry.yarnpkg.com/minimatch/-/minimatch-3.0.4.tgz#5166e286457f03306064be5497e8dbb0c3d32083"