From 484e99b29c6c0cd91b42ec59e8e6d59b2c3752aa Mon Sep 17 00:00:00 2001 From: mmorrison Date: Wed, 9 Jan 2019 05:50:30 -0600 Subject: [PATCH] Improve logging --- protocols/battlefield.js | 2 +- protocols/core.js | 70 ++++++++++++++++++++++++---------------- protocols/ffow.js | 2 +- protocols/gamespy2.js | 10 +++--- protocols/gamespy3.js | 17 ++++------ protocols/minecraft.js | 8 ++--- protocols/unreal2.js | 24 +++++++------- protocols/valve.js | 40 ++++++++++------------- 8 files changed, 88 insertions(+), 85 deletions(-) diff --git a/protocols/battlefield.js b/protocols/battlefield.js index 45968c5..8790b32 100644 --- a/protocols/battlefield.js +++ b/protocols/battlefield.js @@ -98,7 +98,7 @@ class Battlefield extends Core { return await this.tcpSend(socket, outPacket, (data) => { const decoded = this.decodePacket(data); if(decoded) { - if(this.debug) console.log(decoded); + this.debugLog(decoded); if(decoded.shift() !== 'OK') throw new Error('Missing OK'); return decoded; } diff --git a/protocols/core.js b/protocols/core.js index 960d1a0..5e27799 100644 --- a/protocols/core.js +++ b/protocols/core.js @@ -79,7 +79,7 @@ class Core extends EventEmitter { try { leak.cleanup(); } catch(e) { - if (this.debug) console.log("Error during async cleanup: " + e.stack); + this.debugLog("Error during async cleanup: " + e.stack); } } this.asyncLeaks.clear(); @@ -137,18 +137,18 @@ class Core extends EventEmitter { }; const resolveStandard = async (host) => { if(isIp(host)) return host; - if(this.debug) console.log("Standard DNS Lookup: " + host); + this.debugLog("Standard DNS Lookup: " + host); const {address,family} = await dnsLookupAsync(host); - if(this.debug) console.log(address); + this.debugLog(address); return address; }; const resolveSrv = async (srv,host) => { if(isIp(host)) return host; - if(this.debug) console.log("SRV DNS Lookup: " + srv+'.'+host); + this.debugLog("SRV DNS Lookup: " + srv+'.'+host); let records; try { records = await dnsResolveAsync(srv + '.' + host, 'SRV'); - if(this.debug) console.log(records); + this.debugLog(records); if(records.length >= 1) { const record = records[0]; this.options.port = record.port; @@ -156,7 +156,7 @@ class Core extends EventEmitter { return await resolveStandard(srvhost); } } catch(e) { - if (this.debug) console.log(e.toString()); + this.debugLog(e.toString()); } return await resolveStandard(host); }; @@ -169,10 +169,10 @@ class Core extends EventEmitter { const id = ++this.lastAsyncLeakId; const stack = new Error().stack; const entry = { id: id, cleanup: fn, stack: stack }; - if (this.debug) console.log("Registering async leak: " + id); + this.debugLog("Registering async leak: " + id); this.asyncLeaks.add(entry); return () => { - if (this.debug) console.log("Removing async leak: " + id); + this.debugLog("Removing async leak: " + id); this.asyncLeaks.delete(entry); } } @@ -215,24 +215,22 @@ class Core extends EventEmitter { socket.setNoDelay(true); const cancelAsyncLeak = this.addAsyncLeak(() => socket.destroy()); - if(this.debug) { - console.log(address+':'+port+" TCP Connecting"); + this.debugLog(log => { + this.debugLog(address+':'+port+" TCP Connecting"); const writeHook = socket.write; socket.write = (...args) => { - console.log(address+':'+port+" TCP-->"); - console.log(HexUtil.debugDump(args[0])); + log(address+':'+port+" TCP-->"); + log(HexUtil.debugDump(args[0])); writeHook.apply(socket,args); }; - socket.on('error', e => console.log('TCP Error: ' + e)); - socket.on('close', () => console.log('TCP Closed')); + socket.on('error', e => log('TCP Error: ' + e)); + socket.on('close', () => log('TCP Closed')); socket.on('data', (data) => { - if(this.debug) { - console.log(address+':'+port+" <--TCP"); - console.log(HexUtil.debugDump(data)); - } + log(address+':'+port+" <--TCP"); + log(data); }); - socket.on('ready', () => console.log(address+':'+port+" TCP Connected")); - } + socket.on('ready', () => log(address+':'+port+" TCP Connected")); + }); try { await this.timedPromise( @@ -314,22 +312,22 @@ class Core extends EventEmitter { if(!('port_query' in this.options)) throw new Error('Attempted to send without setting a port'); if(!('address' in this.options)) throw new Error('Attempted to send without setting an address'); if(typeof buffer === 'string') buffer = Buffer.from(buffer,'binary'); - if(this.debug) { - console.log(this.options.address+':'+this.options.port_query+" UDP-->"); - console.log(HexUtil.debugDump(buffer)); - } + this.debugLog(log => { + log(this.options.address+':'+this.options.port_query+" UDP-->"); + log(HexUtil.debugDump(buffer)); + }); return await this.withUdpLock(async() => { this.udpSocket.send(buffer,0,buffer.length,this.options.port_query,this.options.address); return await new Promise((resolve,reject) => { const cancelTimeout = this.setTimeout(() => { - if (this.debug) console.log("UDP timeout detected"); + this.debugLog("UDP timeout detected"); let success = false; if (onTimeout) { const result = onTimeout(); if (result !== undefined) { - if (this.debug) console.log("UDP timeout resolved by callback"); + this.debugLog("UDP timeout resolved by callback"); resolve(result); success = true; } @@ -342,7 +340,7 @@ class Core extends EventEmitter { this.udpCallback = (buffer) => { const result = onPacket(buffer); if(result !== undefined) { - if (this.debug) console.log("UDP send finished by callback"); + this.debugLog("UDP send finished by callback"); cancelTimeout(); resolve(result); } @@ -366,6 +364,24 @@ class Core extends EventEmitter { promise.finally(cancelAsyncLeak); return promise; } + + debugLog(...args) { + if (!this.debug) return; + try { + if(args[0] instanceof Buffer) { + this.debugLog(HexUtil.debugDump(args[0])); + } else if (typeof args[0] == 'function') { + const result = args[0].call(undefined, this.debugLog.bind(this)); + if (result !== undefined) { + this.debugLog(result); + } + } else { + console.log(...args); + } + } catch(e) { + console.log("Error while debug logging: " + e); + } + } } module.exports = Core; diff --git a/protocols/ffow.js b/protocols/ffow.js index 8f228d3..92245d6 100644 --- a/protocols/ffow.js +++ b/protocols/ffow.js @@ -7,7 +7,7 @@ class Ffow extends Valve { this.legacyChallenge = true; } async queryInfo(state) { - if(this.debug) console.log("Requesting ffow info ..."); + this.debugLog("Requesting ffow info ..."); const b = await this.sendPacket( 0x46, false, diff --git a/protocols/gamespy2.js b/protocols/gamespy2.js index 941ece2..7076e80 100644 --- a/protocols/gamespy2.js +++ b/protocols/gamespy2.js @@ -64,19 +64,19 @@ class Gamespy2 extends Core { // so we can detect this. if (count > 64) { reader.skip(-1); - if (this.debug) console.log("Detected missing count byte, rewinding by 1"); + this.debugLog("Detected missing count byte, rewinding by 1"); } else { - if (this.debug) console.log("Detected row count: " + count); + this.debugLog("Detected row count: " + count); } - if(this.debug) console.log("Reading fields, starting at: "+reader.rest()); + this.debugLog(() => "Reading fields, starting at: "+reader.rest()); const fields = []; while(!reader.done()) { let field = reader.string(); if(!field) break; fields.push(field); - if(this.debug) console.log("field:"+field); + this.debugLog("field:"+field); } if (!fields.length) return []; @@ -88,7 +88,7 @@ class Gamespy2 extends Core { let key = fields[iField]; let value = reader.string(); if(!value && iField === 0) break outer; - if(this.debug) console.log("value:"+value); + this.debugLog("value:"+value); if(key === 'player_') key = 'name'; else if(key === 'score_') key = 'score'; else if(key === 'deaths_') key = 'deaths'; diff --git a/protocols/gamespy3.js b/protocols/gamespy3.js index 020418b..6a39475 100644 --- a/protocols/gamespy3.js +++ b/protocols/gamespy3.js @@ -39,10 +39,8 @@ class Gamespy3 extends Core { const packet = packets[iPacket]; const reader = this.reader(packet); - if(this.debug) { - console.log("Parsing packet #" + iPacket); - console.log(HexUtil.debugDump(packet)); - } + this.debugLog("Parsing packet #" + iPacket); + this.debugLog(packet); // Parse raw server key/values @@ -58,7 +56,7 @@ class Gamespy3 extends Core { } state.raw[key] = value; - if (this.debug) console.log(key + " = " + value); + this.debugLog(key + " = " + value); } } @@ -92,9 +90,7 @@ class Gamespy3 extends Core { let offset = reader.uint(1); firstMode = false; - if (this.debug) { - console.log("Parsing new field: itemType=" + itemType + " fieldName=" + fieldName + " startOffset=" + offset); - } + this.debugLog(() => "Parsing new field: itemType=" + itemType + " fieldName=" + fieldName + " startOffset=" + offset); while(!reader.done()) { const item = reader.string(); @@ -102,7 +98,7 @@ class Gamespy3 extends Core { while(items.length <= offset) { items.push({}); } items[offset][fieldName] = item; - if (this.debug) console.log("* " + item); + this.debugLog("* " + item); offset++; } } @@ -173,8 +169,7 @@ class Gamespy3 extends Core { packets[id] = reader.rest(); if(this.debug) { - console.log("Received packet #"+id); - if(last) console.log("(last)"); + this.debugLog("Received packet #"+id + (last ? " (last)" : "")); } if(!numPackets || Object.keys(packets).length !== numPackets) return; diff --git a/protocols/minecraft.js b/protocols/minecraft.js index 61c0730..fcf221b 100644 --- a/protocols/minecraft.js +++ b/protocols/minecraft.js @@ -57,17 +57,15 @@ class Minecraft extends Core { let data = receivedData; const packetId = varint.decode(data); - if(this.debug) console.log("Packet ID: "+packetId); + this.debugLog("Packet ID: "+packetId); data = data.slice(varint.decode.bytes); const strLen = varint.decode(data); - if(this.debug) console.log("String Length: "+strLen); + this.debugLog("String Length: "+strLen); data = data.slice(varint.decode.bytes); const str = data.toString('utf8'); - if(this.debug) { - console.log(str); - } + this.debugLog(str); let json; try { diff --git a/protocols/unreal2.js b/protocols/unreal2.js index a34021a..d89147c 100644 --- a/protocols/unreal2.js +++ b/protocols/unreal2.js @@ -87,14 +87,14 @@ class Unreal2 extends Core { ]); } readExtraInfo(reader,state) { - if(this.debug) { - console.log("UNREAL2 EXTRA INFO:"); - console.log(reader.uint(4)); - console.log(reader.uint(4)); - console.log(reader.uint(4)); - console.log(reader.uint(4)); - console.log(reader.buffer.slice(reader.i)); - } + this.debugLog(log => { + log("UNREAL2 EXTRA INFO:"); + log(reader.uint(4)); + log(reader.uint(4)); + log(reader.uint(4)); + log(reader.uint(4)); + log(reader.buffer.slice(reader.i)); + }); } readUnrealString(reader, stripColor) { let length = reader.uint(1); @@ -105,10 +105,10 @@ class Unreal2 extends Core { if(length > 0) out = reader.string(); } else { length = (length&0x7f)*2; - if(this.debug) { - console.log("UCS2 STRING"); - console.log(length,reader.buffer.slice(reader.i,reader.i+length)); - } + this.debugLog(log => { + log("UCS2 STRING"); + log(length,reader.buffer.slice(reader.i,reader.i+length)); + }); out = reader.string({encoding:'ucs2',length:length}); } diff --git a/protocols/valve.js b/protocols/valve.js index 7dfc082..52c033f 100644 --- a/protocols/valve.js +++ b/protocols/valve.js @@ -36,7 +36,7 @@ class Valve extends Core { } async queryInfo(state) { - if(this.debug) console.log("Requesting info ..."); + this.debugLog("Requesting info ..."); const b = await this.sendPacket( 0x54, false, @@ -114,12 +114,10 @@ class Valve extends Core { ) { this._skipSizeInSplitHeader = true; } - if(this.debug) { - console.log("STEAM APPID: "+state.raw.steamappid); - console.log("PROTOCOL: "+state.raw.protocol); - } + this.debugLog("STEAM APPID: "+state.raw.steamappid); + this.debugLog("PROTOCOL: "+state.raw.protocol); if(state.raw.protocol === 48) { - if(this.debug) console.log("GOLDSRC DETECTED - USING MODIFIED SPLIT FORMAT"); + this.debugLog("GOLDSRC DETECTED - USING MODIFIED SPLIT FORMAT"); this.goldsrcSplits = true; } } @@ -128,7 +126,7 @@ class Valve extends Core { if(this.legacyChallenge) { // sendPacket will catch the response packet and // save the challenge for us - if(this.debug) console.log("Requesting legacy challenge key ..."); + this.debugLog("Requesting legacy challenge key ..."); await this.sendPacket( 0x57, false, @@ -146,7 +144,7 @@ class Valve extends Core { // Ignore timeouts in only this case const allowTimeout = state.raw.steamappid === 730; - if(this.debug) console.log("Requesting player list ..."); + this.debugLog("Requesting player list ..."); const b = await this.sendPacket( 0x55, true, @@ -164,7 +162,7 @@ class Valve extends Core { const score = reader.int(4); const time = reader.float(); - if(this.debug) console.log("Found player: "+name+" "+score+" "+time); + this.debugLog("Found player: "+name+" "+score+" "+time); // connecting players don't count as players. if(!name) continue; @@ -180,7 +178,7 @@ class Valve extends Core { async queryRules(state) { state.raw.rules = {}; - if(this.debug) console.log("Requesting rules ..."); + this.debugLog("Requesting rules ..."); const b = await this.sendPacket(0x56,true,null,0x45,true); if (b === null) return; // timed out - the server probably just has rules disabled @@ -258,14 +256,14 @@ class Valve extends Core { (payload) => { const reader = this.reader(payload); const type = reader.uint(1); - if (this.debug) console.log("Received " + type.toString(16) + " expected " + expect.toString(16)); + this.debugLog(() => "Received " + type.toString(16) + " expected " + expect.toString(16)); if (type === 0x41) { const key = reader.uint(4); if (this._challenge !== key) { - if (this.debug) console.log('Received new challenge key: ' + key); + this.debugLog('Received new challenge key: ' + key); this._challenge = key; if (sendChallenge) { - if (this.debug) console.log('Challenge key changed -- allowing query retry if needed'); + this.debugLog('Challenge key changed -- allowing query retry if needed'); requestKeyChanged = true; } } @@ -326,7 +324,7 @@ class Valve extends Core { const header = reader.int(4); if(header === -1) { // full package - if(this.debug) console.log("Received full packet"); + this.debugLog("Received full packet"); return onResponse(reader.rest()); } if(header === -2) { @@ -354,10 +352,8 @@ class Valve extends Core { packets[packetNum] = payload; - if(this.debug) { - console.log("Received partial packet uid:"+uid+" num:"+packetNum); - console.log("Received "+Object.keys(packets).length+'/'+numPackets+" packets for this UID"); - } + this.debugLog(() => "Received partial packet uid:"+uid+" num:"+packetNum); + this.debugLog(() => "Received "+Object.keys(packets).length+'/'+numPackets+" packets for this UID"); if(Object.keys(packets).length !== numPackets) return; @@ -365,20 +361,18 @@ class Valve extends Core { const list = []; for(let i = 0; i < numPackets; i++) { if(!(i in packets)) { - this.fatal('Missing packet #'+i); - return true; + throw new Error('Missing packet #'+i); } list.push(packets[i]); } let assembled = Buffer.concat(list); if(bzip) { - if(this.debug) console.log("BZIP DETECTED - Extracing packet..."); + this.debugLog("BZIP DETECTED - Extracing packet..."); try { assembled = Buffer.from(Bzip2.decompressFile(assembled)); } catch(e) { - this.fatal('Invalid bzip packet'); - return true; + throw new Error('Invalid bzip packet'); } } const assembledReader = this.reader(assembled);