From: Arran Cudbard-Bell Date: Thu, 9 Apr 2020 19:20:37 +0000 (-0500) Subject: trunk/radius: Print out detailed state log X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=b8e91fe53982f0c7da7aecd34e233fd5103ff25d;p=thirdparty%2Ffreeradius-server.git trunk/radius: Print out detailed state log --- diff --git a/src/lib/server/trunk.c b/src/lib/server/trunk.c index 926a6fa9b1d..8594c74251d 100644 --- 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, ""), \ @@ -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, ""), - fr_table_str_by_value(fr_trunk_request_states, log->to, "")); + 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, ""), + fr_table_str_by_value(fr_trunk_request_states, slog->to, "")); } } #endif diff --git a/src/lib/server/trunk.h b/src/lib/server/trunk.h index f0fc0913c6f..e431abfe653 100644 --- 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 d63f613f35f..45b8143b312 100644 --- 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 d59bec681e0..927d5dffff7 100644 --- 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 c553828f36a..3184d47459d 100644 --- 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);