Merge "platform: log when stats are caught"
diff --git a/Makefile b/Makefile
index 5de9eaa..921debb 100644
--- a/Makefile
+++ b/Makefile
@@ -9,6 +9,7 @@
 BUILD_WAVEGUIDE?=y
 BUILD_DVBUTILS?=y
 BUILD_SYSMGR?=y
+BUILD_CACHE_WARMING?=y
 BUILD_STATUTILS?=y
 BUILD_SPEEDTEST?=y
 BUILD_CRYPTDEV?=    # default off: needs libdevmapper
@@ -18,7 +19,7 @@
 export BUILD_HNVRAM BUILD_SSDP BUILD_DNSSD BUILD_LOGUPLOAD \
 	BUILD_IBEACON BUILD_WAVEGUIDE BUILD_DVBUTILS BUILD_SYSMGR \
 	BUILD_STATUTILS BUILD_CRYPTDEV BUILD_SIGNING BUILD_JSONPOLL \
-	BUILD_PRESTERASTATS
+	BUILD_PRESTERASTATS BUILD_CACHE_WARMING
 
 # note: libgpio is not built here.  It's conditionally built
 # via buildroot/packages/google/google_platform/google_platform.mk
@@ -40,6 +41,10 @@
 DIRS+=hnvram
 endif
 
+ifeq ($(BUILD_CACHE_WARMING),y)
+DIRS+=cache_warming
+endif
+
 ifeq ($(BUILD_LOGUPLOAD),y)
 DIRS+=logupload/client
 endif
diff --git a/cache_warming/Makefile b/cache_warming/Makefile
new file mode 100644
index 0000000..eb489d9
--- /dev/null
+++ b/cache_warming/Makefile
@@ -0,0 +1,37 @@
+INSTALL?=install
+PREFIX=$(DESTDIR)/bin
+LIBDIR=$(PREFIX)/cache_warming
+PYTHON?=python
+GPYLINT=$(shell \
+    if which gpylint >/dev/null; then \
+      echo gpylint; \
+    else \
+      echo 'echo "(gpylint-missing)" >&2'; \
+    fi \
+)
+
+all:
+
+%.test: %_test.py
+	$(PYTHON) $<
+
+runtests: $(patsubst %_test.py,%.test,$(wildcard *_test.py))
+
+lint: $(filter-out options.py,$(wildcard *.py))
+	$(GPYLINT) $^
+
+test_only: all
+	PYTHONPATH=..:$(PYTHONPATH) ./wvtest/wvtestrun $(MAKE) runtests
+
+test: all
+	$(MAKE) test_only lint
+
+install:
+	mkdir -p $(LIBDIR)
+	$(INSTALL) -m 0755 -D cache_warming.py $(LIBDIR)/
+
+install-libs:
+	@echo "No libs to install."
+
+clean:
+	rm -rf *~ .*~ *.pyc
\ No newline at end of file
diff --git a/cache_warming/cache_warming.py b/cache_warming/cache_warming.py
index e094d4a..3416b56 100644
--- a/cache_warming/cache_warming.py
+++ b/cache_warming/cache_warming.py
@@ -13,11 +13,13 @@
 import json
 import os
 import socket
+import sys
 import dns.exception
 import dns.resolver
 
 hit_log = {}
 last_fetch = datetime.min
+verbose = False
 TOP_N = 50
 FETCH_INTERVAL = 60  # seconds
 UDP_SERVER_PATH = '/tmp/dns_query_log_socket'
@@ -34,6 +36,8 @@
     log: Dictionary of top requested hosts with host key and tuple value
          containing most recent hit time and hit count.
   """
+  if verbose:
+    print 'Saving hosts in %s.' % HOSTS_JSON_PATH
   d = os.path.dirname(HOSTS_JSON_PATH)
   if not os.path.exists(d):
     os.makedirs(d)
@@ -47,6 +51,8 @@
   Loads dictionary with host key and tuple value containing most recent hit
   time and hit count as hit_log if it exists.
   """
