From 1ce7ac32dbc5c096fccb81f2e3427d2d56100bc0 Mon Sep 17 00:00:00 2001
From: Stephan de Wit <stephan.de.wit@deciso.com>
Date: Thu, 5 Sep 2024 12:29:40 +0200
Subject: [PATCH] filter: live log: switch from poll-based to stream-based

---
 .../Diagnostics/Api/FirewallController.php    |   6 +-
 .../views/OPNsense/Diagnostics/fw_log.volt    | 447 +++++++++++-------
 src/opnsense/scripts/filter/read_log.py       |   4 +-
 .../conf/actions.d/actions_filter.conf        |   2 +-
 4 files changed, 278 insertions(+), 181 deletions(-)

diff --git a/src/opnsense/mvc/app/controllers/OPNsense/Diagnostics/Api/FirewallController.php b/src/opnsense/mvc/app/controllers/OPNsense/Diagnostics/Api/FirewallController.php
index d7ae7d6657..3e53281961 100644
--- a/src/opnsense/mvc/app/controllers/OPNsense/Diagnostics/Api/FirewallController.php
+++ b/src/opnsense/mvc/app/controllers/OPNsense/Diagnostics/Api/FirewallController.php
@@ -59,16 +59,16 @@ class FirewallController extends ApiControllerBase
         }
     }
 
-    public function streamLogAction()
+    public function streamLogAction($lines = 5)
     {
         return $this->configdStream(
             'filter stream log',
-            [],
+            [$lines],
             [
                 'Content-Type: text/event-stream',
                 'Cache-Control: no-cache'
             ],
-            60
+            /* this stream implements a keepalive, the default poll_timeout of 2 should suffice */
         );
     }
 
diff --git a/src/opnsense/mvc/app/views/OPNsense/Diagnostics/fw_log.volt b/src/opnsense/mvc/app/views/OPNsense/Diagnostics/fw_log.volt
index c95e68bdff..4e5fa051d6 100644
--- a/src/opnsense/mvc/app/views/OPNsense/Diagnostics/fw_log.volt
+++ b/src/opnsense/mvc/app/views/OPNsense/Diagnostics/fw_log.volt
@@ -39,19 +39,20 @@
         };
         var interface_descriptions = {};
         let hostnameMap = {};
