From 283c34b0e4e0a3574a0b68e593cea2d54daebf10 Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Wed, 13 Jun 2012 10:10:04 +0200
Subject: [PATCH 01/37] Downgrade 'Sync request unnecessarily sent' to INFO.

Also add comment explaining that this is not an error (and why).
---
 ykval-sync.php | 9 ++++++++-
 1 file changed, 8 insertions(+), 1 deletion(-)

diff --git a/ykval-sync.php b/ykval-sync.php
index 12c81af..31c2fcf 100644
--- a/ykval-sync.php
+++ b/ykval-sync.php
@@ -146,7 +146,14 @@ if ($sync->countersEqual($localParams, $syncParams)) {
 
   if ($syncParams['modified']==$localParams['modified'] &&
       $syncParams['nonce']==$localParams['nonce']) {
-    $myLog->log(LOG_NOTICE, 'Sync request unnecessarily sent');
+    /* This is not an error. When the remote server received an OTP to verify, it would
+     * have sent out sync requests immediately. When the required number of responses had
+     * been received, the current implementation discards all additional responses (to
+     * return the result to the client as soon as possible). If our response sent last
+     * time was discarded, we will end up here when the background ykval-queue processes
+     * the sync request again.
+     */
+    $myLog->log(LOG_INFO, 'Sync request unnecessarily sent');
   }
 
   if ($syncParams['modified']!=$localParams['modified'] &&

From afb42d7c0a627ded29e9fcd0a5194024e34eda5c Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Wed, 13 Jun 2012 13:22:35 +0200
Subject: [PATCH 02/37] Logging improvements.

---
 ykval-synclib.php | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/ykval-synclib.php b/ykval-synclib.php
index 1bf5ef2..c24d221 100644
--- a/ykval-synclib.php
+++ b/ykval-synclib.php
@@ -292,12 +292,12 @@ class SyncLib
     $res=$this->db->customQuery("select distinct server from queue WHERE queued < " . $queued_limit . " or queued is null");
 
     foreach ($res as $my_server) {
-      $this->log(LOG_INFO, "Sending queue request to server on server " . $my_server['server']);
+      $this->log(LOG_INFO, "Processing queue for server " . $my_server['server']);
       $res=$this->db->customQuery("select * from queue WHERE (queued < " . $queued_limit . " or queued is null) and server='" . $my_server['server'] . "'");
       $ch = curl_init();
 
       while ($entry=$res->fetch(PDO::FETCH_ASSOC)) {
-	$this->log(LOG_INFO, "server=" . $entry['server'] . " , info=" . $entry['info']);
+	$this->log(LOG_INFO, "server=" . $entry['server'] . ", server_nonce=" . $entry['server_nonce'] . ", info=" . $entry['info']);
 	$url=$entry['server'] .
 	  "?otp=" . $entry['otp'] .
 	  "&modified=" . $entry['modified'] .

From 2a7a6e3503b94f45e6a3fd32e2dd83168083d040 Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Wed, 13 Jun 2012 13:23:55 +0200
Subject: [PATCH 03/37] Don't LOG_NOTICE when remote server has seen latest OTP
 too.

This is an expected condition for many (most) validation requests
using the asynchronous validation protocol 2.0.
---
 ykval-synclib.php | 10 +++++++++-
 1 file changed, 9 insertions(+), 1 deletion(-)

diff --git a/ykval-synclib.php b/ykval-synclib.php
index c24d221..2627b20 100644
--- a/ykval-synclib.php
+++ b/ykval-synclib.php
@@ -328,8 +328,12 @@ class SyncLib
 
 	  /* Retrieve info from entry info string */
 
+	  /* This is the counter values we had in our database *before* processing the current OTP. */
 	  $validationParams=$this->localParamsFromInfoString($entry['info']);
+	  /* This is the data from the current OTP. */
 	  $otpParams=$this->otpParamsFromInfoString($entry['info']);
+
+	  /* Fetch current information from our database */
 	  $localParams=$this->getLocalParams($otpParams['yk_publicname']);
 
 	  $this->log(LOG_DEBUG, "validation params: ", $validationParams);
@@ -342,7 +346,11 @@ class SyncLib
 	  }
 
 	  if ($this->countersHigherThan($resParams, $validationParams)) {
-	    $this->log(LOG_NOTICE, "Local server out of sync compared to counters at validation request time. ");
+	    if ($this->countersEqual($resParams, $otpParams)) {
+	      $this->log(LOG_INFO, "Remote server had received the current counter values already. ");
+	    } else {
+	      $this->log(LOG_NOTICE, "Local server out of sync compared to counters at validation request time. ");
+	    }
 	  }
 
 	  if ($this->countersHigherThan($localParams, $resParams)) {

From 6dd55013f993f6a26b670ed7cffa4f7d61578d3d Mon Sep 17 00:00:00 2001
From: Klas Lindfors <klas@yubico.com>
Date: Wed, 13 Jun 2012 14:45:37 +0200
Subject: [PATCH 04/37] do $res->rowCount() instead of count($res->fetchAll())

should never be called after select, and will throw exceptions if you do
---
 ykval-db.php | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/ykval-db.php b/ykval-db.php
index 7d9d7e7..6e6bd9f 100644
--- a/ykval-db.php
+++ b/ykval-db.php
@@ -378,7 +378,7 @@ or false on failure.
   public function rowCount()
   {
     if($this->result) {
-      $count=count($this->result->fetchAll());
+      $count=$this->result->rowCount();
       $this->result->closeCursor();
       return $count;
     } else {

From a852e860db44233872d13721ac425d14ad60b81c Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Thu, 14 Jun 2012 12:56:05 +0200
Subject: [PATCH 05/37] Don't refuse sync for disabled YubiKeys.

It is better to consume any OTPs produced by a YubiKey, so if -
for some reason - another validation server has accepted an OTP
we'd better bump our counter values accordingly.
---
 ykval-sync.php | 10 ++++++----
 1 file changed, 6 insertions(+), 4 deletions(-)

diff --git a/ykval-sync.php b/ykval-sync.php
index 31c2fcf..ddf40fe 100644
--- a/ykval-sync.php
+++ b/ykval-sync.php
@@ -117,10 +117,12 @@ if (!$localParams) {
  }
 
 if ($localParams['active'] != 1) {
-  $myLog->log(LOG_NOTICE, 'De-activated Yubikey ' . $yk_publicname);
-  sendResp(S_BAD_OTP, $apiKey);
-  exit;
- }
+  /* The remote server has accepted an OTP from a YubiKey which we would not. We update our
+   * counters
+   */
+  $myLog->log(LOG_WARNING, 'Received sync-request for de-activated Yubikey ' . $yk_publicname .
+	      ' - check database synchronization!!!');
+}
 
 
 /* Conditional update local database */

From cb0de9d8e362995539cb5a8721990c922e488882 Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Thu, 14 Jun 2012 13:00:39 +0200
Subject: [PATCH 06/37] Add __YKREV_IPS__ to template.

---
 ykval-config.php | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/ykval-config.php b/ykval-config.php
index 4a98ead..f092e91 100644
--- a/ykval-config.php
+++ b/ykval-config.php
@@ -17,6 +17,10 @@ $baseParams['__YKVAL_ALLOWED_SYNC_POOL__'] = array("1.2.3.4",
 						   "2.3.4.5",
 						   "3.4.5.6");
 
+# An array of IP addresses allowed to issue YubiKey activation/deactivation
+# requests through ykval-revoke.php. NOTE: You must use IP addresses here.
+$baseParams['__YKREV_IPS__'] = array("127.0.0.1");
+
 # Specify how often the sync daemon awakens
 $baseParams['__YKVAL_SYNC_INTERVAL__'] = 10;
 # Specify how long the sync daemon will wait for response

From 0fe0be9980d0e81696f477965f2eb873bd36b335 Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Thu, 14 Jun 2012 13:30:04 +0200
Subject: [PATCH 07/37] Restore responding BAD_OTP if YubiKey is disabled.

It seems that we might get into problems if responding OK - the other
sync client validation server would think we approved of the OTP.
---
 ykval-sync.php | 19 +++++++++----------
 1 file changed, 9 insertions(+), 10 deletions(-)

diff --git a/ykval-sync.php b/ykval-sync.php
index ddf40fe..c94f9e7 100644
--- a/ykval-sync.php
+++ b/ykval-sync.php
@@ -116,15 +116,6 @@ if (!$localParams) {
   exit;
  }
 
-if ($localParams['active'] != 1) {
-  /* The remote server has accepted an OTP from a YubiKey which we would not. We update our
-   * counters
-   */
-  $myLog->log(LOG_WARNING, 'Received sync-request for de-activated Yubikey ' . $yk_publicname .
-	      ' - check database synchronization!!!');
-}
-
-
 /* Conditional update local database */
 $sync->updateDbCounters($syncParams);
 
@@ -169,7 +160,15 @@ if ($sync->countersEqual($localParams, $syncParams)) {
   }
  }
 
-
+if ($localParams['active'] != 1) {
+  /* The remote server has accepted an OTP from a YubiKey which we would not.
+   * We still needed to update our counters with the counters from the OTP though.
+   */
+  $myLog->log(LOG_WARNING, 'Received sync-request for de-activated Yubikey ' . $yk_publicname .
+	      ' - check database synchronization!!!');
+  sendResp(S_BAD_OTP, $apiKey);
+  exit;
+}
 
 $extra=array('modified'=>$localParams['modified'],
 	     'nonce'=>$localParams['nonce'],

From d37c41011a99d91ffdc1aed478c0453b8a30fd4b Mon Sep 17 00:00:00 2001
From: Klas Lindfors <klas@yubico.com>
Date: Thu, 14 Jun 2012 13:52:53 +0200
Subject: [PATCH 08/37] if the remote sync site says BAD_OTP log and remove
 from queue

---
 ykval-synclib.php | 6 ++++++
 1 file changed, 6 insertions(+)

diff --git a/ykval-synclib.php b/ykval-synclib.php
index 2627b20..f990c42 100644
--- a/ykval-synclib.php
+++ b/ykval-synclib.php
@@ -377,6 +377,12 @@ class SyncLib
 				      array("modified"=>$entry['modified'],
 					    "server_nonce"=>$entry['server_nonce'],
 					    'server'=>$entry['server']));
+	} else if (preg_match("/status=BAD_OTP/", $response)) {
+	  $this->log(LOG_WARNING, "Remote server says BAD_OTP, pointless to try again, removing from queue.");
+	  $this->db->deleteByMultiple('queue',
+				      array("modified"=>$entry['modified'],
+					    "server_nonce"=>$entry['server_nonce'],
+					    'server'=>$entry['server']));
 	} else {
 	  $this->log(LOG_ERR, "Remote server refused our sync request. Check remote server logs.");
 	}

From 658ddef8227de0976dfecc60b29217de3189c636 Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Thu, 14 Jun 2012 14:25:33 +0200
Subject: [PATCH 09/37] Move de-arraying out of retrieveURLasync.

---
 ykval-common.php | 8 +++++---
 1 file changed, 5 insertions(+), 3 deletions(-)

diff --git a/ykval-common.php b/ykval-common.php
index 50bb2e0..59b9bca 100644
--- a/ykval-common.php
+++ b/ykval-common.php
@@ -166,8 +166,7 @@ function retrieveURLasync ($urls, $ans_req=1, $match="^OK", $returl=False) {
 	  }
 	  curl_multi_close ($mh);
 
-	  if ($ans_count==1) return $ans_arr[0];
-	  else return $ans_arr;
+	  return $ans_arr;
 	}
 
 	curl_multi_remove_handle ($mh, $info['handle']);
@@ -205,7 +204,10 @@ function KSMdecryptOTP($urls) {
   } elseif (count($urls) == 1) {
     $response = retrieveURLsimple ($urls[0]);
   } else {
-    $response = retrieveURLasync ($urls);
+    $response = retrieveURLasync ($urls, $ans_req=1, $match="^OK", $returl=False);
+    if (is_array($response)) {
+      $response = $response[0];
+    }
   }
   if ($response) {
     debug("YK-KSM response: " . $response);

From df71d3a5a8437a2dded7552d3443c3ecd6f5df6d Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Thu, 14 Jun 2012 14:34:07 +0200
Subject: [PATCH 10/37] retrieveURLasync: make timeout an argument

---
 ykval-common.php | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/ykval-common.php b/ykval-common.php
index 59b9bca..74c4034 100644
--- a/ykval-common.php
+++ b/ykval-common.php
@@ -117,7 +117,7 @@ function modhex2b64 ($modhex_str) {
 // long as one of the URLs given work, data will be returned.  If all
 // URLs fail, data from some URL that did not match parameter $match
 // (defaults to ^OK) is returned, or if all URLs failed, false.
-function retrieveURLasync ($urls, $ans_req=1, $match="^OK", $returl=False) {
+function retrieveURLasync ($urls, $ans_req=1, $match="^OK", $returl=False, $timeout=10) {
   $mh = curl_multi_init();
 
   $ch = array();
@@ -128,7 +128,7 @@ function retrieveURLasync ($urls, $ans_req=1, $match="^OK", $returl=False) {
     curl_setopt($handle, CURLOPT_USERAGENT, "YK-VAL");
     curl_setopt($handle, CURLOPT_RETURNTRANSFER, 1);
     curl_setopt($handle, CURLOPT_FAILONERROR, true);
-    curl_setopt($handle, CURLOPT_TIMEOUT, 10);
+    curl_setopt($handle, CURLOPT_TIMEOUT, $timeout);
 
     curl_multi_add_handle($mh, $handle);
 
@@ -204,7 +204,7 @@ function KSMdecryptOTP($urls) {
   } elseif (count($urls) == 1) {
     $response = retrieveURLsimple ($urls[0]);
   } else {
-    $response = retrieveURLasync ($urls, $ans_req=1, $match="^OK", $returl=False);
+    $response = retrieveURLasync ($urls, $ans_req=1, $match="^OK", $returl=False, $timeout=10);
     if (is_array($response)) {
       $response = $response[0];
     }

From 41f1e15a43a921da26022f63ce95559bfac27dce Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Thu, 14 Jun 2012 14:49:37 +0200
Subject: [PATCH 11/37] retrieveURLasync: cater for the last need in
 ykval-synclib.

---
 ykval-common.php | 1 +
 1 file changed, 1 insertion(+)

diff --git a/ykval-common.php b/ykval-common.php
index 74c4034..efbb8e1 100644
--- a/ykval-common.php
+++ b/ykval-common.php
@@ -184,6 +184,7 @@ function retrieveURLasync ($urls, $ans_req=1, $match="^OK", $returl=False, $time
   }
   curl_multi_close ($mh);
 
+  if ($ans_count>0) return $ans_arr;
   return $str;
 }
 

From 201416b15adfc5c735f0bb645d2455253b4a2636 Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Thu, 14 Jun 2012 14:54:12 +0200
Subject: [PATCH 12/37] retrieveURLasync: logging using ident string

---
 ykval-common.php | 12 ++++++------
 1 file changed, 6 insertions(+), 6 deletions(-)

diff --git a/ykval-common.php b/ykval-common.php
index efbb8e1..0c7d5d7 100644
--- a/ykval-common.php
+++ b/ykval-common.php
@@ -117,13 +117,13 @@ function modhex2b64 ($modhex_str) {
 // long as one of the URLs given work, data will be returned.  If all
 // URLs fail, data from some URL that did not match parameter $match
 // (defaults to ^OK) is returned, or if all URLs failed, false.
-function retrieveURLasync ($urls, $ans_req=1, $match="^OK", $returl=False, $timeout=10) {
+function retrieveURLasync ($ident, $urls, $ans_req=1, $match="^OK", $returl=False, $timeout=10) {
   $mh = curl_multi_init();
 
   $ch = array();
   foreach ($urls as $id => $url) {
     $handle = curl_init();
-    debug("url is: " . $url);
+    debug($ident . " adding URL : " . $url);
     curl_setopt($handle, CURLOPT_URL, $url);
     curl_setopt($handle, CURLOPT_USERAGENT, "YK-VAL");
     curl_setopt($handle, CURLOPT_RETURNTRANSFER, 1);
@@ -144,17 +144,17 @@ function retrieveURLasync ($urls, $ans_req=1, $match="^OK", $returl=False, $time
       ;
 
     while ($info = curl_multi_info_read($mh)) {
-      debug ("YK-KSM multi", $info);
+      debug ($ident . " curl multi info : ", $info);
       if ($info['result'] == CURLE_OK) {
 	$str = curl_multi_getcontent($info['handle']);
 	debug($str);
 	if (preg_match("/".$match."/", $str)) {
+	  debug($ident . "response matches " . $match);
 	  $error = curl_error ($info['handle']);
 	  $errno = curl_errno ($info['handle']);
 	  $cinfo = curl_getinfo ($info['handle']);
-	  debug("YK-KSM errno/error: " . $errno . "/" . $error, $cinfo);
+	  debug($ident . " errno/error: " . $errno . "/" . $error, $cinfo);
 	  $ans_count++;
-	  debug("found entry");
 	  if ($returl) $ans_arr[]="url=" . $cinfo['url'] . "\n" . $str;
 	  else $ans_arr[]=$str;
 	}
@@ -205,7 +205,7 @@ function KSMdecryptOTP($urls) {
   } elseif (count($urls) == 1) {
     $response = retrieveURLsimple ($urls[0]);
   } else {
-    $response = retrieveURLasync ($urls, $ans_req=1, $match="^OK", $returl=False, $timeout=10);
+    $response = retrieveURLasync ("YK-KSM", $urls, $ans_req=1, $match="^OK", $returl=False, $timeout=10);
     if (is_array($response)) {
       $response = $response[0];
     }

From 32c94e92566faa681a1751751673211cbd855fb9 Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Thu, 14 Jun 2012 14:55:07 +0200
Subject: [PATCH 13/37] Use retrieveURLasync in ykval-common instead.

---
 ykval-synclib.php | 8 ++++++--
 1 file changed, 6 insertions(+), 2 deletions(-)

diff --git a/ykval-synclib.php b/ykval-synclib.php
index 2627b20..6c96317 100644
--- a/ykval-synclib.php
+++ b/ykval-synclib.php
@@ -406,7 +406,7 @@ class SyncLib
     /*
      Send out requests
     */
-    $ans_arr=$this->retrieveURLasync($urls, $ans_req, $timeout);
+    $ans_arr=$this->retrieveURLasync_wrap($urls, $ans_req, $timeout);
 
     if (!is_array($ans_arr)) {
       $this->log(LOG_WARNING, 'No responses from validation server pool');
@@ -510,6 +510,10 @@ class SyncLib
     else return 0;
   }
 
+  function retrieveURLasync_wrap ($urls, $ans_req=1, $timeout=1.0)
+  {
+    return retrieveURLasync("YK-VAL sync", $urls, $ans_req, $match="status=OK", $returl=True, $timeout);
+  }
 
   /*
    This function takes a list of URLs.  It will return the content of
@@ -520,7 +524,7 @@ class SyncLib
    URLs fail, data from some URL that did not match parameter $match
    (defaults to ^OK) is returned, or if all URLs failed, false.
   */
-  function retrieveURLasync ($urls, $ans_req=1, $timeout=1.0) {
+  function retrieveURLasync_old ($urls, $ans_req=1, $timeout=1.0) {
     $mh = curl_multi_init();
 
     $ch = array();

From 01969a279e54baa4be63610490d17163249aee84 Mon Sep 17 00:00:00 2001
From: Klas Lindfors <klas@yubico.com>
Date: Thu, 14 Jun 2012 14:55:50 +0200
Subject: [PATCH 14/37] let sendResp take one more parameter $context

use for logging if it's a response to sync or verify.
---
 ykval-common.php |  7 ++++---
 ykval-sync.php   | 17 ++++++++--------
 ykval-verify.php | 51 ++++++++++++++++++++++++------------------------
 3 files changed, 39 insertions(+), 36 deletions(-)

diff --git a/ykval-common.php b/ykval-common.php
index 50bb2e0..ae204cc 100644
--- a/ykval-common.php
+++ b/ykval-common.php
@@ -219,11 +219,12 @@ function KSMdecryptOTP($urls) {
   return $ret;
 } // End decryptOTP
 
-function sendResp($status, $apiKey = '', $extra = null) {
+function sendResp($status, $context, $apiKey = '', $extra = null) {
   if ($status == null) {
     $status = S_BACKEND_ERROR;
   }
 
+
   $a['status'] = $status;
   $a['t'] = getUTCTimeStamp();
   if ($extra){
@@ -242,8 +243,8 @@ function sendResp($status, $apiKey = '', $extra = null) {
   $str .= "\r\n";
 
   global $ykval_common_log;
-  $ykval_common_log->log(LOG_INFO, "Response: " . $str .
-			 " (at " . date("c") . " " . microtime() . ")");
+  $ykval_common_log->log(LOG_INFO, "Context=" . $context . " Response: " . $str .
+    " (at " . date("c") . " " . microtime() . ")");
 
   echo $str;
 }
diff --git a/ykval-sync.php b/ykval-sync.php
index ddf40fe..2f3111d 100644
--- a/ykval-sync.php
+++ b/ykval-sync.php
@@ -4,11 +4,12 @@ require_once 'ykval-config.php';
 require_once 'ykval-synclib.php';
 
 $apiKey = '';
+$context = 'sync';
 
 header("content-type: text/plain");
 
 if(empty($_SERVER['QUERY_STRING'])) {
-  sendResp(S_MISSING_PARAMETER, $apiKey);
+  sendResp(S_MISSING_PARAMETER, $context, $apiKey);
   exit;
 }
 
@@ -21,7 +22,7 @@ $sync = new SyncLib('ykval-sync:synclib');
 $sync->addField('ip', $_SERVER['REMOTE_ADDR']);
 
 if (! $sync->isConnected()) {
-  sendResp(S_BACKEND_ERROR, $apiKey);
+  sendResp(S_BACKEND_ERROR, $context, $apiKey);
   exit;
  }
 
@@ -41,7 +42,7 @@ foreach ($baseParams['__YKVAL_ALLOWED_SYNC_POOL__'] as $server) {
 }
 if (!$allowed) {
   $myLog->log(LOG_NOTICE, 'Operation not allowed from IP ' . $_SERVER['REMOTE_ADDR']);
-  sendResp(S_OPERATION_NOT_ALLOWED, $apiKey);
+  sendResp(S_OPERATION_NOT_ALLOWED, $context, $apiKey);
   exit;
  }
 
@@ -67,7 +68,7 @@ foreach ($syncParams as $param=>$value) {
   $value = getHttpVal($param, Null);
   if ($value==Null) {
     $myLog->log(LOG_NOTICE, "Received request with parameter[s] (" . $param . ") missing value");
-    sendResp(S_MISSING_PARAMETER, '');
+    sendResp(S_MISSING_PARAMETER, $context, $apiKey);
     exit;
   }
   $syncParams[$param]=$value;
@@ -88,7 +89,7 @@ $sync->addField('otp', $syncParams['otp']);
 foreach (array('modified') as $param) {
   if (preg_match("/^[0-9]+$/", $syncParams[$param])==0) {
     $myLog->log(LOG_NOTICE, 'Input parameters ' . $param . ' not correct');
-    sendResp(S_MISSING_PARAMETER, $apiKey);
+    sendResp(S_MISSING_PARAMETER, $context, $apiKey);
     exit;
   }
 }
@@ -96,7 +97,7 @@ foreach (array('modified') as $param) {
 foreach (array('yk_counter', 'yk_use', 'yk_high', 'yk_low') as $param) {
   if (preg_match("/^(-1|[0-9]+)$/", $syncParams[$param])==0) {
     $myLog->log(LOG_NOTICE, 'Input parameters ' . $param . ' not correct');
-    sendResp(S_MISSING_PARAMETER, $apiKey);
+    sendResp(S_MISSING_PARAMETER, $context, $apiKey);
     exit;
   }
 }
@@ -112,7 +113,7 @@ $yk_publicname = $syncParams['yk_publicname'];
 $localParams = $sync->getLocalParams($yk_publicname);
 if (!$localParams) {
   $myLog->log(LOG_NOTICE, 'Invalid Yubikey ' . $yk_publicname);
-  sendResp(S_BACKEND_ERROR, $apiKey);
+  sendResp(S_BACKEND_ERROR, $context, $apiKey);
   exit;
  }
 
@@ -179,6 +180,6 @@ $extra=array('modified'=>$localParams['modified'],
 	     'yk_high'=>$localParams['yk_high'],
 	     'yk_low'=>$localParams['yk_low']);
 
-sendResp(S_OK, '', $extra);
+sendResp(S_OK, $context, $apiKey, $extra);
 
 ?>
diff --git a/ykval-verify.php b/ykval-verify.php
index 21516c6..a5a5944 100644
--- a/ykval-verify.php
+++ b/ykval-verify.php
@@ -4,6 +4,7 @@ require_once 'ykval-config.php';
 require_once 'ykval-synclib.php';
 
 $apiKey = '';
+$context = 'verify';
 
 header("content-type: text/plain");
 
@@ -56,7 +57,7 @@ if ($protocol_version>=2.0) {
   /* Nonce is required from protocol 2.0 */
   if(!$nonce) {
     $myLog->log(LOG_NOTICE, 'Nonce is missing and protocol version >= 2.0');
-    sendResp(S_MISSING_PARAMETER);
+    sendResp(S_MISSING_PARAMETER, $context);
     exit;
   }
 }
@@ -90,49 +91,49 @@ if (!isset($timeout) || $timeout == '') {
 
 if ($otp == '') {
   $myLog->log(LOG_NOTICE, 'OTP is missing');
-  sendResp(S_MISSING_PARAMETER);
+  sendResp(S_MISSING_PARAMETER, $context);
   exit;
 }
 
 if (strlen($otp) < TOKEN_LEN || strlen ($otp) > OTP_MAX_LEN) {
   $myLog->log(LOG_NOTICE, 'Incorrect OTP length: ' . $otp);
-  sendResp(S_BAD_OTP);
+  sendResp(S_BAD_OTP, $context);
   exit;
 }
 
 if (preg_match("/^[cbdefghijklnrtuv]+$/", $otp)==0) {
   $myLog->log(LOG_NOTICE, 'Invalid OTP: ' . $otp);
-  sendResp(S_BAD_OTP);
+  sendResp(S_BAD_OTP, $context);
   exit;
 }
 
 if (preg_match("/^[0-9]+$/", $client)==0){
   $myLog->log(LOG_NOTICE, 'id provided in request must be an integer');
-  sendResp(S_MISSING_PARAMETER);
+  sendResp(S_MISSING_PARAMETER, $context);
   exit;
 }
 
 if ($timeout && preg_match("/^[0-9]+$/", $timeout)==0) {
   $myLog->log(LOG_NOTICE, 'timeout is provided but not correct');
-  sendResp(S_MISSING_PARAMETER);
+  sendResp(S_MISSING_PARAMETER, $context);
   exit;
 }
 
 if (isset($nonce) && preg_match("/^[A-Za-z0-9]+$/", $nonce)==0) {
   $myLog->log(LOG_NOTICE, 'NONCE is provided but not correct');
-  sendResp(S_MISSING_PARAMETER);
+  sendResp(S_MISSING_PARAMETER, $context);
   exit;
 }
 
 if (isset($nonce) && (strlen($nonce) < 16 || strlen($nonce) > 40)) {
   $myLog->log(LOG_NOTICE, 'Nonce too short or too long');
-  sendResp(S_MISSING_PARAMETER);
+  sendResp(S_MISSING_PARAMETER, $context);
   exit;
 }
 
 if ($sl && (preg_match("/^[0-9]+$/", $sl)==0 || ($sl<0 || $sl>100))) {
   $myLog->log(LOG_NOTICE, 'SL is provided but not correct');
-  sendResp(S_MISSING_PARAMETER);
+  sendResp(S_MISSING_PARAMETER, $context);
   exit;
 }
 
@@ -143,7 +144,7 @@ if ($sl && (preg_match("/^[0-9]+$/", $sl)==0 || ($sl<0 || $sl>100))) {
 //
 if ($client <= 0) {
   $myLog->log(LOG_NOTICE, 'Client ID is missing');
-  sendResp(S_MISSING_PARAMETER);
+  sendResp(S_MISSING_PARAMETER, $context);
   exit;
 }
 
@@ -156,14 +157,14 @@ $sync->addField('ip', $_SERVER['REMOTE_ADDR']);
 $sync->addField('otp', $otp);
 
 if (! $sync->isConnected()) {
-  sendResp(S_BACKEND_ERROR);
+  sendResp(S_BACKEND_ERROR, $context);
   exit;
  }
 
 $cd=$sync->getClientData($client);
 if(!$cd) {
   $myLog->log(LOG_NOTICE, 'Invalid client id ' . $client);
-  sendResp(S_NO_SUCH_CLIENT);
+  sendResp(S_NO_SUCH_CLIENT, $context);
   exit;
  }
 $myLog->log(LOG_DEBUG,"Client data:", $cd);
@@ -189,7 +190,7 @@ if ($h != '') {
   // Compare it
   if ($hmac != $h) {
     $myLog->log(LOG_DEBUG, 'client hmac=' . $h . ', server hmac=' . $hmac);
-    sendResp(S_BAD_SIGNATURE, $apiKey);
+    sendResp(S_BAD_SIGNATURE, $context, $apiKey);
     exit;
   }
 }
@@ -206,7 +207,7 @@ if ($protocol_version<2.0) {
 //
 $urls = otp2ksmurls ($otp, $client);
 if (!is_array($urls)) {
-  sendResp(S_BACKEND_ERROR, $apiKey);
+  sendResp(S_BACKEND_ERROR, $context, $apiKey);
   exit;
 }
 
@@ -214,7 +215,7 @@ if (!is_array($urls)) {
 //
 $otpinfo = KSMdecryptOTP($urls);
 if (!is_array($otpinfo)) {
-  sendResp(S_BAD_OTP, $apiKey);
+  sendResp(S_BAD_OTP, $context, $apiKey);
   exit;
 }
 $myLog->log(LOG_DEBUG, "Decrypted OTP:", $otpinfo);
@@ -226,14 +227,14 @@ $yk_publicname=$devId;
 $localParams = $sync->getLocalParams($yk_publicname);
 if (!$localParams) {
   $myLog->log(LOG_NOTICE, 'Invalid Yubikey ' . $yk_publicname);
-  sendResp(S_BACKEND_ERROR, $apiKey);
+  sendResp(S_BACKEND_ERROR, $context, $apiKey);
   exit;
  }
 
 $myLog->log(LOG_DEBUG, "Auth data:", $localParams);
 if ($localParams['active'] != 1) {
   $myLog->log(LOG_NOTICE, 'De-activated Yubikey ' . $devId);
-  sendResp(S_BAD_OTP, $apiKey);
+  sendResp(S_BAD_OTP, $context, $apiKey);
   exit;
 }
 
@@ -253,7 +254,7 @@ $otpParams=array('modified'=>time(),
 if ($sync->countersEqual($localParams, $otpParams) &&
     $localParams['nonce']==$otpParams['nonce']) {
   $myLog->log(LOG_WARNING, 'Replayed request');
-  sendResp(S_REPLAYED_REQUEST, $apiKey, $extra);
+  sendResp(S_REPLAYED_REQUEST, $context, $apiKey, $extra);
   exit;
  }
 
@@ -262,7 +263,7 @@ if ($sync->countersHigherThanOrEqual($localParams, $otpParams)) {
   $sync->log(LOG_WARNING, 'replayed OTP: Local counters higher');
   $sync->log(LOG_WARNING, 'replayed OTP: Local counters ', $localParams);
   $sync->log(LOG_WARNING, 'replayed OTP: Otp counters ', $otpParams);
-  sendResp(S_REPLAYED_OTP, $apiKey, $extra);
+  sendResp(S_REPLAYED_OTP, $context, $apiKey, $extra);
   exit;
  }
 
@@ -270,7 +271,7 @@ if ($sync->countersHigherThanOrEqual($localParams, $otpParams)) {
 
 if(!$sync->updateDbCounters($otpParams)) {
   $myLog->log(LOG_CRIT, "Failed to update yubikey counters in database");
-  sendResp(S_BACKEND_ERROR, $apiKey);
+  sendResp(S_BACKEND_ERROR, $context, $apiKey);
   exit;
  }
 
@@ -278,7 +279,7 @@ if(!$sync->updateDbCounters($otpParams)) {
 
 if (!$sync->queue($otpParams, $localParams)) {
   $myLog->log(LOG_CRIT, "ykval-verify:critical:failed to queue sync requests");
-  sendResp(S_BACKEND_ERROR, $apiKey);
+  sendResp(S_BACKEND_ERROR, $context, $apiKey);
   exit;
  }
 
@@ -310,11 +311,11 @@ if($syncres==False) {
    there were not enough answers */
   $myLog->log(LOG_WARNING, "ykval-verify:notice:Sync failed");
   if ($nr_valid_answers!=$nr_answers) {
-    sendResp(S_REPLAYED_OTP, $apiKey, $extra);
+    sendResp(S_REPLAYED_OTP, $context, $apiKey, $extra);
     exit;
   } else {
     $extra['sl']=$sl_success_rate;
-    sendResp(S_NOT_ENOUGH_ANSWERS, $apiKey, $extra);
+    sendResp(S_NOT_ENOUGH_ANSWERS, $context, $apiKey, $extra);
     exit;
   }
  }
@@ -362,7 +363,7 @@ if ($sessionCounter == $seenSessionCounter && $sessionUse > $seenSessionUse) {
   if ($deviation > TS_ABS_TOLERANCE && $percent > TS_REL_TOLERANCE) {
     $myLog->log(LOG_NOTICE, "OTP failed phishing test");
     if (0) {
-      sendResp(S_DELAYED_OTP, $apiKey, $extra);
+      sendResp(S_DELAYED_OTP, $context, $apiKey, $extra);
       exit;
     }
   }
@@ -378,6 +379,6 @@ if ($timestamp==1){
   $extra['sessionuse'] = $sessionUse;
  }
 
-sendResp(S_OK, $apiKey, $extra);
+sendResp(S_OK, $context, $apiKey, $extra);
 
 ?>

From 60bfa8ff1ab025ac84a3cb18cf28e21dbb1e3bb7 Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Thu, 14 Jun 2012 15:10:44 +0200
Subject: [PATCH 15/37] minor debug log fixes

---
 ykval-common.php | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/ykval-common.php b/ykval-common.php
index 6e849a1..0809861 100644
--- a/ykval-common.php
+++ b/ykval-common.php
@@ -147,9 +147,9 @@ function retrieveURLasync ($ident, $urls, $ans_req=1, $match="^OK", $returl=Fals
       debug ($ident . " curl multi info : ", $info);
       if ($info['result'] == CURLE_OK) {
 	$str = curl_multi_getcontent($info['handle']);
-	debug($str);
+	debug($ident . " curl multi content : " . $str);
 	if (preg_match("/".$match."/", $str)) {
-	  debug($ident . "response matches " . $match);
+	  debug($ident . " response matches " . $match);
 	  $error = curl_error ($info['handle']);
 	  $errno = curl_errno ($info['handle']);
 	  $cinfo = curl_getinfo ($info['handle']);

From 6c9edb0db24ca9bf96acde5f123b07aa0aca2992 Mon Sep 17 00:00:00 2001
From: Klas Lindfors <klas@yubico.com>
Date: Thu, 14 Jun 2012 15:15:47 +0200
Subject: [PATCH 16/37] instead of passing context to sendResp, give it a
 logger.

---
 ykval-common.php |  6 ++----
 ykval-sync.php   | 24 +++++++++++------------
 ykval-verify.php | 51 ++++++++++++++++++++++++------------------------
 3 files changed, 39 insertions(+), 42 deletions(-)

diff --git a/ykval-common.php b/ykval-common.php
index ae204cc..ce4c9ce 100644
--- a/ykval-common.php
+++ b/ykval-common.php
@@ -219,12 +219,11 @@ function KSMdecryptOTP($urls) {
   return $ret;
 } // End decryptOTP
 
-function sendResp($status, $context, $apiKey = '', $extra = null) {
+function sendResp($status, $logger, $apiKey = '', $extra = null) {
   if ($status == null) {
     $status = S_BACKEND_ERROR;
   }
 
-
   $a['status'] = $status;
   $a['t'] = getUTCTimeStamp();
   if ($extra){
@@ -242,8 +241,7 @@ function sendResp($status, $context, $apiKey = '', $extra = null) {
   $str .= "status=" . ($a['status']) . "\r\n";
   $str .= "\r\n";
 
-  global $ykval_common_log;
-  $ykval_common_log->log(LOG_INFO, "Context=" . $context . " Response: " . $str .
+  $logger->log(LOG_INFO, "Response: " . $str .
     " (at " . date("c") . " " . microtime() . ")");
 
   echo $str;
diff --git a/ykval-sync.php b/ykval-sync.php
index 2f3111d..8a5a6d3 100644
--- a/ykval-sync.php
+++ b/ykval-sync.php
@@ -4,25 +4,25 @@ require_once 'ykval-config.php';
 require_once 'ykval-synclib.php';
 
 $apiKey = '';
-$context = 'sync';
 
 header("content-type: text/plain");
 
-if(empty($_SERVER['QUERY_STRING'])) {
-  sendResp(S_MISSING_PARAMETER, $context, $apiKey);
-  exit;
-}
 
 $myLog = new Log('ykval-sync');
 $myLog->addField('ip', $_SERVER['REMOTE_ADDR']);
 
+if(empty($_SERVER['QUERY_STRING'])) {
+  sendResp(S_MISSING_PARAMETER, $myLog, $apiKey);
+  exit;
+}
+
 $myLog->log(LOG_INFO, "Request: " . $_SERVER['QUERY_STRING']);
 
 $sync = new SyncLib('ykval-sync:synclib');
 $sync->addField('ip', $_SERVER['REMOTE_ADDR']);
 
 if (! $sync->isConnected()) {
-  sendResp(S_BACKEND_ERROR, $context, $apiKey);
+  sendResp(S_BACKEND_ERROR, $myLog, $apiKey);
   exit;
  }
 
@@ -42,7 +42,7 @@ foreach ($baseParams['__YKVAL_ALLOWED_SYNC_POOL__'] as $server) {
 }
 if (!$allowed) {
   $myLog->log(LOG_NOTICE, 'Operation not allowed from IP ' . $_SERVER['REMOTE_ADDR']);
-  sendResp(S_OPERATION_NOT_ALLOWED, $context, $apiKey);
+  sendResp(S_OPERATION_NOT_ALLOWED, $myLog, $apiKey);
   exit;
  }
 
@@ -68,7 +68,7 @@ foreach ($syncParams as $param=>$value) {
   $value = getHttpVal($param, Null);
   if ($value==Null) {
     $myLog->log(LOG_NOTICE, "Received request with parameter[s] (" . $param . ") missing value");
-    sendResp(S_MISSING_PARAMETER, $context, $apiKey);
+    sendResp(S_MISSING_PARAMETER, $myLog, $apiKey);
     exit;
   }
   $syncParams[$param]=$value;
@@ -89,7 +89,7 @@ $sync->addField('otp', $syncParams['otp']);
 foreach (array('modified') as $param) {
   if (preg_match("/^[0-9]+$/", $syncParams[$param])==0) {
     $myLog->log(LOG_NOTICE, 'Input parameters ' . $param . ' not correct');
-    sendResp(S_MISSING_PARAMETER, $context, $apiKey);
+    sendResp(S_MISSING_PARAMETER, $myLog, $apiKey);
     exit;
   }
 }
@@ -97,7 +97,7 @@ foreach (array('modified') as $param) {
 foreach (array('yk_counter', 'yk_use', 'yk_high', 'yk_low') as $param) {
   if (preg_match("/^(-1|[0-9]+)$/", $syncParams[$param])==0) {
     $myLog->log(LOG_NOTICE, 'Input parameters ' . $param . ' not correct');
-    sendResp(S_MISSING_PARAMETER, $context, $apiKey);
+    sendResp(S_MISSING_PARAMETER, $myLog, $apiKey);
     exit;
   }
 }
@@ -113,7 +113,7 @@ $yk_publicname = $syncParams['yk_publicname'];
 $localParams = $sync->getLocalParams($yk_publicname);
 if (!$localParams) {
   $myLog->log(LOG_NOTICE, 'Invalid Yubikey ' . $yk_publicname);
-  sendResp(S_BACKEND_ERROR, $context, $apiKey);
+  sendResp(S_BACKEND_ERROR, $myLog, $apiKey);
   exit;
  }
 
@@ -180,6 +180,6 @@ $extra=array('modified'=>$localParams['modified'],
 	     'yk_high'=>$localParams['yk_high'],
 	     'yk_low'=>$localParams['yk_low']);
 
-sendResp(S_OK, $context, $apiKey, $extra);
+sendResp(S_OK, $myLog, $apiKey, $extra);
 
 ?>
diff --git a/ykval-verify.php b/ykval-verify.php
index a5a5944..58a5cfa 100644
--- a/ykval-verify.php
+++ b/ykval-verify.php
@@ -4,7 +4,6 @@ require_once 'ykval-config.php';
 require_once 'ykval-synclib.php';
 
 $apiKey = '';
-$context = 'verify';
 
 header("content-type: text/plain");
 
@@ -57,7 +56,7 @@ if ($protocol_version>=2.0) {
   /* Nonce is required from protocol 2.0 */
   if(!$nonce) {
     $myLog->log(LOG_NOTICE, 'Nonce is missing and protocol version >= 2.0');
-    sendResp(S_MISSING_PARAMETER, $context);
+    sendResp(S_MISSING_PARAMETER, $myLog);
     exit;
   }
 }
@@ -91,49 +90,49 @@ if (!isset($timeout) || $timeout == '') {
 
 if ($otp == '') {
   $myLog->log(LOG_NOTICE, 'OTP is missing');
-  sendResp(S_MISSING_PARAMETER, $context);
+  sendResp(S_MISSING_PARAMETER, $myLog);
   exit;
 }
 
 if (strlen($otp) < TOKEN_LEN || strlen ($otp) > OTP_MAX_LEN) {
   $myLog->log(LOG_NOTICE, 'Incorrect OTP length: ' . $otp);
-  sendResp(S_BAD_OTP, $context);
+  sendResp(S_BAD_OTP, $myLog);
   exit;
 }
 
 if (preg_match("/^[cbdefghijklnrtuv]+$/", $otp)==0) {
   $myLog->log(LOG_NOTICE, 'Invalid OTP: ' . $otp);
-  sendResp(S_BAD_OTP, $context);
+  sendResp(S_BAD_OTP, $myLog);
   exit;
 }
 
 if (preg_match("/^[0-9]+$/", $client)==0){
   $myLog->log(LOG_NOTICE, 'id provided in request must be an integer');
-  sendResp(S_MISSING_PARAMETER, $context);
+  sendResp(S_MISSING_PARAMETER, $myLog);
   exit;
 }
 
 if ($timeout && preg_match("/^[0-9]+$/", $timeout)==0) {
   $myLog->log(LOG_NOTICE, 'timeout is provided but not correct');
-  sendResp(S_MISSING_PARAMETER, $context);
+  sendResp(S_MISSING_PARAMETER, $myLog);
   exit;
 }
 
 if (isset($nonce) && preg_match("/^[A-Za-z0-9]+$/", $nonce)==0) {
   $myLog->log(LOG_NOTICE, 'NONCE is provided but not correct');
-  sendResp(S_MISSING_PARAMETER, $context);
+  sendResp(S_MISSING_PARAMETER, $myLog);
   exit;
 }
 
 if (isset($nonce) && (strlen($nonce) < 16 || strlen($nonce) > 40)) {
   $myLog->log(LOG_NOTICE, 'Nonce too short or too long');
-  sendResp(S_MISSING_PARAMETER, $context);
+  sendResp(S_MISSING_PARAMETER, $myLog);
   exit;
 }
 
 if ($sl && (preg_match("/^[0-9]+$/", $sl)==0 || ($sl<0 || $sl>100))) {
   $myLog->log(LOG_NOTICE, 'SL is provided but not correct');
-  sendResp(S_MISSING_PARAMETER, $context);
+  sendResp(S_MISSING_PARAMETER, $myLog);
   exit;
 }
 
@@ -144,7 +143,7 @@ if ($sl && (preg_match("/^[0-9]+$/", $sl)==0 || ($sl<0 || $sl>100))) {
 //
 if ($client <= 0) {
   $myLog->log(LOG_NOTICE, 'Client ID is missing');
-  sendResp(S_MISSING_PARAMETER, $context);
+  sendResp(S_MISSING_PARAMETER, $myLog);
   exit;
 }
 
@@ -157,14 +156,14 @@ $sync->addField('ip', $_SERVER['REMOTE_ADDR']);
 $sync->addField('otp', $otp);
 
 if (! $sync->isConnected()) {
-  sendResp(S_BACKEND_ERROR, $context);
+  sendResp(S_BACKEND_ERROR, $myLog);
   exit;
  }
 
 $cd=$sync->getClientData($client);
 if(!$cd) {
   $myLog->log(LOG_NOTICE, 'Invalid client id ' . $client);
-  sendResp(S_NO_SUCH_CLIENT, $context);
+  sendResp(S_NO_SUCH_CLIENT, $myLog);
   exit;
  }
 $myLog->log(LOG_DEBUG,"Client data:", $cd);
@@ -190,7 +189,7 @@ if ($h != '') {
   // Compare it
   if ($hmac != $h) {
     $myLog->log(LOG_DEBUG, 'client hmac=' . $h . ', server hmac=' . $hmac);
-    sendResp(S_BAD_SIGNATURE, $context, $apiKey);
+    sendResp(S_BAD_SIGNATURE, $myLog, $apiKey);
     exit;
   }
 }
@@ -207,7 +206,7 @@ if ($protocol_version<2.0) {
 //
 $urls = otp2ksmurls ($otp, $client);
 if (!is_array($urls)) {
-  sendResp(S_BACKEND_ERROR, $context, $apiKey);
+  sendResp(S_BACKEND_ERROR, $myLog, $apiKey);
   exit;
 }
 
@@ -215,7 +214,7 @@ if (!is_array($urls)) {
 //
 $otpinfo = KSMdecryptOTP($urls);
 if (!is_array($otpinfo)) {
-  sendResp(S_BAD_OTP, $context, $apiKey);
+  sendResp(S_BAD_OTP, $myLog, $apiKey);
   exit;
 }
 $myLog->log(LOG_DEBUG, "Decrypted OTP:", $otpinfo);
@@ -227,14 +226,14 @@ $yk_publicname=$devId;
 $localParams = $sync->getLocalParams($yk_publicname);
 if (!$localParams) {
   $myLog->log(LOG_NOTICE, 'Invalid Yubikey ' . $yk_publicname);
-  sendResp(S_BACKEND_ERROR, $context, $apiKey);
+  sendResp(S_BACKEND_ERROR, $myLog, $apiKey);
   exit;
  }
 
 $myLog->log(LOG_DEBUG, "Auth data:", $localParams);
 if ($localParams['active'] != 1) {
   $myLog->log(LOG_NOTICE, 'De-activated Yubikey ' . $devId);
-  sendResp(S_BAD_OTP, $context, $apiKey);
+  sendResp(S_BAD_OTP, $myLog, $apiKey);
   exit;
 }
 
@@ -254,7 +253,7 @@ $otpParams=array('modified'=>time(),
 if ($sync->countersEqual($localParams, $otpParams) &&
     $localParams['nonce']==$otpParams['nonce']) {
   $myLog->log(LOG_WARNING, 'Replayed request');
-  sendResp(S_REPLAYED_REQUEST, $context, $apiKey, $extra);
+  sendResp(S_REPLAYED_REQUEST, $myLog, $apiKey, $extra);
   exit;
  }
 
@@ -263,7 +262,7 @@ if ($sync->countersHigherThanOrEqual($localParams, $otpParams)) {
   $sync->log(LOG_WARNING, 'replayed OTP: Local counters higher');
   $sync->log(LOG_WARNING, 'replayed OTP: Local counters ', $localParams);
   $sync->log(LOG_WARNING, 'replayed OTP: Otp counters ', $otpParams);
-  sendResp(S_REPLAYED_OTP, $context, $apiKey, $extra);
+  sendResp(S_REPLAYED_OTP, $myLog, $apiKey, $extra);
   exit;
  }
 
@@ -271,7 +270,7 @@ if ($sync->countersHigherThanOrEqual($localParams, $otpParams)) {
 
 if(!$sync->updateDbCounters($otpParams)) {
   $myLog->log(LOG_CRIT, "Failed to update yubikey counters in database");
-  sendResp(S_BACKEND_ERROR, $context, $apiKey);
+  sendResp(S_BACKEND_ERROR, $myLog, $apiKey);
   exit;
  }
 
@@ -279,7 +278,7 @@ if(!$sync->updateDbCounters($otpParams)) {
 
 if (!$sync->queue($otpParams, $localParams)) {
   $myLog->log(LOG_CRIT, "ykval-verify:critical:failed to queue sync requests");
-  sendResp(S_BACKEND_ERROR, $context, $apiKey);
+  sendResp(S_BACKEND_ERROR, $myLog, $apiKey);
   exit;
  }
 
@@ -311,11 +310,11 @@ if($syncres==False) {
    there were not enough answers */
   $myLog->log(LOG_WARNING, "ykval-verify:notice:Sync failed");
   if ($nr_valid_answers!=$nr_answers) {
-    sendResp(S_REPLAYED_OTP, $context, $apiKey, $extra);
+    sendResp(S_REPLAYED_OTP, $myLog, $apiKey, $extra);
     exit;
   } else {
     $extra['sl']=$sl_success_rate;
-    sendResp(S_NOT_ENOUGH_ANSWERS, $context, $apiKey, $extra);
+    sendResp(S_NOT_ENOUGH_ANSWERS, $myLog, $apiKey, $extra);
     exit;
   }
  }
@@ -363,7 +362,7 @@ if ($sessionCounter == $seenSessionCounter && $sessionUse > $seenSessionUse) {
   if ($deviation > TS_ABS_TOLERANCE && $percent > TS_REL_TOLERANCE) {
     $myLog->log(LOG_NOTICE, "OTP failed phishing test");
     if (0) {
-      sendResp(S_DELAYED_OTP, $context, $apiKey, $extra);
+      sendResp(S_DELAYED_OTP, $myLog, $apiKey, $extra);
       exit;
     }
   }
@@ -379,6 +378,6 @@ if ($timestamp==1){
   $extra['sessionuse'] = $sessionUse;
  }
 
-sendResp(S_OK, $context, $apiKey, $extra);
+sendResp(S_OK, $myLog, $apiKey, $extra);
 
 ?>

From c8e9eb828f85e0a5a54727bc99560cea5aafa381 Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Thu, 14 Jun 2012 15:19:04 +0200
Subject: [PATCH 17/37] Pass logger object to retrieveURLasync()

---
 ykval-common.php  | 33 ++++++++++++++++++++++++---------
 ykval-synclib.php |  2 +-
 ykval-verify.php  |  2 +-
 3 files changed, 26 insertions(+), 11 deletions(-)

diff --git a/ykval-common.php b/ykval-common.php
index 0809861..98ce99a 100644
--- a/ykval-common.php
+++ b/ykval-common.php
@@ -63,6 +63,21 @@ function debug() {
   $ykval_common_log->log(LOG_DEBUG, $str);
 }
 
+function log_format() {
+  $str = "";
+  foreach (func_get_args() as $msg)
+    {
+      if (is_array($msg)) {
+	foreach($msg as $key => $value){
+	  $str .= "$key=$value ";
+	}
+      } else {
+	$str .= $msg . " ";
+      }
+    }
+  return $str;
+}
+
 // Return eg. 2008-11-21T06:11:55Z0711
 //
 function getUTCTimeStamp() {
@@ -117,13 +132,13 @@ function modhex2b64 ($modhex_str) {
 // long as one of the URLs given work, data will be returned.  If all
 // URLs fail, data from some URL that did not match parameter $match
 // (defaults to ^OK) is returned, or if all URLs failed, false.
-function retrieveURLasync ($ident, $urls, $ans_req=1, $match="^OK", $returl=False, $timeout=10) {
+function retrieveURLasync ($ident, $urls, $logger, $ans_req=1, $match="^OK", $returl=False, $timeout=10) {
   $mh = curl_multi_init();
 
   $ch = array();
   foreach ($urls as $id => $url) {
     $handle = curl_init();
-    debug($ident . " adding URL : " . $url);
+    $logger->log($ident . " adding URL : " . $url);
     curl_setopt($handle, CURLOPT_URL, $url);
     curl_setopt($handle, CURLOPT_USERAGENT, "YK-VAL");
     curl_setopt($handle, CURLOPT_RETURNTRANSFER, 1);
@@ -144,16 +159,16 @@ function retrieveURLasync ($ident, $urls, $ans_req=1, $match="^OK", $returl=Fals
       ;
 
     while ($info = curl_multi_info_read($mh)) {
-      debug ($ident . " curl multi info : ", $info);
+      $logger->log($ident . " curl multi info : ", $info);
       if ($info['result'] == CURLE_OK) {
 	$str = curl_multi_getcontent($info['handle']);
-	debug($ident . " curl multi content : " . $str);
+	$logger->log($ident . " curl multi content : " . $str);
 	if (preg_match("/".$match."/", $str)) {
-	  debug($ident . " response matches " . $match);
+	  $logger->log($ident . " response matches " . $match);
 	  $error = curl_error ($info['handle']);
 	  $errno = curl_errno ($info['handle']);
 	  $cinfo = curl_getinfo ($info['handle']);
-	  debug($ident . " errno/error: " . $errno . "/" . $error, $cinfo);
+	  $logger->log($ident . " errno/error: " . $errno . "/" . $error, $cinfo);
 	  $ans_count++;
 	  if ($returl) $ans_arr[]="url=" . $cinfo['url'] . "\n" . $str;
 	  else $ans_arr[]=$str;
@@ -198,20 +213,20 @@ function retrieveURLsimple ($url, $match="^OK") {
 }
 
 // $otp: A yubikey OTP
-function KSMdecryptOTP($urls) {
+function KSMdecryptOTP($urls, $logger) {
   $ret = array();
   if (!is_array($urls)) {
     $response = retrieveURLsimple ($urls);
   } elseif (count($urls) == 1) {
     $response = retrieveURLsimple ($urls[0]);
   } else {
-    $response = retrieveURLasync ("YK-KSM", $urls, $ans_req=1, $match="^OK", $returl=False, $timeout=10);
+    $response = retrieveURLasync ("YK-KSM", $urls, $logger, $ans_req=1, $match="^OK", $returl=False, $timeout=10);
     if (is_array($response)) {
       $response = $response[0];
     }
   }
   if ($response) {
-    debug("YK-KSM response: " . $response);
+    $logger->log(LOG_DEBUG, log_format("YK-KSM response: ", $response));
   }
   if (sscanf ($response,
 	      "OK counter=%04x low=%04x high=%02x use=%02x",
diff --git a/ykval-synclib.php b/ykval-synclib.php
index 29ece23..7822d04 100644
--- a/ykval-synclib.php
+++ b/ykval-synclib.php
@@ -518,7 +518,7 @@ class SyncLib
 
   function retrieveURLasync_wrap ($urls, $ans_req=1, $timeout=1.0)
   {
-    return retrieveURLasync("YK-VAL sync", $urls, $ans_req, $match="status=OK", $returl=True, $timeout);
+    return retrieveURLasync("YK-VAL sync", $urls, $this->myLog, $ans_req, $match="status=OK", $returl=True, $timeout);
   }
 
   /*
diff --git a/ykval-verify.php b/ykval-verify.php
index a5a5944..6743840 100644
--- a/ykval-verify.php
+++ b/ykval-verify.php
@@ -213,7 +213,7 @@ if (!is_array($urls)) {
 
 //// Decode OTP from input
 //
-$otpinfo = KSMdecryptOTP($urls);
+$otpinfo = KSMdecryptOTP($urls, $myLog);
 if (!is_array($otpinfo)) {
   sendResp(S_BAD_OTP, $context, $apiKey);
   exit;

From b8d18af10c77f7b0a7fcedf737a7bb00ec67b8d9 Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Thu, 14 Jun 2012 15:22:38 +0200
Subject: [PATCH 18/37] Remove now unused retrieveURLasync_old()

---
 ykval-synclib.php | 79 -----------------------------------------------
 1 file changed, 79 deletions(-)

diff --git a/ykval-synclib.php b/ykval-synclib.php
index 7822d04..f96e2d9 100644
--- a/ykval-synclib.php
+++ b/ykval-synclib.php
@@ -521,85 +521,6 @@ class SyncLib
     return retrieveURLasync("YK-VAL sync", $urls, $this->myLog, $ans_req, $match="status=OK", $returl=True, $timeout);
   }
 
-  /*
-   This function takes a list of URLs.  It will return the content of
-   the first successfully retrieved URL, whose content matches ^OK.
-   The request are sent asynchronously.  Some of the URLs can fail
-   with unknown host, connection errors, or network timeout, but as
-   long as one of the URLs given work, data will be returned.  If all
-   URLs fail, data from some URL that did not match parameter $match
-   (defaults to ^OK) is returned, or if all URLs failed, false.
-  */
-  function retrieveURLasync_old ($urls, $ans_req=1, $timeout=1.0) {
-    $mh = curl_multi_init();
-
-    $ch = array();
-    foreach ($urls as $id => $url) {
-      $this->log(LOG_DEBUG, "url in retrieveURLasync is " . $url);
-      $handle = curl_init();
-
-      curl_setopt($handle, CURLOPT_URL, $url);
-      curl_setopt($handle, CURLOPT_USERAGENT, "YK-VAL");
-      curl_setopt($handle, CURLOPT_RETURNTRANSFER, 1);
-      curl_setopt($handle, CURLOPT_FAILONERROR, true);
-      curl_setopt($handle, CURLOPT_TIMEOUT, $timeout);
-
-      curl_multi_add_handle($mh, $handle);
-
-      $ch[$handle] = $handle;
-    }
-
-    $str = false;
-    $ans_count = 0;
-    $ans_arr = array();
-
-    do {
-      while (($mrc = curl_multi_exec($mh, $active)) == CURLM_CALL_MULTI_PERFORM)
-	;
-
-      while ($info = curl_multi_info_read($mh)) {
-	debug ("YK-KSM multi", $info);
-	if ($info['result'] == CURLE_OK) {
-	  $str = curl_multi_getcontent($info['handle']);
-	  if (preg_match("/status=OK/", $str)) {
-	    $error = curl_error ($info['handle']);
-	    $errno = curl_errno ($info['handle']);
-	    $cinfo = curl_getinfo ($info['handle']);
-	    debug("YK-KSM errno/error: " . $errno . "/" . $error, $cinfo);
-	    $ans_count++;
-	    $ans_arr[]="url=" . $cinfo['url'] . "\n" . $str;
-	  }
-
-	  if ($ans_count >= $ans_req) {
-	    foreach ($ch as $h) {
-	      curl_multi_remove_handle ($mh, $h);
-	      curl_close ($h);
-	    }
-	    curl_multi_close ($mh);
-
-	    return $ans_arr;
-	  }
-
-	  curl_multi_remove_handle ($mh, $info['handle']);
-	  curl_close ($info['handle']);
-	  unset ($ch[$info['handle']]);
-	}
-
-	curl_multi_select ($mh);
-      }
-    } while($active);
-
-
-    foreach ($ch as $h) {
-      curl_multi_remove_handle ($mh, $h);
-      curl_close ($h);
-    }
-    curl_multi_close ($mh);
-
-    if ($ans_count>0) return $ans_arr;
-    else return $str;
-  }
-
 }
 
 ?>

From 6c80f761027630f17c6d318bae000b493be94a2e Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Thu, 14 Jun 2012 15:22:55 +0200
Subject: [PATCH 19/37] Get rid of debug() - use log_format() for the
 formatting part.

---
 ykval-common.php | 22 +++-------------------
 ykval-verify.php |  2 +-
 2 files changed, 4 insertions(+), 20 deletions(-)

diff --git a/ykval-common.php b/ykval-common.php
index 929465f..6e7395e 100644
--- a/ykval-common.php
+++ b/ykval-common.php
@@ -47,22 +47,6 @@ function getHttpVal($key, $defaultVal) {
   	return $v;
 }
 
-function debug() {
-  $str = "";
-  foreach (func_get_args() as $msg)
-    {
-      if (is_array($msg)) {
-	foreach($msg as $key => $value){
-	  $str .= "$key=$value ";
-	}
-      } else {
-	$str .= $msg . " ";
-      }
-    }
-  global $ykval_common_log;
-  $ykval_common_log->log(LOG_DEBUG, $str);
-}
-
 function log_format() {
   $str = "";
   foreach (func_get_args() as $msg)
@@ -101,7 +85,7 @@ function UnixToDbTime($unix)
 
 // Sign a http query string in the array of key-value pairs
 // return b64 encoded hmac hash
-function sign($a, $apiKey) {
+function sign($a, $apiKey, $logger) {
 	ksort($a);
 	$qs = urldecode(http_build_query($a));
 
@@ -109,7 +93,7 @@ function sign($a, $apiKey) {
 	$hmac = hash_hmac('sha1', utf8_encode($qs), $apiKey, true);
 	$hmac = base64_encode($hmac);
 
-	debug('SIGN: ' . $qs . ' H=' . $hmac);
+	$logger->log(LOG_DEBUG, 'SIGN: ' . $qs . ' H=' . $hmac);
 
 	return $hmac;
 
@@ -247,7 +231,7 @@ function sendResp($status, $logger, $apiKey = '', $extra = null) {
   if ($extra){
     foreach ($extra as $param => $value) $a[$param] = $value;
   }
-  $h = sign($a, $apiKey);
+  $h = sign($a, $apiKey, $logger);
 
   $str = "h=" . $h . "\r\n";
   $str .= "t=" . ($a['t']) . "\r\n";
diff --git a/ykval-verify.php b/ykval-verify.php
index 1ddf140..9f39fe8 100644
--- a/ykval-verify.php
+++ b/ykval-verify.php
@@ -185,7 +185,7 @@ if ($h != '') {
   }
   unset($a['h']);
 
-  $hmac = sign($a, $apiKey);
+  $hmac = sign($a, $apiKey, $myLog);
   // Compare it
   if ($hmac != $h) {
     $myLog->log(LOG_DEBUG, 'client hmac=' . $h . ', server hmac=' . $hmac);

From 499377fd2f2101b7588545c80ca57a29fe9829e1 Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Thu, 14 Jun 2012 15:54:51 +0200
Subject: [PATCH 20/37] Change protocol version logging to 'debug'.

---
 ykval-verify.php | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/ykval-verify.php b/ykval-verify.php
index 9f39fe8..e466190 100644
--- a/ykval-verify.php
+++ b/ykval-verify.php
@@ -20,7 +20,7 @@ if (preg_match("/\/wsapi\/([0-9]+)\.([0-9]+)\//", $_SERVER['REQUEST_URI'], $out)
   $protocol_version=1.0;
  }
 
-$myLog->log(LOG_INFO, "found protocol version " . $protocol_version);
+$myLog->log(LOG_DEBUG, "found protocol version " . $protocol_version);
 
 /* Extract values from HTTP request
  */

From 1fd2e77da1d6d02c5148b9f3a179e4fc324a4a69 Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Thu, 14 Jun 2012 16:16:29 +0200
Subject: [PATCH 21/37] Make logdie() take logger as argument.

---
 ykval-common.php | 10 ++--------
 ykval-revoke.php | 20 ++++++++++++--------
 2 files changed, 14 insertions(+), 16 deletions(-)

diff --git a/ykval-common.php b/ykval-common.php
index 6e7395e..fd10d71 100644
--- a/ykval-common.php
+++ b/ykval-common.php
@@ -1,7 +1,5 @@
 <?php
 
-require_once('ykval-log.php');
-
 define('S_OK', 'OK');
 define('S_BAD_OTP', 'BAD_OTP');
 define('S_REPLAYED_OTP', 'REPLAYED_OTP');
@@ -22,13 +20,9 @@ define('TS_ABS_TOLERANCE', 20);
 define('TOKEN_LEN', 32);
 define('OTP_MAX_LEN', 48); // TOKEN_LEN plus public identity of 0..16
 
-global $ykval_common_log;
-$ykval_common_log = new Log('ykval-common');
-
-function logdie ($str)
+function logdie ($logger, $str)
 {
-  global $ykval_common_log;
-  $ykval_common_log->log(LOG_INFO, $str);
+  $logger->log(LOG_INFO, $str);
   die($str . "\n");
 }
 
diff --git a/ykval-revoke.php b/ykval-revoke.php
index b1496df..53551d3 100644
--- a/ykval-revoke.php
+++ b/ykval-revoke.php
@@ -2,24 +2,28 @@
 require_once 'ykval-common.php';
 require_once 'ykval-config.php';
 require_once 'ykval-db.php';
+require_once 'ykval-log.php';
 
 header("content-type: text/plain");
 
+$myLog = new Log('ykval-revoke');
+$myLog->addField('ip', $_SERVER['REMOTE_ADDR']);
+
 if (!in_array ($_SERVER["REMOTE_ADDR"], $baseParams['__YKREV_IPS__'])) {
-  logdie("ERROR Authorization failed (logged ". $_SERVER["REMOTE_ADDR"] .")");
+  logdie($myLog, "ERROR Authorization failed (logged ". $_SERVER["REMOTE_ADDR"] .")");
 }
 
 # Parse input
 $yk = $_REQUEST["yk"];
 $do = $_REQUEST["do"];
 if (!$yk || !$do) {
-  logdie("ERROR Missing parameter");
+  logdie($myLog, "ERROR Missing parameter");
 }
 if (!preg_match("/^([cbdefghijklnrtuv]{0,16})$/", $yk)) {
-  logdie("ERROR Unknown yk value: $yk");
+  logdie($myLog, "ERROR Unknown yk value: $yk");
 }
 if ($do != "enable" && $do != "disable") {
-  logdie("ERROR Unknown do value: $do");
+  logdie($myLog, "ERROR Unknown do value: $do");
 }
 
 # Connect to db
@@ -29,21 +33,21 @@ $db = new Db($baseParams['__YKVAL_DB_DSN__'],
 	     $baseParams['__YKVAL_DB_OPTIONS__'],
 	     'ykval-revoke:db');
 if (!$db->connect()) {
-  logdie("ERROR Database connect error");
+  logdie($myLog, "ERROR Database connect error");
 }
 
 # Check if key exists
 $r = $db->findBy('yubikeys', 'yk_publicname', $yk, 1);
 if (!$r) {
-  logdie("ERROR Unknown yubikey: $yk");
+  logdie($myLog, "ERROR Unknown yubikey: $yk");
 }
 
 # Enable/Disable the yubikey
 if (!$db->updateBy('yubikeys', 'yk_publicname', $yk,
 		   array('active'=>($do == "enable" ? "1" : "0")))) {
-  logdie("ERROR Could not $do for $yk (rows $rows)");
+  logdie($myLog, "ERROR Could not $do for $yk (rows $rows)");
 }
 
 # We are done
-logdie("OK Processed $yk with $do");
+logdie($myLog, "OK Processed $yk with $do");
 ?>

From 9ac5741e6c6ee369c2213e0fd34a7929180a9523 Mon Sep 17 00:00:00 2001
From: Klas Lindfors <klas@yubico.com>
Date: Thu, 14 Jun 2012 16:44:19 +0200
Subject: [PATCH 22/37] only warn about replays if the delta is more than 1 (or
 less than -1)

---
 ykval-sync.php | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/ykval-sync.php b/ykval-sync.php
index 8a5a6d3..55e1a53 100644
--- a/ykval-sync.php
+++ b/ykval-sync.php
@@ -162,7 +162,9 @@ if ($sync->countersEqual($localParams, $syncParams)) {
   if ($syncParams['modified']!=$localParams['modified'] &&
       $syncParams['nonce']==$localParams['nonce']) {
     $deltaModified = $syncParams['modified'] - $localParams['modified'];
-    $myLog->log(LOG_WARNING, 'We might have a replay. 2 events at different times have generated the same counters. The time difference is ' . $deltaModified . ' seconds');
+    if($deltaModified < -1 || $deltaModified > 1) {
+      $myLog->log(LOG_WARNING, 'We might have a replay. 2 events at different times have generated the same counters. The time difference is ' . $deltaModified . ' seconds');
+    }
   }
 
   if ($syncParams['nonce']!=$localParams['nonce']) {

From 42e13cd43bb4b86b0faefd8fdf71d79fbe38ca33 Mon Sep 17 00:00:00 2001
From: Klas Lindfors <klas@yubico.com>
Date: Fri, 15 Jun 2012 10:15:51 +0200
Subject: [PATCH 23/37] simple munin plugin for response types

---
 ykval-munin-responses.pl | 48 ++++++++++++++++++++++++++++++++++++++++
 1 file changed, 48 insertions(+)
 create mode 100755 ykval-munin-responses.pl

diff --git a/ykval-munin-responses.pl b/ykval-munin-responses.pl
new file mode 100755
index 0000000..dc3f6ce
--- /dev/null
+++ b/ykval-munin-responses.pl
@@ -0,0 +1,48 @@
+#!/usr/bin/perl
+#%# family=auto
+#%# capabilities=autoconf
+
+use strict;
+use warnings;
+
+my @types = qw/OK BAD_OTP MISSING_PARAMETER BACKEND_ERROR BAD_SIGNATURE DELAYED_OTP NO_SUCH_CLIENT NOT_ENOUGH_ANSWERS REPLAYED_REQUEST REPLAYED_OTP OPERATION_NOT_ALLOWED/;
+my $logfile = "/var/log/yubikey-val-server-php.log";
+
+if(@ARGV > 0) {
+  if($ARGV[0] eq "autoconf") {
+    print "yes\n";
+    exit 0;
+  } elsif($ARGV[0] eq "config") {
+    print "multigraph yk_responses\n";
+    print "graph_title YK-VAL response types\n";
+    print "graph_vlabel responses\n";
+    print "graph_category ykval\n";
+
+    foreach my $type (@types) {
+      print "${type}.label ${type}\n";
+      print "${type}.type DERIVE\n";
+      print "${type}.info Responses\n";
+      print "${type}.min 0\n";
+      print "${type}.draw LINE1\n";
+    }
+    exit 0
+  }
+  print "unknown command '${ARGV[0]}'\n";
+  exit 1
+}
+
+my %statuses = map { $_ => 0 } @types;
+
+my $reg = qr/status=([A-Z_]+)/;
+open (LOGFILE, "grep 'ykval-verify.*Response' $logfile |");
+while(<LOGFILE>) {
+  next unless /$reg/;
+  $statuses{$1}++;
+}
+close LOGFILE;
+
+print "multigraph yk_responses\n";
+foreach my $type (@types) {
+  print "${type}.value ${statuses{$type}}\n";
+}
+exit 0

From fff8073ac067545a63d6fad22a9781bb0f24912b Mon Sep 17 00:00:00 2001
From: Klas Lindfors <klas@yubico.com>
Date: Fri, 15 Jun 2012 10:22:26 +0200
Subject: [PATCH 24/37] NEWS for 2.17

---
 NEWS | 15 ++++++++++++++-
 1 file changed, 14 insertions(+), 1 deletion(-)

diff --git a/NEWS b/NEWS
index bbe4390..2030fad 100644
--- a/NEWS
+++ b/NEWS
@@ -1,4 +1,17 @@
-* Version 2.17 unreleased
+* Version 2.17 released 2012-06-15
+
+  * Logging improvements.
+    use ykval-verify/ykval-sync correctly for whole flow
+    clarify/degrade various logging messages
+
+  * Fix mysql error introduced in 2.14, also logs
+    database updated/not updated correctly.
+
+  * Accept sync for disabled keys, but still answer BAD_OTP.
+
+  * Remove from sync queue on BAD_OTP answer.
+
+  * Add munin plugin for response types.
 
 * Version 2.16 released 2012-06-13
 

From accebd2a1a026ff4da223e3272fe0031b056ed73 Mon Sep 17 00:00:00 2001
From: Klas Lindfors <klas@yubico.com>
Date: Fri, 15 Jun 2012 10:24:52 +0200
Subject: [PATCH 25/37] bump versions post-release

---
 Makefile | 2 +-
 NEWS     | 2 ++
 2 files changed, 3 insertions(+), 1 deletion(-)

diff --git a/Makefile b/Makefile
index 70257ee..e564d2f 100644
--- a/Makefile
+++ b/Makefile
@@ -1,4 +1,4 @@
-VERSION = 2.17
+VERSION = 2.18
 PACKAGE = yubikey-val
 CODE = COPYING Makefile NEWS ykval-checksum-clients.php			\
 	ykval-common.php ykval-config.php ykval-db.php ykval-db.sql	\
diff --git a/NEWS b/NEWS
index 2030fad..01b6eb5 100644
--- a/NEWS
+++ b/NEWS
@@ -1,3 +1,5 @@
+* Version 2.18 (unreleased)
+
 * Version 2.17 released 2012-06-15
 
   * Logging improvements.

From ce830612de2d2520fd0aeef4701052a706150269 Mon Sep 17 00:00:00 2001
From: Klas Lindfors <klas@yubico.com>
Date: Fri, 15 Jun 2012 10:31:56 +0200
Subject: [PATCH 26/37] actually install the responses munin check

---
 Makefile | 1 +
 1 file changed, 1 insertion(+)

diff --git a/Makefile b/Makefile
index e564d2f..b7373db 100644
--- a/Makefile
+++ b/Makefile
@@ -42,6 +42,7 @@ install:
 	install -D ykval-munin-ksmlatency.php $(DESTDIR)$(muninprefix)/ykval_ksmlatency
 	install -D ykval-munin-vallatency.php $(DESTDIR)$(muninprefix)/ykval_vallatency
 	install -D ykval-munin-queuelength.php $(DESTDIR)$(muninprefix)/ykval_queuelength
+	install -D ykval-munin-responses.pl $(DESTDIR)$(muninprefix)/ykval_responses
 	install -D --backup --mode 640 --group $(wwwgroup) ykval-config.php $(DESTDIR)$(etcprefix)/ykval-config.php-template
 	install -D --mode 644 ykval-db.sql $(DESTDIR)$(docprefix)/ykval-db.sql
 	install -D --mode 644 $(DOCS) $(DESTDIR)$(docprefix)/

From 3b7927ccb35451851848454ebf9dcccd5b9f773a Mon Sep 17 00:00:00 2001
From: Klas Lindfors <klas@yubico.com>
Date: Fri, 15 Jun 2012 10:39:48 +0200
Subject: [PATCH 27/37] add munin pluin to MUNIN so it's included in tar

---
 Makefile | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/Makefile b/Makefile
index b7373db..c1b1f74 100644
--- a/Makefile
+++ b/Makefile
@@ -7,7 +7,7 @@ CODE = COPYING Makefile NEWS ykval-checksum-clients.php			\
 	ykval-sync.php ykval-verify.php ykval-export-clients.php 	\
 	ykval-import-clients.php
 MUNIN = ykval-munin-ksmlatency.php ykval-munin-vallatency.php	\
-	ykval-munin-queuelength.php
+	ykval-munin-queuelength.php ykval-munin-responses.pl
 DOCS = doc/ClientInfoFormat.wiki doc/Installation.wiki			\
 	doc/RevocationService.wiki doc/ServerReplicationProtocol.wiki	\
 	doc/SyncMonitor.wiki doc/Troubleshooting.wiki

From f72f00c33833d91c4030bb2ef107e37f35e36e18 Mon Sep 17 00:00:00 2001
From: Klas Lindfors <klas@yubico.com>
Date: Fri, 15 Jun 2012 10:46:34 +0200
Subject: [PATCH 28/37] rollback to 2.17

---
 Makefile | 2 +-
 NEWS     | 2 --
 2 files changed, 1 insertion(+), 3 deletions(-)

diff --git a/Makefile b/Makefile
index c1b1f74..5e9b5cf 100644
--- a/Makefile
+++ b/Makefile
@@ -1,4 +1,4 @@
-VERSION = 2.18
+VERSION = 2.17
 PACKAGE = yubikey-val
 CODE = COPYING Makefile NEWS ykval-checksum-clients.php			\
 	ykval-common.php ykval-config.php ykval-db.php ykval-db.sql	\
diff --git a/NEWS b/NEWS
index 01b6eb5..2030fad 100644
--- a/NEWS
+++ b/NEWS
@@ -1,5 +1,3 @@
-* Version 2.18 (unreleased)
-
 * Version 2.17 released 2012-06-15
 
   * Logging improvements.

From 69ec7da1769aa8126cb1b5e052e699287b0ad56b Mon Sep 17 00:00:00 2001
From: Klas Lindfors <klas@yubico.com>
Date: Fri, 15 Jun 2012 10:50:39 +0200
Subject: [PATCH 29/37] bump versions post-release

---
 Makefile | 2 +-
 NEWS     | 2 ++
 2 files changed, 3 insertions(+), 1 deletion(-)

diff --git a/Makefile b/Makefile
index 5e9b5cf..c1b1f74 100644
--- a/Makefile
+++ b/Makefile
@@ -1,4 +1,4 @@
-VERSION = 2.17
+VERSION = 2.18
 PACKAGE = yubikey-val
 CODE = COPYING Makefile NEWS ykval-checksum-clients.php			\
 	ykval-common.php ykval-config.php ykval-db.php ykval-db.sql	\
diff --git a/NEWS b/NEWS
index 2030fad..6ce7053 100644
--- a/NEWS
+++ b/NEWS
@@ -1,3 +1,5 @@
+* Version 2.18 unreleased
+
 * Version 2.17 released 2012-06-15
 
   * Logging improvements.

From 38185be07d587864b7d9d29c7403a748abc66042 Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Fri, 15 Jun 2012 11:59:42 +0200
Subject: [PATCH 30/37] Fix errors with our new logging code :(

---
 ykval-common.php | 10 +++++-----
 ykval-sync.php   |  2 +-
 2 files changed, 6 insertions(+), 6 deletions(-)

diff --git a/ykval-common.php b/ykval-common.php
index fd10d71..88fe162 100644
--- a/ykval-common.php
+++ b/ykval-common.php
@@ -116,7 +116,7 @@ function retrieveURLasync ($ident, $urls, $logger, $ans_req=1, $match="^OK", $re
   $ch = array();
   foreach ($urls as $id => $url) {
     $handle = curl_init();
-    $logger->log($ident . " adding URL : " . $url);
+    $logger->log(LOG_DEBUG, $ident . " adding URL : " . $url);
     curl_setopt($handle, CURLOPT_URL, $url);
     curl_setopt($handle, CURLOPT_USERAGENT, "YK-VAL");
     curl_setopt($handle, CURLOPT_RETURNTRANSFER, 1);
@@ -137,16 +137,16 @@ function retrieveURLasync ($ident, $urls, $logger, $ans_req=1, $match="^OK", $re
       ;
 
     while ($info = curl_multi_info_read($mh)) {
-      $logger->log($ident . " curl multi info : ", $info);
+      $logger->log(LOG_DEBUG, $ident . " curl multi info : ", $info);
       if ($info['result'] == CURLE_OK) {
 	$str = curl_multi_getcontent($info['handle']);
-	$logger->log($ident . " curl multi content : " . $str);
+	$logger->log(LOG_DEBUG, $ident . " curl multi content : " . $str);
 	if (preg_match("/".$match."/", $str)) {
-	  $logger->log($ident . " response matches " . $match);
+	  $logger->log(LOG_DEBUG, $ident . " response matches " . $match);
 	  $error = curl_error ($info['handle']);
 	  $errno = curl_errno ($info['handle']);
 	  $cinfo = curl_getinfo ($info['handle']);
-	  $logger->log($ident . " errno/error: " . $errno . "/" . $error, $cinfo);
+	  $logger->log(LOG_DEBUG, $ident . " errno/error: " . $errno . "/" . $error, $cinfo);
 	  $ans_count++;
 	  if ($returl) $ans_arr[]="url=" . $cinfo['url'] . "\n" . $str;
 	  else $ans_arr[]=$str;
diff --git a/ykval-sync.php b/ykval-sync.php
index c9fe517..20545a7 100644
--- a/ykval-sync.php
+++ b/ykval-sync.php
@@ -169,7 +169,7 @@ if ($localParams['active'] != 1) {
    */
   $myLog->log(LOG_WARNING, 'Received sync-request for de-activated Yubikey ' . $yk_publicname .
 	      ' - check database synchronization!!!');
-  sendResp(S_BAD_OTP, $apiKey);
+  sendResp(S_BAD_OTP, $myLog, $apiKey);
   exit;
 }
 

From dfbe5a0ddf958995e93c8bea5143f53ecb8eec70 Mon Sep 17 00:00:00 2001
From: Klas Lindfors <klas@yubico.com>
Date: Fri, 15 Jun 2012 15:01:52 +0200
Subject: [PATCH 31/37] bump versions post-release

---
 Makefile | 2 +-
 NEWS     | 6 +++++-
 2 files changed, 6 insertions(+), 2 deletions(-)

diff --git a/Makefile b/Makefile
index c1b1f74..1918c7d 100644
--- a/Makefile
+++ b/Makefile
@@ -1,4 +1,4 @@
-VERSION = 2.18
+VERSION = 2.19
 PACKAGE = yubikey-val
 CODE = COPYING Makefile NEWS ykval-checksum-clients.php			\
 	ykval-common.php ykval-config.php ykval-db.php ykval-db.sql	\
diff --git a/NEWS b/NEWS
index 6ce7053..62ab4f8 100644
--- a/NEWS
+++ b/NEWS
@@ -1,4 +1,8 @@
-* Version 2.18 unreleased
+* Version 2.19 unreleased
+
+* Version 2.18 released 2012-06-15
+
+  * Logging misstakes that broke 2.17 fixed.
 
 * Version 2.17 released 2012-06-15
 

From 77b95607107277b98251b5bb8984f0ddd7cb2a49 Mon Sep 17 00:00:00 2001
From: Klas Lindfors <klas@yubico.com>
Date: Fri, 15 Jun 2012 21:52:21 +0200
Subject: [PATCH 32/37] with postgres the bool active is returned as a php bool

that's casted to a string gives 1 when true and empty string when false.. cast to an int to get 1 and 0.
---
 ykval-export-clients.php | 2 +-
 ykval-export.php         | 2 +-
 2 files changed, 2 insertions(+), 2 deletions(-)

diff --git a/ykval-export-clients.php b/ykval-export-clients.php
index cf3b5fb..b985f71 100755
--- a/ykval-export-clients.php
+++ b/ykval-export-clients.php
@@ -24,7 +24,7 @@ if (!$db->connect()) {
 $result = $db->customQuery("select id, active, created, secret, email, notes, otp from clients order by id");
 while($row = $result->fetch(PDO::FETCH_ASSOC)){
   echo $row['id'] .
-    "\t" . $row['active'] .
+    "\t" . (int)$row['active'] .
     "\t" . $row['created'] .
     "\t" . $row['secret'] .
     "\t" . $row['email'] .
diff --git a/ykval-export.php b/ykval-export.php
index 8d25a1d..e22a1a1 100755
--- a/ykval-export.php
+++ b/ykval-export.php
@@ -23,7 +23,7 @@ if (!$db->connect()) {
 
 $result=$db->customQuery("SELECT active, created, modified, yk_publicname, yk_counter, yk_use, yk_low, yk_high, nonce, notes FROM yubikeys ORDER BY yk_publicname");
 while($row = $result->fetch(PDO::FETCH_ASSOC)){
-  echo $row['active'] .
+  echo (int)$row['active'] .
     "\t" . $row['created'] .
     "\t" . $row['modified'] .
     "\t" . $row['yk_publicname'] .

From 54d71100363862b3cd8bfe74faf9eb1ec03f2bc2 Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Mon, 18 Jun 2012 12:42:39 +0200
Subject: [PATCH 33/37] Less verbose logging when verifying remote IP.

---
 ykval-sync.php | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/ykval-sync.php b/ykval-sync.php
index 20545a7..19e8b3e 100644
--- a/ykval-sync.php
+++ b/ykval-sync.php
@@ -30,18 +30,18 @@ if (! $sync->isConnected()) {
 # Verify that request comes from valid server
 #
 
-$myLog->log(LOG_INFO, 'remote request ip is ' . $_SERVER['REMOTE_ADDR']);
+$myLog->log(LOG_INFO, 'Received request from ' . $_SERVER['REMOTE_ADDR']);
 $allowed=False;
-$myLog->log(LOG_DEBUG, 'checking for remote ip in allowed sync pool : ' . implode(", ", $baseParams['__YKVAL_ALLOWED_SYNC_POOL__']));
 foreach ($baseParams['__YKVAL_ALLOWED_SYNC_POOL__'] as $server) {
   if ($_SERVER['REMOTE_ADDR'] == $server) {
-    $myLog->log(LOG_DEBUG, 'server ' . $server . ' is allowed');
     $allowed=True;
     break;
   }
 }
 if (!$allowed) {
   $myLog->log(LOG_NOTICE, 'Operation not allowed from IP ' . $_SERVER['REMOTE_ADDR']);
+  $myLog->log(LOG_DEBUG, 'Remote IP ' . $_SERVER['REMOTE_ADDR'] . ' not listed in allowed sync pool : ' .
+	      implode(', ', $baseParams['__YKVAL_ALLOWED_SYNC_POOL__']));
   sendResp(S_OPERATION_NOT_ALLOWED, $myLog, $apiKey);
   exit;
  }

From 2d193e29e15aa55e6751ca28b58b227775853716 Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Mon, 18 Jun 2012 14:19:00 +0200
Subject: [PATCH 34/37] init

---
 ykval-resync.php | 67 ++++++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 67 insertions(+)
 create mode 100644 ykval-resync.php

diff --git a/ykval-resync.php b/ykval-resync.php
new file mode 100644
index 0000000..edb38de
--- /dev/null
+++ b/ykval-resync.php
@@ -0,0 +1,67 @@
+<?php
+require_once 'ykval-common.php';
+require_once 'ykval-config.php';
+require_once 'ykval-db.php';
+require_once 'ykval-log.php';
+require_once 'ykval-synclib.php';
+
+header("content-type: text/plain");
+
+$myLog = new Log('ykval-resync');
+$myLog->addField('ip', $_SERVER['REMOTE_ADDR']);
+
+if (!in_array ($_SERVER["REMOTE_ADDR"], $baseParams['__YKRESYNC_IPS__'])) {
+  logdie($myLog, "ERROR Authorization failed (logged ". $_SERVER["REMOTE_ADDR"] .")");
+}
+
+# Parse input
+$yk = $_REQUEST["yk"];
+if (!$yk) {
+  logdie($myLog, "ERROR Missing parameter");
+}
+if (!preg_match("/^([cbdefghijklnrtuv]{0,16})$/", $yk)) {
+  logdie($myLog, "ERROR Unknown yk value: $yk");
+}
+$myLog->addField('yk', $yk);
+
+# Connect to db
+$db = new Db($baseParams['__YKVAL_DB_DSN__'],
+	     $baseParams['__YKVAL_DB_USER__'],
+	     $baseParams['__YKVAL_DB_PW__'],
+	     $baseParams['__YKVAL_DB_OPTIONS__'],
+	     'ykval-resync:db');
+if (!$db->connect()) {
+  logdie($myLog, 'ERROR Database connect error (1)');
+}
+
+# Check if key exists
+$r = $db->findBy('yubikeys', 'yk_publicname', $yk, 1);
+if (!$r) {
+  logdie($myLog, "ERROR Unknown yubikey: $yk");
+}
+
+/* Initialize the sync library. */
+$sync = new SyncLib('ykval-resync:synclib');
+$sync->addField('ip', $_SERVER['REMOTE_ADDR']);
+$sync->addField('yk', $yk);
+
+if (! $sync->isConnected()) {
+  logdie($myLog, 'ERROR Database connect error (2)');
+}
+
+$localParams = $sync->getLocalParams($yk);
+if (!$localParams) {
+  logdie($myLog, 'ERROR Invalid Yubikey ' . $yk);
+}
+
+$localParams['otp'] = $yk . str_repeat('c', 32); // Fake an OTP, only used for logging.
+$myLog->log(LOG_DEBUG, "Auth data:", $localParams);
+
+/* Queue sync requests */
+if (!$sync->queue($localParams, $localParams)) {
+  logdie($myLog, 'ERROR Failed resync');
+}
+
+# We are done
+logdie($myLog, "OK Initiated resync of $yk");
+?>

From e51efce07930349a18923c8c2628d6aa921790e1 Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Mon, 18 Jun 2012 14:19:09 +0200
Subject: [PATCH 35/37] init

---
 ykval-munin-yubikeystats.php | 82 ++++++++++++++++++++++++++++++++++++
 1 file changed, 82 insertions(+)
 create mode 100755 ykval-munin-yubikeystats.php

diff --git a/ykval-munin-yubikeystats.php b/ykval-munin-yubikeystats.php
new file mode 100755
index 0000000..368b0a2
--- /dev/null
+++ b/ykval-munin-yubikeystats.php
@@ -0,0 +1,82 @@
+#!/usr/bin/php
+<?php
+
+set_include_path(get_include_path() . PATH_SEPARATOR .
+		 "/etc/ykval:/usr/share/ykval");
+
+require_once 'ykval-config.php';
+require_once 'ykval-db.php';
+
+if ($argc==2 && strcmp($argv[1], "autoconf") == 0) {
+  print "yes\n";
+  exit (0);
+}
+
+if ($argc==2 && strcmp($argv[1], "config") == 0) {
+
+  echo "graph_title YK-VAL YubiKey stats\n";
+  echo "graph_vlabel Known YubiKeys\n";
+  echo "graph_category ykval\n";
+
+  echo "yubikeys_enabled.label Enabled YubiKeys\n";
+  echo "yubikeys_enabled.draw AREA\n";
+
+  echo "yubikeys_disabled.label Disabled YubiKeys\n";
+  echo "yubikeys_disabled.draw STACK\n";
+
+  echo "yubikeys_1month.label YubiKeys seen last month\n";
+  echo "yubikeys_1month.draw LINE2\n";
+
+  echo "clients_enabled.label Enabled validation clients\n";
+  echo "clients_enabled.draw LINE2\n";
+
+  echo "clients_disabled.label Disabled validation clients\n";
+  echo "clients_disabled.draw LINE2\n";
+
+  exit (0);
+}
+
+# Connect to db
+$db = new Db($baseParams['__YKVAL_DB_DSN__'],
+	     $baseParams['__YKVAL_DB_USER__'],
+	     $baseParams['__YKVAL_DB_PW__'],
+	     $baseParams['__YKVAL_DB_OPTIONS__'],
+	     'ykval-munin-yubikeystats:db');
+if (!$db->connect()) {
+  logdie($myLog, 'ERROR Database connect error (1)');
+}
+
+function get_count($db, $table, $conditions) {
+  $res = $db->customQuery('SELECT count(1) FROM ' . $table . ' WHERE ' . $conditions);
+  if ($res) {
+    $r = $res->fetch(PDO::FETCH_ASSOC);
+    return $r['count'];
+  }
+
+  return Null;
+}
+
+if ($count = get_count($db, 'yubikeys', 'active=true')) {
+  echo "yubikeys_enabled.value " . $count . "\n";
+}
+
+if ($count = get_count($db, 'yubikeys', 'active=false')) {
+  echo "yubikeys_disabled.value " . $count . "\n";
+}
+
+if ($count = get_count($db, 'yubikeys', 'modified >= ' . (time() - (31 * 86400)))) {
+  echo "yubikeys_1month.value " . $count . "\n";
+}
+
+if ($count = get_count($db, 'clients', 'active=true')) {
+  echo "clients_enabled.value " . $count . "\n";
+}
+
+if ($count = get_count($db, 'clients', 'active=false')) {
+  echo "clients_disabled.value " . $count . "\n";
+}
+
+
+#%# family=auto
+#%# capabilities=autoconf
+?>

From d4cecdfaf4851cec9decbcbd697c16f629a9a927 Mon Sep 17 00:00:00 2001
From: Fredrik Thulin <fredrik@yubico.com>
Date: Mon, 18 Jun 2012 15:05:23 +0200
Subject: [PATCH 36/37] Add __YKRESYNC_IPS__ to template.

---
 ykval-config.php | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/ykval-config.php b/ykval-config.php
index f092e91..a208a32 100644
--- a/ykval-config.php
+++ b/ykval-config.php
@@ -20,6 +20,9 @@ $baseParams['__YKVAL_ALLOWED_SYNC_POOL__'] = array("1.2.3.4",
 # An array of IP addresses allowed to issue YubiKey activation/deactivation
 # requests through ykval-revoke.php. NOTE: You must use IP addresses here.
 $baseParams['__YKREV_IPS__'] = array("127.0.0.1");
+# An array of IP addresses allowed to issue database resync requests through
+# ykval-resync.php. NOTE: You must use IP addresses here.
+$baseParams['__YKRESYNC_IPS__'] = array("127.0.0.1");
 
 # Specify how often the sync daemon awakens
 $baseParams['__YKVAL_SYNC_INTERVAL__'] = 10;

From c4a6fdfc9da32718777428fa984cd9fb07f84808 Mon Sep 17 00:00:00 2001
From: Klas Lindfors <klas@yubico.com>
Date: Fri, 29 Jun 2012 09:52:39 +0200
Subject: [PATCH 37/37] make sure ykval-munin-yubikeystats.php gets installed

---
 Makefile | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/Makefile b/Makefile
index 1918c7d..4973f92 100644
--- a/Makefile
+++ b/Makefile
@@ -7,7 +7,8 @@ CODE = COPYING Makefile NEWS ykval-checksum-clients.php			\
 	ykval-sync.php ykval-verify.php ykval-export-clients.php 	\
 	ykval-import-clients.php
 MUNIN = ykval-munin-ksmlatency.php ykval-munin-vallatency.php	\
-	ykval-munin-queuelength.php ykval-munin-responses.pl
+	ykval-munin-queuelength.php ykval-munin-responses.pl \
+	ykval-munin-yubikeystats.php
 DOCS = doc/ClientInfoFormat.wiki doc/Installation.wiki			\
 	doc/RevocationService.wiki doc/ServerReplicationProtocol.wiki	\
 	doc/SyncMonitor.wiki doc/Troubleshooting.wiki
@@ -43,6 +44,7 @@ install:
 	install -D ykval-munin-vallatency.php $(DESTDIR)$(muninprefix)/ykval_vallatency
 	install -D ykval-munin-queuelength.php $(DESTDIR)$(muninprefix)/ykval_queuelength
 	install -D ykval-munin-responses.pl $(DESTDIR)$(muninprefix)/ykval_responses
+	install -D ykval-munin-yubikeystats.php $(DESTDIR)$(muninprefix)/ykval_yubikeystats
 	install -D --backup --mode 640 --group $(wwwgroup) ykval-config.php $(DESTDIR)$(etcprefix)/ykval-config.php-template
 	install -D --mode 644 ykval-db.sql $(DESTDIR)$(docprefix)/ykval-db.sql
 	install -D --mode 644 $(DOCS) $(DESTDIR)$(docprefix)/