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/iq.c

@@ -38,6 +38,7 @@
 #include <stdlib.h>
 #include <string.h>
 #include <stdio.h>
+#include <time.h>
 #include <glib.h>
 
 #include <strophe.h>
@@ -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);