diff --git a/ykval-common.php b/ykval-common.php index 33174ed..393abcc 100644 --- a/ykval-common.php +++ b/ykval-common.php @@ -246,6 +246,9 @@ function KSMdecryptOTP($urls, $logger, $curlopts) function sendResp($status, $logger, $apiKey = '', $extra = null) { + if ($logger->request !== NULL) + $logger->request->set('status', $status); + $a['status'] = $status; // 2008-11-21T06:11:55Z0711 @@ -273,6 +276,9 @@ function sendResp($status, $logger, $apiKey = '', $extra = null) $logger->log(LOG_INFO, "Response: " . $str . " (at " . gmdate("c") . " " . microtime() . ")"); + if ($logger->request !== NULL) + $logger->request->write(); + echo $str; exit; } diff --git a/ykval-config.php b/ykval-config.php index cf1b365..2a39183 100644 --- a/ykval-config.php +++ b/ykval-config.php @@ -131,3 +131,27 @@ function otp2ksmurls ($otp, $client) "http://127.0.0.1:8002/wsapi/decrypt?otp=$otp", ); } + +/** + * Uncomment to log verify requests just before replying to client. + * + * Available variables: + * %time_start% + * %time_end% + * %time_taken% + * %ip% + * %client% + * %public_id% + * %otp% + * %status% + * %nonce% + * %signed% + * %counter% + * %low% + * %high% + * %use% + * + * If a value is malformed or not available, + * a dash '-' is written instead. + */ +//$baseParams['__YKVAL_VERIFY_LOGFORMAT__'] = '[%time_start%] [%ip%] [%client%] [%public_id%] [%otp%] [%status%] [%time_taken%] [%nonce%] [%signed%] [%counter%] [%low%] [%high%] [%use%]'; diff --git a/ykval-log-verify.php b/ykval-log-verify.php new file mode 100644 index 0000000..cab5b3c --- /dev/null +++ b/ykval-log-verify.php @@ -0,0 +1,185 @@ + NULL, + 'time_end' => NULL, + 'time_taken' => NULL, + 'ip' => NULL, + 'client' => NULL, + 'public_id' => NULL, + 'otp' => NULL, + 'status' => NULL, + 'nonce' => NULL, + 'signed' => NULL, + 'counter' => NULL, + 'low' => NULL, + 'high' => NULL, + 'use' => NULL, + ); + + /** + * Set field value. + * + * @param $name string + * @param $value mixed + * @return bool + */ + public function set($name, $value) + { + // not settable from outside + if ($name === 'time_end' || $name === 'time_taken') + return false; + + if (array_key_exists($name, $this->fields) === FALSE) + return false; + + $this->fields[$name] = $value; + return true; + } + + /** + * Write verify request log line to syslog. + * + * P.S only writes to syslog if __YKVAL_VERIFY_LOGFORMAT__ + * is set correctly in ykval-config.php. + * + * @return bool + */ + public function write() + { + if (($logformat = $this->logformat()) === FALSE) + return false; + + $values = array(); + foreach ($this->sanitized() as $key => $val) + { + $values['%'.$key.'%'] = $val; + } + + $message = strtr($logformat, $values); + + if (!is_string($message)) + return false; + + return syslog(LOG_INFO, $message); + } + + /** + * Fetch the logging format as set in the configuration file. + * + * @return string|bool + */ + private function logformat() + { + require_once 'ykval-config.php'; + + if (!isset($baseParams) + || !is_array($baseParams) + || !array_key_exists('__YKVAL_VERIFY_LOGFORMAT__', $baseParams) + || !is_string($baseParams['__YKVAL_VERIFY_LOGFORMAT__'])) + { + return false; + } + + return $baseParams['__YKVAL_VERIFY_LOGFORMAT__'] + } + + /** + * Sanitize untrusted values from clients before writing them to syslog. + * + * P.S. signed, status, time_start are assumed safe, + * since they are set internally. + * + * @return array sanitized $this->fields + */ + private function sanitized() + { + $a = $this->fields; + + if (preg_match('/^[cbdefghijklnrtuv]+$/', $a['public_id']) !== 1 + || strlen($a['public_id']) < 1 + || strlen($a['public_id']) > (OTP_MAX_LEN - TOKEN_LEN)) + { + $a['public_id'] = '-'; + } + + if (preg_match('/^[cbdefghijklnrtuv]+$/', $a['otp']) !== 1 + || strlen($a['otp']) < TOKEN_LEN + || strlen($a['otp']) > OTP_MAX_LEN)) + { + $a['otp'] = '-'; + } + + if (preg_match('/^[0-9]+$/', $a['client']) !== 1) + $a['client'] = '-'; + + if (filter_var($a['ip'], FILTER_VALIDATE_IP) === FALSE) + $a['ip'] = '-'; + + if (is_int($a['counter']) === FALSE) + $a['counter'] = '-'; + + if (is_int($a['low']) === FALSE) + $a['low'] = '-'; + + if (is_int($a['high']) === FALSE) + $a['high'] = '-'; + + if (is_int($a['use']) === FALSE) + $a['use'] = '-'; + + if (preg_match('/^[a-zA-Z0-9]{16,40}$/', $a['nonce']) !== 1) + $a['nonce'] = '-'; + + $start = explode(' ', $a['time_start']); + $start_msec = $start[0]; + $start_sec = $start[1]; + $start = bcadd($start_sec, $start_msec, 8); + unset($start_sec, $start_msec); + + $end = explode(' ', microtime()); + $end_msec = $end[0]; + $end_sec = $end[1]; + $end = bcadd($end_sec, $end_msec, 8); + unset($end_sec, $end_msec); + + $taken = bcsub($end, $start, 8); + + $a['time_start'] = $start; + $a['time_end'] = $end; + $a['time_taken'] = $taken; + + return $a; + } +} diff --git a/ykval-log.php b/ykval-log.php index 52366f5..20502f3 100644 --- a/ykval-log.php +++ b/ykval-log.php @@ -29,6 +29,9 @@ class Log { + // request logger object + public $request = NULL; + private $log_levels = array( LOG_EMERG => 'LOG_EMERG', LOG_ALERT => 'LOG_ALERT', diff --git a/ykval-verify.php b/ykval-verify.php index 0956197..2fc5bba 100644 --- a/ykval-verify.php +++ b/ykval-verify.php @@ -27,9 +27,12 @@ # (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE # OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. +$time_start = microtime(); + require_once 'ykval-common.php'; require_once 'ykval-config.php'; require_once 'ykval-synclib.php'; +require_once 'ykval-log-verify.php'; header('content-type: text/plain'); @@ -52,6 +55,12 @@ $https = (array_key_exists('HTTPS', $_SERVER) === TRUE $myLog = new Log('ykval-verify'); $myLog->addField('ip', $ipaddr); +$myLog->request = new LogVerify(); +$myLog->request->set('ip', $ipaddr); +$myLog->request->set('time_start', $time_start); +unset($time_start); + + // FIXME $message = ''; if ($_POST) @@ -101,6 +110,10 @@ if (preg_match('/^[jxe.uidchtnbpygk]+$/', $otp)) unset($new_otp); } +$myLog->request->set('signed', ($h === '' ? '-' : 'signed')); +$myLog->request->set('client', ($client === 0 ? NULL : $client)); +$myLog->request->set('otp', $otp); + /** * Construct response parameters @@ -123,6 +136,7 @@ if ($protocol_version >= 2.0) $sl = getHttpVal('sl', ''); $timeout = getHttpVal('timeout', ''); $nonce = getHttpVal('nonce', ''); + $myLog->request->set('nonce', $nonce); /* Nonce is required from protocol 2.0 */ if (!$nonce) @@ -312,10 +326,15 @@ if (($otpinfo = KSMdecryptOTP($urls, $myLog, $curlopts)) === FALSE) */ sendResp(S_BAD_OTP, $myLog, $apiKey); } +$myLog->request->set('counter', $otpinfo['session_counter']); +$myLog->request->set('use', $otpinfo['session_use']); +$myLog->request->set('high', $otpinfo['high']); +$myLog->request->set('low', $otpinfo['low']); $myLog->log(LOG_DEBUG, 'Decrypted OTP:', $otpinfo); // get Yubikey from DB $yk_publicname = substr($otp, 0, strlen ($otp) - TOKEN_LEN); +$myLog->request->set('public_id', $yk_publicname); if (($localParams = $sync->getLocalParams($yk_publicname)) === FALSE) { $myLog->log(LOG_NOTICE, "Invalid Yubikey $yk_publicname");