#6739 Cannot login to replica's WebUI
Closed: fixed 2 years ago Opened 2 years ago by stlaz.

After a replica has been set up, there's no way to log in to the WebUI.

  1. Set up an IPA master
  2. Set up an IPA replica
  3. In firefox, go to replica's hostname
  4. Try to log in

Expected result:
User gets successfully logged in the Web UI.

Actual result:
There's a red message Login failed due to an unknown reason.

Further info:
/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:

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

2 years ago

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

2 years ago

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:

  • 95768de Make PKINIT certificate request logic consistent with other installers
  • b5b23e0 Request PKINIT cert directly from Dogtag API on first master
  • bd18b5f Move PKINIT configuration to a later stage of server/replica install
  • 0699484 Make wait_for_entry raise exceptions
  • 8f4abf7 check that the master requesting PKINIT cert has KDC enabled
  • b45629f check for replica's KDC entry on master before requesting PKINIT cert
  • a1686a9 Try out anonymous PKINIT after it is configured

Metadata Update from @mbasti:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)

2 years ago

Login to comment on this ticket.

Metadata