Bug 1399347

Summary: After upgrading cockpit (with relation to OpenShift) to 0.114, customer is unable to login
Product: Red Hat Enterprise Linux 7 Reporter: Eric Jones <erjones>
Component: cockpit-ws-containerAssignee: Dominik Perpeet <dperpeet>
Status: CLOSED CURRENTRELEASE QA Contact: qe-baseos-daemons
Severity: high Docs Contact:
Priority: low    
Version: 7.3CC: erjones, jscotka, kurktchiev, pvolpe
Target Milestone: rcKeywords: Extras, Unconfirmed
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: cockpit-126-1.el7 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-08-28 10:22:53 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description Eric Jones 2016-11-28 19:46:09 UTC
Description of problem:
Customer was using cockpit with OpenShift and was able to login just fine but after upgrading most of the server, the user was unable to login to cockpit as the web page reloads to the same login prompt. However, if you look at the logs, it will then show that it did log the user in, but they remain unable to do anything on the webpage.

Will attach logs shortly.

Comment 2 Dominik Perpeet 2016-12-06 13:32:41 UTC
I see several potential causes:

- If the client browser is IE, Edge or Safari, you probably need to update to Cockpit 0.122-3 (released in sync with Extras 7.3.1)
- If Cockpit is running as a service, systemd may need to reload and the web service restarted
- Are there any error messages in the javascript console of the browser?
- Are all cockpit subpackages upgraded to the same version?

If these items don't help, it would be good to know
- the installed package versions (cockpit, subpackages)
- to clarify if the user just stays on the login page after logging in or if something else happens.

Comment 3 Boris Kurktchiev 2016-12-06 13:36:45 UTC
Sure I can get a more detailed report posted but &Jericho has a sos report of my system that should have most of the info you are asking for. If it can get attached

Comment 4 Jan Ščotka 2016-12-06 13:39:14 UTC
Hi,
does the problem persist across reboots. (In case also systemd were updated, there is suggested  in erratum to reboot system too)
    Regards
    Honza

