diff --git a/Makefile b/Makefile index eb7cd62..11ed166 100644 --- a/Makefile +++ b/Makefile @@ -1,4 +1,4 @@ -VERSION = 2.17 +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 \ @@ -8,7 +8,8 @@ CODE = COPYING Makefile NEWS ykval-checksum-clients.php \ ykval-import-clients.php ykval-db-oci.php ykval-db-pdo.php \ ykval-db.oracle.sql MUNIN = ykval-munin-ksmlatency.php ykval-munin-vallatency.php \ - ykval-munin-queuelength.php + 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 @@ -45,6 +46,8 @@ 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 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 ykval-db.oracle.sql $(DESTDIR)$(docprefix)/ykval-db.oracle.sql diff --git a/NEWS b/NEWS index bbe4390..62ab4f8 100644 --- a/NEWS +++ b/NEWS @@ -1,4 +1,23 @@ -* Version 2.17 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 + + * 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 diff --git a/ykval-common.php b/ykval-common.php index 50bb2e0..88fe162 100644 --- a/ykval-common.php +++ b/ykval-common.php @@ -1,7 +1,5 @@ log(LOG_INFO, $str); + $logger->log(LOG_INFO, $str); die($str . "\n"); } @@ -47,7 +41,7 @@ function getHttpVal($key, $defaultVal) { return $v; } -function debug() { +function log_format() { $str = ""; foreach (func_get_args() as $msg) { @@ -59,8 +53,7 @@ function debug() { $str .= $msg . " "; } } - global $ykval_common_log; - $ykval_common_log->log(LOG_DEBUG, $str); + return $str; } // Return eg. 2008-11-21T06:11:55Z0711 @@ -86,7 +79,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)); @@ -94,7 +87,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; @@ -117,18 +110,18 @@ 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 ($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("url is: " . $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); curl_setopt($handle, CURLOPT_FAILONERROR, true); - curl_setopt($handle, CURLOPT_TIMEOUT, 10); + curl_setopt($handle, CURLOPT_TIMEOUT, $timeout); curl_multi_add_handle($mh, $handle); @@ -144,17 +137,17 @@ function retrieveURLasync ($urls, $ans_req=1, $match="^OK", $returl=False) { ; while ($info = curl_multi_info_read($mh)) { - debug ("YK-KSM multi", $info); + $logger->log(LOG_DEBUG, $ident . " curl multi info : ", $info); if ($info['result'] == CURLE_OK) { $str = curl_multi_getcontent($info['handle']); - debug($str); + $logger->log(LOG_DEBUG, $ident . " curl multi content : " . $str); if (preg_match("/".$match."/", $str)) { + $logger->log(LOG_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); + $logger->log(LOG_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; } @@ -166,8 +159,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']); @@ -185,6 +177,7 @@ function retrieveURLasync ($urls, $ans_req=1, $match="^OK", $returl=False) { } curl_multi_close ($mh); + if ($ans_count>0) return $ans_arr; return $str; } @@ -198,17 +191,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 ($urls); + $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", @@ -219,7 +215,7 @@ function KSMdecryptOTP($urls) { return $ret; } // End decryptOTP -function sendResp($status, $apiKey = '', $extra = null) { +function sendResp($status, $logger, $apiKey = '', $extra = null) { if ($status == null) { $status = S_BACKEND_ERROR; } @@ -229,7 +225,7 @@ function sendResp($status, $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"; @@ -241,9 +237,8 @@ function sendResp($status, $apiKey = '', $extra = null) { $str .= "status=" . ($a['status']) . "\r\n"; $str .= "\r\n"; - global $ykval_common_log; - $ykval_common_log->log(LOG_INFO, "Response: " . $str . - " (at " . date("c") . " " . microtime() . ")"); + $logger->log(LOG_INFO, "Response: " . $str . + " (at " . date("c") . " " . microtime() . ")"); echo $str; } diff --git a/ykval-config.php b/ykval-config.php index 28c8f82..18823ea 100644 --- a/ykval-config.php +++ b/ykval-config.php @@ -17,6 +17,13 @@ $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"); +# 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; # Specify how long the sync daemon will wait for response diff --git a/ykval-export-clients.php b/ykval-export-clients.php index 6c599ba..b5baed5 100755 --- a/ykval-export-clients.php +++ b/ykval-export-clients.php @@ -20,7 +20,7 @@ if (!$db->connect()) { $result = $db->customQuery("select id, active, created, secret, email, notes, otp from clients order by id"); while($row = $db->fetchArray($result)) { 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 a4c0c84..125ec5b 100755 --- a/ykval-export.php +++ b/ykval-export.php @@ -19,7 +19,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 = $db->fetchArray($result)){ - echo $row['active'] . + echo (int)$row['active'] . "\t" . $row['created'] . "\t" . $row['modified'] . "\t" . $row['yk_publicname'] . 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() { + next unless /$reg/; + $statuses{$1}++; +} +close LOGFILE; + +print "multigraph yk_responses\n"; +foreach my $type (@types) { + print "${type}.value ${statuses{$type}}\n"; +} +exit 0 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 +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 +?> 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 @@ +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"); +?> diff --git a/ykval-revoke.php b/ykval-revoke.php index f88679d..fd3e334 100644 --- a/ykval-revoke.php +++ b/ykval-revoke.php @@ -2,44 +2,48 @@ 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 $db = Db::GetDatabaseHandle($baseParams, 'ykval-revoke'); 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"); ?> diff --git a/ykval-sync.php b/ykval-sync.php index 12c81af..19e8b3e 100644 --- a/ykval-sync.php +++ b/ykval-sync.php @@ -7,21 +7,22 @@ $apiKey = ''; header("content-type: text/plain"); -if(empty($_SERVER['QUERY_STRING'])) { - sendResp(S_MISSING_PARAMETER, $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, $apiKey); + sendResp(S_BACKEND_ERROR, $myLog, $apiKey); exit; } @@ -29,19 +30,19 @@ 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']); - sendResp(S_OPERATION_NOT_ALLOWED, $apiKey); + $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; } @@ -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, $myLog, $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, $myLog, $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, $myLog, $apiKey); exit; } } @@ -112,17 +113,10 @@ $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, $myLog, $apiKey); exit; } -if ($localParams['active'] != 1) { - $myLog->log(LOG_NOTICE, 'De-activated Yubikey ' . $yk_publicname); - sendResp(S_BAD_OTP, $apiKey); - exit; - } - - /* Conditional update local database */ $sync->updateDbCounters($syncParams); @@ -146,13 +140,22 @@ 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'] && $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']) { @@ -160,7 +163,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, $myLog, $apiKey); + exit; +} $extra=array('modified'=>$localParams['modified'], 'nonce'=>$localParams['nonce'], @@ -170,6 +181,6 @@ $extra=array('modified'=>$localParams['modified'], 'yk_high'=>$localParams['yk_high'], 'yk_low'=>$localParams['yk_low']); -sendResp(S_OK, '', $extra); +sendResp(S_OK, $myLog, $apiKey, $extra); ?> diff --git a/ykval-synclib.php b/ykval-synclib.php index e895e13..b62ec04 100644 --- a/ykval-synclib.php +++ b/ykval-synclib.php @@ -286,13 +286,13 @@ class SyncLib $queued_limit=time()-$older_than; $server_res=$this->db->customQuery("select distinct server from queue WHERE queued < " . $queued_limit . " or queued is null"); - while ($my_server=$this->db->fetchArray($server_res)) { - $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=$this->db->fetchArray($res)) { - $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'] . @@ -322,8 +322,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); @@ -336,7 +340,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)) { @@ -360,9 +368,15 @@ class SyncLib ' server_nonce=' . $entry['server_nonce'] . ' server=' . $entry['server']); $this->db->deleteByMultiple('queue', - array("modified"=>$entry['modified'], - "server_nonce"=>$entry['server_nonce'], - 'server'=>$entry['server'])); + 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."); } @@ -393,7 +407,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'); @@ -497,84 +511,9 @@ class SyncLib else return 0; } - - /* - 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 ($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; + function retrieveURLasync_wrap ($urls, $ans_req=1, $timeout=1.0) + { + 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 085427f..61f66b9 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 */ @@ -56,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); + sendResp(S_MISSING_PARAMETER, $myLog); exit; } } @@ -90,49 +90,49 @@ if (!isset($timeout) || $timeout == '') { if ($otp == '') { $myLog->log(LOG_NOTICE, 'OTP is missing'); - sendResp(S_MISSING_PARAMETER); + 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); + sendResp(S_BAD_OTP, $myLog); exit; } if (preg_match("/^[cbdefghijklnrtuv]+$/", $otp)==0) { $myLog->log(LOG_NOTICE, 'Invalid OTP: ' . $otp); - sendResp(S_BAD_OTP); + 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); + 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); + 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); + 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); + 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); + sendResp(S_MISSING_PARAMETER, $myLog); exit; } @@ -143,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); + sendResp(S_MISSING_PARAMETER, $myLog); exit; } @@ -156,14 +156,14 @@ $sync->addField('ip', $_SERVER['REMOTE_ADDR']); $sync->addField('otp', $otp); if (! $sync->isConnected()) { - sendResp(S_BACKEND_ERROR); + 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); + sendResp(S_NO_SUCH_CLIENT, $myLog); exit; } $myLog->log(LOG_DEBUG,"Client data:", $cd); @@ -185,11 +185,11 @@ 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); - sendResp(S_BAD_SIGNATURE, $apiKey); + sendResp(S_BAD_SIGNATURE, $myLog, $apiKey); exit; } } @@ -206,15 +206,15 @@ if ($protocol_version<2.0) { // $urls = otp2ksmurls ($otp, $client); if (!is_array($urls)) { - sendResp(S_BACKEND_ERROR, $apiKey); + sendResp(S_BACKEND_ERROR, $myLog, $apiKey); exit; } //// Decode OTP from input // -$otpinfo = KSMdecryptOTP($urls); +$otpinfo = KSMdecryptOTP($urls, $myLog); if (!is_array($otpinfo)) { - sendResp(S_BAD_OTP, $apiKey); + sendResp(S_BAD_OTP, $myLog, $apiKey); exit; } $myLog->log(LOG_DEBUG, "Decrypted OTP:", $otpinfo); @@ -226,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, $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, $apiKey); + sendResp(S_BAD_OTP, $myLog, $apiKey); exit; } @@ -253,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, $apiKey, $extra); + sendResp(S_REPLAYED_REQUEST, $myLog, $apiKey, $extra); exit; } @@ -262,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, $apiKey, $extra); + sendResp(S_REPLAYED_OTP, $myLog, $apiKey, $extra); exit; } @@ -270,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, $apiKey); + sendResp(S_BACKEND_ERROR, $myLog, $apiKey); exit; } @@ -278,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, $apiKey); + sendResp(S_BACKEND_ERROR, $myLog, $apiKey); exit; } @@ -310,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, $apiKey, $extra); + sendResp(S_REPLAYED_OTP, $myLog, $apiKey, $extra); exit; } else { $extra['sl']=$sl_success_rate; - sendResp(S_NOT_ENOUGH_ANSWERS, $apiKey, $extra); + sendResp(S_NOT_ENOUGH_ANSWERS, $myLog, $apiKey, $extra); exit; } } @@ -362,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, $apiKey, $extra); + sendResp(S_DELAYED_OTP, $myLog, $apiKey, $extra); exit; } } @@ -378,6 +378,6 @@ if ($timestamp==1){ $extra['sessionuse'] = $sessionUse; } -sendResp(S_OK, $apiKey, $extra); +sendResp(S_OK, $myLog, $apiKey, $extra); ?>