X-Git-Url: https://git.proxmox.com/?p=pve-firewall.git;a=blobdiff_plain;f=src%2Fpvefw-logger.c;h=578d1aaebf482ecee01114c1edd4c44e79758586;hp=db7a026027f0b7163507abe3964a52f8b237eabb;hb=b4366f0078a37b8542dbeca999dc39cbd4a00f7f;hpb=ba0b3a0a1eae4d40ea2cdeeea33b47ad150f4ad1

diff --git a/src/pvefw-logger.c b/src/pvefw-logger.c
index db7a026..578d1aa 100644
--- a/src/pvefw-logger.c
+++ b/src/pvefw-logger.c
@@ -29,7 +29,8 @@
 #include <stdarg.h>
 #include <string.h>
 #include <signal.h>
-#include <sys/types.h> 
+#include <sys/signalfd.h>
+#include <sys/types.h>
 #include <sys/stat.h>
 #include <fcntl.h>
 #include <unistd.h>
@@ -44,12 +45,30 @@
 #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;
+GMainLoop *main_loop;
+
+gboolean foreground = FALSE;
+gboolean debug = FALSE;
+
+/*
+
+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"
 
@@ -57,13 +76,20 @@ static struct nlif_handle *nlifh = NULL;
 #define PIDFILE "/var/run/pvefw-logger.pid"
 
 #define LQ_LEN 512
-#define LE_MAX (512 - 16) // try to fit into 512 bytes
+#define LE_MAX (512 - 4) // try to fit into 512 bytes
+
+#define MAX_CHAIN_LEN 28
 
-struct log_entry { 
+struct log_entry {
     guint32 len; // max LE_MAX chars
     char buf[LE_MAX];
 };
 
+#define STATIC_ASSERT(cond) \
+    extern void pve_static_assert(int test[(cond) ? 1 : -1])
+
+STATIC_ASSERT(sizeof(struct log_entry) == 512);
+
 int outfd = -1;
 
 gboolean terminate_threads = FALSE;
@@ -81,7 +107,7 @@ static gboolean write_pidfile(pid_t pid)
 
 static GAsyncQueue *queue;
 
-ssize_t 
+ssize_t
 safe_write(int fd, char *buf, size_t count)
 {
   ssize_t n;
@@ -94,7 +120,7 @@ safe_write(int fd, char *buf, size_t count)
 }
 
 static gpointer
-log_writer_thread(gpointer data) 
+log_writer_thread(gpointer data)
 {
     while (1) {
         struct log_entry *le = (struct log_entry *)g_async_queue_timeout_pop(queue, 250000);
@@ -104,13 +130,17 @@ log_writer_thread(gpointer data)
             }
             continue;
         }
- 
+
+        if (debug) fputs(le->buf, stdout);
+
         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));
+            g_main_loop_quit(main_loop);
+            return NULL;
         }
     }
 
@@ -119,8 +149,8 @@ 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)
 {
@@ -130,9 +160,9 @@ queue_log_entry(struct log_entry *le)
         if (len >= (LQ_LEN - 1)) {
             skipped_logs++;
         } else {
-            int skip_tmp = skipped_logs; 
+            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 {
@@ -148,14 +178,18 @@ queue_log_entry(struct log_entry *le)
 #define LEPRINTF(format, ...) { if (le->len < LE_MAX) le->len += snprintf(le->buf + le->len, LE_MAX - le->len, format, ##__VA_ARGS__); }
 #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, ...) 
+static void
+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,9 +197,13 @@ log_status_message(const char *fmt, ...)
     LEPRINTF("\n");
 
     queue_log_entry(le);
+
+    // also log to syslog
+
+    vsyslog(loglevel, fmt, ap);
 }
 
-static int 
+static int
 print_tcp(struct log_entry *le, struct tcphdr *h, int payload_len)
 {
     LEPRINTF("PROTO=TCP ");
@@ -192,7 +230,7 @@ print_tcp(struct log_entry *le, struct tcphdr *h, int payload_len)
     return 0;
 }
 
-static int 
+static int
 print_udp(struct log_entry *le, struct udphdr *h, int payload_len)
 {
     LEPRINTF("PROTO=UDP ");
@@ -208,7 +246,7 @@ print_udp(struct log_entry *le, struct udphdr *h, int payload_len)
     return 0;
 }
 
-static int 
+static int
 print_icmp(struct log_entry *le, struct icmphdr *h, int payload_len)
 {
     char tmp[INET_ADDRSTRLEN];
@@ -234,7 +272,7 @@ print_icmp(struct log_entry *le, struct icmphdr *h, int payload_len)
         break;
     case ICMP_REDIRECT:
         gateway = ntohl(h->un.gateway);
-        inet_ntop(AF_INET, &gateway, tmp, sizeof(tmp));                
+        inet_ntop(AF_INET, &gateway, tmp, sizeof(tmp));
         LEPRINTF("GATEWAY=%s ", tmp);
         break;
     case ICMP_DEST_UNREACH:
@@ -255,7 +293,7 @@ typedef struct sctphdr {
 	__be32 checksum;
 } __attribute__((packed)) sctp_sctphdr_t;
 
-static int 
+static int
 print_sctp(struct log_entry *le, struct sctphdr *h, int payload_len)
 {
     LEPRINTF("PROTO=SCTP ");
@@ -271,7 +309,7 @@ print_sctp(struct log_entry *le, struct sctphdr *h, int payload_len)
     return 0;
 }
 
-static int 
+static int
 print_iphdr(struct log_entry *le, char * payload, int payload_len)
 {
     if (payload_len < sizeof(struct iphdr)) {
@@ -281,25 +319,25 @@ print_iphdr(struct log_entry *le, char * payload, int payload_len)
     }
 
     struct iphdr *h = (struct iphdr *)payload;
- 
+
     if (payload_len <= (u_int32_t)(h->ihl * 4)) {
         LEPRINTF("INVALID=IHL ");
         return -1;
     }
 
     char tmp[INET_ADDRSTRLEN];
-   
-    inet_ntop(AF_INET, &h->saddr, tmp, sizeof(tmp));                
+
+    inet_ntop(AF_INET, &h->saddr, tmp, sizeof(tmp));
     LEPRINTF("SRC=%s ", tmp);
-    inet_ntop(AF_INET, &h->daddr, tmp, sizeof(tmp));                
+    inet_ntop(AF_INET, &h->daddr, tmp, sizeof(tmp));
     LEPRINTF("DST=%s ", tmp);
 
     LEPRINTF("LEN=%u TOS=0x%02X PREC=0x%02X TTL=%u ID=%u ",
              ntohs(h->tot_len),  h->tos & IPTOS_TOS_MASK,
              h->tos & IPTOS_PREC_MASK, h->ttl, ntohs(h->id));
-                
+
     short ip_off = ntohs(h->frag_off);
-    if (ip_off & IP_OFFMASK) 
+    if (ip_off & IP_OFFMASK)
         LEPRINTF("FRAG=%u ", ip_off & IP_OFFMASK);
 
     if (ip_off & IP_DF) LEPRINTF("DF ");
@@ -337,7 +375,7 @@ print_iphdr(struct log_entry *le, char * payload, int payload_len)
     return 0;
 }
 
-static int 
+static int
 print_ip6hdr(struct log_entry *le, char * payload, int payload_len)
 {
     LEPRINTF("IPV6 logging not implemented ");
@@ -346,7 +384,7 @@ print_ip6hdr(struct log_entry *le, char * payload, int payload_len)
 }
 
 // ebtables -I FORWARD --nflog --nflog-group 0
-static int 
+static int
 print_arp(struct log_entry *le, struct ether_arp *h, int payload_len)
 {
     if (payload_len < sizeof(struct ether_arp)) {
@@ -369,8 +407,8 @@ print_arp(struct log_entry *le, struct ether_arp *h, int payload_len)
         LEPRINTF("REQUEST ");
         break;
     case ARPOP_REPLY:
-        LEPRINTF("REPLY MAC=%02x:%02x:%02x:%02x:%02x:%02x ", 
-                 h->arp_sha[0], h->arp_sha[1], h->arp_sha[2], 
+        LEPRINTF("REPLY MAC=%02x:%02x:%02x:%02x:%02x:%02x ",
+                 h->arp_sha[0], h->arp_sha[1], h->arp_sha[2],
                  h->arp_sha[3], h->arp_sha[4], h->arp_sha[5]);
         break;
     case ARPOP_NAK:
@@ -400,32 +438,89 @@ static int print_pkt(struct log_entry *le, struct nflog_data *ldata, u_int8_t fa
     char *prefix = nflog_get_prefix(ldata);
     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);
@@ -448,7 +543,7 @@ static int print_pkt(struct log_entry *le, struct nflog_data *ldata, u_int8_t fa
     struct nfulnl_msg_packet_hdr *ph = NULL;
 
     switch (family) {
-    case AF_INET: 
+    case AF_INET:
         print_iphdr(le, payload, payload_len);
         break;
     case AF_INET6:
@@ -479,12 +574,12 @@ static int print_pkt(struct log_entry *le, struct nflog_data *ldata, u_int8_t fa
 
 }
 
-static int 
+static int
 nflog_cb(struct nflog_g_handle *gh, struct nfgenmsg *nfmsg,
                struct nflog_data *nfa, void *data)
 {
     struct log_entry *le = g_new0(struct log_entry, 1);
- 
+
     print_pkt(le, nfa, nfmsg->nfgen_family);
 
     LEPRINTF("\n"); // add newline
@@ -503,7 +598,7 @@ nflog_read_cb(GIOChannel *source,
     gchar buf[8192];
 
     int fd =  g_io_channel_unix_get_fd(source);
-   
+
     if ((rv = recv(fd, buf, sizeof(buf), 0)) && rv >= 0) {
          nflog_handle_packet(logh, buf, rv);
     }
@@ -516,55 +611,101 @@ nlif_read_cb(GIOChannel *source,
              GIOCondition condition,
              gpointer data)
 {
-    nlif_catch(nlifh);
-    // fixme: report  errors
-    return TRUE; 
-}
+    static int last_res = 0;
+    int res;
 
-GMainLoop *main_loop;
+    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;
+}
 
 static gboolean
-terminate_request(gpointer data) 
+signal_read_cb(GIOChannel *source,
+               GIOCondition condition,
+               gpointer data)
 {
-    terminate_threads = TRUE;
+    int rv = 0;
+    struct signalfd_siginfo si;
 
-    log_status_message("received terminate request (signal)");
+    int fd =  g_io_channel_unix_get_fd(source);
+
+    if ((rv = read(fd, &si, sizeof(si))) && rv >= 0) {
+        terminate_threads = TRUE;
+        log_status_message(5, "received terminate request (signal)");
+        g_main_loop_quit(main_loop);
+    }
 
-    g_main_loop_quit(main_loop);
-    
     return TRUE;
 }
-                
 
 int
 main(int argc, char *argv[])
 {
     int lockfd = -1;
-    gboolean foreground = FALSE;
+    int sigfd = -1;
+
     gboolean wrote_pidfile = FALSE;
 
     g_thread_init(NULL);
 
+    openlog("pvepw-logger", LOG_CONS|LOG_PID, LOG_DAEMON);
+
+    GOptionContext *context;
+
+    GOptionEntry entries[] = {
+        { "debug", 'd', 0, G_OPTION_ARG_NONE, &debug, "Turn on debug messages", NULL },
+        { "foreground", 'f', 0, G_OPTION_ARG_NONE, &foreground, "Do not daemonize server", NULL },
+        { NULL },
+    };
+
+    context = g_option_context_new("");
+    g_option_context_add_main_entries (context, entries, NULL);
+
+    GError *err = NULL;
+    if (!g_option_context_parse (context, &argc, &argv, &err)) {
+        fprintf(stderr, "error: %s\n", err->message);
+        fprintf(stderr, "%s", g_option_context_get_help(context, FALSE, NULL));
+        g_error_free (err);
+        exit(-1);
+    }
+
+    if (optind < argc) {
+        fprintf(stderr, "error: too many arguments\n");
+        fprintf(stderr, "%s", g_option_context_get_help(context, FALSE, NULL));
+        exit(-1);
+    }
+
+    g_option_context_free(context);
+
+    if (debug) foreground = TRUE;
+
     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\n", LOCKFILE, strerror (errno) );
         exit(-1);
     }
 
     for (int i = 10; i >= 0; i--) {
         if (flock(lockfd, LOCK_EX|LOCK_NB) != 0) {
             if (!i) {
-                fprintf(stderr, "unable to aquire lock '%s': %s", LOCKFILE, strerror (errno));
+                fprintf(stderr, "unable to aquire lock '%s': %s\n", LOCKFILE, strerror (errno));
                 exit(-1);
             }
             if (i == 10)
                 fprintf(stderr, "unable to aquire lock '%s' - trying again.\n", LOCKFILE);
-            
+
             sleep(1);
         }
     }
 
     if ((outfd = open(LOGFILE, O_WRONLY|O_CREAT|O_APPEND, 0644)) == -1) {
-        fprintf(stderr, "unable to open file '%s': %s", LOGFILE, strerror (errno));
+        fprintf(stderr, "unable to open file '%s': %s\n", LOGFILE, strerror (errno));
         exit(-1);
     }
 
@@ -584,7 +725,7 @@ main(int argc, char *argv[])
         exit(-1);
     }
 #endif
-    
+
     if (!nflog_bind_pf(logh, AF_BRIDGE) <= 0) {
         fprintf(stderr, "nflog_bind_pf AF_BRIDGE failed\n");
         exit(-1);
@@ -592,10 +733,10 @@ main(int argc, char *argv[])
 
     struct nflog_g_handle *qh = nflog_bind_group(logh, 0);
     if (!qh) {
-        fprintf(stderr, "no handle for group 1\n");
+        fprintf(stderr, "no nflog handle for group 0\n");
         exit(-1);
     }
- 
+
     if (nflog_set_mode(qh, NFULNL_COPY_PACKET, 0xffff) < 0) {
         fprintf(stderr, "can't set packet copy mode\n");
         exit(-1);
@@ -606,6 +747,18 @@ main(int argc, char *argv[])
         exit(-1);
     }
 
+    sigset_t mask;
+    sigemptyset(&mask);
+    sigaddset(&mask, SIGINT);
+    sigaddset(&mask, SIGTERM);
+    
+    sigprocmask(SIG_BLOCK, &mask, NULL);
+
+    if ((sigfd = signalfd(-1, &mask, SFD_NONBLOCK)) < 0) {
+        fprintf(stderr, "unable to open signalfd: %s\n", strerror (errno));
+        exit(-1);
+    }
+
     if (!foreground) {
         pid_t cpid = fork();
 
@@ -640,7 +793,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);
 
@@ -653,16 +806,19 @@ main(int argc, char *argv[])
 
     g_io_add_watch(nflog_ch, G_IO_IN, nflog_read_cb, NULL);
 
+    GIOChannel *sig_ch = g_io_channel_unix_new(sigfd);
+    printf("TEST0: %p %d\n", sig_ch, sigfd);
+    if (!g_io_add_watch(sig_ch, G_IO_IN, signal_read_cb, NULL)) {
+        printf("TEST1\n"); exit(-1);
+    }
+
     GThread *wthread = g_thread_new("log_writer_thread", log_writer_thread, NULL);
-    
+
     main_loop = g_main_loop_new(NULL, TRUE);
-    
-    g_unix_signal_add(SIGINT, terminate_request, NULL);
-    g_unix_signal_add(SIGTERM, terminate_request, NULL);
-    
+
     g_main_loop_run(main_loop);
 
-    log_status_message("stopping pvefw logger");
+    log_status_message(5, "stopping pvefw logger");
 
     g_thread_join(wthread);