From 782c4cde6b9e07130531b486f33d43234a2805ae Mon Sep 17 00:00:00 2001
From: Dietmar Maurer <dietmar@proxmox.com>
Date: Fri, 14 Mar 2014 13:15:03 +0100
Subject: [PATCH] improve log format

---
 src/PVE/Firewall.pm | 85 +++++++++++++++++++++++++++------------------
 src/pvefw-logger.c  | 80 +++++++++++++++++++++++++++++++++++++-----
 2 files changed, 123 insertions(+), 42 deletions(-)

diff --git a/src/PVE/Firewall.pm b/src/PVE/Firewall.pm
index 495be05..0f2bc11 100644
--- a/src/PVE/Firewall.pm
+++ b/src/PVE/Firewall.pm
@@ -819,6 +819,7 @@ sub ruleset_create_chain {
     my ($ruleset, $chain) = @_;
 
     die "Invalid chain name '$chain' (28 char max)\n" if length($chain) > 28;
+    die "chain name may not contain collons\n" if $chain =~ m/:/; # because of log format
 
     die "chain '$chain' already exists\n" if $ruleset->{$chain};
 
@@ -847,6 +848,31 @@ sub ruleset_insertrule {
    unshift @{$ruleset->{$chain}}, "-A $chain $rule";
 }
 
+sub get_log_rule_base {
+    my ($chain, $vmid, $msg, $loglevel) = @_;
+    
+    die "internal error - no log level" if !defined($loglevel);
+
+    $vmid = 0 if !defined($vmid);
+
+    # Note: we use special format for prefix to pass further 
+    # info to log daemon (VMID, LOGVELEL and CHAIN)
+
+    return "-j NFLOG --nflog-prefix \":$vmid:$loglevel:$chain: $msg\"";
+}
+
+sub ruleset_addlog {
+    my ($ruleset, $chain, $vmid, $msg, $loglevel, $rule) = @_;
+
+    return if !defined($loglevel);
+
+    my $logrule = get_log_rule_base($chain, $vmid, $msg, $loglevel);
+
+    $logrule = "$rule $logrule" if defined($rule);
+
+    ruleset_addrule($ruleset, $chain, $logrule)
+}
+
 sub generate_bridge_chains {
     my ($ruleset, $hostfw_conf, $bridge, $routing_table) = @_;
 
@@ -877,7 +903,7 @@ sub generate_bridge_chains {
 }
 
 sub ruleset_add_chain_policy {
-    my ($ruleset, $chain, $policy, $loglevel, $accept_action) = @_;
+    my ($ruleset, $chain, $vmid, $policy, $loglevel, $accept_action) = @_;
 
     if ($policy eq 'ACCEPT') {
 
@@ -888,15 +914,13 @@ sub ruleset_add_chain_policy {
 
 	ruleset_addrule($ruleset, $chain, "-j PVEFW-Drop");
 
-	ruleset_addrule($ruleset, $chain, "-j NFLOG --nflog-prefix \"$chain-dropped: \"")
-	    if defined($loglevel);
+	ruleset_addlog($ruleset, $chain, $vmid, "policy $policy: ", $loglevel);
 
 	ruleset_addrule($ruleset, $chain, "-j DROP");
     } elsif ($policy eq 'REJECT') {
 	ruleset_addrule($ruleset, $chain, "-j PVEFW-Reject");
 
-	ruleset_addrule($ruleset, $chain, "-j NFLOG --nflog-prefix \"$chain-reject: \"")
-	    if defined($loglevel);
+	ruleset_addlog($ruleset, $chain, $vmid, "policy $policy: ", $loglevel);
 
 	ruleset_addrule($ruleset, $chain, "-g PVEFW-reject");
     } else {
@@ -989,7 +1013,7 @@ sub generate_venet_rules_direction {
     }
 
     my $accept_action = $direction eq 'OUT' ? "PVEFW-SET-ACCEPT-MARK" : "ACCEPT";
-    ruleset_add_chain_policy($ruleset, $chain, $policy, $loglevel, $accept_action);
+    ruleset_add_chain_policy($ruleset, $chain, $vmid, $policy, $loglevel, $accept_action);
 
     # plug into FORWARD, INPUT and OUTPUT chain
     if ($direction eq 'OUT') {
@@ -1016,7 +1040,7 @@ sub generate_venet_rules_direction {
 }
 
 sub generate_tap_rules_direction {
-    my ($ruleset, $groups_conf, $iface, $netid, $macaddr, $vmfw_conf, $bridge, $direction) = @_;
+    my ($ruleset, $groups_conf, $iface, $netid, $macaddr, $vmfw_conf, $vmid, $bridge, $direction) = @_;
 
     my $lc_direction = lc($direction);
 
@@ -1041,7 +1065,7 @@ sub generate_tap_rules_direction {
     }
 
     my $accept_action = $direction eq 'OUT' ? "PVEFW-SET-ACCEPT-MARK" : "ACCEPT";
-    ruleset_add_chain_policy($ruleset, $tapchain, $policy, $loglevel, $accept_action);
+    ruleset_add_chain_policy($ruleset, $tapchain, $vmid, $policy, $loglevel, $accept_action);
 
     # plug the tap chain to bridge chain
     if ($direction eq 'IN') {
@@ -1084,7 +1108,7 @@ sub enable_host_firewall {
 
     # implement input policy
     my $policy = $options->{policy_in} || 'DROP'; # allow nothing by default
-    ruleset_add_chain_policy($ruleset, $chain, $policy, $loglevel, $accept_action);
+    ruleset_add_chain_policy($ruleset, $chain, 0, $policy, $loglevel, $accept_action);
 
     # host outbound firewall
     $chain = "PVEFW-HOST-OUT";
@@ -1109,7 +1133,7 @@ sub enable_host_firewall {
 
     # implement output policy
     $policy = $options->{policy_out} || 'ACCEPT'; # allow everything by default
-    ruleset_add_chain_policy($ruleset, $chain, $policy, $loglevel, $accept_action);
+    ruleset_add_chain_policy($ruleset, $chain, 0, $policy, $loglevel, $accept_action);
 
     ruleset_addrule($ruleset, "PVEFW-OUTPUT", "-j PVEFW-HOST-OUT");
     ruleset_addrule($ruleset, "PVEFW-INPUT", "-j PVEFW-HOST-IN");
@@ -1556,26 +1580,17 @@ sub generate_std_chains {
     my $loglevel = get_option_log_level($options, 'smurf_log_level');
 
     # same as shorewall smurflog.
-    if (defined($loglevel)) {
-	$pve_std_chains-> {'PVEFW-smurflog'} = [
-	    "-j NFLOG --nflog-prefix \"smurfs-dropped: \"",
-	    "-j DROP",
-	    ];
-    } else {
-	$pve_std_chains-> {'PVEFW-smurflog'} = [ "-j DROP" ];
-    }
+    my $chain = 'PVEFW-smurflog';
+
+    push @{$pve_std_chains->{$chain}}, get_log_rule_base($chain, 0, "DROP: ", $loglevel) if $loglevel;
+    push @{$pve_std_chains->{$chain}}, "-j DROP";
 
     # same as shorewall logflags action.
     $loglevel = get_option_log_level($options, 'tcp_flags_log_level');
-    if (defined($loglevel)) {
-	$pve_std_chains-> {'PVEFW-logflags'} = [
-	    # fixme: is this correctly logged by pvewf-logger? (ther is no --log-ip-options for NFLOG)
-	    "-j NFLOG --nflog-prefix \"logflags-dropped: \"",
-	    "-j DROP",
-	    ];
-    } else {
-	$pve_std_chains-> {'PVEFW-logflags'} = [ "-j DROP" ];
-    }
+    $chain = 'PVEFW-logflags';
+    # fixme: is this correctly logged by pvewf-logger? (ther is no --log-ip-options for NFLOG)
+    push @{$pve_std_chains->{$chain}}, get_log_rule_base($chain, 0, "DROP: ", $loglevel) if $loglevel;
+    push @{$pve_std_chains->{$chain}}, "-j DROP";
 
     foreach my $chain (keys %$pve_std_chains) {
 	ruleset_create_chain($ruleset, $chain);
@@ -1696,8 +1711,10 @@ sub compile {
 	    generate_bridge_chains($ruleset, $hostfw_conf, $bridge, $routing_table);
 
 	    my $macaddr = $net->{macaddr};
-	    generate_tap_rules_direction($ruleset, $groups_conf, $iface, $netid, $macaddr, $vmfw_conf, $bridge, 'IN');
-	    generate_tap_rules_direction($ruleset, $groups_conf, $iface, $netid, $macaddr, $vmfw_conf, $bridge, 'OUT');
+	    generate_tap_rules_direction($ruleset, $groups_conf, $iface, $netid, $macaddr, 
+					 $vmfw_conf, $vmid, $bridge, 'IN');
+	    generate_tap_rules_direction($ruleset, $groups_conf, $iface, $netid, $macaddr, 
+					 $vmfw_conf, $vmid, $bridge, 'OUT');
 	}
     }
 
@@ -1729,8 +1746,10 @@ sub compile {
 
 		my $macaddr = $d->{mac};
 		my $iface = $d->{host_ifname};
-		generate_tap_rules_direction($ruleset, $groups_conf, $iface, $netid, $macaddr, $vmfw_conf, $bridge, 'IN');
-		generate_tap_rules_direction($ruleset, $groups_conf, $iface, $netid, $macaddr, $vmfw_conf, $bridge, 'OUT');
+		generate_tap_rules_direction($ruleset, $groups_conf, $iface, $netid, $macaddr, 
+					     $vmfw_conf, $vmid, $bridge, 'IN');
+		generate_tap_rules_direction($ruleset, $groups_conf, $iface, $netid, $macaddr, 
+					     $vmfw_conf, $vmid, $bridge, 'OUT');
 	    }
 	}
     }
@@ -1749,8 +1768,8 @@ sub compile {
     # disable interbridge routing
     ruleset_addrule($ruleset, "PVEFW-FORWARD", "-o vmbr+ -j PVEFW-Drop"); 
     ruleset_addrule($ruleset, "PVEFW-FORWARD", "-i vmbr+ -j PVEFW-Drop");
-    ruleset_addrule($ruleset, "PVEFW-FORWARD", "-o vmbr+ -j NFLOG --nflog-prefix \"PVEFW-FORWARD-dropped \"");  
-    ruleset_addrule($ruleset, "PVEFW-FORWARD", "-i vmbr+ -j NFLOG --nflog-prefix \"PVEFW-FORWARD-dropped \"");  
+    ruleset_addlog($ruleset, "PVEFW-FORWARD", 0, "DROP: ", $loglevel, "-o vmbr+");  
+    ruleset_addlog($ruleset, "PVEFW-FORWARD", 0, "DROP: ", $loglevel, "-i vmbr+");  
     ruleset_addrule($ruleset, "PVEFW-FORWARD", "-o vmbr+ -j DROP");  
     ruleset_addrule($ruleset, "PVEFW-FORWARD", "-i vmbr+ -j DROP");
 
diff --git a/src/pvefw-logger.c b/src/pvefw-logger.c
index db7a026..34a02a7 100644
--- a/src/pvefw-logger.c
+++ b/src/pvefw-logger.c
@@ -51,6 +51,20 @@
 static struct nflog_handle *logh = NULL;
 static struct nlif_handle *nlifh = NULL;
 
+/*
+  
+LOG FORMAT:
+
+Special care was taken to allow fast parsing (and filer messages for a singl VM).
+
+<VMID> <LOGLEVEL> <CHAIN> <TIME> <TIMEZONE> <MSG> 
+
+Example:
+
+117 6 tap117i0-IN 14/Mar/2014:12:47:07 +0100 policy REJECT: IN=vmbr1 ...
+  
+*/
+
 #define LOGFILE "/var/log/pve-firewall.log"
 
 #define LOCKFILE "/var/lock/pvefw-logger.lck"
@@ -59,6 +73,8 @@ static struct nlif_handle *nlifh = NULL;
 #define LQ_LEN 512
 #define LE_MAX (512 - 16) // try to fit into 512 bytes
 
+#define MAX_CHAIN_LEN 28
+
 struct log_entry { 
     guint32 len; // max LE_MAX chars
     char buf[LE_MAX];
@@ -104,7 +120,8 @@ log_writer_thread(gpointer data)
             }
             continue;
         }
- 
+       
+        printf("%s", le->buf);
         int res = safe_write(outfd, le->buf, le->len);
 
         g_free(le);
@@ -119,7 +136,7 @@ log_writer_thread(gpointer data)
 
 static int skipped_logs = 0;
 
-static void log_status_message(const char *fmt, ...);
+static void log_status_message(guint loglevel, const char *fmt, ...);
  
 static void
 queue_log_entry(struct log_entry *le)
@@ -132,7 +149,7 @@ queue_log_entry(struct log_entry *le)
         } else {
             int skip_tmp = skipped_logs; 
             skipped_logs = 0; // clear before calling log_status_message()
-            log_status_message("skipped %d log entries (queue full)", skip_tmp);
+            log_status_message(3, "skipped %d log entries (queue full)", skip_tmp);
             g_async_queue_push(queue, le);
         }
     } else {
@@ -149,13 +166,17 @@ queue_log_entry(struct log_entry *le)
 #define LEPRINTTIME(sec) { time_t tmp_sec = sec; if (le->len < (LE_MAX - 30)) le->len += strftime(le->buf + le->len, LE_MAX - le->len, "%d/%b/%Y:%H:%M:%S %z ", localtime(&tmp_sec)); }
 
 static void 
-log_status_message(const char *fmt, ...) 
+log_status_message(guint loglevel, const char *fmt, ...) 
 {
     va_list ap;
     va_start(ap, fmt);
     
+    if (loglevel > 7 ) loglevel = 7; // syslog defines level 0-7
+
     struct log_entry *le = g_new0(struct log_entry, 1);
 
+    LEPRINTF("0 %d - ", loglevel);
+
     LEPRINTTIME(time(NULL));
 
     le->len += vsnprintf(le->buf + le->len, LE_MAX - le->len, fmt, ap);
@@ -401,13 +422,54 @@ static int print_pkt(struct log_entry *le, struct nflog_data *ldata, u_int8_t fa
     char *payload;
     char devname[256];
     
+    guint32 vmid = 0;
+
+    guint8 log_level = 6; // info
+
+    char *chain_name = "-";
+
+    if (prefix != NULL) {
+        // Note: parse ":$vmid:$loglevel:$chain: $msg"
+        if (prefix[0] == ':') {
+            char *p = prefix + 1;
+            guint32 tmpid = 0;
+            while(*p  >= '0' && *p <= '9') { tmpid *= 10; tmpid += *p - '0'; p++; }
+
+            if ((*p == ':') &&
+                (p[1] >= '0' && p[1] <= '7') &&
+                (p[2] == ':')) {
+
+                guint8 tmp_level = p[1] - '0'; // store for later use
+                char *chain_start = p + 3; // store for later use
+                p = chain_start;
+                while (*p && *p != ':' && *p != ' ') p++;
+                int len = p - chain_start;
+
+                if (*p == ':' && p[1] == ' ' && len && (len <= MAX_CHAIN_LEN)) {
+                    // parsing successful
+
+                    *p = 0; // terminate string
+
+                    vmid = tmpid;
+                    log_level = tmp_level;
+                    chain_name = chain_start;
+                    prefix = p + 2; // the rest
+                } 
+            }
+        }
+    }
+
+    LEPRINTF("%d ", vmid);
+
+    LEPRINTF("%d ", log_level);
+
+    LEPRINTF("%s ", chain_name);
+
     struct timeval ts;
     nflog_get_timestamp(ldata, &ts);
 
     LEPRINTTIME(ts.tv_sec);
 
-    //le->len += strftime(le->buf + le->len, LE_MAX - le->len, "%d/%b/%Y:%H:%M:%S %z ", localtime(&ts.tv_sec));
-
     if (prefix != NULL) {
         LEPRINTF("%s", prefix);
     }
@@ -528,7 +590,7 @@ terminate_request(gpointer data)
 {
     terminate_threads = TRUE;
 
-    log_status_message("received terminate request (signal)");
+    log_status_message(5, "received terminate request (signal)");
 
     g_main_loop_quit(main_loop);
     
@@ -640,7 +702,7 @@ main(int argc, char *argv[])
 
     queue = g_async_queue_new_full(g_free);
 
-    log_status_message("starting pvefw logger");
+    log_status_message(5, "starting pvefw logger");
 
     nlif_query(nlifh);
 
@@ -662,7 +724,7 @@ main(int argc, char *argv[])
     
     g_main_loop_run(main_loop);
 
-    log_status_message("stopping pvefw logger");
+    log_status_message(5, "stopping pvefw logger");
 
     g_thread_join(wthread);
 
-- 
2.39.2