Comment 5 Dominik Perpeet 2016-12-06 13:57:59 UTC
(In reply to Boris Kurktchiev from comment #3)
> Sure I can get a more detailed report posted but &Jericho has a sos report
> of my system that should have most of the info you are asking for. If it can
> get attached

Jan just looked at the installed versions of Cockpit, thanks.

Since cockpit-kubernetes has version 118, could you please try upgrading the other packages to the same version as well?

Comment 6 Boris Kurktchiev 2016-12-06 14:05:35 UTC
Upgraded to -118 on all components and am currently upgrading the system to latest RHEL 7.3.x release and then will bounce and see what shakes loose. Stay tuned.

Comment 7 Boris Kurktchiev 2016-12-06 14:23:55 UTC
After restart still the same effect. As far as looking at it with Dev tools:

GET https://cockpit.cloudapps.unc.edu/cockpit/login 401 (Authentication required)

However, if you look at the journal you can see that the system authenticated me just fine: 

Dec 06 09:20:24 osmaster0p.isis.unc.edu polkitd[818]: Registered Authentication Agent for unix-session:2 (system bus name :1.34 [cockpit-bridge], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
Dec 06 09:20:24 osmaster0p.isis.unc.edu cockpit-ws[1170]: logged in user: boris
Dec 06 09:20:24 osmaster0p.isis.unc.edu cockpit-session[4102]: pam_unix(cockpit:session): session opened for user boris by (uid=0)

Dec 06 09:20:39 osmaster0p.isis.unc.edu cockpit-session[4102]: pam_unix(cockpit:session): session closed for user boris
Dec 06 09:20:39 osmaster0p.isis.unc.edu polkitd[818]: Unregistered Authentication Agent for unix-session:2 (system bus name :1.34, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
Dec 06 09:20:39 osmaster0p.isis.unc.edu cockpit-ws[1170]: boris: timed out

Comment 8 Dominik Perpeet 2016-12-06 15:20:04 UTC
After discussing this with Peter, we think that this could be one of two things:
- the cookies are not taking (if you have access, you could check those in the browser)
- the session is terminating before the login page has a chance to reload

It might also help to turn on debugging for Cockpit in the journal.

Comment 9 Dominik Perpeet 2016-12-06 15:23:49 UTC
More info on enabling debug messages for Cockpit can be found on the upstream repository:

https://github.com/cockpit-project/cockpit/blob/master/HACKING.md#debug-logging-of-cockpit-processes

Comment 10 Boris Kurktchiev 2016-12-06 15:25:59 UTC
Cookies:
there is a cockpit cookie with what looks like a token: dj0yO2s9M2I3Zjk0MDU0N2E4MGQ0MDNkOGFiYzk0NjlhNDE0NGJhOGFjODUxZjNiY2JmNjg5OTY2YTU1ODBhZTIwOTBjZA

I will work on getting debugging setup and see what happens.

Comment 11 Boris Kurktchiev 2016-12-06 15:28:07 UTC
Here is the debug info

Dec 06 10:27:05 osmaster0p.isis.unc.edu atomic-openshift-node[3240]: I1206 10:27:05.039981    3240 node_auth.go:143] Node request attributes: namespace=, user=&user.DefaultInfo{Name:"system:serviceaccount:openshift-infra:heapster", UID:"cb45c36c-a82e-11e6-91bd-00505691bba9", Groups:[]string{"system:serviceaccounts", "system:serviceaccounts:openshift-infra", "system:authenticated", "system:authenticated"}, Extra:map[string][]string{}}, attrs=authorizer.DefaultAuthorizationAttributes{Verb:"create", APIVersion:"v1", APIGroup:"", Resource:"nodes/stats", ResourceName:"osmaster0p.isis.unc.edu", RequestAttributes:interface {}(nil), NonResourceURL:false, URL:"/stats/container/"}
Dec 06 10:27:05 osmaster0p.isis.unc.edu atomic-openshift-node[3240]: I1206 10:27:05.104376    3240 server.go:964] POST /stats/container/: (64.485704ms) 200 [[Go-http-client/1.1] 152.19.229.172:43948]
Dec 06 10:27:18 osmaster0p.isis.unc.edu cockpit-ws[34938]: received unknown/invalid credential cookie
Dec 06 10:27:18 osmaster0p.isis.unc.edu cockpit-ws[34938]: received unknown/invalid credential cookie
Dec 06 10:27:18 osmaster0p.isis.unc.edu cockpit-ws[34938]: /usr/libexec/cockpit-session auth pipe: setting up auth pipe 9 10
Dec 06 10:27:18 osmaster0p.isis.unc.edu cockpit-ws[34938]: spawning /usr/libexec/cockpit-session
Dec 06 10:27:18 osmaster0p.isis.unc.edu cockpit-ws[34938]: /usr/libexec/cockpit-session auth pipe: reporting message
Dec 06 10:27:18 osmaster0p.isis.unc.edu cockpit-ws[34938]: /usr/libexec/cockpit-session says: {  "error": "authentication-unavailable", "message": "Authentication service cannot retrieve authentication info"}
Dec 06 10:27:18 osmaster0p.isis.unc.edu cockpit-ws[34938]: negotiate auth is not available, disabling
Dec 06 10:27:20 osmaster0p.isis.unc.edu atomic-openshift-node[3240]: I1206 10:27:20.021128    3240 node_auth.go:143] Node request attributes: namespace=, user=&user.DefaultInfo{Name:"system:serviceaccount:openshift-infra:heapster", UID:"cb45c36c-a82e-11e6-91bd-00505691bba9", Groups:[]string{"system:serviceaccounts", "system:serviceaccounts:openshift-infra", "system:authenticated", "system:authenticated"}, Extra:map[string][]string{}}, attrs=authorizer.DefaultAuthorizationAttributes{Verb:"create", APIVersion:"v1", APIGroup:"", Resource:"nodes/stats", ResourceName:"osmaster0p.isis.unc.edu", RequestAttributes:interface {}(nil), NonResourceURL:false, URL:"/stats/container/"}
Dec 06 10:27:20 osmaster0p.isis.unc.edu atomic-openshift-node[3240]: I1206 10:27:20.075916    3240 server.go:964] POST /stats/container/: (54.925446ms) 200 [[Go-http-client/1.1] 152.19.229.172:43948]
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-ws[34938]: received unknown/invalid credential cookie
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-ws[34938]: /usr/libexec/cockpit-session auth pipe: setting up auth pipe 9 10
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-ws[34938]: spawning /usr/libexec/cockpit-session
Dec 06 10:27:24 osmaster0p.isis.unc.edu unix_chkpwd[35164]: password check failed for user (boris)
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-session[35162]: pam_unix(cockpit:auth): authentication failure; logname= uid=0 euid=0 tty= ruser= rhost=172.22.158.132  user=boris
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-ws[34938]: cockpit-session: pam: dropping text message Warning: Your password will expire in 84 days on Tue Feb 28 18:38:18 2017
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-session[35162]: pam_krb5[35162]: error reading keytab 'FILE:/etc/krb5.keytab'
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-session[35162]: pam_krb5[35162]: TGT verified
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-session[35162]: pam_krb5[35162]: authentication succeeds for 'boris' (boris.EDU)
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-session[35162]: pam_ssh_add: Identity added: /websyshome/boris/.ssh/id_rsa (/websyshome/boris/.ssh/id_rsa)
Dec 06 10:27:24 osmaster0p.isis.unc.edu systemd-logind[819]: New session 12 of user boris.
Dec 06 10:27:24 osmaster0p.isis.unc.edu systemd[1]: Started Session 12 of user boris.
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-session[35162]: pam_unix(cockpit:session): session opened for user boris by (uid=0)
Dec 06 10:27:24 osmaster0p.isis.unc.edu systemd[1]: Starting Session 12 of user boris.
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-ws[34938]: /usr/libexec/cockpit-session auth pipe: reporting message
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-ws[34938]: /usr/libexec/cockpit-session auth pipe: Auth pipe closed
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-ws[34938]: /usr/libexec/cockpit-session says: {  "user": "boris"}
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-ws[34938]: user authenticated as boris
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-ws[34938]: localhost: new session
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-ws[34938]: boris: login is idle
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-ws[34938]: sending 460f4dc4c7d654996fcd77fe38c847dd8d40390c153ab45926e2715d778b5940 credential id 'cockpit' for user 'boris'
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-ws[34938]: logged in user: boris
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: launched dbus-daemon
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: session bus address: unix:abstract=/tmp/dbus-a74ACI2qtq,guid=9a96982cad65088a876048615846d8dc
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: package server port: 44138
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: base1: no override found
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: base1: added package at /usr/share/cockpit/base1
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: branding: no manifest found
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: dashboard: no override found
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: dashboard: added package at /usr/share/cockpit/dashboard
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: docker: no override found
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: docker: added package at /usr/share/cockpit/docker
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: kubernetes: no override found
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: kubernetes: added package at /usr/share/cockpit/kubernetes
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: networkmanager: no override found
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: network: added package at /usr/share/cockpit/networkmanager
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: realmd: no override found
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: domain: added package at /usr/share/cockpit/realmd
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: selinux: no override found
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: selinux: added package at /usr/share/cockpit/selinux
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: shell: added package at /usr/share/cockpit/shell
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: sosreport: no override found
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: sosreport: added package at /usr/share/cockpit/sosreport
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: static: no manifest found
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: subscriptions: no override found
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: subscriptions: added package at /usr/share/cockpit/subscriptions
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: systemd: no override found
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: system: added package at /usr/share/cockpit/systemd
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: tuned: no override found
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: performance: added package at /usr/share/cockpit/tuned
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: users: no override found
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: users: added package at /usr/share/cockpit/users
Dec 06 10:27:24 osmaster0p.isis.unc.edu polkitd[818]: Registered Authentication Agent for unix-session:12 (system bus name :1.61 [cockpit-bridge], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: registered polkit authentication agent for subject: unix-session:12
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-bridge[35175]: received init message
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-ws[34938]: localhost: received init message
Dec 06 10:27:24 osmaster0p.isis.unc.edu cockpit-ws[34938]: received unknown/invalid credential cookie
Dec 06 10:27:25 osmaster0p.isis.unc.edu cockpit-ws[34938]: received unknown/invalid credential cookie

Comment 12 Peter 2016-12-06 16:28:54 UTC
Looks to be cookie related.

What browser are you using? Or is it any browser?

Have you tried clearing cookies before logging in, to see if that makes a difference?

What we need to try to verify is that the contents of the "Set-Cookie" header you receive in response to the /cockpit/login request that succeeds is same as what get sent to the server in the subsequent reload.

Comment 13 Boris Kurktchiev 2016-12-06 16:31:43 UTC
Well this is interesting. I switched to Safari and got in just fine. Chrome (latest) in both standard and Incognito mode is unable to get me in.

Comment 14 Peter 2016-12-06 16:46:25 UTC
Ok, progress so in chrome open developer tools.

Open the network tab. Go to the login page, then hit the delete button to clear the log. Then check the preserve log checkbox.

Try to login in.

The first network entry should be a call to /cockpit/login with a 200 response. The next entry should be a request to the page you were going to ei: / or /dashboard or something like that.

Can you send the full request / response headers for both of those calls?

Comment 15 Boris Kurktchiev 2016-12-06 16:50:35 UTC
yeah so looks like /login is sending a 401:

Also chrome really needs a dev tools log export option... Here is the crude copy/paste:

cockpit.cloudapps.unc.edu
200
OK
document	Other	33.6 KB
33.2 KB
56 ms
41 ms
branding.css
/cockpit/static
200
OK
stylesheet	(index):1009
Parser
(from disk cache)	5 ms
4 ms
OpenSans-Regular-webfont.woff
/cockpit/static/fonts
200
OK
font	onloadwff.js:1402
Script
(from memory cache)	0 ms
0 ms
OpenSans-Bold-webfont.woff
/cockpit/static/fonts
200
OK
font	onloadwff.js:1402
Script
(from memory cache)	0 ms
0 ms
bg-login.jpg
/cockpit/static
200
OK
jpg	(index):-Infinity
Parser
(from memory cache)	0 ms
0 ms
logo.png
/cockpit/static
200
OK
png	(index):-Infinity
Parser
(from memory cache)	0 ms
0 ms
login
/cockpit
401
Negotiate authentication not available
xhr	(index):197
Script
3.7 KB
3.4 KB
16 ms
15 ms
data:image/png;base…
200
OK
png	onloadwff.js:1255
Script
(from memory cache)	0 ms
0 ms
data:image/png;base…
200
OK
png	onloadwff.js:928
Script
(from memory cache)	0 ms
0 ms
data:image/png;base…
200
OK
png	onloadwff.js:1255
Script
(from memory cache)	0 ms
0 ms
data:image/png;base…
200
OK
png	onloadwff.js:1160
Script
(from memory cache)	0 ms
0 ms

Comment 16 Boris Kurktchiev 2016-12-06 16:51:48 UTC
the 401 error: Negotiate authentication not available

Comment 17 Peter 2016-12-06 16:54:51 UTC
That's the first request, that's expected. There should be a second request to /cockpit/login after you submit a username/password. The two requests we care about are that second /cockpit/login request and the request that gets made directly afterwards.

Comment 18 Boris Kurktchiev 2016-12-06 18:18:16 UTC
Nope, after login attempt i get: 401 Authentication required

Also seeing: OpenSans-Bold-webfont.woff
/cockpit/static/fonts
(failed)
net::ERR_CONNECTION_RESET

But dont think the second one is relevant.

Comment 19 Peter 2016-12-06 18:23:15 UTC
I thought the page was reloading and then taking you back to the login screen. Is that not the case? Are you getting an error message instead?

Be sure you are checking the "preserve log" checkbox. Otherwise chrome clears the list of http calls when the reload happens and you never see the 2nd call to /cockpit/login. Only the first one again because the login page is what reloads.

If this is easier debugged by chat, I'm around on #cockpit on freenode.

Comment 20 Boris Kurktchiev 2016-12-06 18:26:16 UTC
Yes I have it preserve the log and once I click the login button thats all the logs says. Spits me back out to the login page and the network tab says 401 Authentication required. There is no error message displayed on the login page. I am idling in #cockpit, ebalsumgo

Comment 21 Peter 2016-12-06 19:12:53 UTC
Thanks for your help tracking this down Boris.

The bug was an instance of 
https://github.com/cockpit-project/cockpit/pull/5327/commits/9d8bd4cbd773d606a9867dd1c7b92951f20045ba 

Where we weren't parsing cookies correctly so a different cookie set by the load balancer was causing the cockpit auth cookie not to be found.

This was fixed in cockpit version 123.

Dominik Perpeet, will this fix be in the next release?

Comment 22 Dominik Perpeet 2016-12-06 21:09:19 UTC
Thanks Boris and Peter for tracking this down. Unfortunately this patch didn't make it into RHEL Extras 7.3.1, but will make it into 7.3.2.

I will add this bug to the 7.3.2 release so you will get notified once it becomes available.

Comment 23 Dominik Perpeet 2017-08-28 10:22:53 UTC
Apparently the bug wasn't properly attached, but the fix did go out with 7.3.2.

Sorry for the inconvenience.