auth: Include cache hit/miss information in passdb/userdb lookup end events

diff --git a/src/auth/auth-request.c b/src/auth/auth-request.c
index 51b44d9e2dba9c0b4e4c0faf629a8dffbff819da..ee89e753085e89597799d4b37b56f74a9d3b94c8 100644 (file)
--- a/src/auth/auth-request.c
+++ b/src/auth/auth-request.c
@@ -606,6 +606,21 @@ auth_request_want_skip_userdb(struct auth_request *request,
        i_unreached();
 }
 
+static const char *
+auth_request_cache_result_to_str(enum auth_request_cache_result result)
+{
+       switch(result) {
+       case AUTH_REQUEST_CACHE_NONE:
+               return "none";
+       case AUTH_REQUEST_CACHE_HIT:
+               return "hit";
+       case AUTH_REQUEST_CACHE_MISS:
+               return "miss";
+       default:
+               i_unreached();
+       }
+}
+
 void auth_request_passdb_lookup_begin(struct auth_request *request)
 {
        struct event *event;
@@ -614,6 +629,8 @@ void auth_request_passdb_lookup_begin(struct auth_request *request)
        i_assert(request->passdb != NULL);
        i_assert(!request->userdb_lookup);
 
+       request->passdb_cache_result = AUTH_REQUEST_CACHE_NONE;
+
        name = (request->passdb->set->name[0] != '\0' ?
                request->passdb->set->name :
                request->passdb->passdb->iface.name);
@@ -647,6 +664,9 @@ void auth_request_passdb_lookup_end(struct auth_request *request,
                event_create_passthrough(event)->
                set_name("auth_passdb_request_finished")->
                add_str("result", passdb_result_to_string(result));
+       if (request->passdb_cache_result != AUTH_REQUEST_CACHE_NONE &&
+           request->set->cache_ttl != 0 && request->set->cache_size != 0)
+               e->add_str("cache", auth_request_cache_result_to_str(request->passdb_cache_result));
        e_debug(e->event(), "Finished passdb lookup");
        event_unref(&event);
        array_pop_back(&request->authdb_event);
@@ -660,6 +680,8 @@ void auth_request_userdb_lookup_begin(struct auth_request *request)
        i_assert(request->userdb != NULL);
        i_assert(request->userdb_lookup);
 
+       request->userdb_cache_result = AUTH_REQUEST_CACHE_NONE;
+
        name = (request->userdb->set->name[0] != '\0' ?
                request->userdb->set->name :
                request->userdb->userdb->iface->name);
@@ -693,6 +715,9 @@ void auth_request_userdb_lookup_end(struct auth_request *request,
                event_create_passthrough(event)->
                set_name("auth_userdb_request_finished")->
                add_str("result", userdb_result_to_string(result));
+       if (request->userdb_cache_result != AUTH_REQUEST_CACHE_NONE &&
+           request->set->cache_ttl != 0 && request->set->cache_size != 0)
+               e->add_str("cache", auth_request_cache_result_to_str(request->userdb_cache_result));
        e_debug(e->event(), "Finished userdb lookup");
        event_unref(&event);
        array_pop_back(&request->authdb_event);
@@ -1253,11 +1278,14 @@ void auth_request_lookup_credentials_policy_continue(struct auth_request *reques
                if (passdb_cache_lookup_credentials(request, cache_key,
                                                    &cache_cred, &cache_scheme,
                                                    &result, FALSE)) {
+                       request->passdb_cache_result = AUTH_REQUEST_CACHE_HIT;
                        passdb_handle_credentials(
                                result, cache_cred, cache_scheme,
                                auth_request_lookup_credentials_finish,
                                request);
                        return;
+               } else {
+                       request->passdb_cache_result = AUTH_REQUEST_CACHE_MISS;
                }
        }
 
@@ -1360,6 +1388,7 @@ static bool auth_request_lookup_user_cache(struct auth_request *request,
                                  &expired, &neg_expired);
        if (value == NULL || (expired && !use_expired)) {
                stats->auth_cache_miss_count++;
+               request->userdb_cache_result = AUTH_REQUEST_CACHE_MISS;
                e_debug(request->event,
                        value == NULL ? "%suserdb cache miss" :
                        "%suserdb cache expired",
@@ -1367,6 +1396,7 @@ static bool auth_request_lookup_user_cache(struct auth_request *request,
                return FALSE;
        }
        stats->auth_cache_hit_count++;
+       request->userdb_cache_result = AUTH_REQUEST_CACHE_HIT;
        e_debug(request->event,
                "%suserdb cache hit: %s",
                auth_request_get_log_prefix_db(request), value);
@@ -1506,7 +1536,7 @@ void auth_request_userdb_callback(enum userdb_result result,
        if (request->userdb_lookup_tempfailed) {
                /* no caching */
        } else if (result != USERDB_RESULT_INTERNAL_FAILURE) {
-               if (!request->userdb_result_from_cache)
+               if (request->userdb_cache_result != AUTH_REQUEST_CACHE_HIT)
                        auth_request_userdb_save_cache(request, result);
        } else if (passdb_cache != NULL && userdb->cache_key != NULL) {
                /* lookup failed. if we're looking here only because the
@@ -1534,7 +1564,7 @@ void auth_request_lookup_user(struct auth_request *request,
        request->private_callback.userdb = callback;
        request->user_changed_by_lookup = FALSE;
        request->userdb_lookup = TRUE;
-       request->userdb_result_from_cache = FALSE;
+       request->userdb_cache_result = AUTH_REQUEST_CACHE_NONE;
        if (request->fields.userdb_reply == NULL)
                auth_request_init_userdb_reply(request, TRUE);
        else {
@@ -1560,9 +1590,11 @@ void auth_request_lookup_user(struct auth_request *request,
 
                if (auth_request_lookup_user_cache(request, cache_key,
                                                   &result, FALSE)) {
-                       request->userdb_result_from_cache = TRUE;
+                       request->userdb_cache_result = AUTH_REQUEST_CACHE_HIT;
                        auth_request_userdb_callback(result, request);
                        return;
+               } else {
+                       request->userdb_cache_result = AUTH_REQUEST_CACHE_MISS;
                }
        }
 

diff --git a/src/auth/auth-request.h b/src/auth/auth-request.h
index c77b271c4b6e9a7c91a94908758b5579448c0d54..6a458d9841c14e7e4592a4915b9427b21602bf23 100644 (file)
--- a/src/auth/auth-request.h
+++ b/src/auth/auth-request.h
@@ -34,6 +34,12 @@ enum auth_request_secured {
        AUTH_REQUEST_SECURED_TLS,
 };
 
+enum auth_request_cache_result {
+       AUTH_REQUEST_CACHE_NONE,
+       AUTH_REQUEST_CACHE_MISS,
+       AUTH_REQUEST_CACHE_HIT,
+};
+
 /* All auth request fields are exported to auth-worker process. */
 struct auth_request_fields {
         /* user contains the user who is being authenticated.
@@ -160,6 +166,9 @@ struct auth_request {
 
        void *context;
 
+       enum auth_request_cache_result passdb_cache_result;
+       enum auth_request_cache_result userdb_cache_result;
+
        /* this is a lookup on auth socket (not login socket).
           skip any proxying stuff if enabled. */
        bool auth_only:1;
@@ -202,8 +211,6 @@ struct auth_request {
        /* userdb_* fields have been set by the passdb lookup, userdb prefetch
           will work. */
        bool userdb_prefetch_set:1;
-       /* userdb lookup's results are from cache */
-       bool userdb_result_from_cache:1;
        bool stats_sent:1;
        bool policy_refusal:1;
        bool policy_processed:1;

diff --git a/src/auth/passdb-cache.c b/src/auth/passdb-cache.c
index ecababde4e3179909cc536ab023c5c324e7f13fc..6ffaf9b6ebb7ea9ff22b606e3a76833ce0a59404 100644 (file)
--- a/src/auth/passdb-cache.c
+++ b/src/auth/passdb-cache.c
@@ -36,6 +36,8 @@ passdb_cache_lookup(struct auth_request *request, const char *key,
        const char *value;
        bool expired;
 
+       request->passdb_cache_result = AUTH_REQUEST_CACHE_MISS;
+
        /* value = password \t ... */
        value = auth_cache_lookup(passdb_cache, request, key, node_r,
                                  &expired, neg_expired_r);
@@ -48,6 +50,7 @@ passdb_cache_lookup(struct auth_request *request, const char *key,
        }
        stats->auth_cache_hit_count++;
        passdb_cache_log_hit(request, value);
+       request->passdb_cache_result = AUTH_REQUEST_CACHE_HIT;
 
        *value_r = value;
        return TRUE;