Revise logging and add tracing support

CMakeLists.txt

@@ -3,13 +3,17 @@ cmake_minimum_required(VERSION 3.0)
 project(macNock C)
 
 option(MACNOCK_DEBUG "Enable debug messages" OFF)
-
-add_definitions(-Wall -Wextra -pedantic)
-
 if(MACNOCK_DEBUG)
     add_definitions(-DDEBUG)
 endif(MACNOCK_DEBUG)
 
+option(MACNOCK_TRACE "Enable tracing messages" OFF)
+if(MACNOCK_TRACE)
+    add_definitions(-DTRACE)
+endif(MACNOCK_TRACE)
+
+add_definitions(-Wall -Wextra -pedantic)
+
 set(MACNOCK_SRC
     main.c
     macnockserver.c

log.h

@@ -1,12 +1,20 @@
 #ifndef _DEBUG_H
 #define _DEBUG_H
 
-#ifdef DEBUG
+#if defined(DEBUG) || defined(TRACE)
 #include <stdio.h>
+#endif
 
+#ifdef DEBUG
 #define log_debug(...) printf(__VA_ARGS__)
 #else
 #define log_debug(...) do { } while (0);
 #endif
 
+#ifdef TRACE
+#define log_trace(...) printf(__VA_ARGS__)
+#else
+#define log_trace(...) do { } while (0);
+#endif
+
 #endif // _DEBUG_H

macnockclient.c

@@ -29,7 +29,7 @@ static uint8_t stop;
 
 void macNockClient_stop()
 {
-    log_debug("Stopping Client\n");
+    log_debug("[c] Stopping Client\n");
     stop = 1;
 }
 
@@ -84,7 +84,7 @@ void macNockClient_run()
 
     while (!stop)
     {
-        log_debug("[c] sending\n");
+        log_trace("[c] sending\n");
 
         int sent = sendto(fd, nock, len, 0, (struct sockaddr *)&servaddr, sizeof(servaddr));
         if (sent == -1)
@@ -103,6 +103,6 @@ void macNockClient_run()
 
     close(fd);
 
-    log_debug("Client closed\n");
+    log_debug("[c] Client closed\n");
     return;
 }

macnockserver.c

@@ -26,7 +26,7 @@ int fd;
 
 void macNockServer_stop()
 {
-    log_debug("Stopping Server\n");
+    log_debug("[s] Stopping Server\n");
     stop = 1;
     shutdown(fd, SHUT_RDWR);
 }
@@ -66,7 +66,7 @@ void macNockServer_run()
 
     while (!stop)
     {
-        log_debug("[s] waiting for connection\n");
+        log_trace("[s] waiting for connection\n");
 
         struct sockaddr_in6 client_addr;
         socklen_t addrlen = sizeof(client_addr);
@@ -83,7 +83,7 @@ void macNockServer_run()
 
         char addrBuf[INET6_ADDRSTRLEN];
         const char *ret = inet_ntop(AF_INET6, &client_addr.sin6_addr, addrBuf, sizeof(addrBuf));
-        log_debug("[s] received %d bytes from %s\n", recvlen, ret);
+        log_trace("[s] received %d bytes from %s\n", recvlen, ret);
 
         struct NockPackage *nock = (struct NockPackage *)buf;
         nock->hood[nock->hoodLen] = '\0';
@@ -94,25 +94,25 @@ void macNockServer_run()
             continue;
         }
 
-        log_debug("The MAC: %2x:%2x:%2x:%2x:%2x:%2x, the Hood: %s\n",
+        log_trace("[s] The MAC: %02x:%02x:%02x:%02x:%02x:%02x, the Hood: %s\n",
                   nock->mac[0], nock->mac[1], nock->mac[2], nock->mac[3], nock->mac[4], nock->mac[5], nock->hood);
 
         if (strcmp(nock->hood, g_hood) == 0)
         {
-            log_debug("[s] allowing %2x:%2x:%2x:%2x:%2x:%2x\n",
+            log_trace("[s] allowing %02x:%02x:%02x:%02x:%02x:%02x\n",
                   nock->mac[0], nock->mac[1], nock->mac[2], nock->mac[3], nock->mac[4], nock->mac[5]);
             macStorage_add(nock->mac);
         }
         else
         {
-            log_debug("[s] wrong hood. Not allowing %2x:%2x:%2x:%2x:%2x:%2x\n",
+            log_debug("[s] Not allowing %02x:%02x:%02x:%02x:%02x:%02x. Wrong hood: \"%s\"\n",
-                  nock->mac[0], nock->mac[1], nock->mac[2], nock->mac[3], nock->mac[4], nock->mac[5]);
+                  nock->mac[0], nock->mac[1], nock->mac[2], nock->mac[3], nock->mac[4], nock->mac[5], nock->hood);
         }
     }
 
     close(fd);
     tc_stop();
 
-    log_debug("Server closed\n");
+    log_debug("[s] Server closed\n");
     return;
 }

macstorage.c

@@ -56,6 +56,9 @@ void _addEntry(uint8_t mac[6])
 
     if (count != MAXENTRIES)
     {
+        log_debug("[m] new entry: %02x:%02x:%02x:%02x:%02x:%02x.\n",
+              mac[0], mac[1], mac[2], mac[3], mac[4], mac[5]);
+
         uint8_t prio = _getNextFreePrio();
         memcpy(storage[count].mac, mac, 6);
         storage[count].timestamp = time(NULL);
@@ -83,6 +86,10 @@ void _checkTimeout()
     {
         if (storage[i].timestamp < t)
         {
+            log_debug("[m] %02x:%02x:%02x:%02x:%02x:%02x timed out, removing.\n",
+                  storage[i].mac[0], storage[i].mac[1], storage[i].mac[2],
+                  storage[i].mac[3], storage[i].mac[4], storage[i].mac[5]);
+
             tc_disallow_mac(storage[i].mac, storage[i].prio+1);
             _freePrio(storage[i].prio);
             count--;
@@ -97,7 +104,7 @@ void _checkTimeout()
 
 void macStorage_stop()
 {
-    log_debug("Stopping Storage\n");
+    log_debug("[m] Stopping Storage\n");
     stop = 1;
 }
 
@@ -116,6 +123,6 @@ void macStorage_run()
         usleep(5 * 1000 * 1000);
     }
 
-    log_debug("Storage closed\n");
+    log_debug("[m] Storage closed\n");
     return;
 }

main.c

@@ -56,7 +56,7 @@ int main(int argc, char *argv[])
     g_interface = argv[1];
     g_hood = argv[2];
 
-    //log_debug("Running for hood %s (%s) on interface %s (%s)\n", g_hood, argv[1], g_interface, argv[2]);
+    printf("%s: Running for hood %s on interface %s\n", argv[0], g_hood, g_interface);
 
     signal(SIGINT, &sigHandler);
     signal(SIGTERM, &sigHandler);

tc.c

@@ -32,7 +32,7 @@ void tc_add_qdisc_ingress()
 {
     char cmd[2048];
     snprintf(cmd, 2048, "tc qdisc add dev %s ingress", g_interface);
-    log_debug("CMD: %s\n", cmd);
+    log_trace("CMD: %s\n", cmd);
     system(cmd);
 }
 
@@ -40,7 +40,7 @@ void tc_del_qdisc_ingress()
 {
     char cmd[2048];
     snprintf(cmd, 2048, "tc qdisc del dev %s ingress", g_interface);
-    log_debug("CMD: %s\n", cmd);
+    log_trace("CMD: %s\n", cmd);
     system(cmd);
 }
 
@@ -48,7 +48,7 @@ void tc_block_all()
 {
     char cmd[2048];
     snprintf(cmd, 2048, "tc filter add dev %s protocol all parent ffff: prio 65535 basic match \"u32(u16 0x4305 0xffff at -2)\" flowid :1 action drop", g_interface);
-    log_debug("CMD: %s\n", cmd);
+    log_trace("CMD: %s\n", cmd);
     system(cmd);
 }
 
@@ -63,7 +63,7 @@ void tc_allow_mac(const uint8_t mac[], uint8_t prio)
              "basic match \"u32(u32 0x%s 0x%s at -8)\" "
              "and \"u32(u16 0x%s 0x%s at -4)\" flowid :1 action pass",
              g_interface, prio, mac32, mac32, mac16, mac16);
-    log_debug("CMD: %s\n", cmd);
+    log_trace("CMD: %s\n", cmd);
     system(cmd);
 }
 
@@ -78,19 +78,23 @@ void tc_disallow_mac(const uint8_t mac[], uint8_t prio)
              "basic match \"u32(u32 0x%s 0x%s at -8)\" "
              "and \"u32(u16 0x%s 0x%s at -4)\" flowid :1 action pass",
              g_interface, prio, mac32, mac32, mac16, mac16);
-    log_debug("CMD: %s\n", cmd);
+    log_trace("CMD: %s\n", cmd);
     system(cmd);
 }
 
 void tc_start()
 {
+    log_debug("[t] Removing old qdisc.\n");
     tc_del_qdisc_ingress(); // in case a old session is sill there
 
+    log_debug("[t] Adding qdisc.\n");
     tc_add_qdisc_ingress();
+    log_debug("[t] Blocking all batman-adv traffic.\n");
     tc_block_all();
 }
 
 void tc_stop()
 {
+    log_debug("[t] Removing qdisc.\n");
     tc_del_qdisc_ingress();
 }