From 164099fe08077e30d4b5d04e57c4ede53e781cdd Mon Sep 17 00:00:00 2001 From: Eric Caron Date: Sat, 16 Jan 2016 17:49:54 -0600 Subject: [PATCH 1/4] Attach all output into a controllable logger This change keeps outputting, by default, to console. But it also introduces a setLogger prototype for every exposed component to optionally wrap the output into a different logger (e.g. bunyan) or turn off logging altogether. --- README.md | 12 +++++++++++- decode/ethernet_packet.js | 5 +++-- decode/ieee802.11/radio_packet.js | 5 +++-- decode/index.js | 7 +++++-- decode/ipv4.js | 7 ++++--- decode/null_packet.js | 3 ++- decode/pcap_packet.js | 19 ++++++++++++------- decode/sll_packet.js | 5 +++-- decode/tcp.js | 12 +++++++----- pcap.js | 4 ++++ set_logger.js | 18 ++++++++++++++++++ tcp_tracker.js | 19 +++++++++++++------ 12 files changed, 85 insertions(+), 31 deletions(-) create mode 100644 set_logger.js diff --git a/README.md b/README.md index a02c5a2..3cc9528 100644 --- a/README.md +++ b/README.md @@ -107,7 +107,7 @@ This structure is easy to explore with `sys.inspect`. TCP can be analyzed by feeding the packets into a `TCPTracker` and then listening for `session` and `end` events. ```javascript -var pcap = require('./pcap'), +var pcap = require('pcap'), tcp_tracker = new pcap.TCPTracker(), pcap_session = pcap.createSession('en0', "ip proto \\tcp"); @@ -129,6 +129,16 @@ see the wonderful things it can do for you. Hopefully the names of the properti See [http_trace](https://github.com/mranney/http_trace) for an example of how to use these events to decode HTTP (Works only on node 4). +### Logging + +By default, all logging goes to `console`. All exposed methods support an optional `setLogger` function that takes in +a logging component (such as [bunyan](https://www.npmjs.com/package/bunyan) or [winston](https://www.npmjs.com/package/winston)) +to direct logging into your application's preferred style. + +If you'd like to disable logging altogether, simple pass `false` into the `setLogger` function. + +Note: If you use the `pcap.decode` mechanism, your logger must be passed as an optional 3rd argument. + ## Some Common Problems ### TCP Segmentation Offload - TSO diff --git a/decode/ethernet_packet.js b/decode/ethernet_packet.js index 43afcc5..39d43c8 100644 --- a/decode/ethernet_packet.js +++ b/decode/ethernet_packet.js @@ -4,8 +4,9 @@ var IPv6 = require("./ipv6"); var Arp = require("./arp"); var Vlan = require("./vlan"); -function EthernetPacket(emitter) { +function EthernetPacket(emitter, logger) { this.emitter = emitter; + this.logger = logger; this.dhost = null; this.shost = null; this.ethertype = null; @@ -49,7 +50,7 @@ EthernetPacket.prototype.decode = function (raw_packet, offset) { this.payload = "need to implement LLDP"; break; default: - console.log("node_pcap: EthernetFrame() - Don't know how to decode ethertype " + this.ethertype); + this.logger.log("node_pcap: EthernetFrame() - Don't know how to decode ethertype " + this.ethertype); } } diff --git a/decode/ieee802.11/radio_packet.js b/decode/ieee802.11/radio_packet.js index 5024b6a..bb08c4b 100644 --- a/decode/ieee802.11/radio_packet.js +++ b/decode/ieee802.11/radio_packet.js @@ -39,8 +39,9 @@ PresentFieldFlags.prototype.decode = function decode (flags) { return this; }; -function RadioPacket(emitter) { +function RadioPacket(emitter, logger) { this.emitter = emitter; + this.logger = logger; this.headerRevision = undefined; this.headerPad = undefined; this.headerLength = undefined; @@ -95,7 +96,7 @@ RadioPacket.prototype.decode = function (raw_packet, offset) { if(p.txAttenuation) { offset++; } if(p.dbTxAttenuation) { offset += 2; } if(p.dbmTxPower) { offset++; } - if(p.antenna) { + if(p.antenna) { this.antenna = raw_packet[offset++]; } if(p.dbAntennaSignal) { offset++; } diff --git a/decode/index.js b/decode/index.js index 4bc4400..8efc1db 100644 --- a/decode/index.js +++ b/decode/index.js @@ -7,8 +7,11 @@ exports.ArpPacket = require("./arp"); exports.PcapPacket = require("./pcap_packet"); var PcapPacket = exports.PcapPacket; -function decode(packet, emitter) { - return new PcapPacket(emitter).decode(packet); +function decode(packet, emitter, logger) { + if (typeof logger === "undefined") { + logger = console; + } + return new PcapPacket(emitter, logger).decode(packet); } exports.decode = decode; diff --git a/decode/ipv4.js b/decode/ipv4.js index f50230b..e5b2641 100644 --- a/decode/ipv4.js +++ b/decode/ipv4.js @@ -31,8 +31,9 @@ IPFlags.prototype.toString = function () { return ret; }; -function IPv4(emitter) { - this.emitter = emitter; +function IPv4(emitter, logger) { + this.emitter = emitter; + this.logger = logger; this.version = undefined; this.headerLength = undefined; this.diffserv = undefined; @@ -116,7 +117,7 @@ IPv4.prototype.toString = function () { } else { ret += this.payload.constructor.name; } - + return ret + " " + this.payload; }; diff --git a/decode/null_packet.js b/decode/null_packet.js index 4e95521..24a9cef 100644 --- a/decode/null_packet.js +++ b/decode/null_packet.js @@ -1,8 +1,9 @@ var IPv4 = require("./ipv4"); var IPv6 = require("./ipv6"); -function NullPacket(emitter) { +function NullPacket(emitter, logger) { this.emitter = emitter; + this.logger = logger; this.pftype = undefined; this.payload = undefined; this._error = undefined; diff --git a/decode/pcap_packet.js b/decode/pcap_packet.js index ace8a63..02ac91e 100644 --- a/decode/pcap_packet.js +++ b/decode/pcap_packet.js @@ -3,6 +3,7 @@ var NullPacket = require("./null_packet"); var Ipv4 = require("./ipv4"); var RadioPacket = require("./ieee802.11/radio_packet"); var SLLPacket = require("./sll_packet"); +var setLogger = require("../set_logger"); // Setting properties from the C++ side is very slow, so we send in a shared Buffer. // The C++ side does this: @@ -19,13 +20,17 @@ function PcapHeader(raw_header) { this.len = raw_header.readUInt32LE(12, true); } -function PcapPacket(emitter) { +function PcapPacket(emitter, logger) { this.link_type = null; this.pcap_header = null; this.payload = null; this.emitter = emitter; + this.logger = console; + this.setLogger(logger); } +PcapPacket.prototype.setLogger = setLogger; + PcapPacket.prototype.decode = function (packet_with_header) { this.link_type = packet_with_header.link_type; this.pcap_header = new PcapHeader(packet_with_header.header); @@ -34,22 +39,22 @@ PcapPacket.prototype.decode = function (packet_with_header) { switch (this.link_type) { case "LINKTYPE_ETHERNET": - this.payload = new EthernetPacket(this.emitter).decode(buf, 0); + this.payload = new EthernetPacket(this.emitter, this.logger).decode(buf, 0); break; case "LINKTYPE_NULL": - this.payload = new NullPacket(this.emitter).decode(buf, 0); + this.payload = new NullPacket(this.emitter, this.logger).decode(buf, 0); break; case "LINKTYPE_RAW": - this.payload = new Ipv4(this.emitter).decode(buf, 0); + this.payload = new Ipv4(this.emitter, this.logger).decode(buf, 0); break; case "LINKTYPE_IEEE802_11_RADIO": - this.payload = new RadioPacket(this.emitter).decode(buf, 0); + this.payload = new RadioPacket(this.emitter, this.logger).decode(buf, 0); break; case "LINKTYPE_LINUX_SLL": - this.payload = new SLLPacket(this.emitter).decode(buf, 0); + this.payload = new SLLPacket(this.emitter, this.logger).decode(buf, 0); break; default: - console.log("node_pcap: PcapPacket.decode - Don't yet know how to decode link type " + this.link_type); + this.logger.log("node_pcap: PcapPacket.decode - Don't yet know how to decode link type " + this.link_type); } return this; diff --git a/decode/sll_packet.js b/decode/sll_packet.js index 1717144..ab05112 100644 --- a/decode/sll_packet.js +++ b/decode/sll_packet.js @@ -6,8 +6,9 @@ var IPv4 = require("./ipv4"); var IPv6 = require("./ipv6"); var Arp = require("./arp"); -function SLLPacket (emitter) { +function SLLPacket (emitter, logger) { this.emitter = emitter; + this.logger = logger; this.packet_type = null; this.address_type = null; this.address_len = null; @@ -47,7 +48,7 @@ SLLPacket.prototype.decode = function (raw_packet, offset) { this.payload = "need to implement LLDP"; break; default: - console.log("node_pcap: SLLPacket() - Don't know how to decode ethertype " + this.ethertype); + this.logger.log("node_pcap: SLLPacket() - Don't know how to decode ethertype " + this.ethertype); } } diff --git a/decode/tcp.js b/decode/tcp.js index 9d79d6a..dd021a0 100644 --- a/decode/tcp.js +++ b/decode/tcp.js @@ -1,6 +1,6 @@ -function TCPFlags(emitter) { - this.emitter = emitter; +function TCPFlags(logger) { + this.logger = logger; this.nonce = undefined; this.cwr = undefined; this.ece = undefined; @@ -57,7 +57,8 @@ TCPFlags.prototype.toString = function () { return ret; }; -function TCPOptions() { +function TCPOptions(logger) { + this.logger = logger; this.mss = null; this.window_scale = null; this.sack_ok = null; @@ -128,7 +129,7 @@ TCPOptions.prototype.decode = function (raw_packet, offset, len) { offset += 8; break; default: - console.log("Invalid TCP SACK option length " + raw_packet[offset + 1]); + this.logger.log("Invalid TCP SACK option length " + raw_packet[offset + 1]); offset = end_offset; } break; @@ -178,6 +179,7 @@ TCPOptions.prototype.toString = function () { function TCP(emitter) { this.emitter = emitter; + this.logger = console; this.sport = undefined; this.dport = undefined; this.seqno = undefined; @@ -216,7 +218,7 @@ TCP.prototype.decode = function (raw_packet, offset, len) { // of the header. this.headerLength = (raw_packet[offset] & 0xf0) >> 2; - this.flags = new TCPFlags().decode(raw_packet[offset], raw_packet[offset+1]); + this.flags = new TCPFlags(this.logger).decode(raw_packet[offset], raw_packet[offset+1]); offset += 2; this.windowSize = raw_packet.readUInt16BE(offset, true); // 14, 15 offset += 2; diff --git a/pcap.js b/pcap.js index 345986c..90ca551 100644 --- a/pcap.js +++ b/pcap.js @@ -5,6 +5,7 @@ var SocketWatcher = require("socketwatcher").SocketWatcher; var decode = require("./decode").decode; var tcp_tracker = require("./tcp_tracker"); var DNSCache = require("./dns_cache"); +var setLogger = require("./set_logger"); var timers = require("timers"); exports.decode = decode; @@ -13,6 +14,7 @@ exports.TCPSession = tcp_tracker.TCPSession; exports.DNSCache = DNSCache; function PcapSession(is_live, device_name, filter, buffer_size, outfile, is_monitor) { + this.logger = console; this.is_live = is_live; this.device_name = device_name; this.filter = filter || ""; @@ -94,6 +96,8 @@ function PacketWithHeader(buf, header, link_type) { this.link_type = link_type; } +PcapSession.prototype.setLogger = setLogger; + PcapSession.prototype.on_packet_ready = function () { var full_packet = new PacketWithHeader(this.buf, this.header, this.link_type); this.emit("packet", full_packet); diff --git a/set_logger.js b/set_logger.js new file mode 100644 index 0000000..1177194 --- /dev/null +++ b/set_logger.js @@ -0,0 +1,18 @@ +function setLogger(logger) { + if (typeof logger === "undefined") { + this.logger = console; + } else if (logger !== false) { + this.logger = logger; + } else { + this.logger = { + log: function() { }, + info: function() { }, + warn: function() { }, + error: function() { }, + trace: function() { } + }; + } + +} + +module.exports = setLogger; \ No newline at end of file diff --git a/tcp_tracker.js b/tcp_tracker.js index 6a2aff6..adbe6b4 100644 --- a/tcp_tracker.js +++ b/tcp_tracker.js @@ -2,13 +2,17 @@ var EventEmitter = require("events").EventEmitter; var inherits = require("util").inherits; var IPv4 = require("./decode/ipv4"); var TCP = require("./decode/tcp"); +var setLogger = require("./set_logger"); function TCPTracker() { + this.logger = console; this.sessions = {}; EventEmitter.call(this); } inherits(TCPTracker, EventEmitter); +TCPTracker.prototype.setLogger = setLogger; + TCPTracker.prototype.track_packet = function (packet) { var ip, tcp, src, dst, key, session; @@ -28,7 +32,7 @@ TCPTracker.prototype.track_packet = function (packet) { session = this.sessions[key]; if (! session) { is_new = true; - session = new TCPSession(); + session = new TCPSession(this.logger); this.sessions[key] = session; } @@ -44,7 +48,8 @@ TCPTracker.prototype.track_packet = function (packet) { // user should filter these out with their pcap filter, but oh well. }; -function TCPSession() { +function TCPSession(logger) { + this.logger = (typeof logger === "undefined") ? console : logger; this.src = null; this.src_name = null; // from DNS this.dst = null; @@ -83,6 +88,8 @@ function TCPSession() { } inherits(TCPSession, EventEmitter); +TCPSession.prototype.setLogger = setLogger; + TCPSession.prototype.track = function (packet) { var ip = packet.payload.payload; var tcp = ip.payload; @@ -135,7 +142,7 @@ TCPSession.prototype.SYN_SENT = function (packet) { this.state = "CLOSED"; this.emit("reset", this, "recv"); // TODO - check which direction did the reset, probably recv // } else { -// console.log("Didn't get SYN-ACK packet from dst while handshaking: " + util.inspect(tcp, false, 4)); +// this.logger.log("Didn't get SYN-ACK packet from dst while handshaking: " + util.inspect(tcp, false, 4)); } }; @@ -152,7 +159,7 @@ TCPSession.prototype.SYN_RCVD = function (packet) { this.emit("start", this); this.state = "ESTAB"; // } else { -// console.log("Didn't get ACK packet from src while handshaking: " + util.inspect(tcp, false, 4)); +// this.logger.log("Didn't get ACK packet from src while handshaking: " + util.inspect(tcp, false, 4)); } }; @@ -188,7 +195,7 @@ TCPSession.prototype.ESTAB = function (packet) { if (this.recv_packets[tcp.ackno]) { this.send_acks[tcp.ackno] = this.current_cap_time; } - // console.log("sending ACK for packet we didn't see received: " + tcp.ackno); + // this.logger.log("sending ACK for packet we didn't see received: " + tcp.ackno); if (tcp.flags.fin) { this.state = "FIN_WAIT"; } @@ -216,7 +223,7 @@ TCPSession.prototype.ESTAB = function (packet) { this.state = "CLOSE_WAIT"; } } else { - console.log("non-matching packet in session: " + packet); + this.logger.log("non-matching packet in session: " + packet); } }; From ca00da0079a1b9f5669e5bb6f7ac3f404e3ed487 Mon Sep 17 00:00:00 2001 From: Eric Caron Date: Sat, 16 Jan 2016 22:01:27 -0600 Subject: [PATCH 2/4] Including code coverage for set_logger --- set_logger.js | 38 ++++++++++++++++++++++---------------- 1 file changed, 22 insertions(+), 16 deletions(-) diff --git a/set_logger.js b/set_logger.js index 1177194..774fcb2 100644 --- a/set_logger.js +++ b/set_logger.js @@ -1,18 +1,24 @@ -function setLogger(logger) { - if (typeof logger === "undefined") { - this.logger = console; - } else if (logger !== false) { - this.logger = logger; - } else { - this.logger = { - log: function() { }, - info: function() { }, - warn: function() { }, - error: function() { }, - trace: function() { } - }; - } +var set_logger = require("../set_logger"); +require("should"); -} +describe("set_logger", function(){ + beforeEach(function () { + this.instance = {}; + this.instance.logger = undefined; + this.instance.setLogger = set_logger; + }); -module.exports = setLogger; \ No newline at end of file + it("attaches console by default", function(){ + this.instance.setLogger(); + this.instance.logger.should.be.an.instanceOf(Object).and.have.property("Console"); + }); + it("attaches a stubbed console on false", function(){ + this.instance.setLogger(false); + this.instance.logger.should.be.an.instanceOf(Object).and.not.have.property("Console"); + }); + it("attaches whatever else is passed in, if defined and not false", function(){ + // Demonstrates that we don't prevent the user from sending whatever they want to Logger + this.instance.setLogger("b"); + this.instance.logger.should.equal("b"); + }); +}); \ No newline at end of file From 80085331dd08d22535b72a3a2d75cf7d81fb2e2b Mon Sep 17 00:00:00 2001 From: Eric Caron Date: Sat, 16 Jan 2016 22:43:24 -0600 Subject: [PATCH 3/4] Including the spec --- spec/set_logger.js | 24 ++++++++++++++++++++++++ 1 file changed, 24 insertions(+) create mode 100644 spec/set_logger.js diff --git a/spec/set_logger.js b/spec/set_logger.js new file mode 100644 index 0000000..774fcb2 --- /dev/null +++ b/spec/set_logger.js @@ -0,0 +1,24 @@ +var set_logger = require("../set_logger"); +require("should"); + +describe("set_logger", function(){ + beforeEach(function () { + this.instance = {}; + this.instance.logger = undefined; + this.instance.setLogger = set_logger; + }); + + it("attaches console by default", function(){ + this.instance.setLogger(); + this.instance.logger.should.be.an.instanceOf(Object).and.have.property("Console"); + }); + it("attaches a stubbed console on false", function(){ + this.instance.setLogger(false); + this.instance.logger.should.be.an.instanceOf(Object).and.not.have.property("Console"); + }); + it("attaches whatever else is passed in, if defined and not false", function(){ + // Demonstrates that we don't prevent the user from sending whatever they want to Logger + this.instance.setLogger("b"); + this.instance.logger.should.equal("b"); + }); +}); \ No newline at end of file From b3e753a2d0e3d9a0fac642410696c635c7fca4aa Mon Sep 17 00:00:00 2001 From: Eric Caron Date: Sat, 16 Jan 2016 22:47:30 -0600 Subject: [PATCH 4/4] Correcting situation where spec overwrote the true file --- set_logger.js | 38 ++++++++++++++++---------------------- 1 file changed, 16 insertions(+), 22 deletions(-) diff --git a/set_logger.js b/set_logger.js index 774fcb2..6e7af88 100644 --- a/set_logger.js +++ b/set_logger.js @@ -1,24 +1,18 @@ -var set_logger = require("../set_logger"); -require("should"); +function setLogger(logger) { + if (typeof logger === "undefined") { + this.logger = console; + } else if (logger !== false) { + this.logger = logger; + } else { + this.logger = { + log: function() { }, + info: function() { }, + warn: function() { }, + error: function() { }, + trace: function() { } + }; + } -describe("set_logger", function(){ - beforeEach(function () { - this.instance = {}; - this.instance.logger = undefined; - this.instance.setLogger = set_logger; - }); +} - it("attaches console by default", function(){ - this.instance.setLogger(); - this.instance.logger.should.be.an.instanceOf(Object).and.have.property("Console"); - }); - it("attaches a stubbed console on false", function(){ - this.instance.setLogger(false); - this.instance.logger.should.be.an.instanceOf(Object).and.not.have.property("Console"); - }); - it("attaches whatever else is passed in, if defined and not false", function(){ - // Demonstrates that we don't prevent the user from sending whatever they want to Logger - this.instance.setLogger("b"); - this.instance.logger.should.equal("b"); - }); -}); \ No newline at end of file +module.exports = setLogger;