]> git.proxmox.com Git - pve-firewall.git/blobdiff - src/pvefw-logger.c
additionally log status messages to syslog
[pve-firewall.git] / src / pvefw-logger.c
index db7a026027f0b7163507abe3964a52f8b237eabb..044a18ac2e2091f382bdc07f011afb786b94a013 100644 (file)
@@ -44,6 +44,7 @@
 #include <netinet/udp.h>
 #include <netinet/tcp.h>
 #include <netinet/if_ether.h>
+#include <syslog.h>
 
 #include <glib.h>
 #include <glib-unix.h>
 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 +74,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,13 +121,14 @@ log_writer_thread(gpointer data)
             }
             continue;
         }
+       
         int res = safe_write(outfd, le->buf, le->len);
-
         g_free(le);
 
         if (res < 0) {
-            // printf("write failed\n"); // fixme??
+            syslog(3, "writing log failed, stopping daemon - %s", strerror (errno));
+            return NULL;
         }
     }
 
@@ -119,7 +137,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 +150,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 +167,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);
@@ -163,6 +185,10 @@ log_status_message(const char *fmt, ...)
     LEPRINTF("\n");
 
     queue_log_entry(le);
+
+    // also log to syslog
+
+    vsyslog(loglevel, fmt, ap);
 }
 
 static int 
@@ -401,31 +427,88 @@ 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);
     }
     
-    if ((indev > 0) && (nlif_index2name(nlifh, indev, devname) != -1)) {
-        LEPRINTF("IN=%s ", devname); 
+    if (indev > 0) { 
+        if (nlif_index2name(nlifh, indev, devname) != -1) {
+            LEPRINTF("IN=%s ", devname); 
+        } else {
+            LEPRINTF("IN=%u ", indev); 
+        }
     }
 
-    if ((outdev > 0) && (nlif_index2name(nlifh, outdev, devname) != -1)) {
-        LEPRINTF("OUT=%s ", devname);
+    if (outdev > 0) {
+        if (nlif_index2name(nlifh, outdev, devname) != -1) {
+            LEPRINTF("OUT=%s ", devname);
+        } else {
+            LEPRINTF("OUT=%u ", outdev);
+        }
     }
 
-    if ((physindev > 0) && (nlif_index2name(nlifh, physindev, devname) != -1)) {
-        LEPRINTF("PHYSIN=%s ", devname);
+    if (physindev > 0) { 
+        if (nlif_index2name(nlifh, physindev, devname) != -1) {
+            LEPRINTF("PHYSIN=%s ", devname);
+        } else {
+            LEPRINTF("PHYSIN=%u ", physindev);
+        }
     }
          
-    if ((physoutdev > 0) &&  (nlif_index2name(nlifh, physoutdev, devname) != -1)) {
-        LEPRINTF("PHYSOUT=%s ", devname);
+    if (physoutdev > 0) {
+        if (nlif_index2name(nlifh, physoutdev, devname) != -1) {
+            LEPRINTF("PHYSOUT=%s ", devname);
+        } else {
+            LEPRINTF("PHYSOUT=%u ", physoutdev);
+        }
     }
 
     int payload_len = nflog_get_payload(ldata, &payload);
@@ -516,8 +599,18 @@ nlif_read_cb(GIOChannel *source,
              GIOCondition condition,
              gpointer data)
 {
-    nlif_catch(nlifh);
-    // fixme: report  errors
+    static int last_res = 0;
+    int res;
+
+    if ((res = nlif_catch(nlifh)) < 0) {
+        if (last_res == 0) { // only report once
+            log_status_message(3, "nlif_catch failed (res = %d)", res);
+        }
+        last_res = res;
+    } else {
+        last_res = 0;
+    }
+
     return TRUE; 
 }
 
@@ -528,7 +621,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);
     
@@ -545,8 +638,10 @@ main(int argc, char *argv[])
 
     g_thread_init(NULL);
 
+    openlog("pvepw-logger", LOG_CONS|LOG_PID, LOG_DAEMON);
+
     if ((lockfd = open(LOCKFILE, O_RDWR|O_CREAT|O_APPEND, 0644)) == -1) {
-        fprintf(stderr, "unable to create lock '%s': %s", LOCKFILE, strerror (errno));
+        fprintf(stderr, "unable to create lock '%s': %s", LOCKFILE, strerror (errno) );
         exit(-1);
     }
 
@@ -640,7 +735,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 +757,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);