+        let stream = null;
 
         /**
          * reverse lookup address fields (replace address part for hostname if found)
          */
         function reverse_lookup() {
             let to_fetch = [];
-            let unfinshed_lookup = false;
+            let unfinished_lookup = false;
              $(".address").each(function(){
                 let address = $(this).data('address');
                 if (!hostnameMap.hasOwnProperty(address) && !to_fetch.includes(address)) {
                     // limit dns fetches to 50 per cycle
                     if (to_fetch.length >= 50) {
-                        unfinshed_lookup = true;
+                        unfinished_lookup = true;
                         return;
                     }
                     to_fetch.push(address);
@@ -77,7 +78,7 @@
                             hostnameMap[address] = data[address];
                         }
                     });
-                    if (unfinshed_lookup) {
+                    if (unfinished_lookup) {
                         // schedule next fetch
                         reverse_lookup();
                     }
@@ -223,12 +224,100 @@
             return t_fetched;
         }
 
-
-        function fetch_log() {
-            let record_spec = [];
+        function fetch_initial_data(digest='')
+        {
             // Overfetch for limited display scope to increase the chance of being able to find matches.
-            // As we fetch once per second, we would be limited to 25 records/sec of log data when 25 is selected.
             let max_rows = Math.max(1000, parseInt($("#limit").val()));
+            ajaxGet('/api/diagnostics/firewall/log/', {'digest': digest, 'limit': max_rows}, function(data, status) {
+                if (status == 'error') {
+                    return;
+                } else if (data !== undefined && data.length > 0) {
+                    let rows = parse_records(data);
+                    if (rows !== false && rows.length > 0) {
+                        insert_log_rows(rows);
+                    }
+                }
+            });
+        }
+
+        function debounce_queue_limited(fn, delay, limit)
+        {
+            let timeout;
+            let eventQueue = [];
+
+            const processQueue = () => {
+                if (eventQueue.length > 0) {
+                    fn(eventQueue);
+                    eventQueue = [];
+                }
+            };
+
+            return function(event) {
+                if (!event) {
+                    fn(false);
+                    return;
+                }
+                eventQueue.push(event);
+
+                if (eventQueue.length >= limit) {
+                    clearTimeout(timeout);
+                    processQueue();
+                }
+
+                clearTimeout(timeout);
+                timeout = setTimeout(() => {
+                    processQueue();
+                }, delay);
+            };
+        }
+
+        function open_stream()
+        {
+            if (stream === null) {
+                stream = new EventSource('/api/diagnostics/firewall/streamLog/0');
+                // Events may come in very quickly, therefore debounce to update the UI in batches
+                stream.onmessage = debounce_queue_limited(function (events) {
+                    if (!events) {
+                        close_stream();
+                        return;
+                    }
+
+                    let records = [];
+                    events.forEach(event => {
+                        records.push(JSON.parse(event.data));
+                    })
+                    let rows = parse_records(records);
+                    if (!rows || rows.length == 0) {
+                        return;
+                    }
+
+                    insert_log_rows(rows);
+                }, 200, 50);
+                stream.onerror = function(event) {
+                    close_stream(true);
+                };
+            }
+        }
+
+        function close_stream(error = false)
+        {
+            if (stream !== null) {
+                stream.close();
+                stream = null;
+
+                if (error) {
+                    // XXX inform user or retry?
+                    $("#auto_refresh").prop('checked', false);
+                }
+            }
+        }
+
+        function parse_records(records) {
+            if (records === undefined || records.length == 0) {
+                return false;
+            }
+
+            let record_spec = [];
             // read heading, contains field specs
             $("#grid-log > thead > tr > th ").each(function () {
                 record_spec.push({
@@ -237,173 +326,172 @@
                     'class': $(this).attr('class')
                 });
             });
-            // read last digest (record hash) from top data row
-            var last_digest = $("#grid-log > tbody > tr:first > td:first").text();
-            // fetch new log lines and add on top of grid-log
-            ajaxGet('/api/diagnostics/firewall/log/', {'digest': last_digest, 'limit': max_rows}, function(data, status) {
-                if (status == 'error') {
-                    // stop poller on failure
-                    $("#auto_refresh").prop('checked', false);
-                } else if (last_digest != '' && $("#grid-log > tbody > tr").length == 1){
-                    // $("#limit").change(); called, this request should be discarted (data grid reset)
-                    return;
-                } else if (data !== undefined && data.length > 0) {
-                    let record;
-                    let trs = [];
-                    while ((record = data.pop()) != null) {
-                        if (record['__digest__'] != last_digest) {
-                            var log_tr = $("<tr>");
-                            if (record.interface !== undefined && interface_descriptions[record.interface] !== undefined) {
-                                record['interface_name'] = interface_descriptions[record.interface];
-                            } else {
-                                record['interface_name'] = record.interface;
+
+            let record;
+            let trs = [];
+            while ((record = records.pop()) != null) {
+                var log_tr = $("<tr>");
+                if (record.interface !== undefined && interface_descriptions[record.interface] !== undefined) {
+                    record['interface_name'] = interface_descriptions[record.interface];
+                } else {
+                    record['interface_name'] = record.interface;
+                }
+                log_tr.data('details', record);
+                log_tr.hide();
+                $.each(record_spec, function(idx, field){
+                    var log_td = $('<td>').addClass(field['class']);
+                    var column_name = field['column-id'];
+                    var content = null;
+                    switch (field['type']) {
+                        case 'icon':
+                            var icon = field_type_icons[record[column_name]];
+                            if (icon != undefined) {
+                                log_td.html('<i class="fa '+icon+'" aria-hidden="true"></i><span style="display:none">'+record[column_name]+'</span>');
                             }
-                            log_tr.data('details', record);
-                            log_tr.hide();
-                            $.each(record_spec, function(idx, field){
-                                var log_td = $('<td>').addClass(field['class']);
-                                var column_name = field['column-id'];
-                                var content = null;
-                                switch (field['type']) {
-                                    case 'icon':
-                                        var icon = field_type_icons[record[column_name]];
-                                        if (icon != undefined) {
-                                            log_td.html('<i class="fa '+icon+'" aria-hidden="true"></i><span style="display:none">'+record[column_name]+'</span>');
-                                        }
-                                        break;
-                                    case 'address':
-                                        log_td.text(record[column_name]);
-                                        log_td.addClass('address');
-                                        log_td.data('address', record[column_name]);
-                                        if (record[column_name+'port'] !== undefined) {
-                                            if (record['ipversion'] == 6) {
-                                                log_td.text('['+log_td.text()+']:'+record[column_name+'port']);
-                                            } else {
-                                                log_td.text(log_td.text()+':'+record[column_name+'port']);
-                                            }
-                                        }
-                                        break;
-                                    case 'info':
-                                        log_td.html('<button class="act_info btn btn-xs fa fa-info-circle" aria-hidden="true"></i>');
-                                        break;
-                                    case 'label':
-                                        // record data is always html-escaped. no special protection required
-                                        log_td.html(record[column_name]);
-                                        break;
-                                    default:
-                                        if (record[column_name] != undefined) {
-                                            log_td.text(record[column_name]);
-                                        }
-                                }
-                                log_tr.append(log_td);
-                            });
-
-                            if (record['action'] == 'pass') {
-                                log_tr.addClass('fw_pass');
-                            } else if (record['action'] == 'block') {
-                                log_tr.addClass('fw_block');
-                            } else if (record['action'] == 'rdr' || record['action'] == 'nat' || record['action'] == 'binat') {
-                                log_tr.addClass('fw_nat');
-                            }
-                            trs.unshift(log_tr);
-                        }
-                    }
-                    $("#grid-log > tbody > tr:first").before(trs);
-                    // apply filter after load
-                    apply_filter();
-
-                    /**
-                     * Limit output, try to keep max X records on screen.
-                     * By removing the invisible items first, we should be able to keep the filtered ones
-                     * longer in scope. In theory the number of items in memory can grow to 2 x max_rows, but
-                     * in practice that's not really an issue.
-                     */
-                    $("#grid-log > tbody > tr:not(:visible):gt("+max_rows+")").remove();
-                    $("#grid-log > tbody > tr:visible:gt("+max_rows+")").remove();
-
-                    // bind info buttons
-                    $(".act_info").unbind('click').click(function(){
-                        var sender_tr = $(this).parent().parent();
-                        var sender_details = sender_tr.data('details');
-                        var hidden_columns = ['__spec__', '__host__', '__digest__'];
-                        var map_icon = ['dir', 'action'];
-                        var sorted_keys = Object.keys(sender_details).sort();
-                        var tbl = $('<table class="table table-condensed table-hover"/>');
-                        var tbl_tbody = $("<tbody/>");
-                        for (let i=0 ; i < sorted_keys.length; i++) {
-                            if (hidden_columns.indexOf(sorted_keys[i]) === -1 ) {
-                                var row = $("<tr/>");
-                                var icon = null;
-                                if (map_icon.indexOf(sorted_keys[i]) !== -1) {
-                                    if (field_type_icons[sender_details[sorted_keys[i]]] !== undefined) {
-                                        icon = $("<i/>");
-                                        icon.addClass("fa fa-fw").addClass(field_type_icons[sender_details[sorted_keys[i]]]);
-                                    }
-                                }
-                                row.append($("<td/>").text(sorted_keys[i]));
-                                if (sorted_keys[i] == 'rid') {
-                                  // rid field, links to rule origin
-                                  var rid = sender_details[sorted_keys[i]];
-                                  var rid_td = $("<td/>").addClass("act_info_fld_"+sorted_keys[i]);
-                                  if (rid.length == 32) {
-                                      var rid_link = $("<a target='_blank' href='/firewall_rule_lookup.php?rid=" + rid + "'/>");
-                                      rid_link.text(rid);
-                                      rid_td.append($("<i/>").addClass('fa fa-fw fa-search'));
-                                      rid_td.append(rid_link);
-                                  }
-                                  row.append(rid_td);
-                                } else if (icon === null) {
-                                  row.append($("<td/>").addClass("act_info_fld_"+sorted_keys[i]).html(
-                                    sender_details[sorted_keys[i]]
-                                  ));
+                            break;
+                        case 'address':
+                            log_td.text(record[column_name]);
+                            log_td.addClass('address');
+                            log_td.data('address', record[column_name]);
+                            if (record[column_name+'port'] !== undefined) {
+                                if (record['ipversion'] == 6) {
+                                    log_td.text('['+log_td.text()+']:'+record[column_name+'port']);
                                 } else {
-                                  row.append($("<td/>")
-                                      .append(icon)
-                                      .append($("<span/>").addClass("act_info_fld_"+sorted_keys[i]).text(
-                                        " [" + sender_details[sorted_keys[i]] + "]"
-                                      ))
-                                  );
+                                    log_td.text(log_td.text()+':'+record[column_name+'port']);
                                 }
-                                tbl_tbody.append(row);
+                            }
+                            break;
+                        case 'info':
+                            log_td.html('<button class="act_info btn btn-xs fa fa-info-circle" aria-hidden="true"></i>');
+                            break;
+                        case 'label':
+                            // record data is always html-escaped. no special protection required
+                            log_td.html(record[column_name]);
+                            break;
+                        default:
+                            if (record[column_name] != undefined) {
+                                log_td.text(record[column_name]);
+                            }
+                    }
+                    log_tr.append(log_td);
+                });
+
+                if (record['action'] == 'pass') {
+                    log_tr.addClass('fw_pass');
+                } else if (record['action'] == 'block') {
+                    log_tr.addClass('fw_block');
+                } else if (record['action'] == 'rdr' || record['action'] == 'nat' || record['action'] == 'binat') {
+                    log_tr.addClass('fw_nat');
+                }
+                trs.unshift(log_tr);
+            }
+
+            return trs;
+        }
+
+        function insert_log_rows(rows)
+        {
+            // XXX flashy animation, not very UX friendly
+            rows.forEach(function(row) {
+                $("#grid-log > tbody > tr:first").before(row);
+                row.fadeIn(400, function() {
+                    row.animate({backgroundColor: 'transparent'}, 1000);
+                });
+            })
+            // apply filter after load
+            apply_filter();
+
+            /**
+             * Limit output, try to keep max X records on screen.
+             * By removing the invisible items first, we should be able to keep the filtered ones
+             * longer in scope. In theory the number of items in memory can grow to 2 x max_rows, but
+             * in practice that's not really an issue.
+             */
+            let max_rows = Math.max(1000, parseInt($("#limit").val()));
+            $("#grid-log > tbody > tr:not(:visible):gt("+max_rows+")").remove();
+            $("#grid-log > tbody > tr:visible:gt("+max_rows+")").remove();
+
+            // bind info buttons
+            $(".act_info").unbind('click').click(function(){
+                var sender_tr = $(this).parent().parent();
+                var sender_details = sender_tr.data('details');
+                var hidden_columns = ['__spec__', '__host__', '__digest__'];
+                var map_icon = ['dir', 'action'];
+                var sorted_keys = Object.keys(sender_details).sort();
+                var tbl = $('<table class="table table-condensed table-hover"/>');
+                var tbl_tbody = $("<tbody/>");
+                for (let i=0 ; i < sorted_keys.length; i++) {
+                    if (hidden_columns.indexOf(sorted_keys[i]) === -1 ) {
+                        var row = $("<tr/>");
+                        var icon = null;
+                        if (map_icon.indexOf(sorted_keys[i]) !== -1) {
+                            if (field_type_icons[sender_details[sorted_keys[i]]] !== undefined) {
+                                icon = $("<i/>");
+                                icon.addClass("fa fa-fw").addClass(field_type_icons[sender_details[sorted_keys[i]]]);
                             }
                         }
-                        tbl.append(tbl_tbody);
-                        BootstrapDialog.show({
-                           title: "{{ lang._('Detailed rule info') }}",
-                           message: tbl,
-                           type: BootstrapDialog.TYPE_INFO,
-                           draggable: true,
-                           buttons: [{
-                             label: '<i class="fa fa-search" aria-hidden="true"></i>',
-                             action: function(){
-                               $(this).unbind('click');
-                               $(".act_info_fld_src, .act_info_fld_dst").each(function(){
-                                  var target_field = $(this);
-                                  ajaxGet('/api/diagnostics/dns/reverse_lookup', {'address': target_field.text()}, function(data, status) {
-                                      if (data[target_field.text()] != undefined) {
-                                          var resolv_output = data[target_field.text()];
-                                          if (target_field.text() != resolv_output) {
-                                              target_field.text(target_field.text() + ' [' + resolv_output + ']');
-                                          }
-                                      }
-                                      target_field.prepend('<i class="fa fa-search" aria-hidden="true"></i>&nbsp;');
-                                  });
-                               });
-                             }
-                           },{
-                             label: "{{ lang._('Close') }}",
-                             action: function(dialogItself){
-                               dialogItself.close();
-                             }
-                           }]
-                        });
-                    });
-                    // reverse lookup when selected
-                    if ($('#dolookup').is(':checked')) {
-                        reverse_lookup();
+                        row.append($("<td/>").text(sorted_keys[i]));
+                        if (sorted_keys[i] == 'rid') {
+                            // rid field, links to rule origin
+                            var rid = sender_details[sorted_keys[i]];
+                            var rid_td = $("<td/>").addClass("act_info_fld_"+sorted_keys[i]);
+                            if (rid.length == 32) {
+                                var rid_link = $("<a target='_blank' href='/firewall_rule_lookup.php?rid=" + rid + "'/>");
+                                rid_link.text(rid);
+                                rid_td.append($("<i/>").addClass('fa fa-fw fa-search'));
+                                rid_td.append(rid_link);
+                            }
+                            row.append(rid_td);
+                        } else if (icon === null) {
+                            row.append($("<td/>").addClass("act_info_fld_"+sorted_keys[i]).html(
+                            sender_details[sorted_keys[i]]
+                            ));
+                        } else {
+                            row.append($("<td/>")
+                                .append(icon)
+                                .append($("<span/>").addClass("act_info_fld_"+sorted_keys[i]).text(
+                                " [" + sender_details[sorted_keys[i]] + "]"
+                                ))
+                            );
+                        }
+                        tbl_tbody.append(row);
                     }
                 }
+                tbl.append(tbl_tbody);
+                BootstrapDialog.show({
+                    title: "{{ lang._('Detailed rule info') }}",
+                    message: tbl,
+                    type: BootstrapDialog.TYPE_INFO,
+                    draggable: true,
+                    buttons: [{
+                        label: '<i class="fa fa-search" aria-hidden="true"></i>',
+                        action: function(){
+                        $(this).unbind('click');
+                        $(".act_info_fld_src, .act_info_fld_dst").each(function(){
+                            var target_field = $(this);
+                            ajaxGet('/api/diagnostics/dns/reverse_lookup', {'address': target_field.text()}, function(data, status) {
+                                if (data[target_field.text()] != undefined) {
+                                    var resolv_output = data[target_field.text()];
+                                    if (target_field.text() != resolv_output) {
+                                        target_field.text(target_field.text() + ' [' + resolv_output + ']');
+                                    }
+                                }
+                                target_field.prepend('<i class="fa fa-search" aria-hidden="true"></i>&nbsp;');
+                            });
+                        });
+                        }
+                    },{
+                        label: "{{ lang._('Close') }}",
+                        action: function(dialogItself){
+                        dialogItself.close();
+                        }
+                    }]
+                });
             });
+
+            if ($("#dolookup").is(':checked')) {
+                reverse_lookup();
+            }
         }
 
         // matcher
@@ -519,17 +607,26 @@
         // reset log content on limit change, forces a reload
         $("#limit").change(function(){
             $('#grid-log > tbody').html("<tr></tr>");
+            close_stream();
+            fetch_initial_data();
+            open_stream();
         });
 
-        function poller() {
+        $("#auto_refresh").change(function(){
             if ($("#auto_refresh").is(':checked')) {
-                fetch_log();
+                // we may have missed data while the stream was closed, so fetch up until the last digest
+                let last_digest = $("#grid-log > tbody > tr:first > td:first").text();
+                fetch_initial_data(last_digest);
+                open_stream();
+            } else {
+                close_stream();
+            }
+        });
+
+        $("#dolookup").change(function(){
+            if ($("#dolookup").is(':checked')) {
+                reverse_lookup();
             }
-            setTimeout(poller, 1000);
-        }
-        // manual refresh
-        $("#refresh").click(function(){
-            fetch_log();
         });
 
         // templates actions
@@ -665,8 +762,8 @@
 
         });
 
-        // startup poller
-        poller();
+        fetch_initial_data();
+        open_stream();
     });
 </script>
 <style>
diff --git a/src/opnsense/scripts/filter/read_log.py b/src/opnsense/scripts/filter/read_log.py
index 0264f8553f..de8beb093a 100755
--- a/src/opnsense/scripts/filter/read_log.py
+++ b/src/opnsense/scripts/filter/read_log.py
@@ -160,7 +160,7 @@ def parse_record(record, running_conf_descr):
 
 if __name__ == '__main__':
     # read parameters
-    parameters = {'limit': '0', 'digest': '', 'stream': False, 'nlines': '5'}
+    parameters = {'limit': '0', 'digest': '', 'stream': False}
     update_params(parameters)
     parameters['limit'] = int(parameters['limit'])
 
@@ -170,7 +170,7 @@ if __name__ == '__main__':
     if parameters['stream'] != False:
         # tail symlink to latest log, use -F to follow file rotation
         f = subprocess.Popen(
-            ['tail', '-n' + parameters['nlines'], '-F', '/var/log/filter/latest.log'],
+            ['tail', '-n' + str(parameters['limit']), '-F', '/var/log/filter/latest.log'],
             stdout=subprocess.PIPE,
             stderr=subprocess.PIPE,
             bufsize=0,
diff --git a/src/opnsense/service/conf/actions.d/actions_filter.conf b/src/opnsense/service/conf/actions.d/actions_filter.conf
index 3f6022c3f1..a4415ee3b2 100644
--- a/src/opnsense/service/conf/actions.d/actions_filter.conf
+++ b/src/opnsense/service/conf/actions.d/actions_filter.conf
@@ -61,7 +61,7 @@ message:request filter log output
 
 [stream.log]
 command:/usr/local/opnsense/scripts/filter/read_log.py /stream 1
-parameters:
+parameters: /limit %s
 type:stream_output
 message:stream filter log output