After a replica has been set up, there's no way to log in to the WebUI.
Expected result: User gets successfully logged in the Web UI.
Actual result: There's a red message Login failed due to an unknown reason.
Login failed due to an unknown reason.
Further info: /var/log/http/error_log:
/var/log/http/error_log
c1:ad8d:208] mod_wsgi (pid=127361): Exception occurred processing WSGI script '/usr/share/ipa/wsgi.py'. [Wed Mar 08 17:08:06.024523 2017] [wsgi:error] [pid 127361] [remote 2620:52:0:2280:6af7:28ff:fec1:ad8d:208] Traceback (most recent call last): [Wed Mar 08 17:08:06.024565 2017] [wsgi:error] [pid 127361] [remote 2620:52:0:2280:6af7:28ff:fec1:ad8d:208] File "/usr/share/ipa/wsgi.py", line 51, in application [Wed Mar 08 17:08:06.024660 2017] [wsgi:error] [pid 127361] [remote 2620:52:0:2280:6af7:28ff:fec1:ad8d:208] return api.Backend.wsgi_dispatch(environ, start_response) [Wed Mar 08 17:08:06.024682 2017] [wsgi:error] [pid 127361] [remote 2620:52:0:2280:6af7:28ff:fec1:ad8d:208] File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 263, in __call__ [Wed Mar 08 17:08:06.024742 2017] [wsgi:error] [pid 127361] [remote 2620:52:0:2280:6af7:28ff:fec1:ad8d:208] return self.route(environ, start_response) [Wed Mar 08 17:08:06.024774 2017] [wsgi:error] [pid 127361] [remote 2620:52:0:2280:6af7:28ff:fec1:ad8d:208] File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 275, in route [Wed Mar 08 17:08:06.024800 2017] [wsgi:error] [pid 127361] [remote 2620:52:0:2280:6af7:28ff:fec1:ad8d:208] return app(environ, start_response) [Wed Mar 08 17:08:06.024815 2017] [wsgi:error] [pid 127361] [remote 2620:52:0:2280:6af7:28ff:fec1:ad8d:208] File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 921, in __call__ [Wed Mar 08 17:08:06.024856 2017] [wsgi:error] [pid 127361] [remote 2620:52:0:2280:6af7:28ff:fec1:ad8d:208] self.kinit(user, self.api.env.realm, password, ipa_ccache_name) [Wed Mar 08 17:08:06.024871 2017] [wsgi:error] [pid 127361] [remote 2620:52:0:2280:6af7:28ff:fec1:ad8d:208] File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 955, in kinit [Wed Mar 08 17:08:06.024893 2017] [wsgi:error] [pid 127361] [remote 2620:52:0:2280:6af7:28ff:fec1:ad8d:208] kinit_armor(armor_path) [Wed Mar 08 17:08:06.024910 2017] [wsgi:error] [pid 127361] [remote 2620:52:0:2280:6af7:28ff:fec1:ad8d:208] File "/usr/lib/python2.7/site-packages/ipalib/install/kinit.py", line 125, in kinit_armor [Wed Mar 08 17:08:06.024938 2017] [wsgi:error] [pid 127361] [remote 2620:52:0:2280:6af7:28ff:fec1:ad8d:208] run(args, env=env, raiseonerr=True, capture_error=True) [Wed Mar 08 17:08:06.024965 2017] [wsgi:error] [pid 127361] [remote 2620:52:0:2280:6af7:28ff:fec1:ad8d:208] File "/usr/lib/python2.7/site-packages/ipapython/ipautil.py", line 495, in run [Wed Mar 08 17:08:06.024993 2017] [wsgi:error] [pid 127361] [remote 2620:52:0:2280:6af7:28ff:fec1:ad8d:208] raise CalledProcessError(p.returncode, arg_string, str(output)) [Wed Mar 08 17:08:06.025044 2017] [wsgi:error] [pid 127361] [remote 2620:52:0:2280:6af7:28ff:fec1:ad8d:208] CalledProcessError: Command '/usr/bin/kinit -n -c /var/run/ipa/ccaches/armor_127361' returned non-zero exit status 1
/var/log/httpd/access_log:
/var/log/httpd/access_log
2620:52:0:2280:6af7:28ff:fec1:ad8d - - [08/Mar/2017:17:08:05 +0100] "POST /ipa/session/login_password HTTP/1.1" 500 527
Metadata Update from @stlaz: - Issue set to the milestone: 0.0 NEEDS_TRIAGE
Metadata Update from @stlaz: - Issue priority set to: 1 - Issue set to the milestone: FreeIPA 4.5 (was: 0.0 NEEDS_TRIAGE) - Issue tagged with: regression
More details from debug mode:
ipa: INFO: *** PROCESS START *** ipa: DEBUG: WSGI wsgi_dispatch.__call__: ipa: DEBUG: WSGI login_password.__call__: ipa: DEBUG: Obtaining armor in ccache /var/run/ipa/ccaches/armor_5385 ipa: DEBUG: Initializing anonymous ccache ipa: DEBUG: Starting external process ipa: DEBUG: args=/usr/bin/kinit -k -t /var/lib/ipa/api/anon.keytab WELLKNOWN/ANONYMOUS -c /var/run/ipa/ccaches/armor_5385 ipa: DEBUG: Process finished, return code=1 ipa: DEBUG: stdout= ipa: DEBUG: stderr=kinit: Reply has wrong form of session key for anonymous request while getting initial credentials ipa: DEBUG: Failed to init Anonymous keytab: Command '/usr/bin/kinit -k -t /var/lib/ipa/api/anon.keytab WELLKNOWN/ANONYMOUS -c /var/run/ipa/ccaches/armor_5385' returned non-zero exit status 1 Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/ipalib/install/kinit.py", line 114, in kinit_armor run(args, env=env, raiseonerr=True, capture_error=True) File "/usr/lib/python2.7/site-packages/ipapython/ipautil.py", line 495, in run raise CalledProcessError(p.returncode, arg_string, str(output)) CalledProcessError: Command '/usr/bin/kinit -k -t /var/lib/ipa/api/anon.keytab WELLKNOWN/ANONYMOUS -c /var/run/ipa/ccaches/armor_5385' returned non-zero exit status 1 ipa: DEBUG: Fallback to slower Anonymous PKINIT ipa: DEBUG: Starting external process ipa: DEBUG: args=/usr/bin/kinit -n -c /var/run/ipa/ccaches/armor_5385 ipa: DEBUG: Process finished, return code=1 ipa: DEBUG: stdout=Password for WELLKNOWN/ANONYMOUS@ABC.IDM.LAB.ENG.BRQ.REDHAT.COM: ipa: DEBUG: stderr=kinit: Pre-authentication failed: Cannot read password while getting initial credentials [remote 2620:52:0:2280:56ee:75ff:fe5c:14c6:160] mod_wsgi (pid=5385): Exception occurred processing WSGI script '/usr/share/ipa/wsgi.py'. [remote 2620:52:0:2280:56ee:75ff:fe5c:14c6:160] Traceback (most recent call last): [remote 2620:52:0:2280:56ee:75ff:fe5c:14c6:160] File "/usr/share/ipa/wsgi.py", line 51, in application [remote 2620:52:0:2280:56ee:75ff:fe5c:14c6:160] return api.Backend.wsgi_dispatch(environ, start_response) [remote 2620:52:0:2280:56ee:75ff:fe5c:14c6:160] File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 262, in __call__ [remote 2620:52:0:2280:56ee:75ff:fe5c:14c6:160] return self.route(environ, start_response) [remote 2620:52:0:2280:56ee:75ff:fe5c:14c6:160] File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 274, in route [remote 2620:52:0:2280:56ee:75ff:fe5c:14c6:160] return app(environ, start_response) [remote 2620:52:0:2280:56ee:75ff:fe5c:14c6:160] File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 901, in __call__ [remote 2620:52:0:2280:56ee:75ff:fe5c:14c6:160] self.kinit(user_principal, password, ipa_ccache_name) [remote 2620:52:0:2280:56ee:75ff:fe5c:14c6:160] File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 935, in kinit [remote 2620:52:0:2280:56ee:75ff:fe5c:14c6:160] kinit_armor(armor_path) [remote 2620:52:0:2280:56ee:75ff:fe5c:14c6:160] File "/usr/lib/python2.7/site-packages/ipalib/install/kinit.py", line 125, in kinit_armor [remote 2620:52:0:2280:56ee:75ff:fe5c:14c6:160] run(args, env=env, raiseonerr=True, capture_error=True) [remote 2620:52:0:2280:56ee:75ff:fe5c:14c6:160] File "/usr/lib/python2.7/site-packages/ipapython/ipautil.py", line 495, in run [remote 2620:52:0:2280:56ee:75ff:fe5c:14c6:160] raise CalledProcessError(p.returncode, arg_string, str(output)) [remote 2620:52:0:2280:56ee:75ff:fe5c:14c6:160] CalledProcessError: Command '/usr/bin/kinit -n -c /var/run/ipa/ccaches/armor_5385' returned non-zero exit status 1
KRB5_TRACE from annon kinit
[root@vm-024 ~]# KRB5_TRACE=/dev/stderr kinit -kt /var/lib/ipa/api/anon.keytab WELLKNOWN/ANONYMOUS@ABC.IDM.LAB.ENG.BRQ.REDHAT.COM [5536] 1489075718.704944: Resolving unique ccache of type KEYRING [5536] 1489075718.704988: Getting initial credentials for WELLKNOWN/ANONYMOUS@ABC.IDM.LAB.ENG.BRQ.REDHAT.COM [5536] 1489075718.707036: Looked up etypes in keytab: aes256-cts, aes128-cts [5536] 1489075718.707102: Sending request (218 bytes) to ABC.IDM.LAB.ENG.BRQ.REDHAT.COM [5536] 1489075718.707303: Initiating TCP connection to stream 10.34.78.24:88 [5536] 1489075718.707418: Sending TCP request to stream 10.34.78.24:88 [5536] 1489075718.710392: Received answer (315 bytes) from stream 10.34.78.24:88 [5536] 1489075718.710406: Terminating TCP connection to stream 10.34.78.24:88 [5536] 1489075718.710499: Response was from master KDC [5536] 1489075718.710531: Received error from KDC: -1765328359/Additional pre-authentication required [5536] 1489075718.710551: Processing preauth types: 136, 19, 2, 133 [5536] 1489075718.710561: Selected etype info: etype aes256-cts, salt "PZ] ?o7{.L,>&isq", params "" [5536] 1489075718.710567: Received cookie: MIT [5536] 1489075718.710612: Retrieving WELLKNOWN/ANONYMOUS@ABC.IDM.LAB.ENG.BRQ.REDHAT.COM from FILE:/var/lib/ipa/api/anon.keytab (vno 0, enctype aes256-cts) with result: 0/Success [5536] 1489075718.710624: AS key obtained for encrypted timestamp: aes256-cts/E1B5 [5536] 1489075718.710661: Encrypted timestamp (for 1489075718.710364): plain 301AA011180F32303137303330393136303833385AA10502030AD6DC, encrypted 34DABD3E426FB2D12AB7083AAF6CA9A9ADB919CBD28E6348996674D1FD8CCF781DCC5F1326CC888811BBC14803B38CA70F7675A9D6BF1C29 [5536] 1489075718.710672: Preauth module encrypted_timestamp (2) (real) returned: 0/Success [5536] 1489075718.710678: Produced preauth for next request: 133, 2 [5536] 1489075718.710688: Sending request (313 bytes) to ABC.IDM.LAB.ENG.BRQ.REDHAT.COM [5536] 1489075718.710740: Initiating TCP connection to stream 10.34.78.24:88 [5536] 1489075718.710815: Sending TCP request to stream 10.34.78.24:88 [5536] 1489075718.750009: Received answer (768 bytes) from stream 10.34.78.24:88 [5536] 1489075718.750033: Terminating TCP connection to stream 10.34.78.24:88 [5536] 1489075718.750111: Response was from master KDC [5536] 1489075718.750141: Processing preauth types: 19 [5536] 1489075718.750153: Selected etype info: etype aes256-cts, salt "PZ] ?o7{.L,>&isq", params "" [5536] 1489075718.750162: Produced preauth for next request: (empty) [5536] 1489075718.750169: AS key determined by preauth: aes256-cts/E1B5 [5536] 1489075718.750234: Decrypted AS reply; session key is: aes256-cts/F41C [5536] 1489075718.750256: FAST negotiation: available kinit: Reply has wrong form of session key for anonymous request while getting initial credentials
2017-03-09T15:58:04Z DEBUG [3/5]: installing X509 Certificate for PKINIT 2017-03-09T15:58:04Z DEBUG certmonger request is in state dbus.String(u'GENERATING_KEY_PAIR', variant_level=1) 2017-03-09T15:58:09Z DEBUG certmonger request is in state dbus.String(u'CA_UNREACHABLE', variant_level=1) 2017-03-09T15:58:09Z DEBUG duration: 5 seconds 2017-03-09T15:58:09Z DEBUG [4/5]: starting the KDC
There is missing kdc.crt because certmonger failed to receive certificate
because certmonger cannot connect to KDC
Mar 09 16:58:04 vm-024.abc.idm.lab.eng.brq.redhat.com certmonger[3819]: 2017-03-09 16:58:04 [3819] Error setting up ccache for "host" service on client using default keytab: Cannot contact any KDC for requested
Because installer configured krb5.conf to point to replica before local KDC is operational
So this is error in replica installer, probably KDC config should be upgraded after this step
master:
Metadata Update from @mbasti: - Issue close_status updated to: fixed - Issue status updated to: Closed (was: Open)
ipa-4-9:
ipa-4-6:
ipa-4-8:
Log in to comment on this ticket.