+  if verbose:
+    print 'Loading hosts from %s.' % HOSTS_JSON_PATH
   if os.path.isfile(HOSTS_JSON_PATH):
     with open(HOSTS_JSON_PATH, 'r') as hosts_json:
       global hit_log
@@ -64,6 +70,8 @@
             '[Unix time] [host name]'.
   """
   time, _, host = qry.partition(' ')
+  if verbose:
+    print 'Received query for %s.' % host
   if host in hit_log:
     hit_log[host] = (hit_log[host][0] + 1, time)
   else:
@@ -103,9 +111,13 @@
   if len(hosts) > TOP_N:
     hosts = hosts[:TOP_N]
   for host in hosts:
+    if verbose:
+      print 'Fetching %s.' % host
     try:
       my_resolver.query(host)
     except dns.exception.DNSException:
+      if verbose:
+        print 'Failed to fetch %s.' % host
       del hit_log[host]
       hosts.remove(host)
 
@@ -121,14 +133,20 @@
   return sorted(hit_log, key=hit_log.get, reverse=True)
 
 
-def warm_cache():
+def warm_cache(port, server):
   """Warms cache with predetermined number of most requested hosts.
 
   Sorts hosts in hit log by hit count, fetches predetermined
   number of top requested hosts, updates last fetch time.
