Clarify when LDAP credentials get refreshed

[copumpkin]

I see some code (and even tests) in the server for refreshing credentials when an authentication failure occurs, but it doesn't seem to be happening in practice for my running server. It's kind of hard to reduce other than saying that I have the whole thing running and working, but after adding keys to my LDAP server, Hologram won't let people authenticate with the new keys until I restart the daemon.

[copumpkin]

This is the test code I'm talking about: https://github.com/AdRoll/hologram/blob/master/server/usercache_test.go#L154-L178.

[gaylatea]

The intended behaviour of the server should be that when a signature comes in that cannot be verified with any of the keys that Hologram has in its cache, it will silently fail, re-load its cache from the backing store (in this case LDAP), and then try signature verification again.

If this pass fails, then it will emit a failure message back to the client.

For debugging purposes, I added signal support to Hologram before we released it: You can send SIGUSR1 to the server to make it emit debug logging, and SIGHUP will force a re-load of the cache (which, when debug logging is on, will tell you exactly what keys it has loaded for which users). SIGUSR2 will make the server stop debug logging once you're done.

Including this information would help us figure out what's going on here. I know that the system works properly at AdRoll, at least insofar as I haven't heard about it not working. 😺

[copumpkin]

Interesting. This is what I found with debug logging and a failed auth:

May 17 23:54:59 ip-10-60-31-104.qafire.com hologram[16371]: (/tmp/nix-build-go1.4-hologram-2bf08f0.drv-0/go/src/github.com/AdRoll/hologram/server/server.go:99) Handling an assumeRole request.
May 17 23:54:59 ip-10-60-31-104.qafire.com hologram-server[16371]: [DEBUG  ] 2015-05-17T23:54:59Z (/tmp/nix-build-go1.4-hologram-2bf08f0.drv-0/go/src/github.com/AdRoll/hologram/server/server.go:99) Handling an assumeRole request.
May 17 23:54:59 ip-10-60-31-104.qafire.com hologram[16371]: (/tmp/nix-build-go1.4-hologram-2bf08f0.drv-0/go/src/github.com/AdRoll/hologram/server/usercache.go:178) Could not find derp in the LDAP cache; updating from the server.
May 17 23:54:59 ip-10-60-31-104.qafire.com hologram-server[16371]: [DEBUG  ] 2015-05-17T23:54:59Z (/tmp/nix-build-go1.4-hologram-2bf08f0.drv-0/go/src/github.com/AdRoll/hologram/server/usercache.go:178) Could not find derp in the LDAP cache; updating from the server.

Even more oddly, sending SIGHUP to the running process emits:

May 17 23:58:46 ip-10-60-31-104.qafire.com hologram[16371]: (/tmp/nix-build-go1.4-hologram-2bf08f0.drv-0/go/src/github.com/AdRoll/hologram/cmd/hologram-server/main.go:205) Force-reloading user cache.
May 17 23:58:46 ip-10-60-31-104.qafire.com hologram-server[16371]: [INFO   ] 2015-05-17T23:58:46Z (/tmp/nix-build-go1.4-hologram-2bf08f0.drv-0/go/src/github.com/AdRoll/hologram/cmd/hologram-server/main.go:205) Force-reloading user cache.

But doesn't say anything else beyond that (no list of users that I normally see on startup) and still fails authenticating me. Of course, reloading the service fixes the problem.

The one odd thing about my setup is that I'm running my simple authorization code. I wonder if perhaps that's obstructing my usercache updates. Will check up and report back on anything I find!

[copumpkin]

Hmm, now that I look more carefully I think that this

if retUser == nil {
  log.Debug("Could not find %s in the LDAP cache; updating from the server.", username)
  luc.stats.Counter(1.0, "ldapCacheMiss", 1)

  // We should update LDAP cache again to retry keys.
  luc.Update()
  return luc._verify(username, challenge, sshSig)
}

needs error handling on the luc.Update() call. My hypothesis is that my LDAP server kills the connection (which Hologram only dials once at startup) after a while, and the LDAP calls die quickly returning an error, which then gets ignored above. I'm tempted to just have the user cache updater dial the connection on demand and then close it when it's done if that ends up being the case.

[copumpkin]

Yep, pretty sure the connection just drops after a while. I started a new server and sending it SIGHUP worked for a bit. Then I left it overnight and SIGHUPped it again, and it worked as before. Does anyone see any issues with just dialing LDAP with every call to the usercache update? There doesn't seem to be much benefit to keeping a long-lived connection there.

I'm guessing the AdRoll LDAP server is friendlier to long-lived connections.

[gaylatea]

That's fine by me. Or keep a long-running connection going and if it died,
then
re-dial.