search

Yubico / yubikey-val

YubiKey OTP validation server in PHP
https://developers.yubico.com/yubikey-val
BSD 2-Clause "Simplified" License
130 stars 43 forks source link

Correct way to use two validation servers? #31

Open camAtGitHub opened 9 years ago

camAtGitHub commented 9 years ago

I am configuring a total of two validation servers - my concern is: In the default configuration you need to specify both the localhost and peer validation server in "YKVAL_SYNC_POOL" and set "$baseParams['YKVAL_SYNC_DEFAULT_LEVEL'] = 50" for validation to work when one node has failed. This I can accept.

My concern is that reviewing the log file, the validation server doesn't expect this to happen and reports that the "Sync request unnecessarily sent" and "Local server out of sync" and updates the database 3 times for the one request.

What is the correct way to configure the validation / sync service with only two nodes and allowing for it to work if one node is in-accessible?

Thanks Cam

Log file below: (keys and values are not sensitive)

May 28 13:04:53 yubikey1 ykval[14616]: LOG_INFO:ykval-verify:[127.0.0.1] Request: id=1&nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe&otp=tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic (at 2015-05-28T13:04:53+10:00 0.04450200 1432782293) HTTP May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:[127.0.0.1] found protocol version 2 May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] DB query is: SELECT id, secret FROM clients WHERE active='1' AND id='1' May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] Client data: id=1 secret=debbcd4b169e2b6020d4aa95c9f3cbf3efc84922 May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] YK-KSM adding URL : http://127.0.0.1/wsapi/decrypt?otp=tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic May 28 13:04:53 yubikey1 ykksm[14611]: SUCCESS OTP tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic PT 4fb80b61665c0500180c8c1d4e89354c OK counter=0005 low=0c18 high=8c use=1d 127.0.0.1 - - [28/May/2015:13:04:53 +1000] "GET /wsapi/decrypt?otp=tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic HTTP/1.1" 200 40 May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] YK-KSM curl multi info : msg=1 result=0 handle=Resource id #9 May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] YK-KSM curl multi content : OK counter=0005 low=0c18 high=8c use=1d May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] YK-KSM response matches ^OK May 28 13:04:53 yubikey1 ykval[14616]: LOG_INFO:ykval-verify:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] YK-KSM errno/error: 0/ url=http://127.0.0.1/wsapi/decrypt?otp=tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic content_type=text/html; charset=UTF-8 http_code=200 header_size=192 request_size=130 filetime=-1 ssl_verify_result=0 redirect_count=0 total_time=0.005587 namelookup_time=5.2E-5 connect_time=9.4E-5 pretransfer_time=0.000115 size_upload=0 size_download=40 speed_download=7159 speed_upload=0 download_content_length=40 upload_content_length=0 starttransfer_time=0.00557 redirect_time=0 certinfo= May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] YK-KSM response: OK counter=0005 low=0c18 high=8c use=1d#012 May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] Decrypted OTP: session_counter=5 low=3096 high=140 session_use=29 May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:synclib:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] searching for yk_publicname tfdurdtkubbl in local db May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] DB query is: SELECT * FROM yubikeys WHERE yk_publicname = 'tfdurdtkubbl' LIMIT 1 May 28 13:04:53 yubikey1 ykval[14616]: LOG_INFO:ykval-verify:synclib:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] yubikey found in db modified=1432782181 nonce=jsmeyghkwotzkmvjpnwnbwuxycacouxy yk_publicname=tfdurdtkubbl yk_counter=5 yk_use=28 yk_high=140 yk_low=2210 May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] Auth data: modified=1432782181 nonce=jsmeyghkwotzkmvjpnwnbwuxycacouxy active=1 yk_publicname=tfdurdtkubbl yk_counter=5 yk_use=28 yk_high=140 yk_low=2210 May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] DB query is: UPDATE yubikeys SET modified='1432782293', yk_counter='5', yk_use='29', yk_low='3096', yk_high='140', nonce='kgmsczgodsqyjhiblgndnhwbwhlbscxe' WHERE yk_publicname = 'tfdurdtkubbl' and (5>yk_counter or (5=yk_counter and 29>yk_use)) May 28 13:04:53 yubikey1 ykval[14616]: LOG_INFO:ykval-verify:synclib:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] updated database modified=1432782293 nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe yk_publicname=tfdurdtkubbl yk_counter=5 yk_use=29 yk_high=140 yk_low=3096 May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] DB query is: INSERT INTO queue (queued,modified,otp,server,server_nonce,info) VALUES ('1432782293','1432782293','tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic','http://127.0.0.1/wsapi/2.0/sync','f2b2ccb565fa6e38a25b86d20b8cbde5','yk_publicname=tfdurdtkubbl&yk_counter=5&yk_use=29&yk_high=140&yk_low=3096&nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe,local_counter=5&local_use=28') May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] DB query is: INSERT INTO queue (queued,modified,otp,server,server_nonce,info) VALUES ('1432782293','1432782293','tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic','http://10.10.0.179/wsapi/2.0/sync','f2b2ccb565fa6e38a25b86d20b8cbde5','yk_publicname=tfdurdtkubbl&yk_counter=5&yk_use=29&yk_high=140&yk_low=3096&nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe,local_counter=5&local_use=28') May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] DB query is: SELECT * FROM queue WHERE modified = '1432782293' and server_nonce = 'f2b2ccb565fa6e38a25b86d20b8cbde5' May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:synclib:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] YK-VAL sync adding URL : http://127.0.0.1/wsapi/2.0/sync?otp=tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic&modified=1432782293&yk_publicname=tfdurdtkubbl&yk_counter=5&yk_use=29&yk_high=140&yk_low=3096&nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:synclib:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] YK-VAL sync adding URL : http://10.10.0.179/wsapi/2.0/sync?otp=tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic&modified=1432782293&yk_publicname=tfdurdtkubbl&yk_counter=5&yk_use=29&yk_high=140&yk_low=3096&nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe May 28 13:04:53 yubikey1 ykval[14614]: LOG_INFO:ykval-sync:[127.0.0.1] Request: otp=tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic&modified=1432782293&yk_publicname=tfdurdtkubbl&yk_counter=5&yk_use=29&yk_high=140&yk_low=3096&nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe May 28 13:04:53 yubikey1 ykval[14614]: LOG_DEBUG:ykval-sync:[127.0.0.1] Received request from 127.0.0.1 May 28 13:04:53 yubikey1 ykval[14614]: LOG_INFO:ykval-sync:[127.0.0.1] Received modified=1432782293 otp=tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe yk_publicname=tfdurdtkubbl yk_counter=5 yk_use=29 yk_high=140 yk_low=3096 May 28 13:04:53 yubikey1 ykval[14614]: LOG_DEBUG:ykval-sync:synclib:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] searching for yk_publicname tfdurdtkubbl in local db May 28 13:04:53 yubikey1 ykval[14614]: LOG_DEBUG:ykval-sync:synclib:db:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] DB query is: SELECT * FROM yubikeys WHERE yk_publicname = 'tfdurdtkubbl' LIMIT 1 May 28 13:04:53 yubikey1 ykval[14614]: LOG_INFO:ykval-sync:synclib:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] yubikey found in db modified=1432782293 nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe yk_publicname=tfdurdtkubbl yk_counter=5 yk_use=29 yk_high=140 yk_low=3096 May 28 13:04:53 yubikey1 ykval[14614]: LOG_DEBUG:ykval-sync:synclib:db:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] DB query is: UPDATE yubikeys SET modified='1432782293', yk_counter='5', yk_use='29', yk_low='3096', yk_high='140', nonce='kgmsczgodsqyjhiblgndnhwbwhlbscxe' WHERE yk_publicname = 'tfdurdtkubbl' and (5>yk_counter or (5=yk_counter and 29>yk_use)) template - - [28/May/2015:13:04:53 +1000] "GET /wsapi/2.0/sync?otp=tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic&modified=1432782293&yk_publicname=tfdurdtkubbl&yk_counter=5&yk_use=29&yk_high=140&yk_low=3096&nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe HTTP/1.1" 200 213 May 28 13:04:53 yubikey1 ykval[14614]: LOG_INFO:ykval-sync:synclib:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] database not updated modified=1432782293 nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe yk_publicname=tfdurdtkubbl yk_counter=5 yk_use=29 yk_high=140 yk_low=3096 May 28 13:04:53 yubikey1 ykval[14614]: LOG_DEBUG:ykval-sync:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] Local params modified=1432782293 nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe active=1 yk_publicname=tfdurdtkubbl yk_counter=5 yk_use=29 yk_high=140 yk_low=3096 May 28 13:04:53 yubikey1 ykval[14614]: LOG_DEBUG:ykval-sync:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] Sync request params modified=1432782293 otp=tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe yk_publicname=tfdurdtkubbl yk_counter=5 yk_use=29 yk_high=140 yk_low=3096 May 28 13:04:53 yubikey1 ykval[14614]: LOG_INFO:ykval-sync:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] Sync request unnecessarily sent May 28 13:04:53 yubikey1 ykval[14614]: LOG_DEBUG:ykval-sync:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] SIGN: modified=1432782293&nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe&status=OK&t=2015-05-28T03:04:53Z0075&yk_counter=5&yk_high=140&yk_low=3096&yk_publicname=tfdurdtkubbl&yk_use=29 H=RGoPlaXx5KmNsWF4uz8X0keCs8Y= May 28 13:04:53 yubikey1 ykval[14614]: LOG_INFO:ykval-sync:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] Response: h=RGoPlaXx5KmNsWF4uz8X0keCs8Y=#015#012t=2015-05-28T03:04:53Z0075#015#012modified=1432782293#015#012nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe#015#012yk_publicname=tfdurdtkubbl#015#012yk_counter=5#015#012yk_use=29#015#012yk_high=140#015#012yk_low=3096#015#012status=OK#015#012#015#012 (at 2015-05-28T03:04:53+00:00 0.07547100 1432782293) May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:synclib:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] YK-VAL sync curl multi info : msg=1 result=0 handle=Resource id #11 May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:synclib:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] YK-VAL sync curl multi content : h=RGoPlaXx5KmNsWF4uz8X0keCs8Y=#015#012t=2015-05-28T03:04:53Z0075#015#012modified=1432782293#015#012nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe#015#012yk_publicname=tfdurdtkubbl#015#012yk_counter=5#015#012yk_use=29#015#012yk_high=140#015#012yk_low=3096#015#012status=OK#015#012#015 May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:synclib:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] YK-VAL sync response matches status=OK May 28 13:04:53 yubikey1 ykval[14616]: LOG_INFO:ykval-verify:synclib:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] YK-VAL sync errno/error: 0/ url=http://127.0.0.1/wsapi/2.0/sync?otp=tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic&modified=1432782293&yk_publicname=tfdurdtkubbl&yk_counter=5&yk_use=29&yk_high=140&yk_low=3096&nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe content_type=text/plain; charset=UTF-8 http_code=200 header_size=194 request_size=264 filetime=-1 ssl_verify_result=0 redirect_count=0 total_time=0.020582 namelookup_time=4.9E-5 connect_time=9.9E-5 pretransfer_time=0.000204 size_upload=0 size_download=213 speed_download=10348 speed_upload=0 download_content_length=213 upload_content_length=0 starttransfer_time=0.020565 redirect_time=0 certinfo= May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:synclib:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] local db contains modified=1432782181 nonce=jsmeyghkwotzkmvjpnwnbwuxycacouxy yk_publicname=tfdurdtkubbl yk_counter=5 yk_use=28 yk_high=140 yk_low=2210 May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:synclib:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] response contains modified=1432782293 nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe yk_publicname=tfdurdtkubbl yk_counter=5 yk_use=29 yk_high=140 yk_low=3096 May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:synclib:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] OTP contains modified=1432782293 nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe yk_publicname=tfdurdtkubbl yk_counter=5 yk_use=29 yk_high=140 yk_low=3096 May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] DB query is: UPDATE yubikeys SET modified='1432782293', yk_counter='5', yk_use='29', yk_low='3096', yk_high='140', nonce='kgmsczgodsqyjhiblgndnhwbwhlbscxe' WHERE yk_publicname = 'tfdurdtkubbl' and (5>yk_counter or (5=yk_counter and 29>yk_use)) May 28 13:04:53 yubikey1 ykval[14616]: LOG_INFO:ykval-verify:synclib:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] database not updated modified=1432782293 nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe yk_publicname=tfdurdtkubbl yk_counter=5 yk_use=29 yk_high=140 yk_low=3096 May 28 13:04:53 yubikey1 ykval[14616]: LOG_NOTICE:ykval-verify:synclib:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] Local server out of sync May 28 13:04:53 yubikey1 ykval[14616]: LOG_INFO:ykval-verify:synclib:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] deleting server=http://127.0.0.1/wsapi/2.0/sync modified=1432782293 server_nonce=f2b2ccb565fa6e38a25b86d20b8cbde5 May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] DB query is: DELETE FROM queue WHERE modified = '1432782293' and server_nonce = 'f2b2ccb565fa6e38a25b86d20b8cbde5' and server = 'http://127.0.0.1/wsapi/2.0/sync' May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] DB query is: UPDATE queue SET queued=NULL WHERE server_nonce = 'f2b2ccb565fa6e38a25b86d20b8cbde5' May 28 13:04:53 yubikey1 ykval[14616]: LOG_INFO:ykval-verify:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] ykval-verify:notice:synclevel=50 nr servers=2 req answers=1 answers=1 valid answers=1 sl success rate=50 timeout=1 May 28 13:04:53 yubikey1 ykval[14616]: LOG_INFO:ykval-verify:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] Timestamp seen=9177250 this=9178136 delta=886 secs=110.75 accessed=1432782181 (2015-05-28 13:03:01) now=1432782293 (2015-05-28 13:04:53) elapsed=112 deviation=1.25 secs or 1% May 28 13:04:53 yubikey1 ykval[14616]: LOG_DEBUG:ykval-verify:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] SIGN: nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe&otp=tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic&sl=50&status=OK&t=2015-05-28T03:04:53Z0078 H=uLDbqjGsMMOT7hzyORLbO+cRUAg= May 28 13:04:53 yubikey1 ykval[14616]: LOG_INFO:ykval-verify:[127.0.0.1] [tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic] Response: h=uLDbqjGsMMOT7hzyORLbO+cRUAg=#015#012t=2015-05-28T03:04:53Z0078#015#012otp=tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic#015#012nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe#015#012sl=50#015#012status=OK#015#012#015#012 (at 2015-05-28T03:04:53+00:00 0.07902000 1432782293) template - - [28/May/2015:13:04:53 +1000] "GET /wsapi/2.0/verify?id=1&nonce=kgmsczgodsqyjhiblgndnhwbwhlbscxe&otp=tfdurdtkubblrggheiedjndlcefheljvetjbgleudvic HTTP/1.1" 200 170

klali commented 9 years ago

Hello,

Typically we suggest to use at least 3 validation servers if you want to enforce any level of sync while one is down. The percentage is calulcated over the number of servers you're going to sync with, so if you have two servers that sync with each other any number other than 0 will mean that sync is always enforced. This is because it's a minimum percentage of accepted sync.

As you've seen the sync traffic adds quite a bit of overhead, that is often not needed since a typical client will also have contacted all validation servers with the OTP.

/klas