dbus-vis: Initial commit
dbus-vis visualizes PCAP files captured by busctl as well as
text-format outputs from busctl.
dbus-vis displays the visualized results in horizontal
timelines, where each horizontal bar represents a DBus request, or
an IPMI request (an IPMI request is a specific kind of DBus request
sent to the IPMI daemon.)
The requests may be grouped by one or more fields including
type, sender, destination, path, interface, member.
In addition, if the BMC console is available, dbus-vis can connect
to the BMC console and capture DBus/IPMI requests in real time.
dbus-vis is in the form of a web page and is wrapped using Electron
to run as a desktop app.
Basic usage:
* Mouse click and drag:
* If mouse is over time axis: drag timeline horizontally
* If mouse is over vertical scroll bar: scroll up/down
* Otherwise: select a region for measuring time & zooming in
* Mouse Scroll wheel:
* If mouse is over time axis: zoom in/out
* Otherwise: scroll up/down
* Click on the expandable headers will expand/collapse the entries under
that particular header.
Signed-off-by: Sui Chen <suichen@google.com>
Change-Id: I863c2ba80025d10efb44fd12868e37912fae9a47
diff --git a/dbus-vis/ipmi_capture.js b/dbus-vis/ipmi_capture.js
new file mode 100644
index 0000000..eb1ac9e
--- /dev/null
+++ b/dbus-vis/ipmi_capture.js
@@ -0,0 +1,507 @@
+const { spawn } = require('child_process');
+const targz = require('targz');
+
+const DBUS_MONITOR_LEGACY =
+ 'dbus-monitor --system | grep "sendMessage\\|ReceivedMessage" -A7 \n';
+const DBUS_MONITOR_NEW =
+ 'dbus-monitor --system | grep "member=execute\\|method return" -A7 \n';
+
+// Capture state for all scripts
+var g_capture_state = 'not started';
+var g_capture_mode = 'live';
+
+// For capturing IPMI requests live
+var g_dbus_monitor_cmd = '';
+
+// For tracking transfer
+var g_hexdump = '';
+var g_hexdump_received_size = 0;
+var g_hexdump_total_size = 0;
+
+function currTimestamp() {
+ var tmp = new Date();
+ return (tmp.getTime() + tmp.getTimezoneOffset() * 60000) / 1000;
+}
+
+var g_child;
+var g_rz;
+
+var g_capture_live = true;
+var g_dbus_capture_tarfile_size = 0;
+
+function ParseHexDump(hd) {
+ let ret = [];
+ let lines = hd.split('\n');
+ let tot_size = 0;
+ for (let i = 0; i < lines.length; i++) {
+ const line = lines[i].trimEnd();
+ const sp = line.split(' ');
+ if (line.length < 1) continue;
+ if (sp.length < 1) continue;
+
+ for (let j = 1; j < sp.length; j++) {
+ let b0 = sp[j].slice(2);
+ let b1 = sp[j].slice(0, 2);
+ b0 = parseInt(b0, 16);
+ b1 = parseInt(b1, 16);
+ ret.push(b0);
+ ret.push(b1);
+ }
+
+ console.log('[' + line + ']')
+
+ {
+ tot_size = parseInt(sp[0], 16);
+ console.log('File size: ' + tot_size + ' ' + sp[0]);
+ }
+ }
+ ret = ret.slice(0, tot_size);
+ return new Buffer(ret);
+}
+
+function SaveHexdumpToFile(hd, file_name) {
+ const buf = ParseHexDump(hd);
+ fs.writeFileSync(file_name, buf)
+}
+
+// Delimiters: ">>>>>>" and "<<<<<<"
+function ExtractMyDelimitedStuff(x, parse_as = undefined) {
+ let i0 = x.lastIndexOf('>>>>>>'), i1 = x.lastIndexOf('<<<<<<');
+ if (i0 != -1 && i1 != -1) {
+ let ret = x.substr(i0 + 6, i1 - i0 - 6);
+ if (parse_as == undefined)
+ return ret;
+ else if (parse_as == 'int')
+ return parseInt(ret);
+ } else
+ return null;
+}
+
+function streamWrite(stream, chunk, encoding = 'utf8') {
+ return new Promise((resolve, reject) => {
+ const errListener = (err) => {
+ stream.removeListener('error', errListener);
+ reject(err);
+ };
+ stream.addListener('error', errListener);
+ const callback = () => {
+ stream.removeListener('error', errListener);
+ resolve(undefined);
+ };
+ stream.write(chunk, encoding, callback);
+ });
+}
+
+function ExtractTarFile() {
+ const tar_file = 'DBUS_MONITOR.tar.gz';
+ const target = '.';
+ targz.decompress({src: tar_file, dest: target}, function(err) {
+ if (err) {
+ console.log('Error decompressing .tar.gz file:' + err);
+ }
+ // Attempt to load even if error occurs
+ // example error: "Error decompressing .tar.gz file:Error: incorrect data check"
+ console.log('Done! will load file contents');
+ if (g_capture_mode == 'staged') {
+ fs.readFile('./DBUS_MONITOR', {encoding: 'utf-8'}, (err, data) => {
+ if (err) {
+ console.log('Error in readFile: ' + err);
+ } else {
+ ParseIPMIDump(data);
+ }
+ });
+ } else if (g_capture_mode == 'staged2') {
+ OpenDBusPcapFile('./DBUS_MONITOR');
+ }
+ });
+}
+
+function OnCaptureStart() {
+ switch (g_capture_state) {
+ case 'not started':
+ capture_info.textContent = 'dbus-monitor running on BMC';
+ break;
+ default:
+ break;
+ }
+}
+
+function OnCaptureStop() {
+ btn_start_capture.disabled = false;
+ select_capture_mode.disabled = false;
+ text_hostname.disabled = false;
+ g_capture_state = 'not started';
+}
+
+async function OnTransferCompleted() {
+ setTimeout(function() {
+ console.log('OnTransferCompleted');
+ g_child.kill('SIGINT');
+ }, 5000);
+
+ capture_info.textContent = 'Loaded the capture file';
+ OnCaptureStop();
+ ExtractTarFile();
+}
+
+// Example output from stderr:
+// ^M Bytes received: 2549/ 2549 BPS:6370
+async function LaunchRZ() {
+ // On the Host
+
+ // Remove existing file
+ const file_names = ['DBUS_MONITOR', 'DBUS_MONITOR.tar.gz'];
+ try {
+ for (let i = 0; i < 2; i++) {
+ const fn = file_names[i];
+ if (fs.existsSync(fn)) {
+ fs.unlinkSync(fn); // unlink is basically rm
+ console.log('Removed file: ' + fn);
+ }
+ }
+ } catch (err) {
+ }
+
+ g_rz = spawn(
+ 'screen', ['rz', '-a', '-e', '-E', '-r', '-w', '32767'], {shell: false});
+ g_rz.stdout.on('data', (data) => {
+ console.log('[rz] received ' + data.length + ' B');
+ console.log(data);
+ console.log(data + '');
+ // data = MyCorrection(data);
+ if (data != undefined) g_child.stdin.write(data);
+ });
+ g_rz.stderr.on('data', (data) => {
+ console.log('[rz] error: ' + data);
+ let s = data.toString();
+ let idx = s.lastIndexOf('Bytes received:');
+ if (idx != -1) {
+ capture_info.textContent = s.substr(idx);
+ }
+ if (data.indexOf('Transfer complete') != -1) {
+ OnTransferCompleted();
+ } else if (data.indexOf('Transfer incomplete') != -1) {
+ // todo: retry transfer
+ // Bug info
+ // Uncaught Error [ERR_STREAM_WRITE_AFTER_END]: write after end
+ // at writeAfterEnd (_stream_writable.js:253)
+ // at Socket.Writable.write (_stream_writable.js:302)
+ // at Socket.<anonymous> (ipmi_capture.js:317)
+ // at Socket.emit (events.js:210)
+ // at addChunk (_stream_readable.js:308)
+ // at readableAddChunk (_stream_readable.js:289)
+ // at Socket.Readable.push (_stream_readable.js:223)
+ // at Pipe.onStreamRead (internal/stream_base_commons.js:182)
+ capture_info.textContent = 'Transfer incomplete';
+ }
+ });
+ await Promise.all(
+ [g_rz.stdin.pipe(g_child.stdout), g_rz.stdout.pipe(g_child.stdin)]);
+}
+
+function ClearAllPendingTimeouts() {
+ var id = setTimeout(function() {}, 0);
+ for (; id >= 0; id--) clearTimeout(id);
+}
+
+function StartDbusMonitorFileSizePollLoop() {
+ QueueDbusMonitorFileSize(5);
+}
+
+function QueueDbusMonitorFileSize(secs = 5) {
+ setTimeout(function() {
+ g_child.stdin.write(
+ 'a=`ls -l /run/initramfs/DBUS_MONITOR | awk \'{print $5}\'` ; echo ">>>>>>$a<<<<<<" \n\n\n\n');
+ QueueDbusMonitorFileSize(secs);
+ }, secs * 1000);
+}
+
+function StopCapture() {
+ switch (g_capture_mode) {
+ case 'live':
+ g_child.stdin.write('\x03 ');
+ g_capture_state = 'stopping';
+ capture_info.textContent = 'Ctrl+C sent to BMC console';
+ break;
+ case 'staged':
+ ClearAllPendingTimeouts();
+ g_child.stdin.write(
+ 'echo ">>>>>>" && killall busctl && echo "<<<<<<" \n\n\n\n');
+ g_capture_state = 'stopping';
+ capture_info.textContent = 'Stopping dbus-monitor';
+ case 'staged2':
+ g_hexdump_received_size = 0;
+ g_hexdump_total_size = 0;
+ ClearAllPendingTimeouts();
+ g_child.stdin.write(
+ 'echo ">>>>>>" && killall busctl && echo "<<<<<<" \n\n\n\n');
+ g_capture_state = 'stopping';
+ capture_info.textContent = 'Stopping busctl';
+ break;
+ }
+}
+
+function QueueBMCConsoleHello(secs = 3) {
+ setTimeout(function() {
+ try {
+ if (g_capture_state == 'not started') {
+ console.log('Sending hello <cr> to the BMC');
+ g_child.stdin.write('\n');
+ QueueBMCConsoleHello(secs);
+ }
+ } catch (err) {
+ console.log('g_child may have ended as intended');
+ }
+ }, secs * 1000);
+}
+
+// The command line needed to access the BMC. The expectation is
+// executing this command brings the user to the BMC's console.
+function GetCMDLine() {
+ let v = text_hostname.value.split(' ');
+ return [v[0], v.slice(1, v.length)];
+}
+
+async function StartCapture(host) {
+ // Disable buttons
+ HideWelcomeScreen();
+ ShowIPMITimeline();
+ ShowNavigation();
+ let args = GetCMDLine();
+ btn_start_capture.disabled = true;
+ select_capture_mode.disabled = true;
+ text_hostname.disabled = true;
+ capture_info.textContent = 'Contacting BMC console: ' + args.toString();
+
+ // On the B.M.C.
+ let last_t = currTimestamp();
+ let attempt = 0;
+ console.log('Args: ' + args);
+ g_child = spawn(args[0], args[1], {shell: true});
+ g_child.stdout.on('data', async function(data) {
+ QueueBMCConsoleHello();
+
+ var t = currTimestamp();
+ {
+ switch (g_capture_state) {
+ case 'not started': // Do nothing
+ break;
+ case 'started':
+ attempt++;
+ console.log('attempt ' + attempt);
+ g_child.stdin.write('echo "haha" \n');
+ await streamWrite(g_child.stdin, 'whoami \n');
+ let idx = data.indexOf('haha');
+ if (idx != -1) {
+ ClearAllPendingTimeouts();
+ OnCaptureStart(); // Successfully logged on, start
+
+ if (g_capture_mode == 'live') {
+ g_child.stdin.write(
+ '\n\n' +
+ 'a=`pidof btbridged`;b=`pidof kcsbridged`;c=`pidof netipmid`;' +
+ 'echo ">>>>>>$a,$b,$c<<<<<<"\n\n');
+ g_capture_state = 'determine bridge daemon';
+ } else {
+ g_capture_state = 'dbus monitor start';
+ }
+ capture_info.textContent = 'Reached BMC console';
+
+ } else {
+ console.log('idx=' + idx);
+ }
+ break;
+ case 'determine bridge daemon': {
+ const abc = ExtractMyDelimitedStuff(data.toString());
+ if (abc == null) break;
+ const sp = abc.split(',');
+ if (parseInt(sp[0]) >= 0) { // btbridged, legacy interface
+ g_dbus_monitor_cmd = DBUS_MONITOR_LEGACY;
+ console.log('The BMC is using btbridged.');
+ } else if (parseInt(sp[1]) >= 0) { // new iface
+ g_dbus_monitor_cmd = DBUS_MONITOR_NEW;
+ console.log('The BMC is using kcsbridged.');
+ } else if (parseInt(sp[2]) >= 0) {
+ g_dbus_monitor_cmd = DBUS_MONITOR_NEW;
+ console.log('The BMC is using netipmid.');
+ } else {
+ console.log('Cannot determine the IPMI bridge daemon\n')
+ return;
+ }
+ g_capture_state = 'dbus monitor start';
+ break;
+ }
+ case 'dbus monitor start':
+ if (g_capture_mode == 'live') {
+ // It would be good to make sure the console bit rate is greater
+ // than the speed at which outputs are generated.
+ // g_child.stdin.write("dbus-monitor --system | grep
+ // \"sendMessage\\|ReceivedMessage\" -A7 \n")
+ ClearAllPendingTimeouts();
+ g_child.stdin.write(
+ 'dbus-monitor --system | grep "member=execute\\|method return" -A7 \n');
+ capture_info.textContent = 'Started dbus-monitor for live capture';
+ } else {
+ // g_child.stdin.write("dbus-monitor --system | grep
+ // \"sendMessage\\|ReceivedMessage\" -A7 >
+ // /run/initramfs/DBUS_MONITOR & \n\n\n")
+ ClearAllPendingTimeouts();
+ if (g_capture_mode == 'staged') {
+ g_child.stdin.write(
+ 'dbus-monitor --system > /run/initramfs/DBUS_MONITOR & \n\n\n');
+ capture_info.textContent =
+ 'Started dbus-monitor for staged IPMI capture';
+ } else if (g_capture_mode == 'staged2') {
+ g_child.stdin.write(
+ 'busctl capture > /run/initramfs/DBUS_MONITOR & \n\n\n');
+ capture_info.textContent =
+ 'Started busctl for staged IPMI + DBus capture';
+ }
+ StartDbusMonitorFileSizePollLoop();
+ }
+ g_capture_state = 'dbus monitor running';
+ break;
+ case 'dbus monitor running':
+ if (g_capture_mode == 'staged' || g_capture_mode == 'staged2') {
+ let s = data.toString();
+ let tmp = ExtractMyDelimitedStuff(s, 'int');
+ if (tmp != undefined) {
+ let sz = Math.floor(parseInt(tmp) / 1024);
+ if (!isNaN(sz)) {
+ capture_info.textContent =
+ 'Raw Dbus capture size: ' + sz + ' KiB';
+ } else { // This can happen if the output is cut by half & may be
+ // fixed by queuing console outputs
+ }
+ }
+ } else {
+ AppendToParseBuffer(data.toString());
+ MunchLines();
+ UpdateLayout();
+ ComputeHistogram();
+ }
+ break;
+ case 'dbus monitor end': // Todo: add speed check
+ let s = data.toString();
+ let i0 = s.lastIndexOf('>>>>'), i1 = s.lastIndexOf('<<<<');
+ if (i0 != -1 && i1 != -1) {
+ let tmp = s.substr(i0 + 4, i1 - i0 - 4);
+ let sz = parseInt(tmp);
+ if (isNaN(sz)) {
+ console.log(
+ 'Error: the tentative dbus-profile dump is not found!');
+ } else {
+ let bps = sz / 10;
+ console.log('dbus-monitor generates ' + bps + 'B per second');
+ }
+ }
+ g_child.kill('SIGINT');
+ break;
+ case 'sz sending':
+ console.log('[sz] Received a chunk of size ' + data.length);
+ console.log(data);
+ console.log(data + '');
+ // capture_info.textContent = "Received a chunk of size " +
+ // data.length
+ g_rz.stdin.write(data);
+ break;
+ case 'stopping':
+ let t = data.toString();
+ if (g_capture_mode == 'live') {
+ if (t.lastIndexOf('^C') != -1) {
+ // Live mode
+ g_child.kill('SIGINT');
+ g_capture_state = 'not started';
+ OnCaptureStop();
+ capture_info.textContent = 'connection to BMC closed';
+ // Log mode
+ }
+ } else if (
+ g_capture_mode == 'staged' || g_capture_mode == 'staged2') {
+ ClearAllPendingTimeouts();
+ if (t.lastIndexOf('<<<<<<') != -1) {
+ g_capture_state = 'compressing';
+ g_child.stdin.write(
+ 'echo ">>>>>>" && cd /run/initramfs && tar cfz DBUS_MONITOR.tar.gz DBUS_MONITOR && echo "<<<<<<" \n\n\n\n');
+ capture_info.textContent = 'Compressing dbus monitor dump on BMC';
+ }
+ }
+ break;
+ case 'compressing':
+ g_child.stdin.write(
+ '\n\na=`ls -l /run/initramfs/DBUS_MONITOR.tar.gz | awk \'{print $5}\'` && echo ">>>>>>$a<<<<<<" \n\n\n\n');
+ g_capture_state = 'dbus_monitor size';
+ capture_info.textContent = 'Obtaining size of compressed dbus dump';
+ break;
+ case 'dbus_monitor size':
+ // Starting RZ
+ let tmp = ExtractMyDelimitedStuff(data.toString(), 'int');
+ if (tmp != null && !isNaN(tmp)) { // Wait until result shows up
+ g_hexdump_total_size = tmp;
+ console.log(
+ 'dbus_monitor size tmp=' + tmp + ', ' + data.toString());
+
+ // if (tmp != undefined) {
+ // g_dbus_capture_tarfile_size = tmp;
+ // capture_info.textContent =
+ // 'Starting rz and sz, file size: ' + Math.floor(tmp / 1024)
+ // + ' KiB';
+ // } else {
+ // capture_info.textContent = 'Starting rz and sz';
+ // }
+ // g_capture_state = 'sz start';
+ // g_child.stdin.write(
+ // '\n\n\n\n' +
+ // 'sz -a -e -R -L 512 -w 32767 -y
+ // /run/initramfs/DBUS_MONITOR.tar.gz\n');
+ // g_capture_state = 'sz sending';
+ // LaunchRZ();
+ g_child.stdin.write(
+ 'echo ">>>>>>"; hexdump /run/initramfs/DBUS_MONITOR.tar.gz ; echo "<<<<<<"; \n');
+ g_capture_state = 'test hexdump running';
+ g_hexdump = new Buffer([]);
+ }
+
+ break;
+ case 'test hexdump start':
+ g_child.stdin.write(
+ 'echo ">>>>>>"; hexdump /run/initramfs/DBUS_MONITOR.tar.gz ; echo "<<<<<<"; \n');
+ g_capture_state = 'test hexdump running';
+ g_hexdump = new Buffer([]);
+ g_hexdump_received_size = 0;
+ break;
+ case 'test hexdump running':
+ g_hexdump += data;
+ const lines = data.toString().split('\n');
+ for (let j = lines.length - 1; j >= 0; j--) {
+ sp = lines[j].trimEnd().split(' ');
+ if (sp.length >= 1) {
+ const sz = parseInt(sp[0], 16)
+ if (!isNaN(sz)) {
+ if (g_hexdump_received_size < sz) {
+ g_hexdump_received_size = sz;
+ capture_info.textContent = 'Receiving capture file: ' + sz +
+ ' / ' + g_hexdump_total_size + ' B';
+ break;
+ }
+ }
+ }
+ }
+ if (data.includes('<<<<<<') && !data.includes('echo')) {
+ g_hexdump = ExtractMyDelimitedStuff(g_hexdump);
+ SaveHexdumpToFile(g_hexdump, 'DBUS_MONITOR.tar.gz');
+ OnTransferCompleted();
+ }
+ break;
+ }
+ last_t = t;
+ }
+ });
+ g_child.stderr.on('data', (data) => {
+ console.log('[bmc] err=' + data);
+ g_child.stdin.write('echo "haha" \n\n');
+ });
+ g_child.on('close', (code) => {
+ console.log('return code: ' + code);
+ });
+}