tm: enhance fr/retr timers logging

- Mention when FR timeout is reached, and which of FR timers expired
- Log when starting FR/RETR timers
- log when changing default timeouts to user set values
- log when resetting fr/retr timers on provisional replies

src/modules/tm/t_lookup.c

@@ -1818,6 +1818,9 @@ int t_set_fr(struct sip_msg* msg, unsigned int fr_inv_to, unsigned int fr_to)
 		set_msgid_val(user_fr_inv_timeout, msg->id, int, (int)fr_inv);
 		set_msgid_val(user_fr_timeout, msg->id, int, (int)fr);
 	}else{
+#ifdef TIMER_DEBUG
+		LM_DBG("changing default FR timeout values: (\"fr_inv_timeout\": %d, \"fr_timeout\": %d)\n", fr_inv, fr);
+#endif
 		change_fr(t, fr_inv, fr); /* change running uac timers */
 	}
 	return 1;
@@ -1880,6 +1883,9 @@ int t_set_retr(struct sip_msg* msg, unsigned int t1_ms, unsigned int t2_ms)
 		set_msgid_val(user_rt_t1_timeout_ms, msg->id, int, (int)t1_ms);
 		set_msgid_val(user_rt_t2_timeout_ms, msg->id, int, (int)t2_ms);
 	}else{
+#ifdef TIMER_DEBUG
+		LM_DBG("changing default RETR timeout values to: (\"retr_t1_interval\": %d, \"retr_t2_interval\": %d)\n", t1_ms, t2_ms);
+#endif
 		change_retr(t, 1, t1_ms, t2_ms); /* change running uac timers */
 	}
 	return 1;

src/modules/tm/t_reply.c

@@ -2718,6 +2718,9 @@ int reply_received( struct sip_msg  *p_msg )
 				( (last_uac_status<msg_status) &&
 					((msg_status>=180) || (last_uac_status==0)) )
 			) ) { /* provisional now */
+#ifdef TIMER_DEBUG
+		LM_DBG("updating FR/RETR timers, \"fr_inv_timeout\": %d\n", t->fr_inv_timeout);
+#endif
 		restart_rb_fr(& uac->request, t->fr_inv_timeout);
 		uac->request.flags|=F_RB_FR_INV; /* mark fr_inv */
 	} /* provisional replies */

src/modules/tm/t_suspend.c

@@ -486,6 +486,9 @@ int t_continue_helper(unsigned int hash_index, unsigned int label,
 			( (last_uac_status<msg_status) &&
 			((msg_status>=180) || (last_uac_status==0)) )
 		) ) { /* provisional now */
+#ifdef TIMER_DEBUG
+			LM_DBG("updating FR/RETR timers, \"fr_inv_timeout\": %d\n", t->fr_inv_timeout);
+#endif
 			restart_rb_fr(& t->uac[branch].request, t->fr_inv_timeout);
 			t->uac[branch].request.flags|=F_RB_FR_INV; /* mark fr_inv */
 		}

src/modules/tm/timer.c

@@ -510,6 +510,13 @@ ticks_t retr_buf_handler(ticks_t ticks, struct timer_ln *tl, void *p)
 							  a little race risk, but
 							  nothing bad would happen */
 		rbuf->flags |= F_RB_TIMEOUT;
+#ifdef TIMER_DEBUG
+		if (rbuf->flags & F_RB_FR_INV) {
+			LM_DBG("reached the \"fr_inv_timeout\"\n");
+		} else {
+			LM_DBG("reached the \"fr_timeout\"\n");
+		}
+#endif
 		/* WARNING:  the next line depends on taking care not to start the
 		 *           wait timer before finishing with t (if this is not
 		 *           guaranteed then comment the timer_allow_del() line) */

src/modules/tm/timer.h

@@ -168,6 +168,10 @@ inline static int _set_fr_retr(struct retr_buf *rb, unsigned retr_ms)
 	ticks_t retr_ticks;
 	int ret;
 
+#ifdef TIMER_DEBUG
+	LM_DBG("starting FR/RETR timers\n");
+#endif
+
 	ticks = get_ticks_raw();
 	timeout = rb->my_T->fr_timeout;
 	eol = rb->my_T->end_of_life;