gssapi-with-mic works immediately after kinit; fails on subsequent runs

[mbklein]

I'm having a problem that I'm not quite familiar with GSSAPI enough to debug on my own, but I believe it may come down to a bug in the net-ssh-kerberos GSS driver. The behavior exists on both OS X (10.6) and Linux (RHEL 5) clients, but manifests itself in different ways (described below). I've tried three different servers (two RHEL 5 and one Solaris), with the same results on all of them.

I've boiled the problem down to an app does virtually nothing:

Net::SSH.start(host,user,:auth_methods => %w(gssapi-with-mic publickey hostbased), :verbose => :info) do |ssh|
  response = ssh.exec!('ls')
  puts "received #{response.length} bytes"
end

OS X

Here's my output on OS X (with host and user changed to "testhost" and "testuser," respectively):

mbpr mbklein$ kinit
mbpr mbklein$ bin/ssh-test.rb 
I, [2011-06-29T15:17:27.956515 #20942]  INFO -- net.ssh.transport.server_version[809726f8]: negotiating protocol version
I, [2011-06-29T15:17:27.973812 #20942]  INFO -- net.ssh.transport.algorithms[80971e74]: got KEXINIT from server
I, [2011-06-29T15:17:27.974026 #20942]  INFO -- net.ssh.transport.algorithms[80971e74]: sending KEXINIT
I, [2011-06-29T15:17:27.974327 #20942]  INFO -- net.ssh.transport.algorithms[80971e74]: negotiating algorithms
I, [2011-06-29T15:17:28.157752 #20942]  INFO -- net.ssh.authentication.methods.gssapi_with_mic[8095eab8]: gssapi-with-mic success
I, [2011-06-29T15:17:28.167194 #20942]  INFO -- net.ssh.connection.session[80948c40]: channel_open_confirmation: 0 0 0 32768
I, [2011-06-29T15:17:28.167350 #20942]  INFO -- net.ssh.connection.channel[80948a24]: sending channel request "exec"
I, [2011-06-29T15:17:28.170621 #20942]  INFO -- net.ssh.connection.session[80948c40]: channel_window_adjust: 0 +131072
I, [2011-06-29T15:17:28.170821 #20942]  INFO -- net.ssh.connection.session[80948c40]: channel_success: 0
I, [2011-06-29T15:17:28.303559 #20942]  INFO -- net.ssh.connection.session[80948c40]: channel_data: 0 812b
I, [2011-06-29T15:17:28.304053 #20942]  INFO -- net.ssh.connection.session[80948c40]: channel_eof: 0
I, [2011-06-29T15:17:28.304450 #20942]  INFO -- net.ssh.connection.session[80948c40]: channel_request: 0 exit-status false
I, [2011-06-29T15:17:28.304840 #20942]  INFO -- net.ssh.connection.session[80948c40]: channel_close: 0
received 812 bytes
I, [2011-06-29T15:17:28.305201 #20942]  INFO -- net.ssh.connection.session[80948c40]: closing remaining channels (0 open)

mbpr mbklein$ bin/ssh-test.rb 
I, [2011-06-29T15:17:32.317105 #20943]  INFO -- net.ssh.transport.server_version[809726f8]: negotiating protocol version
I, [2011-06-29T15:17:32.333929 #20943]  INFO -- net.ssh.transport.algorithms[80971e74]: got KEXINIT from server
I, [2011-06-29T15:17:32.334141 #20943]  INFO -- net.ssh.transport.algorithms[80971e74]: sending KEXINIT
I, [2011-06-29T15:17:32.334439 #20943]  INFO -- net.ssh.transport.algorithms[80971e74]: negotiating algorithms
I, [2011-06-29T15:17:32.496261 #20943]  INFO -- net.ssh.authentication.methods.gssapi_with_mic[8095e838]: gssapi-with-mic failed (USERAUTH_FAILURE)
E, [2011-06-29T15:17:32.499063 #20943] ERROR -- net.ssh.authentication.session[8095f56c]: all authorization methods failed (tried gssapi-with-mic, publickey)
/Users/mbklein/.rvm/gems/ruby-1.8.7-p302@checksum-tools/gems/net-ssh-2.1.4/lib/net/ssh.rb:197:in `start': testuser (Net::SSH::AuthenticationFailed)
    from bin/ssh-test.rb:10
mbpr mbklein$ 

If I run klist, I can see that I still have a valid ticket for the host in question (and, in fact, the script will acquire a new one if the existing one has expired), but the script won't actually succeed in logging in until I manually run kinit again. I can SSH to the same host from the command line with the same credentials, so I know the ticket is still good.

If I had root access on one of the machines I'm trying to log into, I'd turn the logging up to 11 and see if there's anything to be learned from that end. But unfortunately, I don't.

Linux

On Linux, I get a different type of strange behavior, but it may be related. If I run the test immediately after running kinit, the first and subsequent logins all succeed, but running klist after each one shows that an additional host ticket is being acquired for the target machine on each run. However, if I ssh into the target machine from the command line first (thereby obtaining a host ticket), the test script will run multiple times successfully without obtaining any new tickets.

I certainly hope this behavior makes sense to you, because it has me completely baffled.

[joekhoobyar]

I'd need to take a deeper look at this and perhaps try and duplicate the problem. I have an OS X machine but it doesn't currently have access to any "kerberized" SSH servers. I really need to set up a new test environment anyway...

[mbklein]

If I can be of any assistance (with debug logs, or testing, or anything else), please let me know. I still don't really understand the whole GSSAPI process (yet), but I'm a decent troubleshooter.

[mbklein]

I'll also check this out on Mac OS 10.7 (Lion), which may exhibit different behavior now that Apple has switched from MIT Kerberos to Heimdal Kerberos as the underlying K5 library.

[joekhoobyar]

Let me know how that worked out. I still haven't gotten a test environment setup involving a Mac... I'm a bit busy on other projects currently... :(

[mbklein]

I haven't been able to upgrade to Lion yet because of other Kerberos-related issues (Adium doesn't support GSSAPI login to Jabber under Lion), so I haven't had the chance to test it yet.