qemu logging extensions

(1) Clear the logs upon receiving a SIGUSR1 signal
(2) Add logging timestamps for network connections
(3) Extended TCP redirect logs to include local src
    ip/port and fixed byte-ordering in log files

Change-Id: I51e7293c8eeb5979a92e67f52f1c6416400d83c6

6 files changed, 152 insertions, 42 deletions

diff --git a/slirp-android/libslirp.h b/slirp-android/libslirp.h
index 120e3d3..e8b63a8 100644
--- a/slirp-android/libslirp.h
+++ b/slirp-android/libslirp.h
@@ -43,6 +43,9 @@ void slirp_drop_tcp();
 void slirp_add_allow(unsigned long dst_addr, int dst_lport,
                      int dst_hport, u_int8_t proto);
 void slirp_drop_log_fd(FILE* fd);
+
+/** Get the drop log fd */
+FILE* get_slirp_drop_log_fd(void);
 int slirp_should_drop(unsigned long dst_addr,
                       int dst_port,
                       u_int8_t proto);
@@ -64,6 +67,8 @@ int slirp_should_net_forward(unsigned long remote_ip, int remote_port,
  */
 
 void slirp_dns_log_fd(FILE* fd);
+/** Get the dns log fd */
+FILE* get_slirp_dns_log_fd(void);
 /** Logs the DNS name in DNS query issued by the VM. */
 int slirp_log_dns(struct mbuf* m, int dropped);
 /** IP packet dump of DNS queris and responses. */
diff --git a/slirp-android/slirp.c b/slirp-android/slirp.c
index 015918f..6a62e4b 100644
--- a/slirp-android/slirp.c
+++ b/slirp-android/slirp.c
@@ -923,6 +923,14 @@ void slirp_dns_log_fd(FILE* fd) {
     dns_log_fd = fd;
 }
 
+FILE* get_slirp_drop_log_fd(void) {
+  return drop_log_fd;
+}
+
+FILE* get_slirp_dns_log_fd(void) {
+  return dns_log_fd;
+}
+
 /* Address and ports are in host byte order */
 int slirp_should_drop(unsigned long dst_addr,
                       int dst_port,
diff --git a/slirp-android/socket.c b/slirp-android/socket.c
index 285a8ef..439590a 100644
--- a/slirp-android/socket.c
+++ b/slirp-android/socket.c
@@ -578,12 +578,13 @@ sosendto(struct socket *so, struct mbuf *m)
         int fport = addr_port;
 
 	if (slirp_should_net_forward(faddr, fport, &faddr, &fport)) {
-	    slirp_drop_log(
+      time_t timestamp = time(NULL);
+      slirp_drop_log(
 	       "Redirected UDP: src: 0x%08lx:0x%04x org dst: 0x%08lx:0x%04x "
-	       "new dst: 0x%08lx:0x%04x\n",
+	       "new dst: 0x%08lx:0x%04x %ld\n",
 	        so->so_laddr_ip, so->so_laddr_port,
 	        addr_ip, addr_port,
-	        faddr, fport
+	        faddr, fport, timestamp
 	    );
 	}
 	addr_ip = faddr;
diff --git a/slirp-android/tcp_subr.c b/slirp-android/tcp_subr.c
index 0550d4b..cfcc3cb 100644
--- a/slirp-android/tcp_subr.c
+++ b/slirp-android/tcp_subr.c
@@ -384,7 +384,7 @@ tcp_proxy_event( struct socket*  so,
  */
 int is_qemu_special_address(unsigned long dst_addr, unsigned long *redir_addr)
 {
-  if ((dst_addr & htonl(0xffffff00)) == special_addr_ip) {
+  if ((dst_addr & 0xffffff00) == special_addr_ip) {
     /* It's an alias */
 
     int  last_byte = dst_addr & 0xff;
@@ -416,6 +416,7 @@ int tcp_fconnect(struct socket *so)
     SockAddress    sockaddr;
     unsigned long       sock_ip;
     int                 sock_port;
+    int redirect_happened = 0; /* for logging new src ip/port after connect */
 
     DEBUG_CALL("tcp_fconnect");
     DEBUG_ARG("so = %lx", (long )so);
@@ -423,7 +424,7 @@ int tcp_fconnect(struct socket *so)
     /* when true, a connection that otherwise would be dropped will instead be
      * redirected to the sink ('-net-forward-tcp2sink') */
     int forward_dropped_to_sink = 0;
-
+    time_t timestamp = time(NULL);
 
     /*-------------------------------------------------------------*/
     /* User mode network stack restrictions */
@@ -432,22 +433,24 @@ int tcp_fconnect(struct socket *so)
       /* If forwarding to sink is enabled, don't actually drop it */
       if (slirp_should_forward_dropped_tcp2sink()) {
         slirp_drop_log(
-            "About to be dropped TCP forwarded to sink: "
-            "src: 0x%08lx:0x%04x dst: 0x%08lx:0x%04x\n",
+            "About to be dropped TCP allowed to sink: "
+            "0x%08lx:0x%04x -> 0x%08lx:0x%04x %ld\n",
               so->so_laddr_ip,
               so->so_laddr_port,
               so->so_faddr_ip,
-              so->so_faddr_port
+              so->so_faddr_port,
+              timestamp
         );
         forward_dropped_to_sink = 1;
       }
       else {
         slirp_drop_log(
-            "Dropped TCP: src: 0x%08lx:0x%04x dst: 0x%08lx:0x%04x\n",
+            "Dropped TCP: 0x%08lx:0x%04x -> 0x%08lx:0x%04x %ld\n",
             so->so_laddr_ip,
             so->so_laddr_port,
             so->so_faddr_ip,
-            so->so_faddr_port
+            so->so_faddr_port,
+            timestamp
         );
         //errno = ENETUNREACH;
         errno = ECONNREFUSED;
@@ -455,11 +458,12 @@ int tcp_fconnect(struct socket *so)
       }
     } else {
       slirp_drop_log(
-          "Allowed TCP: src: 0x%08lx:0x%04x dst: 0x%08lx:0x%04x\n",
+          "Allowed TCP: 0x%08lx:0x%04x -> 0x%08lx:0x%04x %ld\n",
           so->so_laddr_ip,
           so->so_laddr_port,
           so->so_faddr_ip,
-          so->so_faddr_port
+          so->so_faddr_port,
+          timestamp
       );
     }
     /*-------------------------------------------------------------*/
@@ -479,14 +483,7 @@ int tcp_fconnect(struct socket *so)
            * dropped connections is enabled, redirect it to the sink */
           sock_ip = slirp_get_tcp_sink_ip();
           sock_port= slirp_get_tcp_sink_port();
-          slirp_drop_log(
-              "Redirected would-be dropped TCP to sink: "
-                "src: 0x%08lx:0x%04x org dst: 0x%08lx:0x%04x "
-              "new dst: 0x%08lx:0x%04x\n",
-              so->so_laddr_ip, so->so_laddr_port,
-              so->so_faddr_ip, so->so_faddr_port,
-              sock_ip, sock_port
-            );
+          redirect_happened = 1;
         }
         else {   /* An allowed connection */
 
@@ -498,19 +495,13 @@ int tcp_fconnect(struct socket *so)
           /* faddr and fport are modified only on success */
           if (slirp_should_net_forward(so->so_faddr_ip, so->so_faddr_port,
                                        &faddr, &fport)) {
-            slirp_drop_log(
-                "Redirected TCP: src: 0x%08lx:0x%04x org dst: 0x%08lx:0x%04x "
-                "new dst: 0x%08lx:0x%04x\n",
-                so->so_laddr_ip, so->so_laddr_port,
-                so->so_faddr_ip, so->so_faddr_port,
-                faddr, fport
-            );
+            redirect_happened = 1;
             sock_ip = faddr;              /* forced dst addr */
             sock_port= fport;                 /* forced dst port */
           }
           /* Determine if this is a connection to a special qemu service,
            * and change the destination address accordingly.
-           * 'faddr' is modified only onsuccess  */
+           * 'faddr' is modified only on success  */
           else if (is_qemu_special_address(so->so_faddr_ip, &faddr)) {
 
           /* We keep the original destination port. If a special service
@@ -548,7 +539,24 @@ int tcp_fconnect(struct socket *so)
         /* We don't care what port we get */
         socket_connect(s, &sockaddr);
 
-        /*
+        if (redirect_happened) {
+          SockAddress local_addr;
+          if (socket_get_address(s, &local_addr)) {
+            fprintf (stderr,
+                     "Warning: tcp_fconnect: could not get socket name\n");
+          }
+          slirp_drop_log(
+              "Redirected TCP: orig 0x%08lx:0x%04x -> 0x%08lx:0x%04x "
+              "new 0x%08lx:0x%04x -> 0x%08lx:0x%04x %ld\n",
+              so->so_laddr_ip, so->so_laddr_port,
+              so->so_faddr_ip, so->so_laddr_port,
+              sock_address_get_ip(&local_addr),
+              sock_address_get_port(&local_addr),
+              sock_ip, sock_port, timestamp
+          );
+        }
+
+       /*
         * If it's not in progress, it failed, so we just return 0,
         * without clearing SS_NOFDREF
         */
diff --git a/slirp-android/udp.c b/slirp-android/udp.c
index a9c9a82..1de938a 100644
--- a/slirp-android/udp.c
+++ b/slirp-android/udp.c
@@ -129,24 +129,28 @@ udp_input(register struct mbuf *m, int iphlen)
 	/* ------------------------------------------------------*/
 	/* User mode network stack restrictions */
 	/* slirp_should_drop requires host byte ordering in arguments */
+	time_t timestamp = time(NULL);
+
 	if (slirp_should_drop(ntohl(ip->ip_dst.addr), ntohs(uh->uh_dport.port),
 	                      IPPROTO_UDP)) {
 	  slirp_drop_log(
-	    "Dropped UDP: src: 0x%08lx:0x%04x dst: 0x%08lx:0x%04x\n",
-	    ip->ip_src.addr,
-	    uh->uh_sport.port,
-	    ip->ip_dst.addr,
-	    uh->uh_dport.port
+	    "Dropped UDP: src: 0x%08lx:0x%04x dst: 0x%08lx:0x%04x %ld\n",
+	    ntohl(ip->ip_src.addr),
+	    ntohs(uh->uh_sport.port),
+	    ntohl(ip->ip_dst.addr),
+	    ntohs(uh->uh_dport.port),
+	    timestamp
 	  );
 	  goto bad; /* drop the packet */
 	}
 	else {
 	  slirp_drop_log(
-	    "Allowed UDP: src: 0x%08lx:0x%04x dst: 0x%08lx:0x%04x\n",
-	    ip->ip_src.addr,
-	    uh->uh_sport.port,
-	    ip->ip_dst.addr,
-	    uh->uh_dport.port
+	    "Allowed UDP: src: 0x%08lx:0x%04x dst: 0x%08lx:0x%04x %ld\n",
+	    ntohl(ip->ip_src.addr),
+	    ntohs(uh->uh_sport.port),
+	    ntohl(ip->ip_dst.addr),
+	    ntohs(uh->uh_dport.port),
+	    timestamp
 	  );
 	}
   /* ------------------------------------------------------*/
@@ -354,7 +358,7 @@ int udp_output2_(struct socket *so, struct mbuf *m,
 	STAT(udpstat.udps_opackets++);
 
 	//  DNS logging
-	if (so != NULL && so->so_faddr_port == htons(53)) {
+	if (so != NULL && so->so_faddr_port == 53) {  /*so has host byte order */
 	  if (!slirp_dump_dns(m)) {
 	    DEBUG_MISC((dfd,"Error logging DNS packet"));
 	  }
diff --git a/vl-android.c b/vl-android.c
index d94bec0..cb32eb2 100644
--- a/vl-android.c
+++ b/vl-android.c
@@ -406,6 +406,10 @@ extern int android_display_bpp;
 
 extern void  dprint( const char* format, ... );
 
+const char* dns_log_filename = NULL;
+const char* drop_log_filename = NULL;
+static int rotate_logs_requested = 0;
+
 const char* savevm_on_exit = NULL;
 
 #define TFR(expr) do { if ((expr) != -1) break; } while (errno == EINTR)
@@ -512,6 +516,52 @@ static void default_ioport_writel(void *opaque, uint32_t address, uint32_t data)
 #endif
 }
 
+/*
+ * Sets a flag (rotate_logs_requested) to clear both the DNS and the
+ * drop logs upon receiving a SIGUSR1 signal. We need to clear the logs
+ * between the tasks that do not require restarting Qemu.
+ */
+void rotate_qemu_logs_handler(int signum) {
+  rotate_logs_requested = 1;
+}
+
+/*
+ * Resets the rotate_log_requested_flag. Normally called after qemu
+ * logs has been rotated.
+ */
+void reset_rotate_qemu_logs_request(void) {
+  rotate_logs_requested = 0;
+}
+
+/*
+ * Clears the passed qemu log when the rotate_logs_requested
+ * is set. We need to clear the logs between the tasks that do not
+ * require restarting Qemu.
+ */
+FILE* rotate_qemu_log(FILE* old_log_fd, const char* filename) {
+  FILE* new_log_fd = NULL;
+  if (old_log_fd) {
+    if (fclose(old_log_fd) == -1) {
+      fprintf(stderr, "Cannot close old_log fd\n");
+      exit(errno);
+    }
+  }
+
+  if (!filename) {
+    fprintf(stderr, "The log filename to be rotated is not provided");
+    exit(-1);
+  }
+
+  new_log_fd = fopen(filename , "wb+");
+  if (new_log_fd == NULL) {
+    fprintf(stderr, "Cannot open the log file: %s for write.\n",
+            filename);
+    exit(1);
+  }
+
+  return new_log_fd;
+}
+
 /***********************************************************/
 void hw_error(const char *fmt, ...)
 {
@@ -3122,6 +3172,17 @@ static void main_loop(void)
 #ifdef CONFIG_PROFILER
             dev_time += profile_getclock() - ti;
 #endif
+
+            if (rotate_logs_requested) {
+                FILE* new_dns_log_fd = rotate_qemu_log(get_slirp_dns_log_fd(),
+                                                        dns_log_filename);
+                FILE* new_drop_log_fd = rotate_qemu_log(get_slirp_drop_log_fd(),
+                                                         drop_log_filename);
+                slirp_dns_log_fd(new_dns_log_fd);
+                slirp_drop_log_fd(new_drop_log_fd);
+                reset_rotate_qemu_logs_request();
+            }
+
         } while (vm_can_run());
 
         if (qemu_debug_requested())
@@ -3623,6 +3684,23 @@ parse_int(const char *str, int *result)
     return 0;
 }
 
+#ifndef _WIN32
+/*
+ * Initializes the SIGUSR1 signal handler to clear Qemu logs.
+ */
+void init_qemu_clear_logs_sig() {
+  struct sigaction act;
+  sigfillset(&act.sa_mask);
+  act.sa_flags = 0;
+  act.sa_handler = rotate_qemu_logs_handler;
+  if (sigaction(SIGUSR1, &act, NULL) == -1) {
+    fprintf(stderr, "Failed to setup SIGUSR1 handler to clear Qemu logs\n");
+    exit(-1);
+  }
+}
+#endif
+
+
 
 /* parses a null-terminated string specifying a network port (e.g., "80") or
  * port range (e.g., "[6666-7000]"). In case of a single port, lport and hport
@@ -4580,7 +4658,8 @@ int main(int argc, char **argv, char **envp)
              case QEMU_OPTION_drop_log:
                 {
                     FILE* drop_log_fd;
-                    drop_log_fd = fopen(optarg, "w");
+                    drop_log_filename = optarg;
+                    drop_log_fd = fopen(optarg, "w+");
 
                     if (!drop_log_fd) {
                         fprintf(stderr, "Cannot open drop log: %s\n", optarg);
@@ -4594,7 +4673,8 @@ int main(int argc, char **argv, char **envp)
             case QEMU_OPTION_dns_log:
                 {
                     FILE* dns_log_fd;
-                    dns_log_fd = fopen(optarg, "wb");
+                    dns_log_filename = optarg;
+                    dns_log_fd = fopen(optarg, "wb+");
 
                     if (dns_log_fd == NULL) {
                         fprintf(stderr, "Cannot open dns log: %s\n", optarg);
@@ -5359,6 +5439,10 @@ int main(int argc, char **argv, char **envp)
     }
 #endif
 
+#ifndef _WIN32
+    init_qemu_clear_logs_sig();
+#endif
+
     /* init the dynamic translator */
     cpu_exec_init_all(tb_size * 1024 * 1024);