Fix nowait poll

Readme.md → README.md

@@ -34,7 +34,9 @@ You can grab this repo from github:
   pip install --upgrade -r requirements.txt
 ```
 
-By hook or by crook you'll need to manufacture the Duo credentials:
+Copy Duo credentials from Mosler e.g. `vm-prod/logger/duo_watcher/credentials`
+
+The credentials should be a JSON object with keys: `apihost`, `ikey` and `skey`.
 
 ```bash
   ssh ${loggerN}
@@ -128,7 +130,7 @@ Anybody can send the duo_watcher a "status" ding:
   Sent message 's' to 127.0.0.1 (2681).
   Recv message from   127.0.0.1 (2681) len=203.
   Got: P0Ready
-     
+
      auth: At 20:54:43 up to 20-08-31 20:52:32 count: 2 interval: 90
      admin: At 20:54:42 up to 20-08-31 18:46:57 count: 1 interval: 90
      phone: At 20:54:42 up to 20-08-31 20:54:03 count: 1 interval: 90
@@ -144,7 +146,7 @@ individual threads:
   Sent message 'help' to 127.0.0.1 (2681).
   Recv message from   127.0.0.1 (2681) len=342.
   Got: P3Help yourself
-     
+
      Commands are:
        clear: Clear status
        status: Report status
@@ -157,6 +159,6 @@ individual threads:
        auth: Duo authentication log watcher
        admin: Duo administrator log watcher
        phone: Duo telephony log watcher
-     
-  Mess: 
+
+  Mess:
 ```

collect.py

@@ -27,18 +27,22 @@ def looper(tp):
     sys.stdout.flush()
 
     while not tp.terminate.isSet():
-        while not tp.terminate.isSet():
-            tp.timestamp = time.time()
-            result = tp.handle.fetch()
-            tp.count = tp.count + 1
-            t0 = strftime('%H:%M:%S', localtime(tp.timestamp))
-            t1 = strftime('%y-%m-%d %H:%M:%S', localtime(tp.handle.state['timestamp']))
-            tp.status = 'At {wall} up to {log} count: {count} interval: {val}'.format(wall=t0, log=t1, count=tp.count, val=tp.interval)
-            if tp.handle.backoff > 0:
-                tp.status = tp.status + '+{bo}'.format(bo=tp.handle.backoff)
-            if not result:
-                break
-        tp.terminate.wait(tp.interval + tp.handle.backoff)
+        tp.timestamp = time.time()
+        result = tp.handle.fetch()
+        tp.count = tp.count + 1
+        t0 = strftime('%H:%M:%S', localtime(tp.timestamp))
+        t1 = strftime('%y-%m-%d %H:%M:%S', localtime(tp.handle.state['timestamp']))
+        tp.status = 'At {wall} up to {log} count: {count} interval: {val}'.format(wall=t0, log=t1, count=tp.count, val=tp.interval)
+        if tp.handle.backoff > 0:
+            tp.status = tp.status + '+{bo}'.format(bo=tp.handle.backoff)
+        wait_val = tp.interval + tp.handle.backoff
+        print("{ts} waiting {wait_val} seconds for next poll for {name}".format(
+              ts = time.strftime('%y-%m-%d %H:%M:%S'),
+              wait_val=wait_val,
+              name=tp.name,
+              ),
+        flush=True)
+        tp.terminate.wait(wait_val)
         if tp.maxcount > 0 and tp.count > tp.maxcount:
             break
 
@@ -47,8 +51,9 @@ def looper(tp):
     print('{ts} {pid}: Thread {name} terminating.'.format(
         ts = time.strftime('%y-%m-%d %H:%M:%S'),
         pid = os.getpid(),
-        name = tp.name))
-    sys.stdout.flush()
+        name = tp.name),
+        flush=True,
+    )
 
 #
 #  Initialize our thread descriptions

duo_watcher.py

@@ -55,6 +55,11 @@ def fetch(self):
                 params,
             )
         except RuntimeError as e:
+            print("{ts} fetch failure for {name}: {e}".format(
+                  ts = time.strftime('%y-%m-%d %H:%M:%S'),
+                  name = self.name,
+                  e=e,
+            ), flush=True)
             if e.args == ('Received 429 Too Many Requests',):
                 self.backoff = 1 + 2 * self.backoff
                 if self.backoff > 1800:
@@ -64,11 +69,21 @@ def fetch(self):
                         ts = time.strftime('%y-%m-%d %H:%M:%S'),
                         pid = os.getpid(),
                         bo = self.backoff,
-                        name = self.name))
-                    sys.stdout.flush()
+                        name = self.name), flush=True)
                 return False
             raise
+        except Exception as e:
+            print("{ts} fetch failure for {name} of the non-runtime variety: {e}".format(
+                  ts = time.strftime('%y-%m-%d %H:%M:%S'),
+                  name = self.name,
+                  e=e,
+            ), flush=True)
+            raise
         else:
+            print("{ts} fetch success for {name}".format(
+              ts = time.strftime('%y-%m-%d %H:%M:%S'),
+              name = self.name,
+            ), flush=True)
             self.backoff = self.backoff / 2
 
         prev_ts = -1