+
+  Args:
+    port: Port to which to send queries (default is 53).
+    server: Alternate nameservers to query (default is None).
   """
+  if verbose:
+    print 'Warming cache.'
   sorted_hosts = sort_hit_log()
-  fetch(sorted_hosts, args.port, args.server)
+  fetch(sorted_hosts, port, server)
   global last_fetch
   last_fetch = datetime.now()
 
@@ -144,11 +162,15 @@
                       help='port to which to send queries (default is 53).')
   parser.add_argument('-s', '--server', nargs='*', type=str,
                       help='alternate nameservers to query (default is None).')
+  parser.add_argument('-v', '--verbose', action='store_true')
   return parser.parse_args()
 
 
 if __name__ == '__main__':
+  sys.stdout = os.fdopen(1, 'w', 1)
+  sys.stderr = os.fdopen(2, 'w', 1)
   args = set_args()
+  verbose = args.verbose
   load_hosts()
 
   server_address = UDP_SERVER_PATH
@@ -161,10 +183,12 @@
   sock.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
   sock.bind(server_address)
   os.chmod(server_address, 0o777)
+  if verbose:
+    print 'Set up socket at %s.' % HOSTS_JSON_PATH
 
   while 1:
     diff = datetime.now() - last_fetch
     if diff.total_seconds() > 60:
-      warm_cache()
+      warm_cache(args.port, args.server)
     data = sock.recv(128)
     process_query(data)
diff --git a/cmds/.gitignore b/cmds/.gitignore
index 5189e0e..fcc39f5 100644
--- a/cmds/.gitignore
+++ b/cmds/.gitignore
@@ -1,4 +1,5 @@
 *.o
+*.tmp.*
 alivemonitor
 asus_hosts
 balloon
@@ -9,15 +10,19 @@
 cpulog
 device_stats.pb.h
 dhcp-rogue
+dhcpnametax
+dhcpvendortax
 dir-monitor
 diskbench
 dnsck
 dnssd_hosts
+eddystone
 freemegs
 gsetsid
 gstatic
 host-*
 http_bouncer
+ibeacon
 ionice
 isoping
 isostream
diff --git a/cmds/Makefile b/cmds/Makefile
index 38557fa..60c1b5e 100644
--- a/cmds/Makefile
+++ b/cmds/Makefile
@@ -225,13 +225,14 @@
 wifi_files: LIBS += -lnl-3 -lnl-genl-3 -lglib-2.0
 host-wifi_files_test: host-wifi_files_test.o
 host-wifi_files_test: LIBS += -lnl-3 -lnl-genl-3 -lglib-2.0
-dhcpvendortax: dhcpvendortax.o dhcpvendorlookup.o
-dhcpvendorlookup.c: dhcpvendorlookup.gperf
-	$(GPERF) -G -C -t -L ANSI-C -N exact_match -K vendor_class --delimiters="|" \
-		--includes --output-file=dhcpvendorlookup.c dhcpvendorlookup.gperf
-dhcpvendorlookup.o: CFLAGS += -Wno-missing-field-initializers
-host-dhcpvendorlookup.o: CFLAGS += -Wno-missing-field-initializers
-host-dhcpvendortax: host-dhcpvendortax.o host-dhcpvendorlookup.o
+dhcpvendortax: dhcpvendortax.o dhcpvendorlookup.tmp.o
+dhcpvendorlookup.tmp.c: dhcpvendorlookup.gperf
+	$(GPERF) -G -C -t -L ANSI-C -N exact_match -K vendor_class \
+		--delimiters="|" \
+		--includes --output-file=$@ $<
+dhcpvendorlookup.tmp.o: CFLAGS += -Wno-missing-field-initializers
+host-dhcpvendorlookup.tmp.o: CFLAGS += -Wno-missing-field-initializers
+host-dhcpvendortax: host-dhcpvendortax.o host-dhcpvendorlookup.tmp.o
 dnssdmon: dnssdmon.o l2utils.o modellookup.o
 dnssdmon: LIBS += -lnl-3 -lstdc++ -lm -lresolv
 modellookup.c: modellookup.gperf
@@ -239,13 +240,14 @@
 		--includes --output-file=modellookup.c modellookup.gperf
 modellookup.o: CFLAGS += -Wno-missing-field-initializers
 host-modellookup.o: CFLAGS += -Wno-missing-field-initializers
-dhcpnametax: dhcpnametax.o hostnamelookup.o
-host-dhcpnametax: host-dhcpnametax.o host-hostnamelookup.o
-hostnamelookup.c: hostnamelookup.gperf
-	$(GPERF) -G -C -t -T -L ANSI-C -n -c -N hostname_lookup -K name --delimiters="|" \
-		--includes --output-file=hostnamelookup.c hostnamelookup.gperf
-hostnamelookup.o: CFLAGS += -Wno-missing-field-initializers
-host-hostnamelookup.o: CFLAGS += -Wno-missing-field-initializers
+dhcpnametax: dhcpnametax.o hostnamelookup.tmp.o
+host-dhcpnametax: host-dhcpnametax.o host-hostnamelookup.tmp.o
+hostnamelookup.tmp.c: hostnamelookup.gperf
+	$(GPERF) -G -C -t -T -L ANSI-C -n -c -N hostname_lookup -K name \
+		--delimiters="|" \
+		--includes --output-file=$@ $<
+hostnamelookup.tmp.o: CFLAGS += -Wno-missing-field-initializers
+host-hostnamelookup.tmp.o: CFLAGS += -Wno-missing-field-initializers
 
 
 TESTS = $(wildcard test-*.sh) $(wildcard test-*.py) $(wildcard *_test.py) $(TEST_TARGETS)
@@ -269,5 +271,5 @@
 		$(TEST_TARGETS) \
 		$(HOST_TEST_TARGETS) \
 		$(ARCH_TARGETS) \
-		*~ .*~ */*.pyc test_file *.pb.*
+		*~ .*~ */*.pyc test_file *.pb.* *.tmp.*
 	rm -rf test_dir
diff --git a/cmds/gstatic.c b/cmds/gstatic.c
index 15b23fc..518871f 100644
--- a/cmds/gstatic.c
+++ b/cmds/gstatic.c
@@ -85,11 +85,13 @@
   total = 0;
   while (total < count) {
     rc = write(fd, buf + total, count - total);
-    if (rc < 0)
-      perror_die("write");
-    else if (rc == 0)
+    if (rc < 0) {
+      perror("write");
+      return -1;
+    } else if (rc == 0) {
+      fprintf(stderr, "write: EOF\n");
       return total;
-    else
+    } else
       total += rc;
   }
 
@@ -125,8 +127,10 @@
   socket_set_blocking(fd, false);
 
   rc = connect(fd, addr->ai_addr, addr->ai_addrlen);
-  if (rc < 0 && errno != EINPROGRESS)
-    perror_die("connect");
+  if (rc < 0 && errno != EINPROGRESS) {
+    perror("connect");
+    return -1;
+  }
 
   if (rc != 0) {
     FD_ZERO(&writeset);
@@ -136,7 +140,8 @@
 
     rc = select(fd + 1, NULL, &writeset, NULL, &timeout);
     if (rc < 0) {
-      perror_die("select");
+      perror("connect-select");
+      return -1;
     } else if (rc == 0) {
       /* timeout */
       return -1;
@@ -156,27 +161,24 @@
 
 ssize_t read_timeout(int fd, void *buf, size_t count, int timeout_ms)
 {
-  fd_set readset, exceptset;
+  fd_set readset;
   struct timeval timeout;
   int rc;
 
   FD_ZERO(&readset);
   FD_SET(fd, &readset);
-  exceptset = readset;
   timeout.tv_sec = timeout_ms / 1000;
   timeout.tv_usec = (timeout_ms % 1000) * 1000;
 
-  rc = select(fd + 1, &readset, NULL, &exceptset, &timeout);
+  rc = select(fd + 1, &readset, NULL, NULL, &timeout);
   if (rc < 0) {
-    perror_die("select");
+    perror("select");
+    return -1;
   } else if (rc == 0) {
-    /* timeout */
-    return 0;
+    fprintf(stderr, "select: timed out\n");
+    return -1;
   }
 
-  if (FD_ISSET(fd, &exceptset))
-    return 0;
-
   return read(fd, buf, count);
 }
 
@@ -198,7 +200,7 @@
 
   rc = xwrite(fd, HTTP_REQUEST, sizeof(HTTP_REQUEST));
   if (rc < (ssize_t)sizeof(HTTP_REQUEST))
-    perror_die("write");
+    goto err;
 
   rc = read_timeout(fd, http_response, sizeof(http_response), TIMEOUT_MS);
   if (rc < 0)
@@ -223,6 +225,9 @@
   int bad;
   int rc;
 
+  // In case we get stuck in one of the blocking syscalls (write, read, etc)
+  alarm(60);
+
   memset(&hints, 0, sizeof(hints));
   hints.ai_family = AF_UNSPEC;
   hints.ai_socktype = SOCK_STREAM;
@@ -241,8 +246,11 @@
     int fd;
 
     fd = socket(res->ai_family, res->ai_socktype, res->ai_protocol);
-    if (fd < 0)
-      perror_die("socket");
+    if (fd < 0) {
+      perror("socket");
+      bad = 1;
+      continue;
+    }
 
     rc = do_http_request(fd, res);
     if (rc != 0)
diff --git a/waveguide/waveguide.py b/waveguide/waveguide.py
index cbc9fe8..87324c3 100755
--- a/waveguide/waveguide.py
+++ b/waveguide/waveguide.py
@@ -907,7 +907,8 @@
     wifiblaster.enable         Enable WiFi performance measurement.
     wifiblaster.interval       Average time between automated measurements in
                                seconds, or 0 to disable automated measurements.
-    wifiblaster.measureall     Unix time at which to measure all clients.
+    wifiblaster.measureall     Unix time at which to measure all clients, or 0
+                               to disable measureall requests.
     wifiblaster.onassociation  Enable WiFi performance measurement after clients
                                associate.
 
@@ -938,6 +939,20 @@
     except ValueError:
       return None
 
+  def _GetParameters(self):
+    """Reads and returns all parameters if valid, or Nones."""
+    duration = self._ReadParameter('duration', float)
+    enable = self._ReadParameter('enable', self._StrToBool)
+    fraction = self._ReadParameter('fraction', int)
+    interval = self._ReadParameter('interval', float)
+    measureall = self._ReadParameter('measureall', float)
+    onassociation = self._ReadParameter('onassociation', self._StrToBool)
+    size = self._ReadParameter('size', int)
+    if (duration > 0 and enable and fraction > 0 and interval >= 0
+        and measureall >= 0 and size > 0):
+      return (duration, fraction, interval, measureall, onassociation, size)
+    return (None, None, None, None, None, None)
+
   def _SaveResult(self, line):
     """Save wifiblaster result to the status file for that client."""
     g = re.search(MACADDR_REGEX, line)
@@ -975,23 +990,18 @@
     """Return the time of the next measurement event."""
     return self._next_measurement_time
 
-  def Measure(self, interface, client):
+  def Measure(self, interface, client, duration, fraction, size):
     """Measures the performance of a client."""
-    enable = self._ReadParameter('enable', self._StrToBool)
-    duration = self._ReadParameter('duration', float)
-    fraction = self._ReadParameter('fraction', int)
-    size = self._ReadParameter('size', int)
-    if enable and duration > 0 and fraction > 0 and size > 0:
-      RunProc(callback=self._HandleResults,
-              args=[WIFIBLASTER_BIN, '-i', interface, '-d', str(duration),
-                    '-f', str(fraction), '-s', str(size),
-                    helpers.DecodeMAC(client)])
+    RunProc(callback=self._HandleResults,
+            args=[WIFIBLASTER_BIN, '-i', interface, '-d', str(duration),
+                  '-f', str(fraction), '-s', str(size),
+                  helpers.DecodeMAC(client)])
 
   def MeasureOnAssociation(self, interface, client):
     """Measures the performance of a client after association."""
-    onassociation = self._ReadParameter('onassociation', self._StrToBool)
+    (duration, fraction, _, _, onassociation, size) = self._GetParameters()
     if onassociation:
-      self.Measure(interface, client)
+      self.Measure(interface, client, duration, fraction, size)
 
   def Poll(self, now):
     """Polls the state machine."""
@@ -1005,29 +1015,33 @@
       # Inter-arrival times in a Poisson process are exponentially distributed.
       # The timebase slip prevents a burst of measurements in case we fall
       # behind.
-      self._next_measurement_time = now + random.expovariate(1 / interval)
+      self._next_measurement_time = now + random.expovariate(1.0 / interval)
 
-    interval = self._ReadParameter('interval', float)
-    if interval <= 0:
+    # Read parameters.
+    (duration, fraction, interval, measureall, _, size) = self._GetParameters()
+
+    # Handle automated mode.
+    if interval > 0:
+      if self._interval != interval:
+        # Enable or change interval.
+        StartMeasurementTimer(interval)
+      elif now >= self._next_measurement_time:
+        # Measure a random client.
+        StartMeasurementTimer(interval)
+        try:
+          (interface, client) = random.choice(self._GetAllClients())
+        except IndexError:
+          pass
+        else:
+          self.Measure(interface, client, duration, fraction, size)
+    else:
       Disable()
-    elif self._interval != interval:
-      # Enable or change interval.
-      StartMeasurementTimer(interval)
-    elif now >= self._next_measurement_time:
-      # Measure a random client.
-      StartMeasurementTimer(interval)
-      try:
-        (interface, client) = random.choice(self._GetAllClients())
-      except IndexError:
-        pass
-      else:
-        self.Measure(interface, client)
 
-    measureall = self._ReadParameter('measureall', float)
+    # Handle measureall request.
     if time.time() >= measureall and measureall > self._last_measureall_time:
       self._last_measureall_time = measureall
       for (interface, client) in self._GetAllClients():
-        self.Measure(interface, client)
+        self.Measure(interface, client, duration, fraction, size)
 
     # Poll again in at most one second. This allows parameter changes (e.g. a
     # measureall request or a long interval to a short interval) to take effect
diff --git a/waveguide/wifiblaster_controller_test.py b/waveguide/wifiblaster_controller_test.py
index 6b562b1..9e300f2 100755
--- a/waveguide/wifiblaster_controller_test.py
+++ b/waveguide/wifiblaster_controller_test.py
@@ -17,6 +17,7 @@
 
 import glob
 import os
+import random
 import shutil
 import sys
 import tempfile
@@ -102,6 +103,7 @@
   d = tempfile.mkdtemp()
   old_wifiblaster_dir = waveguide.WIFIBLASTER_DIR
   waveguide.WIFIBLASTER_DIR = tempfile.mkdtemp()
+  oldexpovariate = random.expovariate
   oldpath = os.environ['PATH']
   oldtime = time.time
 
@@ -110,6 +112,7 @@
     return faketime[0]
 
   try:
+    random.expovariate = lambda lambd: random.uniform(0, 2 * 1.0 / lambd)
     time.time = FakeTime
     os.environ['PATH'] = 'fake:' + os.environ['PATH']
     sys.path.insert(0, 'fake')
@@ -141,11 +144,6 @@
       WriteConfig('measureall', '0')
       WriteConfig('size', '1470')
 
-      # Disabled. No measurements should be run.
-      print manager.GetState()
-      for t in xrange(0, 100):
-        wc.Poll(t)
-
       def CountRuns():
         try:
           v = open('fake/wifiblaster.out').readlines()
@@ -155,16 +153,24 @@
           os.unlink('fake/wifiblaster.out')
           return len(v)
 
-      CountRuns()  # get rid of any leftovers
+      # Get rid of any leftovers.
+      CountRuns()
+
+      # Disabled.
+      # No measurements should be run.
+      print manager.GetState()
+      for t in xrange(0, 100):
+        wc.Poll(t)
       wvtest.WVPASSEQ(CountRuns(), 0)
 
+      # Enabled.
       # The first measurement should be one cycle later than the start time.
       # This is not an implementation detail: it prevents multiple APs from
       # running simultaneous measurements if measurements are enabled at the
       # same time.
       WriteConfig('enable', 'True')
       wc.Poll(100)
-      wvtest.WVPASSGE(wc.NextMeasurement(), 100)
+      wvtest.WVPASSGT(wc.NextMeasurement(), 100)
       for t in xrange(101, 200):
         wc.Poll(t)
       wvtest.WVPASSGE(CountRuns(), 1)
@@ -183,20 +189,16 @@
         wc.Poll(t)
       wvtest.WVPASSGE(CountRuns(), 1)
 
-      # Run the measurement at t=400 to restart the timer.
-      wc.Poll(400)
-      wvtest.WVPASSGE(CountRuns(), 0)
-
       # Next poll should be in at most one second regardless of interval.
-      wvtest.WVPASSLE(wc.NextTimeout(), 401)
+      wvtest.WVPASSLE(wc.NextTimeout(), 400)
 
-      # Enabled with longer average interval.  The change in interval should
+      # Enabled with shorter average interval.  The change in interval should
       # trigger a change in next poll timeout.
       WriteConfig('interval', '0.5')
       old_to = wc.NextMeasurement()
-      wc.Poll(401)
+      wc.Poll(400)
       wvtest.WVPASSNE(old_to, wc.NextMeasurement())
-      for t in xrange(402, 500):
+      for t in xrange(401, 500):
         wc.Poll(t)
       wvtest.WVPASSGE(CountRuns(), 1)
 
@@ -218,6 +220,7 @@
                               manager.GetState().assoc[0].mac)
       wvtest.WVPASSEQ(CountRuns(), 1)
   finally:
+    random.expovariate = oldexpovariate
     time.time = oldtime
     shutil.rmtree(d)
     os.environ['PATH'] = oldpath