We've got two YubiRadius VirtualAppliances which are in sync.
But when i shutdown one of the two YRVA, authentification fails on the running still running YRVA.
The IP adresses of the YRVA are:
172.30.66.72 yubico01.iam.ia
172.30.66.73 yubico02.iam.ia
I've added some logging of the working and not working situation:
Working situation (2 active in sync YRVA):
Code:
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_INFO:ykval-verify:[127.0.0.1] Request: id=1&nonce=dbd034d222b3837618a4c46f2726aaa2&otp=--- MY YUBIKEY OTP ---&h=f9QhPNglNI45%2BC6zzkblZA38%2BXE= (at 2012-08-
09T10:54:39+02:00 0.70370900 1344502479) HTTP
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [--- MY YUBIKEY OTP ---] DB query is: SELECT id, secret FROM clients WHERE active AND id='1'
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_DEBUG:ykval-verify:[127.0.0.1] [--- MY YUBIKEY OTP ---] Client data: id=1 secret=s1lgixvlvNAtrqJeYH4VPLkJxT0=
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_DEBUG:ykval-common:SIGN: id=1&nonce=dbd034d222b3837618a4c46f2726aaa2&otp=--- MY YUBIKEY OTP --- H=f9QhPNglNI45+C6zzkblZA38+XE=
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_DEBUG:ykval-verify:[127.0.0.1] [--- MY YUBIKEY OTP ---] Decrypted OTP: session_counter=10 low=53616 high=114 session_use=5
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_INFO:ykval-verify:synclib:[127.0.0.1] [--- MY YUBIKEY OTP ---] searching for yk_publicname --- MY YUBIKEY --- in local db
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [--- MY YUBIKEY OTP ---] DB query is: SELECT * FROM yubikeys WHERE yk_publicname = '--- MY YUBIKEY ---' LIMIT 1
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_INFO:ykval-verify:synclib:[127.0.0.1] [--- MY YUBIKEY OTP ---] yubikey found in db modified=1344502391 nonce=6e9d071896eea37f8f7516954613aa3e yk_publicname=--- MY YUBIKEY
--- yk_counter=10 yk_use=4 yk_high=114 yk_low=52911
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_DEBUG:ykval-verify:[127.0.0.1] [--- MY YUBIKEY OTP ---] Auth data: modified=1344502391 nonce=6e9d071896eea37f8f7516954613aa3e active=1 yk_publicname=--- MY YUBIKEY ---
yk_counter=10 yk_use=4 yk_high=114 yk_low=52911
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [--- MY YUBIKEY OTP ---] DB query is: UPDATE yubikeys SET modified='1344502479', yk_counter='10', yk_use='5', yk_low='53616',
yk_high='114', nonce='dbd034d222b3837618a4c46f2726aaa2' WHERE yk_publicname = '--- MY YUBIKEY ---' and (10>yk_counter or (10=yk_counter and 5>yk_use))
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_INFO:ykval-verify:synclib:[127.0.0.1] [--- MY YUBIKEY OTP ---] updated database modified=1344502479 nonce=dbd034d222b3837618a4c46f2726aaa2 yk_publicname=--- MY YUBIKEY ---
yk_counter=10 yk_use=5 yk_high=114 yk_low=53616
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [--- MY YUBIKEY OTP ---] DB query is: INSERT INTO queue (queued,modified,otp,server,server_nonce,info) VALUES
('1344502479','1344502479','--- MY YUBIKEY OTP ---','http://172.30.66.73/wsapi/2.0/sync','8bb7650ce1a22250609b600c26ab8401','yk_publicname=--- MY YUBIKEY ---
&yk_counter=10&yk_use=5&yk_high=114&yk_low=53616&nonce=dbd034d222b3837618a4c46f2726aaa2,local_counter=10&local_use=4')
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [--- MY YUBIKEY OTP ---] DB query is: SELECT * FROM queue WHERE modified = '1344502479' and server_nonce =
'8bb7650ce1a22250609b600c26ab8401'
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_DEBUG:ykval-verify:synclib:[127.0.0.1] [--- MY YUBIKEY OTP ---] url in retrieveURLasync is http://172.30.66.73/wsapi/2.0/sync?otp=--- MY YUBIKEY OTP ---
&modified=1344502479&yk_publicname=--- MY YUBIKEY ---&yk_counter=10&yk_use=5&yk_high=114&yk_low=53616&nonce=dbd034d222b3837618a4c46f2726aaa2
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_DEBUG:ykval-common:YK-KSM errno/error: 0/ url=http://172.30.66.73/wsapi/2.0/sync?otp=--- MY YUBIKEY OTP ---&modified=1344502479&yk_publicname=--- MY YUBIKEY ---
&yk_counter=10&yk_use=5&yk_high=114&yk_low=53616&nonce=dbd034d222b3837618a4c46f2726aaa2 content_type=text/plain http_code=200 header_size=245 request_size=268 filetime=-1 ssl_verify_result=0 redirect_count=0
total_time=0.042231 namelookup_time=5.4E-5 connect_time=0.000512 pretransfer_time=0.000517 size_upload=0 size_download=214 speed_download=5067 speed_upload=0 download_content_length=214 upload_content_length=0
starttransfer_time=0.042209 redirect_time=0 certinfo=Array
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_DEBUG:ykval-verify:synclib:[127.0.0.1] [--- MY YUBIKEY OTP ---] local db contains modified=1344502391 nonce=6e9d071896eea37f8f7516954613aa3e yk_publicname=--- MY YUBIKEY
--- yk_counter=10 yk_use=4 yk_high=114 yk_low=52911
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_DEBUG:ykval-verify:synclib:[127.0.0.1] [--- MY YUBIKEY OTP ---] response contains modified=1344502391 nonce=6e9d071896eea37f8f7516954613aa3e yk_publicname=--- MY YUBIKEY
--- yk_counter=10 yk_use=4 yk_high=114 yk_low=52911
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_DEBUG:ykval-verify:synclib:[127.0.0.1] [--- MY YUBIKEY OTP ---] OTP contains modified=1344502479 nonce=dbd034d222b3837618a4c46f2726aaa2 yk_publicname=--- MY YUBIKEY ---
yk_counter=10 yk_use=5 yk_high=114 yk_low=53616
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [--- MY YUBIKEY OTP ---] DB query is: UPDATE yubikeys SET modified='1344502391', yk_counter='10', yk_use='4', yk_low='52911',
yk_high='114', nonce='6e9d071896eea37f8f7516954613aa3e' WHERE yk_publicname = '--- MY YUBIKEY ---' and (10>yk_counter or (10=yk_counter and 4>yk_use))
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_INFO:ykval-verify:synclib:[127.0.0.1] [--- MY YUBIKEY OTP ---] database not updated modified=1344502391 nonce=6e9d071896eea37f8f7516954613aa3e yk_publicname=--- MY YUBIKEY
--- yk_counter=10 yk_use=4 yk_high=114 yk_low=52911
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_INFO:ykval-verify:synclib:[127.0.0.1] [--- MY YUBIKEY OTP ---] deleting server=http://172.30.66.73/wsapi/2.0/sync modified=1344502479
server_nonce=8bb7650ce1a22250609b600c26ab8401
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [--- MY YUBIKEY OTP ---] DB query is: DELETE FROM queue WHERE modified = '1344502479' and server_nonce =
'8bb7650ce1a22250609b600c26ab8401' and server = 'http://172.30.66.73/wsapi/2.0/sync'
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [--- MY YUBIKEY OTP ---] DB query is: UPDATE queue SET queued=NULL WHERE server_nonce = '8bb7650ce1a22250609b600c26ab8401'
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_INFO:ykval-verify:[127.0.0.1] [--- MY YUBIKEY OTP ---] ykval-verify:notice:synclevel=60 nr servers=1 req answers=1 answers=1 valid answers=1 sl success rate=100 timeout=1
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_INFO:ykval-verify:[127.0.0.1] [--- MY YUBIKEY OTP ---] Timestamp seen=7524015 this=7524720 delta=705 secs=88.125 accessed=1344502391 (2012-08-09 10:53:11) now=1344502479
(2012-08-09 10:54:39) elapsed=88 deviation=0.125 secs or 0%
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_DEBUG:ykval-common:SIGN: nonce=dbd034d222b3837618a4c46f2726aaa2&otp=--- MY YUBIKEY OTP ---&sl=100&status=OK&t=2012-08-09T08:54:39Z0895 H=CcI6ldcs5iB3xKbt3mE9d9HByGo=
Aug 9 10:54:39 yubico01 ykval[16269]: LOG_INFO:ykval-common:Response: h=CcI6ldcs5iB3xKbt3mE9d9HByGo=#015#012t=2012-08-09T08:54:39Z0895#015#012otp=--- MY YUBIKEY OTP ---
#015#012nonce=dbd034d222b3837618a4c46f2726aaa2#015#012sl=100#015#012status=OK#015#012#015#012 (at 2012-08-09T08:54:39+00:00 0.89565800 1344502479)
Not working situation yubico02.iam.ia powered off:
Code:
Aug 9 10:57:03 yubico01 ykval[16270]: LOG_INFO:ykval-verify:[127.0.0.1] Request: id=1&nonce=68074094b8a386bfc4966dc00fb344e0&otp= --- MY YUBIKEY OTP ---&h=2OCW3/eEWwXF1Cd70AzNERtrU9U= (at 2012-08-09T10:57:03+02:00 0.88526200 1344502623) HTTP
Aug 9 10:57:03 yubico01 ykval[16270]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [ --- MY YUBIKEY OTP ---] DB query is: SELECT id, secret FROM clients WHERE active AND id='1'
Aug 9 10:57:03 yubico01 ykval[16270]: LOG_DEBUG:ykval-verify:[127.0.0.1] [ --- MY YUBIKEY OTP ---] Client data: id=1 secret=s1lgixvlvNAtrqJeYH4VPLkJxT0=
Aug 9 10:57:03 yubico01 ykval[16270]: LOG_DEBUG:ykval-common:SIGN: id=1&nonce=68074094b8a386bfc4966dc00fb344e0&otp= --- MY YUBIKEY OTP --- H=2OCW3/eEWwXF1Cd70AzNERtrU9U=
Aug 9 10:57:04 yubico01 ykval[16270]: LOG_DEBUG:ykval-verify:[127.0.0.1] [ --- MY YUBIKEY OTP ---] Decrypted OTP: session_counter=10 low=54768 high=114 session_use=6
Aug 9 10:57:04 yubico01 ykval[16270]: LOG_INFO:ykval-verify:synclib:[127.0.0.1] [ --- MY YUBIKEY OTP ---] searching for yk_publicname djcccbcccbrd in local db
Aug 9 10:57:04 yubico01 ykval[16270]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [ --- MY YUBIKEY OTP ---] DB query is: SELECT * FROM yubikeys WHERE yk_publicname = 'djcccbcccbrd' LIMIT 1
Aug 9 10:57:04 yubico01 ykval[16270]: LOG_INFO:ykval-verify:synclib:[127.0.0.1] [ --- MY YUBIKEY OTP ---] yubikey found in db modified=1344502479 nonce=dbd034d222b3837618a4c46f2726aaa2 yk_publicname=djcccbcccbrd yk_counter=10 yk_use=5 yk_high=114 yk_low=53616
Aug 9 10:57:04 yubico01 ykval[16270]: LOG_DEBUG:ykval-verify:[127.0.0.1] [ --- MY YUBIKEY OTP ---] Auth data: modified=1344502479 nonce=dbd034d222b3837618a4c46f2726aaa2 active=1 yk_publicname=djcccbcccbrd yk_counter=10 yk_use=5 yk_high=114 yk_low=53616
Aug 9 10:57:04 yubico01 ykval[16270]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [ --- MY YUBIKEY OTP ---] DB query is: UPDATE yubikeys SET modified='1344502624', yk_counter='10', yk_use='6', yk_low='54768', yk_high='114', nonce='68074094b8a386bfc4966dc00fb344e0' WHERE yk_publicname = 'djcccbcccbrd' and (10>yk_counter or (10=yk_counter and 6>yk_use))
Aug 9 10:57:04 yubico01 ykval[16270]: LOG_INFO:ykval-verify:synclib:[127.0.0.1] [ --- MY YUBIKEY OTP ---] updated database modified=1344502624 nonce=68074094b8a386bfc4966dc00fb344e0 yk_publicname=djcccbcccbrd yk_counter=10 yk_use=6 yk_high=114 yk_low=54768
Aug 9 10:57:04 yubico01 ykval[16270]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [ --- MY YUBIKEY OTP ---] DB query is: INSERT INTO queue (queued,modified,otp,server,server_nonce,info) VALUES ('1344502624','1344502624',' --- MY YUBIKEY OTP ---','http://172.30.66.73/wsapi/2.0/sync','fb3ce2b60e28af2cf4d2f2032e2d89da','yk_publicname=djcccbcccbrd&yk_counter=10&yk_use=6&yk_high=114&yk_low=54768&nonce=68074094b8a386bfc4966dc00fb344e0,local_counter=10&local_use=5')
Aug 9 10:57:04 yubico01 ykval[16270]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [ --- MY YUBIKEY OTP ---] DB query is: SELECT * FROM queue WHERE modified = '1344502624' and server_nonce = 'fb3ce2b60e28af2cf4d2f2032e2d89da'
Aug 9 10:57:04 yubico01 ykval[16270]: LOG_DEBUG:ykval-verify:synclib:[127.0.0.1] [ --- MY YUBIKEY OTP ---] url in retrieveURLasync is http://172.30.66.73/wsapi/2.0/sync?otp= --- MY YUBIKEY OTP ---&modified=1344502624&yk_publicname=djcccbcccbrd&yk_counter=10&yk_use=6&yk_high=114&yk_low=54768&nonce=68074094b8a386bfc4966dc00fb344e0
Aug 9 10:57:06 yubico01 ykval[16270]: LOG_WARNING:ykval-verify:synclib:[127.0.0.1] [ --- MY YUBIKEY OTP ---] No responses from validation server pool
Aug 9 10:57:06 yubico01 ykval[16270]: LOG_DEBUG:ykval-verify:synclib:db:[127.0.0.1] [ --- MY YUBIKEY OTP ---] DB query is: UPDATE queue SET queued=NULL WHERE server_nonce = 'fb3ce2b60e28af2cf4d2f2032e2d89da'
Aug 9 10:57:06 yubico01 ykval[16270]: LOG_INFO:ykval-verify:[127.0.0.1] [ --- MY YUBIKEY OTP ---] ykval-verify:notice:synclevel=60 nr servers=1 req answers=1 answers=0 valid answers=0 sl success rate=0 timeout=1
Aug 9 10:57:06 yubico01 ykval[16270]: LOG_WARNING:ykval-verify:[127.0.0.1] [ --- MY YUBIKEY OTP ---] ykval-verify:notice:Sync failed
Aug 9 10:57:06 yubico01 ykval[16270]: LOG_DEBUG:ykval-common:SIGN: nonce=68074094b8a386bfc4966dc00fb344e0&otp= --- MY YUBIKEY OTP ---&sl=0&status=NOT_ENOUGH_ANSWERS&t=2012-08-09T08:57:06Z0037 H=1gEpAlbSfF3zcnKohnk4lkN4Dr0=
Aug 9 10:57:06 yubico01 ykval[16270]: LOG_INFO:ykval-common:Response: h=1gEpAlbSfF3zcnKohnk4lkN4Dr0=#015#012t=2012-08-09T08:57:06Z0037#015#012otp= --- MY YUBIKEY OTP ---#015#012nonce=68074094b8a386bfc4966dc00fb344e0#015#012sl=0#015#012status=NOT_ENOUGH_ANSWERS#015#012#015#012 (at 2012-08-09T08:57:06+00:00 0.03761800 1344502626)
Aug 9 10:57:07 yubico01 ykval[2241]: LOG_INFO:ykval-queue:synclib:server=http://172.30.66.73/wsapi/2.0/sync , info=yk_publicname=djcccbcccbrd&yk_counter=10&yk_use=6&yk_high=114&yk_low=54768&nonce=68074094b8a386bfc4966dc00fb344e0,local_counter=10&local_use=5
Aug 9 10:57:07 yubico01 ykval[2241]: LOG_DEBUG:ykval-queue:synclib:url is http://172.30.66.73/wsapi/2.0/sync?otp= --- MY YUBIKEY OTP ---&modified=1344502624&yk_publicname=djcccbcccbrd&yk_counter=10&yk_use=6&yk_high=114&yk_low=54768&nonce=68074094b8a386bfc4966dc00fb344e0
[b]Aug 9 10:57:29 yubico01 ykval[2241]: LOG_INFO:ykval-queue:synclib:server=http://172.30.66.73/wsapi/2.0/sync ,[/b] info=yk_publicname=djcccbcccbrd&yk_counter=10&yk_use=6&yk_high=114&yk_low=54768&nonce=68074094b8a386bfc4966dc00fb344e0,local_counter=10&local_use=5
Aug 9 10:57:29 yubico01 ykval[2241]: LOG_DEBUG:ykval-queue:synclib:url is http://172.30.66.73/wsapi/2.0/sync?otp= --- MY YUBIKEY OTP ---&modified=1344502624&yk_publicname=djcccbcccbrd&yk_counter=10&yk_use=6&yk_high=114&yk_low=54768&nonce=68074094b8a386bfc4966dc00fb344e0
As you see above when i try to authenticate on yubico01.iam.ia, yubico01 tries to make an connection with yubico02.iam.ia 172.30.66.73.
I hope someone can help me, with this stange problem. We need to go live with our yubiradius servers.
Kind regards,
Remco Bierings