trunk/radius: Print out detailed state log

diff --git a/src/lib/server/trunk.c b/src/lib/server/trunk.c
index 926a6fa9b1d76063cd1cb6a781ccb8098889d750..8594c74251d3cfdd15258b79eb1803d1425047c7 100644 (file)
--- a/src/lib/server/trunk.c
+++ b/src/lib/server/trunk.c
@@ -372,7 +372,7 @@ do { \
 } while (0)
 #define REQUEST_BAD_STATE_TRANSITION(_new) \
 do { \
-       fr_trunk_request_state_log_print(treq); \
+       fr_trunk_request_state_log(&default_log, L_ERR, __FILE__, __LINE__, treq); \
        if (!fr_cond_assert_msg(0, "Trunk request %" PRIu64 " invalid transition %s -> %s", \
                                treq->id, \
                                fr_table_str_by_value(fr_trunk_request_states, treq->pub.state, "<INVALID>"), \
@@ -2256,19 +2256,19 @@ fr_trunk_enqueue_t fr_trunk_request_enqueue_on_conn(fr_trunk_request_t **treq_ou
 }
 
 #ifndef NDEBUG
-void fr_trunk_request_state_log_print(fr_trunk_request_t const *treq)
+void fr_trunk_request_state_log(fr_log_t const *log, fr_log_type_t log_type, char const *file, int line,
+                               fr_trunk_request_t const *treq)
 {
-       fr_trunk_t                      *trunk = treq->pub.trunk;
-       fr_trunk_request_state_log_t    *log = NULL;
+       fr_trunk_request_state_log_t    *slog = NULL;
 
        int i;
 
-       for (log = fr_dlist_head(&treq->log), i = 0;
-            log;
-            log = fr_dlist_next(&treq->log, log), i++) {
-               ERROR("[%u] %s:%i - %s -> %s", i, log->function, log->line,
-                     fr_table_str_by_value(fr_trunk_request_states, log->from, "<INVALID>"),
-                     fr_table_str_by_value(fr_trunk_request_states, log->to, "<INVALID>"));
+       for (slog = fr_dlist_head(&treq->log), i = 0;
+            slog;
+            slog = fr_dlist_next(&treq->log, slog), i++) {
+               fr_log(log, log_type, file, line, "[%u] %s:%i - %s -> %s", i, slog->function, slog->line,
+                      fr_table_str_by_value(fr_trunk_request_states, slog->from, "<INVALID>"),
+                      fr_table_str_by_value(fr_trunk_request_states, slog->to, "<INVALID>"));
        }
 }
 #endif

diff --git a/src/lib/server/trunk.h b/src/lib/server/trunk.h
index f0fc0913c6f099ac1f27eef92a1f0e45ff28a2b8..e431abfe653de550c98ccdd3f33c93ba5189b4d8 100644 (file)
--- a/src/lib/server/trunk.h
+++ b/src/lib/server/trunk.h
@@ -703,7 +703,8 @@ fr_trunk_enqueue_t fr_trunk_request_enqueue_on_conn(fr_trunk_request_t **treq_ou
                                                    bool ignore_limits) CC_HINT(nonnull(2));
 
 #ifndef NDEBUG
-void           fr_trunk_request_state_log_print(fr_trunk_request_t const *treq);
+void           fr_trunk_request_state_log(fr_log_t const *log, fr_log_type_t log_type, char const *file, int line,
+                                          fr_trunk_request_t const *treq);
 #endif
 /** @} */
 

diff --git a/src/modules/rlm_radius/rlm_radius_udp.c b/src/modules/rlm_radius/rlm_radius_udp.c
index d63f613f35f1720a45498231b24782b05c615723..45b8143b3124266162d13533355fb4ad768e46bf 100644 (file)
--- a/src/modules/rlm_radius/rlm_radius_udp.c
+++ b/src/modules/rlm_radius/rlm_radius_udp.c
@@ -267,6 +267,29 @@ static decode_fail_t       decode(TALLOC_CTX *ctx, VALUE_PAIR **reply, uint8_t *respon
 
 static void            protocol_error_reply(udp_request_t *u, udp_result_t *r, udp_handle_t *h);
 
+#ifndef NDEBUG
+/** Log additional information about a tracking entry
+ *
+ * @param[in] te       Tracking entry we're logging information for.
+ * @param[in] log      destination.
+ * @param[in] log_type Type of log message.
+ * @param[in] file     the logging request was made in.
+ * @param[in] line     logging request was made on.
+ */
+static void udp_tracking_entry_log(fr_log_t const *log, fr_log_type_t log_type, char const *file, int line,
+                                  radius_track_entry_t *te)
+{
+       REQUEST                 *request;
+
+       request = talloc_get_type_abort(te->request, REQUEST);
+
+       fr_log(log, log_type, file, line, "\trequest %s, allocated %s:%u", request->name,
+              request->alloc_file, request->alloc_line);
+
+       fr_trunk_request_state_log(log, log_type, file, line, talloc_get_type_abort(te->uctx, fr_trunk_request_t));
+}
+#endif
+
 /** Clear a UDP request, ready for moving or retransmission
  *
  * @note We don't necessarily have to clear the packet here.
@@ -820,7 +843,7 @@ static void conn_close(UNUSED fr_event_list_t *el, void *handle, UNUSED void *uc
         */
        if (h->tt && (h->tt->num_requests != 0)) {
 #ifndef NDEBUG
-               radius_track_state_log(h->tt);
+               radius_track_state_log(&default_log, L_ERR, __FILE__, __LINE__, h->tt, udp_tracking_entry_log);
 #endif
                fr_cond_assert_fail(__FILE__, __LINE__, "0", "%u tracking entries still allocated at conn close",
                                    h->tt->num_requests);
@@ -1714,10 +1737,12 @@ static void request_mux(fr_event_list_t *el,
                if (!u->packet || !u->can_retransmit) {
                        rad_assert(!u->rr);
 
-                       if (!fr_cond_assert_msg((radius_track_entry_reserve(&u->rr, treq, h->tt,
-                                                                           request, u->code, treq)) == 0,
-                                               "Tracking entry allocation failed")) {
-
+                       if (unlikely(radius_track_entry_reserve(&u->rr, treq, h->tt, request, u->code, treq) < 0)) {
+#ifndef NDEBUG
+                               radius_track_state_log(&default_log, L_ERR, __FILE__, __LINE__,
+                                                      h->tt, udp_tracking_entry_log);
+#endif
+                               fr_cond_assert_fail(__FILE__, __LINE__, "0", "Tracking entry allocation failed");
                        fail:
                                fr_trunk_request_signal_fail(treq);
                                continue;
@@ -2254,7 +2279,7 @@ static void request_demux(fr_trunk_connection_t *tconn, fr_connection_t *conn, U
                        continue;
                }
 
-               treq = talloc_get_type_abort(rr->rctx, fr_trunk_request_t);
+               treq = talloc_get_type_abort(rr->uctx, fr_trunk_request_t);
                request = treq->request;
                rad_assert(request != NULL);
                u = talloc_get_type_abort(treq->preq, udp_request_t);

diff --git a/src/modules/rlm_radius/track.c b/src/modules/rlm_radius/track.c
index d59bec681e0edc6850e54f35a34d05b484d30382..927d5dffff7ed6605130c5a932e24388fe707dde 100644 (file)
--- a/src/modules/rlm_radius/track.c
+++ b/src/modules/rlm_radius/track.c
@@ -87,9 +87,10 @@ static int _radius_track_entry_release_on_free(radius_track_entry_t ***te_p)
        return 0;
 }
 
-#ifndef NDEBUG
 /** Allocate a tracking entry.
  *
+ * @param[in] file             The allocation was made in.
+ * @param[in] line             The allocation was made on.
  * @param[out] te_out          Where the tracking entry should be written.
  *                             If ctx is not-null, then this pointer must
  *                             remain valid for the lifetime of the ctx.
@@ -98,20 +99,18 @@ static int _radius_track_entry_release_on_free(radius_track_entry_t ***te_p)
  * @param[in] tt               The radius_track_t tracking table.
  * @param[in] request          The request which will send the proxied packet.
  * @param[in] code             Of the outbound request.
- * @param[in] rctx             The context to associate with the request
- * @param[in] file             The allocation was made in.
- * @param[in] line             The allocation was made on.
+ * @param[in] uctx             The context to associate with the request
  * @return
  *     - 0 on success.
  *     - -1 on failure.
  */
-int _radius_track_entry_reserve(radius_track_entry_t **te_out,
-                               TALLOC_CTX *ctx, radius_track_t *tt, REQUEST *request, uint8_t code, void *rctx,
-                               char const *file, int line)
+#ifndef NDEBUG
+int _radius_track_entry_reserve(char const *file, int line,
 #else
-int radius_track_entry_reserve(radius_track_entry_t **te_out,
-                              TALLOC_CTX *ctx, radius_track_t *tt, REQUEST *request, uint8_t code, void *rctx)
+int radius_track_entry_reserve(
 #endif
+                               radius_track_entry_t **te_out,
+                               TALLOC_CTX *ctx, radius_track_t *tt, REQUEST *request, uint8_t code, void *uctx)
 {
        radius_track_entry_t *te;
 
@@ -173,7 +172,7 @@ retry:
 done:
        te->tt = tt;
        te->request = request;
-       te->rctx = rctx;
+       te->uctx = uctx;
        te->code = code;
 #ifndef NDEBUG
        te->operation = te->tt->operation++;
@@ -196,20 +195,21 @@ done:
        return 0;
 }
 
-#ifndef NDEBUG
 /** Release a tracking entry
  *
- * @param[in,out] te_to_free           The #radius_track_entry_t allocated via #radius_track_entry_reserve.
  * @param[in] file                     Allocation was released in.
  * @param[in] line                     Allocation was released on.
+ * @param[in,out] te_to_free           The #radius_track_entry_t allocated via #radius_track_entry_reserve.
  * @return
  *     - <0 on error
  *     - 0 on success
  */
-int _radius_track_entry_release(radius_track_entry_t **te_to_free, char const *file, int line)
+#ifndef NDEBUG
+int _radius_track_entry_release(char const *file, int line,
 #else
-int radius_track_entry_release(radius_track_entry_t **te_to_free)
+int radius_track_entry_release(
 #endif
+                               radius_track_entry_t **te_to_free)
 {
        radius_track_entry_t    *te = *te_to_free;
        radius_track_t          *tt = talloc_get_type_abort(te->tt, radius_track_t);    /* Make sure table is still valid */
@@ -410,8 +410,15 @@ void radius_track_use_authenticator(radius_track_t *tt, bool flag)
 #ifndef NDEBUG
 /** Print out the state of every tracking entry
  *
+ * @param[in] log      destination.
+ * @param[in] log_type Type of log message.
+ * @param[in] file     this function was called in.
+ * @param[in] line     this function was called on.
+ * @param[in] tt       Table to print.
+ * @param[in] extra    Callback function for printing extra detail.
  */
-void radius_track_state_log(radius_track_t *tt)
+void radius_track_state_log(fr_log_t const *log, fr_log_type_t log_type, char const *file, int line,
+                           radius_track_t *tt, radius_track_log_extra_t extra)
 {
        size_t i;
 
@@ -421,13 +428,17 @@ void radius_track_state_log(radius_track_t *tt)
                entry = &tt->id[i];
 
                if (entry->request) {
-                       INFO("[%zu] %"PRIu64 " - Allocated at %s:%u to request %p (%s), rctx %p",
-                            i, entry->operation,
-                            entry->file, entry->line, entry->request, entry->request->name, entry->rctx);
+                       fr_log(log, log_type, file, line,
+                              "[%zu] %"PRIu64 " - Allocated at %s:%u to request %p (%s), uctx %p",
+                              i, entry->operation,
+                              entry->file, entry->line, entry->request, entry->request->name, entry->uctx);
                } else {
-                       INFO("[%zu] %"PRIu64 " - Freed at %s:%u",
-                            i, entry->operation, entry->file, entry->line);
+                       fr_log(log, log_type, file, line,
+                              "[%zu] %"PRIu64 " - Freed at %s:%u",
+                              i, entry->operation, entry->file, entry->line);
                }
+
+               if (extra) extra(log, log_type, file, line, entry);
        }
 }
 #endif

diff --git a/src/modules/rlm_radius/track.h b/src/modules/rlm_radius/track.h
index c553828f36ac9a766a5da7fd1fbc70b520e3e097..3184d47459d5df5d8441449fd0226fd44197a03a 100644 (file)
--- a/src/modules/rlm_radius/track.h
+++ b/src/modules/rlm_radius/track.h
@@ -42,7 +42,7 @@ struct radius_track_entry_s {
 
        REQUEST         *request;               //!< as always...
 
-       void            *rctx;                  //!< Result/resumption context.
+       void            *uctx;                  //!< Result/resumption context.
 
        uint8_t         code;                   //!< packet code (sigh)
        uint8_t         id;                     //!< our ID
@@ -82,26 +82,31 @@ radius_track_t              *radius_track_alloc(TALLOC_CTX *ctx);
  *     Debug functions which track allocations and frees
  */
 #ifndef NDEBUG
-#  define              radius_track_entry_reserve(_te_out, _ctx, _tt, _request, _code, _rctx) \
-                               _radius_track_entry_reserve(_te_out, _ctx, _tt, _request, _code, _rctx, __FILE__, __LINE__)
-int                    _radius_track_entry_reserve(radius_track_entry_t **te_out,
+#  define              radius_track_entry_reserve(_te_out, _ctx, _tt, _request, _code, _uctx) \
+                               _radius_track_entry_reserve( __FILE__, __LINE__, _te_out, _ctx, _tt, _request, _code, _uctx)
+int                    _radius_track_entry_reserve(char const *file, int line,
+                                                   radius_track_entry_t **te_out,
                                                    TALLOC_CTX *ctx, radius_track_t *tt, REQUEST *request,
-                                                   uint8_t code, void *rctx, char const *file, int line)
-                                                   CC_HINT(nonnull(1,3,4));
+                                                   uint8_t code, void *uctx)
+                                                   CC_HINT(nonnull(3,5,6));
 
 #  define              radius_track_entry_release(_te) \
-                               _radius_track_entry_release(_te, __FILE__, __LINE__)
-int                    _radius_track_entry_release(radius_track_entry_t **te, char const *file, int line)
+                               _radius_track_entry_release( __FILE__, __LINE__, _te)
+int                    _radius_track_entry_release(char const *file, int line, radius_track_entry_t **te)
                                                    CC_HINT(nonnull);
 
-void                   radius_track_state_log(radius_track_t *tt);
+typedef void (*radius_track_log_extra_t)(fr_log_t const *log, fr_log_type_t log_type, char const *file, int line,
+                                        radius_track_entry_t *te);
+
+void                   radius_track_state_log(fr_log_t const *log, fr_log_type_t log_type, char const *file, int line,
+                                              radius_track_t *tt, radius_track_log_extra_t extra);
 /*
  *     Non-debug functions
  */
 #else
 int                    radius_track_entry_reserve(radius_track_entry_t **te_out,
                                                   TALLOC_CTX *ctx, radius_track_t *tt, REQUEST *request,
-                                                  uint8_t code, void *rctx)
+                                                  uint8_t code, void *uctx)
                                                   CC_HINT(nonnull(1,3,4));
 
 int                    radius_track_entry_release(radius_track_entry_t **te) CC_HINT(nonnull);