From 12ae019394bd233733b8c4fd28ec89e2ee7df2d5 Mon Sep 17 00:00:00 2001 From: "jabber.developer2" Date: Thu, 20 Nov 2025 11:36:56 +0300 Subject: [PATCH 1/5] feat(xmpp): add comprehensive connection debug logging Add detailed debug output tracking connection lifecycle, autoping events, and session state transitions with timestamps and counters. - Track connection attempts, successes, disconnects, and reconnects - Log autoping timer events, responses, and timeouts - Record session login, logout, and reconnection attempts - Add elapsed time calculations since key events - Use [CONNDBG] tag for easy log filtering Files: connection.c, iq.c, session.c, connection.h --- src/xmpp/connection.c | 116 ++++++++++++++++++++++++++++++++++++++++++ src/xmpp/connection.h | 10 ++++ src/xmpp/iq.c | 70 ++++++++++++++++++++++++- src/xmpp/session.c | 90 ++++++++++++++++++++++++++++++++ 4 files changed, 285 insertions(+), 1 deletion(-) diff --git a/src/xmpp/connection.c b/src/xmpp/connection.c index 59412718..ab6e2412 100644 --- a/src/xmpp/connection.c +++ b/src/xmpp/connection.c @@ -39,9 +39,11 @@ #include #include #include +#include #include #include +#include #include @@ -84,6 +86,74 @@ static ProfConnection conn; static gchar* profanity_instance_id = NULL; static gchar* prof_identifier = NULL; +// Extended debug tracking +static time_t prof_last_connect_attempt_ts = 0; // when connection_connect was last called +static time_t prof_last_successful_connect_ts = 0; // when we last transitioned to CONNECT/RAW_CONNECT +static time_t prof_last_disconnect_ts = 0; // when we last transitioned to DISCONNECT +static unsigned long prof_connect_attempt_counter = 0; // total calls to connection_connect +static unsigned long prof_successful_connect_counter = 0; // successful CONNECTs +static unsigned long prof_reconnect_counter = 0; // times we forced a reconnect (XMPP_CONN_RECONNECT logic) + +// helper to format elapsed seconds (returns "n/a" if base == 0) +char* +_connection_format_elapsed_time(time_t base, time_t now, char* buf, size_t len) +{ + if (base == 0) { + snprintf(buf, len, "n/a"); + } else { + snprintf(buf, len, "%lds", (long)(now - base)); + } + return buf; +} + +static void +_log_event_header(const char* tag) +{ + time_t now = time(NULL); + struct tm tm_now; + localtime_r(&now, &tm_now); + char ts[32]; + strftime(ts, sizeof(ts), "%Y-%m-%d %H:%M:%S", &tm_now); + + char elapsed_success[32]; + char elapsed_disconnect[32]; + _connection_format_elapsed_time(prof_last_successful_connect_ts, now, elapsed_success, sizeof(elapsed_success)); + _connection_format_elapsed_time(prof_last_disconnect_ts, now, elapsed_disconnect, sizeof(elapsed_disconnect)); + + log_debug("[CONNDBG] %s ts=%s attempts=%lu successes=%lu reconnects=%lu elapsed-since-success=%s elapsed-since-disconnect=%s", tag, ts, + prof_connect_attempt_counter, prof_successful_connect_counter, prof_reconnect_counter, + elapsed_success, elapsed_disconnect); +} + +// Helper to log connection details +static void +_log_connection_details(const char* jid, const char* altdomain, int port, + const char* tls_policy, const char* auth_policy) +{ + char elapsed_disconnect[32]; + time_t now = time(NULL); + _connection_format_elapsed_time(prof_last_disconnect_ts, now, elapsed_disconnect, sizeof(elapsed_disconnect)); + + log_debug("[CONNDBG] details jid=%s altdomain=%s port=%d tls_policy=%s auth_policy=%s attempt#=%lu since-last-disconnect=%s", jid, + altdomain ? altdomain : "(default)", port, tls_policy ? tls_policy : "(default)", + auth_policy ? auth_policy : "(default)", prof_connect_attempt_counter, elapsed_disconnect); +} + +// Helper to log connection status with formatted extra info +static void +_log_connection_status_simple(const char* event, const char* jid, gboolean secured, long flags, const char* format, ...) +{ + auto_gchar gchar* extra_info = NULL; + if (format) { + va_list args; + va_start(args, format); + extra_info = g_strdup_vprintf(format, args); + va_end(args); + } + + log_debug("[CONNDBG] %s jid=%s secured=%d flags=0x%lx %s", event, jid ? jid : "(null)", secured, flags, extra_info ? extra_info : ""); +} + static void _xmpp_file_logger(void* const userdata, const xmpp_log_level_t level, const char* const area, const char* const msg); static void _connection_handler(xmpp_conn_t* const xmpp_conn, const xmpp_conn_event_t status, const int error, @@ -267,7 +337,12 @@ connection_connect(const char* const jid, const char* const passwd, const char* { assert(jid != NULL); assert(passwd != NULL); + prof_connect_attempt_counter++; + prof_last_connect_attempt_ts = time(NULL); + _log_event_header("CONNECT_ATTEMPT"); log_info("Connecting as %s", jid); + + _log_connection_details(jid, altdomain, port, tls_policy, auth_policy); _conn_apply_settings(jid, passwd, tls_policy, auth_policy); @@ -280,8 +355,10 @@ connection_connect(const char* const jid, const char* const passwd, const char* if (connect_status == 0) { conn.conn_status = JABBER_CONNECTING; + log_debug("[CONNDBG] libstrophe connect_client returned success (async). status=JABBER_CONNECTING flags=0x%lx", xmpp_conn_get_flags(conn.xmpp_conn)); } else { conn.conn_status = JABBER_DISCONNECTED; + log_debug("[CONNDBG] libstrophe connect_client returned failure (sync). status=JABBER_DISCONNECTED error=%d", connect_status); } return conn.conn_status; @@ -974,8 +1051,15 @@ _connection_handler(xmpp_conn_t* const xmpp_conn, const xmpp_conn_event_t status // login success case XMPP_CONN_CONNECT: + _log_event_header("CONNECT_SUCCESS"); log_debug("Connection handler: XMPP_CONN_CONNECT"); conn.conn_status = JABBER_CONNECTED; + prof_successful_connect_counter++; + prof_last_successful_connect_ts = time(NULL); + + _log_connection_status_simple("connected", xmpp_conn_get_jid(conn.xmpp_conn), xmpp_conn_is_secured(xmpp_conn), + xmpp_conn_get_flags(conn.xmpp_conn), + conn.queued_messages ? "queued_messages=yes" : "queued_messages=no"); connection_get_jid(); conn.domain = strdup(conn.jid->domainpart); @@ -1000,8 +1084,14 @@ _connection_handler(xmpp_conn_t* const xmpp_conn, const xmpp_conn_event_t status // raw connection success case XMPP_CONN_RAW_CONNECT: + _log_event_header("RAW_CONNECT_SUCCESS"); log_debug("Connection handler: XMPP_CONN_RAW_CONNECT"); conn.conn_status = JABBER_RAW_CONNECTED; + prof_successful_connect_counter++; + prof_last_successful_connect_ts = time(NULL); + + _log_connection_status_simple("raw connected", xmpp_conn_get_jid(conn.xmpp_conn), FALSE, + xmpp_conn_get_flags(conn.xmpp_conn), ""); connection_get_jid(); conn.jid = jid_create(xmpp_conn_get_jid(conn.xmpp_conn)); @@ -1018,13 +1108,25 @@ _connection_handler(xmpp_conn_t* const xmpp_conn, const xmpp_conn_event_t status // disconnected case XMPP_CONN_DISCONNECT: + _log_event_header("DISCONNECT_EVENT"); log_debug("Connection handler: XMPP_CONN_DISCONNECT"); + + _log_connection_status_simple("disconnect", NULL, FALSE, 0, + "previous_status=%d error=%d has_stream_error=%s", + (int)conn.conn_status, error, + (stream_error && stream_error->stanza) ? "yes" : "no"); + prof_last_disconnect_ts = time(NULL); // lost connection for unknown reason if (conn.conn_status == JABBER_CONNECTED || conn.conn_status == JABBER_DISCONNECTING) { if (prefs_get_boolean(PREF_STROPHE_SM_ENABLED)) { int send_queue_len = xmpp_conn_send_queue_len(conn.xmpp_conn); log_debug("Connection handler: Lost connection for unknown reason, %d messages in send queue", send_queue_len); + log_debug("[CONNDBG] SM enabled=%d resend_pref=%d send_queue_len=%d", + prefs_get_boolean(PREF_STROPHE_SM_ENABLED), + prefs_get_boolean(PREF_STROPHE_SM_RESEND), + send_queue_len); + conn.sm_state = xmpp_conn_get_sm_state(conn.xmpp_conn); if (send_queue_len > 0 && prefs_get_boolean(PREF_STROPHE_SM_RESEND)) { conn.queued_messages = calloc(send_queue_len + 1, sizeof(*conn.queued_messages)); @@ -1045,6 +1147,10 @@ _connection_handler(xmpp_conn_t* const xmpp_conn, const xmpp_conn_event_t status if (stream_error && stream_error->stanza && _get_other_host(stream_error->stanza, &host, &port)) { session_reconnect(host, port); log_debug("Connection handler: Forcing a re-connect to \"%s\"", host); + prof_reconnect_counter++; + log_debug("[CONNDBG] trigger=see-other-host host=%s port=%d reconnect_counter=%lu", + host, port, prof_reconnect_counter); + conn.conn_status = JABBER_RECONNECT; return; } @@ -1059,7 +1165,10 @@ _connection_handler(xmpp_conn_t* const xmpp_conn, const xmpp_conn_event_t status // connection failed case XMPP_CONN_FAIL: + _log_event_header("CONNECT_FAIL_EVENT"); log_debug("Connection handler: XMPP_CONN_FAIL"); + + _log_connection_status_simple("fail", NULL, FALSE, 0, "previous_status=%d error=%d", (int)conn.conn_status, error); break; // unknown state @@ -1193,3 +1302,10 @@ connection_debug_print_features() log_debug("=== End of Features ==="); } + +// --- Extended debug accessors --- +time_t connection_last_successful_connect_ts(void) { return prof_last_successful_connect_ts; } +time_t connection_last_disconnect_ts(void) { return prof_last_disconnect_ts; } +unsigned long connection_connect_attempts(void) { return prof_connect_attempt_counter; } +unsigned long connection_successful_connects(void) { return prof_successful_connect_counter; } +unsigned long connection_reconnect_counter(void) { return prof_reconnect_counter; } diff --git a/src/xmpp/connection.h b/src/xmpp/connection.h index 897a9fbc..50eee7a6 100644 --- a/src/xmpp/connection.h +++ b/src/xmpp/connection.h @@ -37,6 +37,7 @@ #define XMPP_CONNECTION_H #include "xmpp/xmpp.h" +#include #define CON_RAND_ID_LEN 15 @@ -68,4 +69,13 @@ void connection_remove_available_resource(const char* const resource); char* connection_create_stanza_id(void); +// Extended debug accessors +time_t connection_last_successful_connect_ts(void); +time_t connection_last_disconnect_ts(void); +unsigned long connection_connect_attempts(void); +unsigned long connection_successful_connects(void); +unsigned long connection_reconnect_counter(void); + +char* _connection_format_elapsed_time(time_t base, time_t now, char* buf, size_t len); + #endif diff --git a/src/xmpp/iq.c b/src/xmpp/iq.c index 5609d2ec..191557b7 100644 --- a/src/xmpp/iq.c +++ b/src/xmpp/iq.c @@ -38,6 +38,7 @@ #include #include #include +#include #include #include @@ -172,6 +173,32 @@ static GHashTable* rooms_cache = NULL; static GSList* late_delivery_windows = NULL; static gboolean received_disco_items = FALSE; +static void +_iq_get_debug_stats(time_t* now_out, char* elapsed_connect, size_t len) +{ + time_t now = time(NULL); + time_t last_success = connection_last_successful_connect_ts(); + if (now_out) *now_out = now; + _connection_format_elapsed_time(last_success, now, elapsed_connect, len); +} + +// Helper function to log autoping debug info +static void +_iq_log_autoping_debug(const char* event, const char* extra_info) +{ + time_t now; + char elapsed_connect[32]; + _iq_get_debug_stats(&now, elapsed_connect, sizeof(elapsed_connect)); + + if (extra_info) { + log_debug("[CONNDBG] %s ts=%ld elapsed-since-connect=%s %s", + event, (long)now, elapsed_connect, extra_info); + } else { + log_debug("[CONNDBG] %s ts=%ld elapsed-since-connect=%s", + event, (long)now, elapsed_connect); + } +} + static int _iq_handler(xmpp_conn_t* const conn, xmpp_stanza_t* const stanza, void* const userdata) { @@ -371,6 +398,10 @@ iq_id_handler_add(const char* const id, ProfIqCallback func, ProfIqFreeCallback void iq_autoping_timer_cancel(void) { + gdouble elapsed = autoping_time ? g_timer_elapsed(autoping_time, NULL) : 0.0; + auto_gchar gchar* extra = g_strdup_printf("was_waiting=%d elapsed=%.3fs", autoping_wait, elapsed); + _iq_log_autoping_debug("AUTOPING_TIMER_CANCEL", extra); + autoping_wait = FALSE; if (autoping_time) { g_timer_destroy(autoping_time); @@ -397,6 +428,9 @@ iq_autoping_check(void) unsigned long seconds_elapsed = elapsed * 1.0; gint timeout = prefs_get_autoping_timeout(); if (timeout > 0 && seconds_elapsed >= timeout) { + auto_gchar gchar* extra = g_strdup_printf("elapsed=%.1fs timeout=%ds", elapsed, timeout); + _iq_log_autoping_debug("AUTOPING_TIMEOUT", extra); + cons_show("Autoping response timed out after %u seconds.", timeout); log_debug("Autoping check: timed out after %u seconds, disconnecting", timeout); iq_autoping_timer_cancel(); @@ -408,6 +442,8 @@ void iq_set_autoping(const int seconds) { if (connection_get_status() != JABBER_CONNECTED) { + auto_gchar gchar* extra = g_strdup_printf("seconds=%d reason=not_connected", seconds); + _iq_log_autoping_debug("AUTOPING_SET_SKIPPED", extra); return; } @@ -415,9 +451,14 @@ iq_set_autoping(const int seconds) xmpp_timed_handler_delete(conn, _autoping_timed_send); if (seconds == 0) { + _iq_log_autoping_debug("AUTOPING_DISABLED", "seconds=0"); return; } + int timeout = prefs_get_autoping_timeout(); + auto_gchar gchar* extra = g_strdup_printf("interval=%ds timeout=%ds", seconds, timeout); + _iq_log_autoping_debug("AUTOPING_SET", extra); + int millis = seconds * 1000; xmpp_ctx_t* const ctx = connection_get_ctx(); xmpp_timed_handler_add(conn, _autoping_timed_send, millis, ctx); @@ -1426,9 +1467,16 @@ _autoping_timed_send(xmpp_conn_t* const conn, void* const userdata) return 1; } + int autoping_interval = prefs_get_autoping(); + int autoping_timeout = prefs_get_autoping_timeout(); + auto_gchar gchar* extra = g_strdup_printf("interval=%ds timeout=%ds", autoping_interval, autoping_timeout); + _iq_log_autoping_debug("AUTOPING_TIMER_FIRED", extra); + if (connection_supports(XMPP_FEATURE_PING) == FALSE) { // TODO: do we need to check it on each autoping call? log_warning("Server doesn't advertise %s feature.", XMPP_FEATURE_PING); + auto_gchar gchar* feat_extra = g_strdup_printf("feature=%s", XMPP_FEATURE_PING); + _iq_log_autoping_debug("AUTOPING_FEATURE_MISSING", feat_extra); if (!autoping_error_shown) { connection_debug_print_features(); cons_show_error("Server ping not supported (%s). Check log for details.", XMPP_FEATURE_PING); @@ -1438,6 +1486,7 @@ _autoping_timed_send(xmpp_conn_t* const conn, void* const userdata) if (autoping_wait) { log_debug("Autoping: Existing ping already in progress, aborting"); + _iq_log_autoping_debug("AUTOPING_ALREADY_PENDING", NULL); return 1; } @@ -1445,6 +1494,9 @@ _autoping_timed_send(xmpp_conn_t* const conn, void* const userdata) xmpp_stanza_t* iq = stanza_create_ping_iq(ctx, NULL); const char* id = xmpp_stanza_get_id(iq); log_debug("Autoping: Sending ping request: %s", id); + + auto_gchar gchar* send_extra = g_strdup_printf("id=%s timeout=%ds", id, autoping_timeout); + _iq_log_autoping_debug("AUTOPING_SEND", send_extra); // add pong handler iq_id_handler_add(id, _auto_pong_id_handler, NULL, NULL); @@ -1463,8 +1515,12 @@ _autoping_timed_send(xmpp_conn_t* const conn, void* const userdata) void autoping_timer_extend(void) { - if (autoping_time) + if (autoping_time) { + gdouble elapsed = g_timer_elapsed(autoping_time, NULL); + auto_gchar gchar* extra = g_strdup_printf("elapsed_before_reset=%.3fs", elapsed); + _iq_log_autoping_debug("AUTOPING_TIMER_EXTEND", extra); g_timer_start(autoping_time); + } } static int @@ -1473,8 +1529,12 @@ _auto_pong_id_handler(xmpp_stanza_t* const stanza, void* const userdata) iq_autoping_timer_cancel(); const char* id = xmpp_stanza_get_id(stanza); + gdouble response_time = autoping_time ? g_timer_elapsed(autoping_time, NULL) : 0.0; + if (id == NULL) { log_debug("Autoping: Pong handler fired."); + auto_gchar gchar* extra = g_strdup_printf("id=(null) response_time=%.3fs", response_time); + _iq_log_autoping_debug("AUTOPING_PONG_RECEIVED", extra); return 0; } @@ -1482,15 +1542,21 @@ _auto_pong_id_handler(xmpp_stanza_t* const stanza, void* const userdata) const char* type = xmpp_stanza_get_type(stanza); if (type == NULL) { + auto_gchar gchar* extra = g_strdup_printf("id=%s response_time=%.3fs type=(null)", id, response_time); + _iq_log_autoping_debug("AUTOPING_PONG_RECEIVED", extra); return 0; } if (g_strcmp0(type, STANZA_TYPE_ERROR) != 0) { + auto_gchar gchar* extra = g_strdup_printf("id=%s response_time=%.3fs type=%s", id, response_time, type); + _iq_log_autoping_debug("AUTOPING_PONG_SUCCESS", extra); return 0; } // show warning if error auto_char char* error_msg = stanza_get_error_message(stanza); log_warning("Server ping (id=%s) responded with error: %s", id, error_msg); + auto_gchar gchar* err_extra = g_strdup_printf("id=%s response_time=%.3fs error=%s", id, response_time, error_msg); + _iq_log_autoping_debug("AUTOPING_PONG_ERROR", err_extra); // turn off autoping if error type is 'cancel' xmpp_stanza_t* error = xmpp_stanza_get_child_by_name(stanza, STANZA_NAME_ERROR); @@ -1503,6 +1569,8 @@ _auto_pong_id_handler(xmpp_stanza_t* const stanza, void* const userdata) } if (g_strcmp0(errtype, STANZA_TYPE_CANCEL) == 0) { log_warning("Server ping (id=%s) error type 'cancel', disabling autoping.", id); + auto_gchar gchar* disable_extra = g_strdup_printf("id=%s errtype=cancel", id); + _iq_log_autoping_debug("AUTOPING_DISABLED", disable_extra); prefs_set_autoping(0); cons_show_error("Autoping is not supported by the server (stanza cancelled). The feature has been disabled automatically."); xmpp_timed_handler_delete(connection_get_conn(), _autoping_timed_send); diff --git a/src/xmpp/session.c b/src/xmpp/session.c index 75fa891a..3e48a82d 100644 --- a/src/xmpp/session.c +++ b/src/xmpp/session.c @@ -38,6 +38,7 @@ #include #include #include +#include #include "profanity.h" #include "log.h" @@ -95,6 +96,72 @@ static GTimer* reconnect_timer; static activity_state_t activity_state; static resource_presence_t saved_presence; static char* saved_status; +static unsigned long session_reconnect_attempt_counter = 0; // extended debug counter + +static void +_session_get_debug_stats(time_t* now_out, char* elapsed_success, size_t success_len, char* elapsed_disconnect, size_t disconnect_len) +{ + time_t now = time(NULL); + time_t last_success = connection_last_successful_connect_ts(); + time_t last_disc = connection_last_disconnect_ts(); + + if (now_out) *now_out = now; + _connection_format_elapsed_time(last_success, now, elapsed_success, success_len); + _connection_format_elapsed_time(last_disc, now, elapsed_disconnect, disconnect_len); +} + +// Helper function to log connection debug info +static void +_session_log_connect_debug(const char* event, const char* account, const char* jid, + const char* server, int port, const char* tls_policy, const char* auth_policy) +{ + time_t now; + char elapsed_success[32]; + char elapsed_disconnect[32]; + _session_get_debug_stats(&now, elapsed_success, sizeof(elapsed_success), elapsed_disconnect, sizeof(elapsed_disconnect)); + + log_debug("[CONNDBG] %s ts=%ld account=%s jid=%s server=%s port=%d tls_policy=%s auth_policy=%s elapsed-since-success=%s elapsed-since-disconnect=%s total-attempts=%lu total-success=%lu", + event, (long)now, account ? account : "(none)", jid ? jid : "(none)", + server ? server : "(default)", port, + tls_policy ? tls_policy : "(default)", + auth_policy ? auth_policy : "(default)", + elapsed_success, elapsed_disconnect, + connection_connect_attempts(), connection_successful_connects()); +} + +// Helper function to log session state debug info +static void +_session_log_state_debug(const char* event, int extra_param) +{ + time_t now; + char elapsed_success[32]; + char elapsed_disconnect[32]; + _session_get_debug_stats(&now, elapsed_success, sizeof(elapsed_success), elapsed_disconnect, sizeof(elapsed_disconnect)); + + log_debug("[CONNDBG] %s ts=%ld param=%d account=%s elapsed-since-success=%s elapsed-since-disconnect=%s total-attempts=%lu total-success=%lu session-reconnects=%lu", + event, (long)now, extra_param, + saved_account.name ? saved_account.name : "(none)", + elapsed_success, elapsed_disconnect, + connection_connect_attempts(), connection_successful_connects(), + session_reconnect_attempt_counter); +} + +// Helper function to log reconnect attempt +static void +_session_log_reconnect_debug(unsigned long attempt_num, const char* account, const char* jid, + const char* server, unsigned short port, const char* tls_policy, const char* auth_policy) +{ + time_t now; + char elapsed_success[32]; + char elapsed_disconnect[32]; + _session_get_debug_stats(&now, elapsed_success, sizeof(elapsed_success), elapsed_disconnect, sizeof(elapsed_disconnect)); + + log_debug("[CONNDBG] RECONNECT_ATTEMPT #%lu ts=%ld account=%s jid=%s server=%s port=%u tls_policy=%s auth_policy=%s elapsed-since-success=%s elapsed-since-disconnect=%s total-connect-attempts=%lu total-success=%lu global-reconnects=%lu", + attempt_num, (long)now, account, jid, server ? server : "(null)", port, + tls_policy ? tls_policy : "(default)", auth_policy ? auth_policy : "(default)", + elapsed_success, elapsed_disconnect, + connection_connect_attempts(), connection_successful_connects(), connection_reconnect_counter()); +} static void _session_free_internals(void); static void _session_free_saved_details(void); @@ -133,6 +200,8 @@ session_connect_with_account(const ProfAccount* const account) assert(account != NULL); log_info("Connecting using account: %s", account->name); + _session_log_connect_debug("SESSION_CONNECT_WITH_ACCOUNT", account->name, account->jid, + account->server, account->port, account->tls_policy, account->auth_policy); _session_free_internals(); @@ -166,6 +235,9 @@ session_connect_with_details(const char* const jid, const char* const passwd, co assert(jid != NULL); assert(passwd != NULL); + _session_log_connect_debug("SESSION_CONNECT_WITH_DETAILS", NULL, jid, + altdomain, port, tls_policy, auth_policy); + _session_free_internals(); // save details for reconnect, remember name for account creating on success @@ -218,12 +290,17 @@ session_connect_with_details(const char* const jid, const char* const passwd, co void session_autoping_fail(void) { + int autoping_timeout = prefs_get_autoping_timeout(); + _session_log_state_debug("SESSION_AUTOPING_FAIL", autoping_timeout); session_lost_connection(); } void session_disconnect(void) { + jabber_conn_status_t conn_status = connection_get_status(); + _session_log_state_debug("SESSION_DISCONNECT", (int)conn_status); + // if connected, send end stream and wait for response if (connection_get_status() == JABBER_CONNECTED) { log_info("Closing connection"); @@ -319,6 +396,8 @@ _receive_mood(xmpp_stanza_t* const stanza, void* const userdata) void session_login_success(gboolean secured) { + _session_log_state_debug("SESSION_LOGIN_SUCCESS", secured); + chat_sessions_init(); message_handlers_init(); @@ -370,6 +449,8 @@ session_login_success(gboolean secured) void session_login_failed(void) { + _session_log_state_debug("SESSION_LOGIN_FAILED", reconnect_timer != NULL); + if (reconnect_timer == NULL) { log_debug("Connection handler: No reconnect timer"); sv_ev_failed_login(); @@ -389,12 +470,17 @@ session_login_failed(void) void session_lost_connection(void) { + int reconnect_sec = prefs_get_reconnect(); + _session_log_state_debug("SESSION_LOST_CONNECTION", reconnect_sec); + /* this callback also clears all cached data */ sv_ev_lost_connection(); if (prefs_get_reconnect() != 0) { assert(reconnect_timer == NULL); reconnect_timer = g_timer_new(); + log_debug("[CONNDBG] created reconnect timer, will reconnect in %d seconds", reconnect_sec); } else { + log_debug("[CONNDBG] reconnect disabled, freeing session internals"); _session_free_internals(); } } @@ -574,6 +660,10 @@ session_reconnect_now(void) port = account->port; } + session_reconnect_attempt_counter++; + _session_log_reconnect_debug(session_reconnect_attempt_counter, account->name, jid, + server, port, account->tls_policy, account->auth_policy); + log_debug("Attempting reconnect with account %s", account->name); connection_connect(jid, saved_account.passwd, server, port, account->tls_policy, account->auth_policy); account_free(account); -- 2.49.1 From 4933e1cff9530399903d91bb5e4c87b3c9735491 Mon Sep 17 00:00:00 2001 From: "jabber.developer2" Date: Thu, 20 Nov 2025 11:45:21 +0300 Subject: [PATCH 2/5] fix(xmpp): clang-tidy warnings for extended debug info --- src/xmpp/connection.c | 80 +++++++++++++++++++++++++++---------------- src/xmpp/iq.c | 9 ++--- src/xmpp/session.c | 13 +++---- 3 files changed, 62 insertions(+), 40 deletions(-) diff --git a/src/xmpp/connection.c b/src/xmpp/connection.c index ab6e2412..8fa95400 100644 --- a/src/xmpp/connection.c +++ b/src/xmpp/connection.c @@ -87,12 +87,12 @@ static gchar* profanity_instance_id = NULL; static gchar* prof_identifier = NULL; // Extended debug tracking -static time_t prof_last_connect_attempt_ts = 0; // when connection_connect was last called -static time_t prof_last_successful_connect_ts = 0; // when we last transitioned to CONNECT/RAW_CONNECT -static time_t prof_last_disconnect_ts = 0; // when we last transitioned to DISCONNECT -static unsigned long prof_connect_attempt_counter = 0; // total calls to connection_connect +static time_t prof_last_connect_attempt_ts = 0; // when connection_connect was last called +static time_t prof_last_successful_connect_ts = 0; // when we last transitioned to CONNECT/RAW_CONNECT +static time_t prof_last_disconnect_ts = 0; // when we last transitioned to DISCONNECT +static unsigned long prof_connect_attempt_counter = 0; // total calls to connection_connect static unsigned long prof_successful_connect_counter = 0; // successful CONNECTs -static unsigned long prof_reconnect_counter = 0; // times we forced a reconnect (XMPP_CONN_RECONNECT logic) +static unsigned long prof_reconnect_counter = 0; // times we forced a reconnect (XMPP_CONN_RECONNECT logic) // helper to format elapsed seconds (returns "n/a" if base == 0) char* @@ -114,7 +114,7 @@ _log_event_header(const char* tag) localtime_r(&now, &tm_now); char ts[32]; strftime(ts, sizeof(ts), "%Y-%m-%d %H:%M:%S", &tm_now); - + char elapsed_success[32]; char elapsed_disconnect[32]; _connection_format_elapsed_time(prof_last_successful_connect_ts, now, elapsed_success, sizeof(elapsed_success)); @@ -127,7 +127,7 @@ _log_event_header(const char* tag) // Helper to log connection details static void -_log_connection_details(const char* jid, const char* altdomain, int port, +_log_connection_details(const char* jid, const char* altdomain, int port, const char* tls_policy, const char* auth_policy) { char elapsed_disconnect[32]; @@ -135,7 +135,7 @@ _log_connection_details(const char* jid, const char* altdomain, int port, _connection_format_elapsed_time(prof_last_disconnect_ts, now, elapsed_disconnect, sizeof(elapsed_disconnect)); log_debug("[CONNDBG] details jid=%s altdomain=%s port=%d tls_policy=%s auth_policy=%s attempt#=%lu since-last-disconnect=%s", jid, - altdomain ? altdomain : "(default)", port, tls_policy ? tls_policy : "(default)", + altdomain ? altdomain : "(default)", port, tls_policy ? tls_policy : "(default)", auth_policy ? auth_policy : "(default)", prof_connect_attempt_counter, elapsed_disconnect); } @@ -150,7 +150,7 @@ _log_connection_status_simple(const char* event, const char* jid, gboolean secur extra_info = g_strdup_vprintf(format, args); va_end(args); } - + log_debug("[CONNDBG] %s jid=%s secured=%d flags=0x%lx %s", event, jid ? jid : "(null)", secured, flags, extra_info ? extra_info : ""); } @@ -341,7 +341,7 @@ connection_connect(const char* const jid, const char* const passwd, const char* prof_last_connect_attempt_ts = time(NULL); _log_event_header("CONNECT_ATTEMPT"); log_info("Connecting as %s", jid); - + _log_connection_details(jid, altdomain, port, tls_policy, auth_policy); _conn_apply_settings(jid, passwd, tls_policy, auth_policy); @@ -1056,9 +1056,9 @@ _connection_handler(xmpp_conn_t* const xmpp_conn, const xmpp_conn_event_t status conn.conn_status = JABBER_CONNECTED; prof_successful_connect_counter++; prof_last_successful_connect_ts = time(NULL); - - _log_connection_status_simple("connected", xmpp_conn_get_jid(conn.xmpp_conn), xmpp_conn_is_secured(xmpp_conn), - xmpp_conn_get_flags(conn.xmpp_conn), + + _log_connection_status_simple("connected", xmpp_conn_get_jid(conn.xmpp_conn), xmpp_conn_is_secured(xmpp_conn), + xmpp_conn_get_flags(conn.xmpp_conn), conn.queued_messages ? "queued_messages=yes" : "queued_messages=no"); connection_get_jid(); @@ -1089,7 +1089,7 @@ _connection_handler(xmpp_conn_t* const xmpp_conn, const xmpp_conn_event_t status conn.conn_status = JABBER_RAW_CONNECTED; prof_successful_connect_counter++; prof_last_successful_connect_ts = time(NULL); - + _log_connection_status_simple("raw connected", xmpp_conn_get_jid(conn.xmpp_conn), FALSE, xmpp_conn_get_flags(conn.xmpp_conn), ""); @@ -1110,10 +1110,10 @@ _connection_handler(xmpp_conn_t* const xmpp_conn, const xmpp_conn_event_t status case XMPP_CONN_DISCONNECT: _log_event_header("DISCONNECT_EVENT"); log_debug("Connection handler: XMPP_CONN_DISCONNECT"); - - _log_connection_status_simple("disconnect", NULL, FALSE, 0, - "previous_status=%d error=%d has_stream_error=%s", - (int)conn.conn_status, error, + + _log_connection_status_simple("disconnect", NULL, FALSE, 0, + "previous_status=%d error=%d has_stream_error=%s", + (int)conn.conn_status, error, (stream_error && stream_error->stanza) ? "yes" : "no"); prof_last_disconnect_ts = time(NULL); @@ -1122,11 +1122,11 @@ _connection_handler(xmpp_conn_t* const xmpp_conn, const xmpp_conn_event_t status if (prefs_get_boolean(PREF_STROPHE_SM_ENABLED)) { int send_queue_len = xmpp_conn_send_queue_len(conn.xmpp_conn); log_debug("Connection handler: Lost connection for unknown reason, %d messages in send queue", send_queue_len); - log_debug("[CONNDBG] SM enabled=%d resend_pref=%d send_queue_len=%d", - prefs_get_boolean(PREF_STROPHE_SM_ENABLED), - prefs_get_boolean(PREF_STROPHE_SM_RESEND), + log_debug("[CONNDBG] SM enabled=%d resend_pref=%d send_queue_len=%d", + prefs_get_boolean(PREF_STROPHE_SM_ENABLED), + prefs_get_boolean(PREF_STROPHE_SM_RESEND), send_queue_len); - + conn.sm_state = xmpp_conn_get_sm_state(conn.xmpp_conn); if (send_queue_len > 0 && prefs_get_boolean(PREF_STROPHE_SM_RESEND)) { conn.queued_messages = calloc(send_queue_len + 1, sizeof(*conn.queued_messages)); @@ -1148,9 +1148,9 @@ _connection_handler(xmpp_conn_t* const xmpp_conn, const xmpp_conn_event_t status session_reconnect(host, port); log_debug("Connection handler: Forcing a re-connect to \"%s\"", host); prof_reconnect_counter++; - log_debug("[CONNDBG] trigger=see-other-host host=%s port=%d reconnect_counter=%lu", + log_debug("[CONNDBG] trigger=see-other-host host=%s port=%d reconnect_counter=%lu", host, port, prof_reconnect_counter); - + conn.conn_status = JABBER_RECONNECT; return; } @@ -1167,7 +1167,7 @@ _connection_handler(xmpp_conn_t* const xmpp_conn, const xmpp_conn_event_t status case XMPP_CONN_FAIL: _log_event_header("CONNECT_FAIL_EVENT"); log_debug("Connection handler: XMPP_CONN_FAIL"); - + _log_connection_status_simple("fail", NULL, FALSE, 0, "previous_status=%d error=%d", (int)conn.conn_status, error); break; @@ -1304,8 +1304,28 @@ connection_debug_print_features() } // --- Extended debug accessors --- -time_t connection_last_successful_connect_ts(void) { return prof_last_successful_connect_ts; } -time_t connection_last_disconnect_ts(void) { return prof_last_disconnect_ts; } -unsigned long connection_connect_attempts(void) { return prof_connect_attempt_counter; } -unsigned long connection_successful_connects(void) { return prof_successful_connect_counter; } -unsigned long connection_reconnect_counter(void) { return prof_reconnect_counter; } +time_t +connection_last_successful_connect_ts(void) +{ + return prof_last_successful_connect_ts; +} +time_t +connection_last_disconnect_ts(void) +{ + return prof_last_disconnect_ts; +} +unsigned long +connection_connect_attempts(void) +{ + return prof_connect_attempt_counter; +} +unsigned long +connection_successful_connects(void) +{ + return prof_successful_connect_counter; +} +unsigned long +connection_reconnect_counter(void) +{ + return prof_reconnect_counter; +} diff --git a/src/xmpp/iq.c b/src/xmpp/iq.c index 191557b7..0363bcf6 100644 --- a/src/xmpp/iq.c +++ b/src/xmpp/iq.c @@ -178,7 +178,8 @@ _iq_get_debug_stats(time_t* now_out, char* elapsed_connect, size_t len) { time_t now = time(NULL); time_t last_success = connection_last_successful_connect_ts(); - if (now_out) *now_out = now; + if (now_out) + *now_out = now; _connection_format_elapsed_time(last_success, now, elapsed_connect, len); } @@ -401,7 +402,7 @@ iq_autoping_timer_cancel(void) gdouble elapsed = autoping_time ? g_timer_elapsed(autoping_time, NULL) : 0.0; auto_gchar gchar* extra = g_strdup_printf("was_waiting=%d elapsed=%.3fs", autoping_wait, elapsed); _iq_log_autoping_debug("AUTOPING_TIMER_CANCEL", extra); - + autoping_wait = FALSE; if (autoping_time) { g_timer_destroy(autoping_time); @@ -1494,7 +1495,7 @@ _autoping_timed_send(xmpp_conn_t* const conn, void* const userdata) xmpp_stanza_t* iq = stanza_create_ping_iq(ctx, NULL); const char* id = xmpp_stanza_get_id(iq); log_debug("Autoping: Sending ping request: %s", id); - + auto_gchar gchar* send_extra = g_strdup_printf("id=%s timeout=%ds", id, autoping_timeout); _iq_log_autoping_debug("AUTOPING_SEND", send_extra); @@ -1530,7 +1531,7 @@ _auto_pong_id_handler(xmpp_stanza_t* const stanza, void* const userdata) const char* id = xmpp_stanza_get_id(stanza); gdouble response_time = autoping_time ? g_timer_elapsed(autoping_time, NULL) : 0.0; - + if (id == NULL) { log_debug("Autoping: Pong handler fired."); auto_gchar gchar* extra = g_strdup_printf("id=(null) response_time=%.3fs", response_time); diff --git a/src/xmpp/session.c b/src/xmpp/session.c index 3e48a82d..69597081 100644 --- a/src/xmpp/session.c +++ b/src/xmpp/session.c @@ -105,7 +105,8 @@ _session_get_debug_stats(time_t* now_out, char* elapsed_success, size_t success_ time_t last_success = connection_last_successful_connect_ts(); time_t last_disc = connection_last_disconnect_ts(); - if (now_out) *now_out = now; + if (now_out) + *now_out = now; _connection_format_elapsed_time(last_success, now, elapsed_success, success_len); _connection_format_elapsed_time(last_disc, now, elapsed_disconnect, disconnect_len); } @@ -113,7 +114,7 @@ _session_get_debug_stats(time_t* now_out, char* elapsed_success, size_t success_ // Helper function to log connection debug info static void _session_log_connect_debug(const char* event, const char* account, const char* jid, - const char* server, int port, const char* tls_policy, const char* auth_policy) + const char* server, int port, const char* tls_policy, const char* auth_policy) { time_t now; char elapsed_success[32]; @@ -149,7 +150,7 @@ _session_log_state_debug(const char* event, int extra_param) // Helper function to log reconnect attempt static void _session_log_reconnect_debug(unsigned long attempt_num, const char* account, const char* jid, - const char* server, unsigned short port, const char* tls_policy, const char* auth_policy) + const char* server, unsigned short port, const char* tls_policy, const char* auth_policy) { time_t now; char elapsed_success[32]; @@ -201,7 +202,7 @@ session_connect_with_account(const ProfAccount* const account) log_info("Connecting using account: %s", account->name); _session_log_connect_debug("SESSION_CONNECT_WITH_ACCOUNT", account->name, account->jid, - account->server, account->port, account->tls_policy, account->auth_policy); + account->server, account->port, account->tls_policy, account->auth_policy); _session_free_internals(); @@ -236,7 +237,7 @@ session_connect_with_details(const char* const jid, const char* const passwd, co assert(passwd != NULL); _session_log_connect_debug("SESSION_CONNECT_WITH_DETAILS", NULL, jid, - altdomain, port, tls_policy, auth_policy); + altdomain, port, tls_policy, auth_policy); _session_free_internals(); @@ -662,7 +663,7 @@ session_reconnect_now(void) session_reconnect_attempt_counter++; _session_log_reconnect_debug(session_reconnect_attempt_counter, account->name, jid, - server, port, account->tls_policy, account->auth_policy); + server, port, account->tls_policy, account->auth_policy); log_debug("Attempting reconnect with account %s", account->name); connection_connect(jid, saved_account.passwd, server, port, account->tls_policy, account->auth_policy); -- 2.49.1 From ade40a823839af60e1cd5225a20ae10f4219ab0f Mon Sep 17 00:00:00 2001 From: "jabber.developer2" Date: Fri, 21 Nov 2025 11:09:40 +0300 Subject: [PATCH 3/5] refactor(xmpp): remove extended debug logging and related functions --- src/xmpp/connection.c | 142 ++---------------------------------------- src/xmpp/connection.h | 10 --- src/xmpp/iq.c | 71 +-------------------- src/xmpp/session.c | 103 +++--------------------------- 4 files changed, 17 insertions(+), 309 deletions(-) diff --git a/src/xmpp/connection.c b/src/xmpp/connection.c index 8fa95400..728eb191 100644 --- a/src/xmpp/connection.c +++ b/src/xmpp/connection.c @@ -39,11 +39,9 @@ #include #include #include -#include #include #include -#include #include @@ -86,74 +84,6 @@ static ProfConnection conn; static gchar* profanity_instance_id = NULL; static gchar* prof_identifier = NULL; -// Extended debug tracking -static time_t prof_last_connect_attempt_ts = 0; // when connection_connect was last called -static time_t prof_last_successful_connect_ts = 0; // when we last transitioned to CONNECT/RAW_CONNECT -static time_t prof_last_disconnect_ts = 0; // when we last transitioned to DISCONNECT -static unsigned long prof_connect_attempt_counter = 0; // total calls to connection_connect -static unsigned long prof_successful_connect_counter = 0; // successful CONNECTs -static unsigned long prof_reconnect_counter = 0; // times we forced a reconnect (XMPP_CONN_RECONNECT logic) - -// helper to format elapsed seconds (returns "n/a" if base == 0) -char* -_connection_format_elapsed_time(time_t base, time_t now, char* buf, size_t len) -{ - if (base == 0) { - snprintf(buf, len, "n/a"); - } else { - snprintf(buf, len, "%lds", (long)(now - base)); - } - return buf; -} - -static void -_log_event_header(const char* tag) -{ - time_t now = time(NULL); - struct tm tm_now; - localtime_r(&now, &tm_now); - char ts[32]; - strftime(ts, sizeof(ts), "%Y-%m-%d %H:%M:%S", &tm_now); - - char elapsed_success[32]; - char elapsed_disconnect[32]; - _connection_format_elapsed_time(prof_last_successful_connect_ts, now, elapsed_success, sizeof(elapsed_success)); - _connection_format_elapsed_time(prof_last_disconnect_ts, now, elapsed_disconnect, sizeof(elapsed_disconnect)); - - log_debug("[CONNDBG] %s ts=%s attempts=%lu successes=%lu reconnects=%lu elapsed-since-success=%s elapsed-since-disconnect=%s", tag, ts, - prof_connect_attempt_counter, prof_successful_connect_counter, prof_reconnect_counter, - elapsed_success, elapsed_disconnect); -} - -// Helper to log connection details -static void -_log_connection_details(const char* jid, const char* altdomain, int port, - const char* tls_policy, const char* auth_policy) -{ - char elapsed_disconnect[32]; - time_t now = time(NULL); - _connection_format_elapsed_time(prof_last_disconnect_ts, now, elapsed_disconnect, sizeof(elapsed_disconnect)); - - log_debug("[CONNDBG] details jid=%s altdomain=%s port=%d tls_policy=%s auth_policy=%s attempt#=%lu since-last-disconnect=%s", jid, - altdomain ? altdomain : "(default)", port, tls_policy ? tls_policy : "(default)", - auth_policy ? auth_policy : "(default)", prof_connect_attempt_counter, elapsed_disconnect); -} - -// Helper to log connection status with formatted extra info -static void -_log_connection_status_simple(const char* event, const char* jid, gboolean secured, long flags, const char* format, ...) -{ - auto_gchar gchar* extra_info = NULL; - if (format) { - va_list args; - va_start(args, format); - extra_info = g_strdup_vprintf(format, args); - va_end(args); - } - - log_debug("[CONNDBG] %s jid=%s secured=%d flags=0x%lx %s", event, jid ? jid : "(null)", secured, flags, extra_info ? extra_info : ""); -} - static void _xmpp_file_logger(void* const userdata, const xmpp_log_level_t level, const char* const area, const char* const msg); static void _connection_handler(xmpp_conn_t* const xmpp_conn, const xmpp_conn_event_t status, const int error, @@ -337,13 +267,8 @@ connection_connect(const char* const jid, const char* const passwd, const char* { assert(jid != NULL); assert(passwd != NULL); - prof_connect_attempt_counter++; - prof_last_connect_attempt_ts = time(NULL); - _log_event_header("CONNECT_ATTEMPT"); log_info("Connecting as %s", jid); - _log_connection_details(jid, altdomain, port, tls_policy, auth_policy); - _conn_apply_settings(jid, passwd, tls_policy, auth_policy); int connect_status = xmpp_connect_client( @@ -355,10 +280,8 @@ connection_connect(const char* const jid, const char* const passwd, const char* if (connect_status == 0) { conn.conn_status = JABBER_CONNECTING; - log_debug("[CONNDBG] libstrophe connect_client returned success (async). status=JABBER_CONNECTING flags=0x%lx", xmpp_conn_get_flags(conn.xmpp_conn)); } else { conn.conn_status = JABBER_DISCONNECTED; - log_debug("[CONNDBG] libstrophe connect_client returned failure (sync). status=JABBER_DISCONNECTED error=%d", connect_status); } return conn.conn_status; @@ -389,6 +312,7 @@ iq_reg2_cb(xmpp_conn_t* xmpp_conn, xmpp_stanza_t* stanza, void* userdata) goto quit; quit: + log_debug("[CONNDBG] iq_reg2_cb: disconnecting after registration completion"); xmpp_disconnect(xmpp_conn); return 0; @@ -627,6 +551,7 @@ connection_disconnect(void) // don't disconnect already disconnected connection, // or we get infinite loop otherwise if (conn.conn_last_event == XMPP_CONN_CONNECT) { + log_debug("[CONNDBG] connection_disconnect: user-initiated disconnect (status=%d)", (int)conn.conn_status); conn.conn_status = JABBER_DISCONNECTING; xmpp_disconnect(conn.xmpp_conn); @@ -634,6 +559,7 @@ connection_disconnect(void) session_process_events(); } } else { + log_debug("[CONNDBG] connection_disconnect: already disconnected (last_event=%d)", (int)conn.conn_last_event); conn.conn_status = JABBER_DISCONNECTED; } @@ -1051,15 +977,8 @@ _connection_handler(xmpp_conn_t* const xmpp_conn, const xmpp_conn_event_t status // login success case XMPP_CONN_CONNECT: - _log_event_header("CONNECT_SUCCESS"); log_debug("Connection handler: XMPP_CONN_CONNECT"); conn.conn_status = JABBER_CONNECTED; - prof_successful_connect_counter++; - prof_last_successful_connect_ts = time(NULL); - - _log_connection_status_simple("connected", xmpp_conn_get_jid(conn.xmpp_conn), xmpp_conn_is_secured(xmpp_conn), - xmpp_conn_get_flags(conn.xmpp_conn), - conn.queued_messages ? "queued_messages=yes" : "queued_messages=no"); connection_get_jid(); conn.domain = strdup(conn.jid->domainpart); @@ -1084,14 +1003,8 @@ _connection_handler(xmpp_conn_t* const xmpp_conn, const xmpp_conn_event_t status // raw connection success case XMPP_CONN_RAW_CONNECT: - _log_event_header("RAW_CONNECT_SUCCESS"); log_debug("Connection handler: XMPP_CONN_RAW_CONNECT"); conn.conn_status = JABBER_RAW_CONNECTED; - prof_successful_connect_counter++; - prof_last_successful_connect_ts = time(NULL); - - _log_connection_status_simple("raw connected", xmpp_conn_get_jid(conn.xmpp_conn), FALSE, - xmpp_conn_get_flags(conn.xmpp_conn), ""); connection_get_jid(); conn.jid = jid_create(xmpp_conn_get_jid(conn.xmpp_conn)); @@ -1108,25 +1021,16 @@ _connection_handler(xmpp_conn_t* const xmpp_conn, const xmpp_conn_event_t status // disconnected case XMPP_CONN_DISCONNECT: - _log_event_header("DISCONNECT_EVENT"); log_debug("Connection handler: XMPP_CONN_DISCONNECT"); - - _log_connection_status_simple("disconnect", NULL, FALSE, 0, - "previous_status=%d error=%d has_stream_error=%s", - (int)conn.conn_status, error, - (stream_error && stream_error->stanza) ? "yes" : "no"); - prof_last_disconnect_ts = time(NULL); + log_debug("[CONNDBG] disconnect: previous_status=%d error=%d has_stream_error=%s", + (int)conn.conn_status, error, + (stream_error && stream_error->stanza) ? "yes" : "no"); // lost connection for unknown reason if (conn.conn_status == JABBER_CONNECTED || conn.conn_status == JABBER_DISCONNECTING) { if (prefs_get_boolean(PREF_STROPHE_SM_ENABLED)) { int send_queue_len = xmpp_conn_send_queue_len(conn.xmpp_conn); log_debug("Connection handler: Lost connection for unknown reason, %d messages in send queue", send_queue_len); - log_debug("[CONNDBG] SM enabled=%d resend_pref=%d send_queue_len=%d", - prefs_get_boolean(PREF_STROPHE_SM_ENABLED), - prefs_get_boolean(PREF_STROPHE_SM_RESEND), - send_queue_len); - conn.sm_state = xmpp_conn_get_sm_state(conn.xmpp_conn); if (send_queue_len > 0 && prefs_get_boolean(PREF_STROPHE_SM_RESEND)) { conn.queued_messages = calloc(send_queue_len + 1, sizeof(*conn.queued_messages)); @@ -1147,10 +1051,6 @@ _connection_handler(xmpp_conn_t* const xmpp_conn, const xmpp_conn_event_t status if (stream_error && stream_error->stanza && _get_other_host(stream_error->stanza, &host, &port)) { session_reconnect(host, port); log_debug("Connection handler: Forcing a re-connect to \"%s\"", host); - prof_reconnect_counter++; - log_debug("[CONNDBG] trigger=see-other-host host=%s port=%d reconnect_counter=%lu", - host, port, prof_reconnect_counter); - conn.conn_status = JABBER_RECONNECT; return; } @@ -1165,10 +1065,7 @@ _connection_handler(xmpp_conn_t* const xmpp_conn, const xmpp_conn_event_t status // connection failed case XMPP_CONN_FAIL: - _log_event_header("CONNECT_FAIL_EVENT"); log_debug("Connection handler: XMPP_CONN_FAIL"); - - _log_connection_status_simple("fail", NULL, FALSE, 0, "previous_status=%d error=%d", (int)conn.conn_status, error); break; // unknown state @@ -1302,30 +1199,3 @@ connection_debug_print_features() log_debug("=== End of Features ==="); } - -// --- Extended debug accessors --- -time_t -connection_last_successful_connect_ts(void) -{ - return prof_last_successful_connect_ts; -} -time_t -connection_last_disconnect_ts(void) -{ - return prof_last_disconnect_ts; -} -unsigned long -connection_connect_attempts(void) -{ - return prof_connect_attempt_counter; -} -unsigned long -connection_successful_connects(void) -{ - return prof_successful_connect_counter; -} -unsigned long -connection_reconnect_counter(void) -{ - return prof_reconnect_counter; -} diff --git a/src/xmpp/connection.h b/src/xmpp/connection.h index 50eee7a6..897a9fbc 100644 --- a/src/xmpp/connection.h +++ b/src/xmpp/connection.h @@ -37,7 +37,6 @@ #define XMPP_CONNECTION_H #include "xmpp/xmpp.h" -#include #define CON_RAND_ID_LEN 15 @@ -69,13 +68,4 @@ void connection_remove_available_resource(const char* const resource); char* connection_create_stanza_id(void); -// Extended debug accessors -time_t connection_last_successful_connect_ts(void); -time_t connection_last_disconnect_ts(void); -unsigned long connection_connect_attempts(void); -unsigned long connection_successful_connects(void); -unsigned long connection_reconnect_counter(void); - -char* _connection_format_elapsed_time(time_t base, time_t now, char* buf, size_t len); - #endif diff --git a/src/xmpp/iq.c b/src/xmpp/iq.c index 0363bcf6..5609d2ec 100644 --- a/src/xmpp/iq.c +++ b/src/xmpp/iq.c @@ -38,7 +38,6 @@ #include #include #include -#include #include #include @@ -173,33 +172,6 @@ static GHashTable* rooms_cache = NULL; static GSList* late_delivery_windows = NULL; static gboolean received_disco_items = FALSE; -static void -_iq_get_debug_stats(time_t* now_out, char* elapsed_connect, size_t len) -{ - time_t now = time(NULL); - time_t last_success = connection_last_successful_connect_ts(); - if (now_out) - *now_out = now; - _connection_format_elapsed_time(last_success, now, elapsed_connect, len); -} - -// Helper function to log autoping debug info -static void -_iq_log_autoping_debug(const char* event, const char* extra_info) -{ - time_t now; - char elapsed_connect[32]; - _iq_get_debug_stats(&now, elapsed_connect, sizeof(elapsed_connect)); - - if (extra_info) { - log_debug("[CONNDBG] %s ts=%ld elapsed-since-connect=%s %s", - event, (long)now, elapsed_connect, extra_info); - } else { - log_debug("[CONNDBG] %s ts=%ld elapsed-since-connect=%s", - event, (long)now, elapsed_connect); - } -} - static int _iq_handler(xmpp_conn_t* const conn, xmpp_stanza_t* const stanza, void* const userdata) { @@ -399,10 +371,6 @@ iq_id_handler_add(const char* const id, ProfIqCallback func, ProfIqFreeCallback void iq_autoping_timer_cancel(void) { - gdouble elapsed = autoping_time ? g_timer_elapsed(autoping_time, NULL) : 0.0; - auto_gchar gchar* extra = g_strdup_printf("was_waiting=%d elapsed=%.3fs", autoping_wait, elapsed); - _iq_log_autoping_debug("AUTOPING_TIMER_CANCEL", extra); - autoping_wait = FALSE; if (autoping_time) { g_timer_destroy(autoping_time); @@ -429,9 +397,6 @@ iq_autoping_check(void) unsigned long seconds_elapsed = elapsed * 1.0; gint timeout = prefs_get_autoping_timeout(); if (timeout > 0 && seconds_elapsed >= timeout) { - auto_gchar gchar* extra = g_strdup_printf("elapsed=%.1fs timeout=%ds", elapsed, timeout); - _iq_log_autoping_debug("AUTOPING_TIMEOUT", extra); - cons_show("Autoping response timed out after %u seconds.", timeout); log_debug("Autoping check: timed out after %u seconds, disconnecting", timeout); iq_autoping_timer_cancel(); @@ -443,8 +408,6 @@ void iq_set_autoping(const int seconds) { if (connection_get_status() != JABBER_CONNECTED) { - auto_gchar gchar* extra = g_strdup_printf("seconds=%d reason=not_connected", seconds); - _iq_log_autoping_debug("AUTOPING_SET_SKIPPED", extra); return; } @@ -452,14 +415,9 @@ iq_set_autoping(const int seconds) xmpp_timed_handler_delete(conn, _autoping_timed_send); if (seconds == 0) { - _iq_log_autoping_debug("AUTOPING_DISABLED", "seconds=0"); return; } - int timeout = prefs_get_autoping_timeout(); - auto_gchar gchar* extra = g_strdup_printf("interval=%ds timeout=%ds", seconds, timeout); - _iq_log_autoping_debug("AUTOPING_SET", extra); - int millis = seconds * 1000; xmpp_ctx_t* const ctx = connection_get_ctx(); xmpp_timed_handler_add(conn, _autoping_timed_send, millis, ctx); @@ -1468,16 +1426,9 @@ _autoping_timed_send(xmpp_conn_t* const conn, void* const userdata) return 1; } - int autoping_interval = prefs_get_autoping(); - int autoping_timeout = prefs_get_autoping_timeout(); - auto_gchar gchar* extra = g_strdup_printf("interval=%ds timeout=%ds", autoping_interval, autoping_timeout); - _iq_log_autoping_debug("AUTOPING_TIMER_FIRED", extra); - if (connection_supports(XMPP_FEATURE_PING) == FALSE) { // TODO: do we need to check it on each autoping call? log_warning("Server doesn't advertise %s feature.", XMPP_FEATURE_PING); - auto_gchar gchar* feat_extra = g_strdup_printf("feature=%s", XMPP_FEATURE_PING); - _iq_log_autoping_debug("AUTOPING_FEATURE_MISSING", feat_extra); if (!autoping_error_shown) { connection_debug_print_features(); cons_show_error("Server ping not supported (%s). Check log for details.", XMPP_FEATURE_PING); @@ -1487,7 +1438,6 @@ _autoping_timed_send(xmpp_conn_t* const conn, void* const userdata) if (autoping_wait) { log_debug("Autoping: Existing ping already in progress, aborting"); - _iq_log_autoping_debug("AUTOPING_ALREADY_PENDING", NULL); return 1; } @@ -1496,9 +1446,6 @@ _autoping_timed_send(xmpp_conn_t* const conn, void* const userdata) const char* id = xmpp_stanza_get_id(iq); log_debug("Autoping: Sending ping request: %s", id); - auto_gchar gchar* send_extra = g_strdup_printf("id=%s timeout=%ds", id, autoping_timeout); - _iq_log_autoping_debug("AUTOPING_SEND", send_extra); - // add pong handler iq_id_handler_add(id, _auto_pong_id_handler, NULL, NULL); @@ -1516,12 +1463,8 @@ _autoping_timed_send(xmpp_conn_t* const conn, void* const userdata) void autoping_timer_extend(void) { - if (autoping_time) { - gdouble elapsed = g_timer_elapsed(autoping_time, NULL); - auto_gchar gchar* extra = g_strdup_printf("elapsed_before_reset=%.3fs", elapsed); - _iq_log_autoping_debug("AUTOPING_TIMER_EXTEND", extra); + if (autoping_time) g_timer_start(autoping_time); - } } static int @@ -1530,12 +1473,8 @@ _auto_pong_id_handler(xmpp_stanza_t* const stanza, void* const userdata) iq_autoping_timer_cancel(); const char* id = xmpp_stanza_get_id(stanza); - gdouble response_time = autoping_time ? g_timer_elapsed(autoping_time, NULL) : 0.0; - if (id == NULL) { log_debug("Autoping: Pong handler fired."); - auto_gchar gchar* extra = g_strdup_printf("id=(null) response_time=%.3fs", response_time); - _iq_log_autoping_debug("AUTOPING_PONG_RECEIVED", extra); return 0; } @@ -1543,21 +1482,15 @@ _auto_pong_id_handler(xmpp_stanza_t* const stanza, void* const userdata) const char* type = xmpp_stanza_get_type(stanza); if (type == NULL) { - auto_gchar gchar* extra = g_strdup_printf("id=%s response_time=%.3fs type=(null)", id, response_time); - _iq_log_autoping_debug("AUTOPING_PONG_RECEIVED", extra); return 0; } if (g_strcmp0(type, STANZA_TYPE_ERROR) != 0) { - auto_gchar gchar* extra = g_strdup_printf("id=%s response_time=%.3fs type=%s", id, response_time, type); - _iq_log_autoping_debug("AUTOPING_PONG_SUCCESS", extra); return 0; } // show warning if error auto_char char* error_msg = stanza_get_error_message(stanza); log_warning("Server ping (id=%s) responded with error: %s", id, error_msg); - auto_gchar gchar* err_extra = g_strdup_printf("id=%s response_time=%.3fs error=%s", id, response_time, error_msg); - _iq_log_autoping_debug("AUTOPING_PONG_ERROR", err_extra); // turn off autoping if error type is 'cancel' xmpp_stanza_t* error = xmpp_stanza_get_child_by_name(stanza, STANZA_NAME_ERROR); @@ -1570,8 +1503,6 @@ _auto_pong_id_handler(xmpp_stanza_t* const stanza, void* const userdata) } if (g_strcmp0(errtype, STANZA_TYPE_CANCEL) == 0) { log_warning("Server ping (id=%s) error type 'cancel', disabling autoping.", id); - auto_gchar gchar* disable_extra = g_strdup_printf("id=%s errtype=cancel", id); - _iq_log_autoping_debug("AUTOPING_DISABLED", disable_extra); prefs_set_autoping(0); cons_show_error("Autoping is not supported by the server (stanza cancelled). The feature has been disabled automatically."); xmpp_timed_handler_delete(connection_get_conn(), _autoping_timed_send); diff --git a/src/xmpp/session.c b/src/xmpp/session.c index 69597081..09534a8d 100644 --- a/src/xmpp/session.c +++ b/src/xmpp/session.c @@ -38,7 +38,6 @@ #include #include #include -#include #include "profanity.h" #include "log.h" @@ -96,73 +95,6 @@ static GTimer* reconnect_timer; static activity_state_t activity_state; static resource_presence_t saved_presence; static char* saved_status; -static unsigned long session_reconnect_attempt_counter = 0; // extended debug counter - -static void -_session_get_debug_stats(time_t* now_out, char* elapsed_success, size_t success_len, char* elapsed_disconnect, size_t disconnect_len) -{ - time_t now = time(NULL); - time_t last_success = connection_last_successful_connect_ts(); - time_t last_disc = connection_last_disconnect_ts(); - - if (now_out) - *now_out = now; - _connection_format_elapsed_time(last_success, now, elapsed_success, success_len); - _connection_format_elapsed_time(last_disc, now, elapsed_disconnect, disconnect_len); -} - -// Helper function to log connection debug info -static void -_session_log_connect_debug(const char* event, const char* account, const char* jid, - const char* server, int port, const char* tls_policy, const char* auth_policy) -{ - time_t now; - char elapsed_success[32]; - char elapsed_disconnect[32]; - _session_get_debug_stats(&now, elapsed_success, sizeof(elapsed_success), elapsed_disconnect, sizeof(elapsed_disconnect)); - - log_debug("[CONNDBG] %s ts=%ld account=%s jid=%s server=%s port=%d tls_policy=%s auth_policy=%s elapsed-since-success=%s elapsed-since-disconnect=%s total-attempts=%lu total-success=%lu", - event, (long)now, account ? account : "(none)", jid ? jid : "(none)", - server ? server : "(default)", port, - tls_policy ? tls_policy : "(default)", - auth_policy ? auth_policy : "(default)", - elapsed_success, elapsed_disconnect, - connection_connect_attempts(), connection_successful_connects()); -} - -// Helper function to log session state debug info -static void -_session_log_state_debug(const char* event, int extra_param) -{ - time_t now; - char elapsed_success[32]; - char elapsed_disconnect[32]; - _session_get_debug_stats(&now, elapsed_success, sizeof(elapsed_success), elapsed_disconnect, sizeof(elapsed_disconnect)); - - log_debug("[CONNDBG] %s ts=%ld param=%d account=%s elapsed-since-success=%s elapsed-since-disconnect=%s total-attempts=%lu total-success=%lu session-reconnects=%lu", - event, (long)now, extra_param, - saved_account.name ? saved_account.name : "(none)", - elapsed_success, elapsed_disconnect, - connection_connect_attempts(), connection_successful_connects(), - session_reconnect_attempt_counter); -} - -// Helper function to log reconnect attempt -static void -_session_log_reconnect_debug(unsigned long attempt_num, const char* account, const char* jid, - const char* server, unsigned short port, const char* tls_policy, const char* auth_policy) -{ - time_t now; - char elapsed_success[32]; - char elapsed_disconnect[32]; - _session_get_debug_stats(&now, elapsed_success, sizeof(elapsed_success), elapsed_disconnect, sizeof(elapsed_disconnect)); - - log_debug("[CONNDBG] RECONNECT_ATTEMPT #%lu ts=%ld account=%s jid=%s server=%s port=%u tls_policy=%s auth_policy=%s elapsed-since-success=%s elapsed-since-disconnect=%s total-connect-attempts=%lu total-success=%lu global-reconnects=%lu", - attempt_num, (long)now, account, jid, server ? server : "(null)", port, - tls_policy ? tls_policy : "(default)", auth_policy ? auth_policy : "(default)", - elapsed_success, elapsed_disconnect, - connection_connect_attempts(), connection_successful_connects(), connection_reconnect_counter()); -} static void _session_free_internals(void); static void _session_free_saved_details(void); @@ -201,8 +133,6 @@ session_connect_with_account(const ProfAccount* const account) assert(account != NULL); log_info("Connecting using account: %s", account->name); - _session_log_connect_debug("SESSION_CONNECT_WITH_ACCOUNT", account->name, account->jid, - account->server, account->port, account->tls_policy, account->auth_policy); _session_free_internals(); @@ -236,9 +166,6 @@ session_connect_with_details(const char* const jid, const char* const passwd, co assert(jid != NULL); assert(passwd != NULL); - _session_log_connect_debug("SESSION_CONNECT_WITH_DETAILS", NULL, jid, - altdomain, port, tls_policy, auth_policy); - _session_free_internals(); // save details for reconnect, remember name for account creating on success @@ -291,17 +218,13 @@ session_connect_with_details(const char* const jid, const char* const passwd, co void session_autoping_fail(void) { - int autoping_timeout = prefs_get_autoping_timeout(); - _session_log_state_debug("SESSION_AUTOPING_FAIL", autoping_timeout); + log_debug("[CONNDBG] session_autoping_fail: autoping timeout, triggering lost connection"); session_lost_connection(); } void session_disconnect(void) { - jabber_conn_status_t conn_status = connection_get_status(); - _session_log_state_debug("SESSION_DISCONNECT", (int)conn_status); - // if connected, send end stream and wait for response if (connection_get_status() == JABBER_CONNECTED) { log_info("Closing connection"); @@ -342,11 +265,14 @@ session_process_events(void) if ((reconnect_sec != 0) && reconnect_timer) { int elapsed_sec = g_timer_elapsed(reconnect_timer, NULL); if (elapsed_sec > reconnect_sec) { + log_debug("[CONNDBG] session_process_events: auto-reconnect triggered after %d seconds (threshold=%d)", + elapsed_sec, reconnect_sec); session_reconnect_now(); } } break; case JABBER_RECONNECT: + log_debug("[CONNDBG] session_process_events: JABBER_RECONNECT state, calling session_reconnect_now"); session_reconnect_now(); break; default: @@ -397,8 +323,6 @@ _receive_mood(xmpp_stanza_t* const stanza, void* const userdata) void session_login_success(gboolean secured) { - _session_log_state_debug("SESSION_LOGIN_SUCCESS", secured); - chat_sessions_init(); message_handlers_init(); @@ -450,14 +374,12 @@ session_login_success(gboolean secured) void session_login_failed(void) { - _session_log_state_debug("SESSION_LOGIN_FAILED", reconnect_timer != NULL); - if (reconnect_timer == NULL) { - log_debug("Connection handler: No reconnect timer"); + log_debug("[CONNDBG] Connection handler: No reconnect timer"); sv_ev_failed_login(); _session_free_internals(); } else { - log_debug("Connection handler: Restarting reconnect timer"); + log_debug("[CONNDBG] Connection handler: Restarting reconnect timer"); if (prefs_get_reconnect() != 0) { g_timer_start(reconnect_timer); } @@ -471,17 +393,16 @@ session_login_failed(void) void session_lost_connection(void) { - int reconnect_sec = prefs_get_reconnect(); - _session_log_state_debug("SESSION_LOST_CONNECTION", reconnect_sec); - + log_debug("[CONNDBG] session_lost_connection: connection lost, reconnect_interval=%d", + prefs_get_reconnect()); /* this callback also clears all cached data */ sv_ev_lost_connection(); if (prefs_get_reconnect() != 0) { assert(reconnect_timer == NULL); reconnect_timer = g_timer_new(); - log_debug("[CONNDBG] created reconnect timer, will reconnect in %d seconds", reconnect_sec); + log_debug("[CONNDBG] session_lost_connection: reconnect timer started"); } else { - log_debug("[CONNDBG] reconnect disabled, freeing session internals"); + log_debug("[CONNDBG] session_lost_connection: auto-reconnect disabled, cleaning up"); _session_free_internals(); } } @@ -661,10 +582,6 @@ session_reconnect_now(void) port = account->port; } - session_reconnect_attempt_counter++; - _session_log_reconnect_debug(session_reconnect_attempt_counter, account->name, jid, - server, port, account->tls_policy, account->auth_policy); - log_debug("Attempting reconnect with account %s", account->name); connection_connect(jid, saved_account.passwd, server, port, account->tls_policy, account->auth_policy); account_free(account); -- 2.49.1 From 68857100fffc436fd7251cbf50aa814abf8844a3 Mon Sep 17 00:00:00 2001 From: "jabber.developer2" Date: Fri, 21 Nov 2025 11:19:44 +0300 Subject: [PATCH 4/5] feat(xmpp): enhance connection debug logging with context tags --- src/xmpp/session.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/xmpp/session.c b/src/xmpp/session.c index 09534a8d..2779c048 100644 --- a/src/xmpp/session.c +++ b/src/xmpp/session.c @@ -331,12 +331,12 @@ session_login_success(gboolean secured) // logged in with account if (saved_account.name) { - log_debug("Connection handler: logged in with account name: %s", saved_account.name); + log_debug("[CONNDBG] Connection handler: logged in with account name: %s", saved_account.name); sv_ev_login_account_success(saved_account.name, secured); // logged in without account, use details to create new account } else { - log_debug("Connection handler: logged in with jid: %s", saved_details.name); + log_debug("[CONNDBG] Connection handler: logged in with jid: %s", saved_details.name); accounts_add(saved_details.name, saved_details.altdomain, saved_details.port, saved_details.tls_policy, saved_details.auth_policy); accounts_set_jid(saved_details.name, saved_details.jid); -- 2.49.1 From cd7cee84d34525d61dee15d24c1c6c84e14ee141 Mon Sep 17 00:00:00 2001 From: "jabber.developer2" Date: Fri, 21 Nov 2025 11:21:46 +0300 Subject: [PATCH 5/5] fix(xmpp): format debug logging statements for consistency --- src/xmpp/connection.c | 4 ++-- src/xmpp/session.c | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/src/xmpp/connection.c b/src/xmpp/connection.c index 728eb191..0f71ca2f 100644 --- a/src/xmpp/connection.c +++ b/src/xmpp/connection.c @@ -1022,8 +1022,8 @@ _connection_handler(xmpp_conn_t* const xmpp_conn, const xmpp_conn_event_t status // disconnected case XMPP_CONN_DISCONNECT: log_debug("Connection handler: XMPP_CONN_DISCONNECT"); - log_debug("[CONNDBG] disconnect: previous_status=%d error=%d has_stream_error=%s", - (int)conn.conn_status, error, + log_debug("[CONNDBG] disconnect: previous_status=%d error=%d has_stream_error=%s", + (int)conn.conn_status, error, (stream_error && stream_error->stanza) ? "yes" : "no"); // lost connection for unknown reason diff --git a/src/xmpp/session.c b/src/xmpp/session.c index 2779c048..4d0a64b9 100644 --- a/src/xmpp/session.c +++ b/src/xmpp/session.c @@ -265,7 +265,7 @@ session_process_events(void) if ((reconnect_sec != 0) && reconnect_timer) { int elapsed_sec = g_timer_elapsed(reconnect_timer, NULL); if (elapsed_sec > reconnect_sec) { - log_debug("[CONNDBG] session_process_events: auto-reconnect triggered after %d seconds (threshold=%d)", + log_debug("[CONNDBG] session_process_events: auto-reconnect triggered after %d seconds (threshold=%d)", elapsed_sec, reconnect_sec); session_reconnect_now(); } @@ -393,7 +393,7 @@ session_login_failed(void) void session_lost_connection(void) { - log_debug("[CONNDBG] session_lost_connection: connection lost, reconnect_interval=%d", + log_debug("[CONNDBG] session_lost_connection: connection lost, reconnect_interval=%d", prefs_get_reconnect()); /* this callback also clears all cached data */ sv_ev_lost_connection(); -- 2.49.1