Improve logging

This commit is contained in:
mmorrison 2019-01-09 05:50:30 -06:00
parent 9b8423b20a
commit 484e99b29c
8 changed files with 88 additions and 85 deletions

View File

@ -98,7 +98,7 @@ class Battlefield extends Core {
return await this.tcpSend(socket, outPacket, (data) => { return await this.tcpSend(socket, outPacket, (data) => {
const decoded = this.decodePacket(data); const decoded = this.decodePacket(data);
if(decoded) { if(decoded) {
if(this.debug) console.log(decoded); this.debugLog(decoded);
if(decoded.shift() !== 'OK') throw new Error('Missing OK'); if(decoded.shift() !== 'OK') throw new Error('Missing OK');
return decoded; return decoded;
} }

View File

@ -79,7 +79,7 @@ class Core extends EventEmitter {
try { try {
leak.cleanup(); leak.cleanup();
} catch(e) { } catch(e) {
if (this.debug) console.log("Error during async cleanup: " + e.stack); this.debugLog("Error during async cleanup: " + e.stack);
} }
} }
this.asyncLeaks.clear(); this.asyncLeaks.clear();
@ -137,18 +137,18 @@ class Core extends EventEmitter {
}; };
const resolveStandard = async (host) => { const resolveStandard = async (host) => {
if(isIp(host)) return 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); const {address,family} = await dnsLookupAsync(host);
if(this.debug) console.log(address); this.debugLog(address);
return address; return address;
}; };
const resolveSrv = async (srv,host) => { const resolveSrv = async (srv,host) => {
if(isIp(host)) return 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; let records;
try { try {
records = await dnsResolveAsync(srv + '.' + host, 'SRV'); records = await dnsResolveAsync(srv + '.' + host, 'SRV');
if(this.debug) console.log(records); this.debugLog(records);
if(records.length >= 1) { if(records.length >= 1) {
const record = records[0]; const record = records[0];
this.options.port = record.port; this.options.port = record.port;
@ -156,7 +156,7 @@ class Core extends EventEmitter {
return await resolveStandard(srvhost); return await resolveStandard(srvhost);
} }
} catch(e) { } catch(e) {
if (this.debug) console.log(e.toString()); this.debugLog(e.toString());
} }
return await resolveStandard(host); return await resolveStandard(host);
}; };
@ -169,10 +169,10 @@ class Core extends EventEmitter {
const id = ++this.lastAsyncLeakId; const id = ++this.lastAsyncLeakId;
const stack = new Error().stack; const stack = new Error().stack;
const entry = { id: id, cleanup: fn, stack: 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); this.asyncLeaks.add(entry);
return () => { return () => {
if (this.debug) console.log("Removing async leak: " + id); this.debugLog("Removing async leak: " + id);
this.asyncLeaks.delete(entry); this.asyncLeaks.delete(entry);
} }
} }
@ -215,24 +215,22 @@ class Core extends EventEmitter {
socket.setNoDelay(true); socket.setNoDelay(true);
const cancelAsyncLeak = this.addAsyncLeak(() => socket.destroy()); const cancelAsyncLeak = this.addAsyncLeak(() => socket.destroy());
if(this.debug) { this.debugLog(log => {
console.log(address+':'+port+" TCP Connecting"); this.debugLog(address+':'+port+" TCP Connecting");
const writeHook = socket.write; const writeHook = socket.write;
socket.write = (...args) => { socket.write = (...args) => {
console.log(address+':'+port+" TCP-->"); log(address+':'+port+" TCP-->");
console.log(HexUtil.debugDump(args[0])); log(HexUtil.debugDump(args[0]));
writeHook.apply(socket,args); writeHook.apply(socket,args);
}; };
socket.on('error', e => console.log('TCP Error: ' + e)); socket.on('error', e => log('TCP Error: ' + e));
socket.on('close', () => console.log('TCP Closed')); socket.on('close', () => log('TCP Closed'));
socket.on('data', (data) => { socket.on('data', (data) => {
if(this.debug) { log(address+':'+port+" <--TCP");
console.log(address+':'+port+" <--TCP"); log(data);
console.log(HexUtil.debugDump(data));
}
}); });
socket.on('ready', () => console.log(address+':'+port+" TCP Connected")); socket.on('ready', () => log(address+':'+port+" TCP Connected"));
} });
try { try {
await this.timedPromise( 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(!('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(!('address' in this.options)) throw new Error('Attempted to send without setting an address');
if(typeof buffer === 'string') buffer = Buffer.from(buffer,'binary'); if(typeof buffer === 'string') buffer = Buffer.from(buffer,'binary');
if(this.debug) { this.debugLog(log => {
console.log(this.options.address+':'+this.options.port_query+" UDP-->"); log(this.options.address+':'+this.options.port_query+" UDP-->");
console.log(HexUtil.debugDump(buffer)); log(HexUtil.debugDump(buffer));
} });
return await this.withUdpLock(async() => { return await this.withUdpLock(async() => {
this.udpSocket.send(buffer,0,buffer.length,this.options.port_query,this.options.address); this.udpSocket.send(buffer,0,buffer.length,this.options.port_query,this.options.address);
return await new Promise((resolve,reject) => { return await new Promise((resolve,reject) => {
const cancelTimeout = this.setTimeout(() => { const cancelTimeout = this.setTimeout(() => {
if (this.debug) console.log("UDP timeout detected"); this.debugLog("UDP timeout detected");
let success = false; let success = false;
if (onTimeout) { if (onTimeout) {
const result = onTimeout(); const result = onTimeout();
if (result !== undefined) { if (result !== undefined) {
if (this.debug) console.log("UDP timeout resolved by callback"); this.debugLog("UDP timeout resolved by callback");
resolve(result); resolve(result);
success = true; success = true;
} }
@ -342,7 +340,7 @@ class Core extends EventEmitter {
this.udpCallback = (buffer) => { this.udpCallback = (buffer) => {
const result = onPacket(buffer); const result = onPacket(buffer);
if(result !== undefined) { if(result !== undefined) {
if (this.debug) console.log("UDP send finished by callback"); this.debugLog("UDP send finished by callback");
cancelTimeout(); cancelTimeout();
resolve(result); resolve(result);
} }
@ -366,6 +364,24 @@ class Core extends EventEmitter {
promise.finally(cancelAsyncLeak); promise.finally(cancelAsyncLeak);
return promise; 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; module.exports = Core;

View File

@ -7,7 +7,7 @@ class Ffow extends Valve {
this.legacyChallenge = true; this.legacyChallenge = true;
} }
async queryInfo(state) { async queryInfo(state) {
if(this.debug) console.log("Requesting ffow info ..."); this.debugLog("Requesting ffow info ...");
const b = await this.sendPacket( const b = await this.sendPacket(
0x46, 0x46,
false, false,

View File

@ -64,19 +64,19 @@ class Gamespy2 extends Core {
// so we can detect this. // so we can detect this.
if (count > 64) { if (count > 64) {
reader.skip(-1); 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 { } 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 = []; const fields = [];
while(!reader.done()) { while(!reader.done()) {
let field = reader.string(); let field = reader.string();
if(!field) break; if(!field) break;
fields.push(field); fields.push(field);
if(this.debug) console.log("field:"+field); this.debugLog("field:"+field);
} }
if (!fields.length) return []; if (!fields.length) return [];
@ -88,7 +88,7 @@ class Gamespy2 extends Core {
let key = fields[iField]; let key = fields[iField];
let value = reader.string(); let value = reader.string();
if(!value && iField === 0) break outer; if(!value && iField === 0) break outer;
if(this.debug) console.log("value:"+value); this.debugLog("value:"+value);
if(key === 'player_') key = 'name'; if(key === 'player_') key = 'name';
else if(key === 'score_') key = 'score'; else if(key === 'score_') key = 'score';
else if(key === 'deaths_') key = 'deaths'; else if(key === 'deaths_') key = 'deaths';

View File

@ -39,10 +39,8 @@ class Gamespy3 extends Core {
const packet = packets[iPacket]; const packet = packets[iPacket];
const reader = this.reader(packet); const reader = this.reader(packet);
if(this.debug) { this.debugLog("Parsing packet #" + iPacket);
console.log("Parsing packet #" + iPacket); this.debugLog(packet);
console.log(HexUtil.debugDump(packet));
}
// Parse raw server key/values // Parse raw server key/values
@ -58,7 +56,7 @@ class Gamespy3 extends Core {
} }
state.raw[key] = value; 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); let offset = reader.uint(1);
firstMode = false; firstMode = false;
if (this.debug) { this.debugLog(() => "Parsing new field: itemType=" + itemType + " fieldName=" + fieldName + " startOffset=" + offset);
console.log("Parsing new field: itemType=" + itemType + " fieldName=" + fieldName + " startOffset=" + offset);
}
while(!reader.done()) { while(!reader.done()) {
const item = reader.string(); const item = reader.string();
@ -102,7 +98,7 @@ class Gamespy3 extends Core {
while(items.length <= offset) { items.push({}); } while(items.length <= offset) { items.push({}); }
items[offset][fieldName] = item; items[offset][fieldName] = item;
if (this.debug) console.log("* " + item); this.debugLog("* " + item);
offset++; offset++;
} }
} }
@ -173,8 +169,7 @@ class Gamespy3 extends Core {
packets[id] = reader.rest(); packets[id] = reader.rest();
if(this.debug) { if(this.debug) {
console.log("Received packet #"+id); this.debugLog("Received packet #"+id + (last ? " (last)" : ""));
if(last) console.log("(last)");
} }
if(!numPackets || Object.keys(packets).length !== numPackets) return; if(!numPackets || Object.keys(packets).length !== numPackets) return;

View File

@ -57,17 +57,15 @@ class Minecraft extends Core {
let data = receivedData; let data = receivedData;
const packetId = varint.decode(data); const packetId = varint.decode(data);
if(this.debug) console.log("Packet ID: "+packetId); this.debugLog("Packet ID: "+packetId);
data = data.slice(varint.decode.bytes); data = data.slice(varint.decode.bytes);
const strLen = varint.decode(data); const strLen = varint.decode(data);
if(this.debug) console.log("String Length: "+strLen); this.debugLog("String Length: "+strLen);
data = data.slice(varint.decode.bytes); data = data.slice(varint.decode.bytes);
const str = data.toString('utf8'); const str = data.toString('utf8');
if(this.debug) { this.debugLog(str);
console.log(str);
}
let json; let json;
try { try {

View File

@ -87,14 +87,14 @@ class Unreal2 extends Core {
]); ]);
} }
readExtraInfo(reader,state) { readExtraInfo(reader,state) {
if(this.debug) { this.debugLog(log => {
console.log("UNREAL2 EXTRA INFO:"); log("UNREAL2 EXTRA INFO:");
console.log(reader.uint(4)); log(reader.uint(4));
console.log(reader.uint(4)); log(reader.uint(4));
console.log(reader.uint(4)); log(reader.uint(4));
console.log(reader.uint(4)); log(reader.uint(4));
console.log(reader.buffer.slice(reader.i)); log(reader.buffer.slice(reader.i));
} });
} }
readUnrealString(reader, stripColor) { readUnrealString(reader, stripColor) {
let length = reader.uint(1); let length = reader.uint(1);
@ -105,10 +105,10 @@ class Unreal2 extends Core {
if(length > 0) out = reader.string(); if(length > 0) out = reader.string();
} else { } else {
length = (length&0x7f)*2; length = (length&0x7f)*2;
if(this.debug) { this.debugLog(log => {
console.log("UCS2 STRING"); log("UCS2 STRING");
console.log(length,reader.buffer.slice(reader.i,reader.i+length)); log(length,reader.buffer.slice(reader.i,reader.i+length));
} });
out = reader.string({encoding:'ucs2',length:length}); out = reader.string({encoding:'ucs2',length:length});
} }

View File

@ -36,7 +36,7 @@ class Valve extends Core {
} }
async queryInfo(state) { async queryInfo(state) {
if(this.debug) console.log("Requesting info ..."); this.debugLog("Requesting info ...");
const b = await this.sendPacket( const b = await this.sendPacket(
0x54, 0x54,
false, false,
@ -114,12 +114,10 @@ class Valve extends Core {
) { ) {
this._skipSizeInSplitHeader = true; this._skipSizeInSplitHeader = true;
} }
if(this.debug) { this.debugLog("STEAM APPID: "+state.raw.steamappid);
console.log("STEAM APPID: "+state.raw.steamappid); this.debugLog("PROTOCOL: "+state.raw.protocol);
console.log("PROTOCOL: "+state.raw.protocol);
}
if(state.raw.protocol === 48) { 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; this.goldsrcSplits = true;
} }
} }
@ -128,7 +126,7 @@ class Valve extends Core {
if(this.legacyChallenge) { if(this.legacyChallenge) {
// sendPacket will catch the response packet and // sendPacket will catch the response packet and
// save the challenge for us // save the challenge for us
if(this.debug) console.log("Requesting legacy challenge key ..."); this.debugLog("Requesting legacy challenge key ...");
await this.sendPacket( await this.sendPacket(
0x57, 0x57,
false, false,
@ -146,7 +144,7 @@ class Valve extends Core {
// Ignore timeouts in only this case // Ignore timeouts in only this case
const allowTimeout = state.raw.steamappid === 730; const allowTimeout = state.raw.steamappid === 730;
if(this.debug) console.log("Requesting player list ..."); this.debugLog("Requesting player list ...");
const b = await this.sendPacket( const b = await this.sendPacket(
0x55, 0x55,
true, true,
@ -164,7 +162,7 @@ class Valve extends Core {
const score = reader.int(4); const score = reader.int(4);
const time = reader.float(); 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. // connecting players don't count as players.
if(!name) continue; if(!name) continue;
@ -180,7 +178,7 @@ class Valve extends Core {
async queryRules(state) { async queryRules(state) {
state.raw.rules = {}; state.raw.rules = {};
if(this.debug) console.log("Requesting rules ..."); this.debugLog("Requesting rules ...");
const b = await this.sendPacket(0x56,true,null,0x45,true); const b = await this.sendPacket(0x56,true,null,0x45,true);
if (b === null) return; // timed out - the server probably just has rules disabled if (b === null) return; // timed out - the server probably just has rules disabled
@ -258,14 +256,14 @@ class Valve extends Core {
(payload) => { (payload) => {
const reader = this.reader(payload); const reader = this.reader(payload);
const type = reader.uint(1); 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) { if (type === 0x41) {
const key = reader.uint(4); const key = reader.uint(4);
if (this._challenge !== key) { if (this._challenge !== key) {
if (this.debug) console.log('Received new challenge key: ' + key); this.debugLog('Received new challenge key: ' + key);
this._challenge = key; this._challenge = key;
if (sendChallenge) { 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; requestKeyChanged = true;
} }
} }
@ -326,7 +324,7 @@ class Valve extends Core {
const header = reader.int(4); const header = reader.int(4);
if(header === -1) { if(header === -1) {
// full package // full package
if(this.debug) console.log("Received full packet"); this.debugLog("Received full packet");
return onResponse(reader.rest()); return onResponse(reader.rest());
} }
if(header === -2) { if(header === -2) {
@ -354,10 +352,8 @@ class Valve extends Core {
packets[packetNum] = payload; packets[packetNum] = payload;
if(this.debug) { this.debugLog(() => "Received partial packet uid:"+uid+" num:"+packetNum);
console.log("Received partial packet uid:"+uid+" num:"+packetNum); this.debugLog(() => "Received "+Object.keys(packets).length+'/'+numPackets+" packets for this UID");
console.log("Received "+Object.keys(packets).length+'/'+numPackets+" packets for this UID");
}
if(Object.keys(packets).length !== numPackets) return; if(Object.keys(packets).length !== numPackets) return;
@ -365,20 +361,18 @@ class Valve extends Core {
const list = []; const list = [];
for(let i = 0; i < numPackets; i++) { for(let i = 0; i < numPackets; i++) {
if(!(i in packets)) { if(!(i in packets)) {
this.fatal('Missing packet #'+i); throw new Error('Missing packet #'+i);
return true;
} }
list.push(packets[i]); list.push(packets[i]);
} }
let assembled = Buffer.concat(list); let assembled = Buffer.concat(list);
if(bzip) { if(bzip) {
if(this.debug) console.log("BZIP DETECTED - Extracing packet..."); this.debugLog("BZIP DETECTED - Extracing packet...");
try { try {
assembled = Buffer.from(Bzip2.decompressFile(assembled)); assembled = Buffer.from(Bzip2.decompressFile(assembled));
} catch(e) { } catch(e) {
this.fatal('Invalid bzip packet'); throw new Error('Invalid bzip packet');
return true;
} }
} }
const assembledReader = this.reader(assembled); const assembledReader = this.reader(assembled);