Introduce log macro helper LOGPMS

Change-Id: Ib304ced06531a5154b7ec8bf87f9717dfd7d1397

4 files changed, 29 insertions, 21 deletions

diff --git a/src/gprs_ms.cpp b/src/gprs_ms.cpp
index 494ed2e2..f82026a5 100644
--- a/src/gprs_ms.cpp
+++ b/src/gprs_ms.cpp
@@ -685,13 +685,12 @@ void GprsMs::update_cs_ul(const pcu_l1_meas *meas)
 		mcs_inc_kind(&new_cs_ul, mode());
 
 	if (m_current_cs_ul != new_cs_ul) {
-		LOGP(DRLCMACMEAS, LOGL_INFO,
-			"MS (IMSI %s): "
-			"Link quality %ddB (old %ddB) left window [%d, %d], "
-			"modifying uplink CS level: %s -> %s\n",
-			imsi(), meas->link_qual, old_link_qual,
-			low, high,
-			mcs_name(m_current_cs_ul), mcs_name(new_cs_ul));
+		LOGPMS(this, DRLCMACMEAS, LOGL_INFO,
+		       "Link quality %ddB (old %ddB) left window [%d, %d], "
+		       "modifying uplink CS level: %s -> %s\n",
+		       meas->link_qual, old_link_qual,
+		       low, high,
+		       mcs_name(m_current_cs_ul), mcs_name(new_cs_ul));
 
 		m_current_cs_ul = new_cs_ul;
 	}
diff --git a/src/gprs_ms.h b/src/gprs_ms.h
index 1e5a1558..0a1dda75 100644
--- a/src/gprs_ms.h
+++ b/src/gprs_ms.h
@@ -39,6 +39,7 @@ extern "C" {
 
 #include <stdint.h>
 #include <stddef.h>
+#include <inttypes.h>
 
 struct BTS;
 struct gprs_rlcmac_trx;
@@ -296,3 +297,10 @@ inline gprs_rlcmac_trx *GprsMs::current_trx() const
 {
 	return m_current_trx;
 }
+
+#define LOGPMS(ms, category, level, fmt, args...) \
+	LOGP(category, level, "MS(TLLI=0x%08x, IMSI=%s, TA=%" PRIu8 ", %" PRIu8 "/%" PRIu8 ",%s%s) " fmt, \
+	     (ms)->tlli(), (ms)->imsi(), (ms)->ta(), (ms)->ms_class(), (ms)->egprs_ms_class(), \
+	     (ms)->ul_tbf() ? " UL": "", \
+	     (ms)->dl_tbf() ? " DL": "", \
+	     ## args)
diff --git a/src/gprs_rlcmac_meas.cpp b/src/gprs_rlcmac_meas.cpp
index f4a7e479..e4df559e 100644
--- a/src/gprs_rlcmac_meas.cpp
+++ b/src/gprs_rlcmac_meas.cpp
@@ -26,6 +26,7 @@ extern "C" {
 #include <pcu_l1_if.h>
 #include <tbf.h>
 #include <tbf_dl.h>
+#include <gprs_ms.h>
 
 #include <string.h>
 #include <errno.h>
@@ -105,8 +106,8 @@ int gprs_rlcmac_rssi_rep(struct gprs_rlcmac_tbf *tbf)
 	if (!tbf->meas.rssi_num)
 		return -EINVAL;
 
-	LOGP(DRLCMACMEAS, LOGL_INFO, "UL RSSI of TLLI=0x%08x: %d dBm\n",
-		tbf->tlli(), tbf->meas.rssi_sum / tbf->meas.rssi_num);
+	LOGPMS(tbf->ms(), DRLCMACMEAS, LOGL_INFO, "UL RSSI: %d dBm\n",
+	       tbf->meas.rssi_sum / tbf->meas.rssi_num);
 
 	return 0;
 }
diff --git a/tests/tbf/TbfTest.err b/tests/tbf/TbfTest.err
index 195d8508..681e7a3d 100644
--- a/tests/tbf/TbfTest.err
+++ b/tests/tbf/TbfTest.err
@@ -1467,7 +1467,7 @@ TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) starting timer T3169 [RACH (new UL-
 Tx Immediate Assignment on AGCH: TRX=0 (ARFCN 0) TS=7 TA=7 TSC=0 TFI=0 USF=0
 Got CS-1 RLC block: R=0, SI=0, TFI=0, CPS=0, RSB=0, rc=184
 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) UL DATA TFI=0 received (V(Q)=0 .. V(R)=0)
-MS (IMSI ): Link quality 12dB (old 12dB) left window [0, 0], modifying uplink CS level: CS-1 -> CS-2
+MS(TLLI=0x00000000, IMSI=, TA=7, 0/0, UL) Link quality 12dB (old 12dB) left window [0, 0], modifying uplink CS level: CS-1 -> CS-2
 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) restarting timer T3169 [acked (data)] with 5 sec. 0 microsec, cur_fn=0
 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) Got CS-1 RLC data block: CV=0, BSN=0, SPB=0, PI=0, E=1, TI=1, bitoffs=24
 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) BSN 0 storing in window (0..63)
@@ -1820,7 +1820,7 @@ TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=NULL) changes state from NULL to ASSIGN
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) starting timer T3169 [allocation (UL-TBF)] with 5 sec. 0 microsec, cur_fn=0
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) change control TS 7 -> 7 until assignment is complete.
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) changes UL ASS state from GPRS_RLCMAC_UL_ASS_NONE to GPRS_RLCMAC_UL_ASS_SEND_ASS
-MS (IMSI ): Link quality 12dB (old 12dB) left window [0, 0], modifying uplink CS level: CS-1 -> CS-2
+MS(TLLI=0xf1223344, IMSI=, TA=7, 1/0, UL) Link quality 12dB (old 12dB) left window [0, 0], modifying uplink CS level: CS-1 -> CS-2
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) start Packet Uplink Assignment (PACCH)
 +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++
 ------------------------- TX : Packet Uplink Assignment -------------------------
@@ -1835,7 +1835,7 @@ TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) changes UL ASS state from GPRS_RL
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) changes state from ASSIGN to FLOW
 Got CS-1 RLC block: R=0, SI=0, TFI=0, CPS=0, RSB=0, rc=184
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) UL DATA TFI=0 received (V(Q)=0 .. V(R)=0)
-MS (IMSI ): Link quality 12dB (old 12dB) left window [0, 0], modifying uplink CS level: CS-2 -> CS-3
+MS(TLLI=0xf1223344, IMSI=, TA=7, 1/0, UL) Link quality 12dB (old 12dB) left window [0, 0], modifying uplink CS level: CS-2 -> CS-3
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) restarting timer T3169 [acked (data)] with 5 sec. 0 microsec, cur_fn=0
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) Got CS-1 RLC data block: CV=15, BSN=0, SPB=0, PI=0, E=1, TI=0, bitoffs=24
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) BSN 0 storing in window (0..63)
@@ -1870,7 +1870,7 @@ TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) starting timer T0 [assignment (PA
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) appending 20 bytes
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) appending 20 bytes
 Old MS: TLLI = 0xf1223344, TA = 7, IMSI = 0011223344, LLC = 2
-UL RSSI of TLLI=0xf1223344: 31 dBm
+MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 1/0, UL DL) UL RSSI: 31 dBm
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) free
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) FIXME: Software error: Pending downlink assignment in state GPRS_RLCMAC_DL_ASS_SEND_ASS. This may not happen, because the assignment message never gets transmitted. Please be sure not to free in this state. PLEASE FIX!
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) stopping timer T3169 [freeing TBF]
@@ -1905,7 +1905,7 @@ TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=NULL) changes state from NULL to ASSIGN
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) starting timer T3169 [allocation (UL-TBF)] with 5 sec. 0 microsec, cur_fn=0
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) change control TS 7 -> 7 until assignment is complete.
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) changes UL ASS state from GPRS_RLCMAC_UL_ASS_NONE to GPRS_RLCMAC_UL_ASS_SEND_ASS
-MS (IMSI 0011223344): Link quality 12dB (old 12dB) left window [0, 0], modifying uplink CS level: CS-3 -> CS-4
+MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 1/0, UL DL) Link quality 12dB (old 12dB) left window [0, 0], modifying uplink CS level: CS-3 -> CS-4
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) start Packet Uplink Assignment (PACCH)
 +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++
 ------------------------- TX : Packet Uplink Assignment -------------------------
@@ -1962,7 +1962,7 @@ TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=NULL) changes state from NULL to ASSIGN
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) starting timer T3169 [allocation (UL-TBF)] with 5 sec. 0 microsec, cur_fn=0
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) change control TS 7 -> 7 until assignment is complete.
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) changes UL ASS state from GPRS_RLCMAC_UL_ASS_NONE to GPRS_RLCMAC_UL_ASS_SEND_ASS
-MS (IMSI ): Link quality 12dB (old 12dB) left window [0, 0], modifying uplink CS level: CS-1 -> CS-2
+MS(TLLI=0xf1223344, IMSI=, TA=7, 1/0, UL) Link quality 12dB (old 12dB) left window [0, 0], modifying uplink CS level: CS-1 -> CS-2
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) start Packet Uplink Assignment (PACCH)
 +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++
 ------------------------- TX : Packet Uplink Assignment -------------------------
@@ -1977,7 +1977,7 @@ TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) changes UL ASS state from GPRS_RL
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) changes state from ASSIGN to FLOW
 Got CS-1 RLC block: R=0, SI=0, TFI=0, CPS=0, RSB=0, rc=184
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) UL DATA TFI=0 received (V(Q)=0 .. V(R)=0)
-MS (IMSI ): Link quality 12dB (old 12dB) left window [0, 0], modifying uplink CS level: CS-2 -> CS-3
+MS(TLLI=0xf1223344, IMSI=, TA=7, 1/0, UL) Link quality 12dB (old 12dB) left window [0, 0], modifying uplink CS level: CS-2 -> CS-3
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) restarting timer T3169 [acked (data)] with 5 sec. 0 microsec, cur_fn=0
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) Got CS-1 RLC data block: CV=15, BSN=0, SPB=0, PI=0, E=1, TI=0, bitoffs=24
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) BSN 0 storing in window (0..63)
@@ -2012,7 +2012,7 @@ TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) starting timer T0 [assignment (PA
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) appending 20 bytes
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) appending 20 bytes
 Old MS: TLLI = 0xf1223344, TA = 7, IMSI = 0011223344, LLC = 2
-UL RSSI of TLLI=0xf1223344: 31 dBm
+MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 1/0, UL DL) UL RSSI: 31 dBm
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) free
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) FIXME: Software error: Pending downlink assignment in state GPRS_RLCMAC_DL_ASS_SEND_ASS. This may not happen, because the assignment message never gets transmitted. Please be sure not to free in this state. PLEASE FIX!
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) stopping timer T3169 [freeing TBF]
@@ -2045,7 +2045,7 @@ TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) starting timer T3169 [RACH (new UL-
 Tx Immediate Assignment on AGCH: TRX=0 (ARFCN 0) TS=7 TA=7 TSC=0 TFI=0 USF=0
 Got CS-1 RLC block: R=0, SI=0, TFI=0, CPS=0, RSB=0, rc=184
 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) UL DATA TFI=0 received (V(Q)=0 .. V(R)=0)
-MS (IMSI ): Link quality 12dB (old 12dB) left window [0, 0], modifying uplink CS level: CS-1 -> CS-2
+MS(TLLI=0x00000000, IMSI=, TA=7, 0/0, UL) Link quality 12dB (old 12dB) left window [0, 0], modifying uplink CS level: CS-1 -> CS-2
 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) restarting timer T3169 [acked (data)] with 5 sec. 0 microsec, cur_fn=0
 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) Got CS-1 RLC data block: CV=0, BSN=0, SPB=0, PI=0, E=1, TI=1, bitoffs=24
 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) BSN 0 storing in window (0..63)
@@ -2108,7 +2108,7 @@ TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=NULL) changes state from NULL to ASSIGN
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) starting timer T3169 [allocation (UL-TBF)] with 5 sec. 0 microsec, cur_fn=0
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) change control TS 7 -> 7 until assignment is complete.
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) changes UL ASS state from GPRS_RLCMAC_UL_ASS_NONE to GPRS_RLCMAC_UL_ASS_SEND_ASS
-MS (IMSI ): Link quality 12dB (old 12dB) left window [0, 0], modifying uplink CS level: CS-1 -> CS-2
+MS(TLLI=0xf1223344, IMSI=, TA=7, 1/0, UL) Link quality 12dB (old 12dB) left window [0, 0], modifying uplink CS level: CS-1 -> CS-2
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) start Packet Uplink Assignment (PACCH)
 +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++
 ------------------------- TX : Packet Uplink Assignment -------------------------
@@ -2123,7 +2123,7 @@ TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) changes UL ASS state from GPRS_RL
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) changes state from ASSIGN to FLOW
 Got CS-1 RLC block: R=0, SI=0, TFI=0, CPS=0, RSB=0, rc=184
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) UL DATA TFI=0 received (V(Q)=0 .. V(R)=0)
-MS (IMSI ): Link quality 12dB (old 12dB) left window [0, 0], modifying uplink CS level: CS-2 -> CS-3
+MS(TLLI=0xf1223344, IMSI=, TA=7, 1/0, UL) Link quality 12dB (old 12dB) left window [0, 0], modifying uplink CS level: CS-2 -> CS-3
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) restarting timer T3169 [acked (data)] with 5 sec. 0 microsec, cur_fn=0
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) Got CS-1 RLC data block: CV=15, BSN=0, SPB=0, PI=0, E=1, TI=0, bitoffs=24
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) BSN 0 storing in window (0..63)
@@ -2787,7 +2787,7 @@ TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT RELEASE) changes DL ASS state from G
 TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NULL) changes state from NULL to ASSIGN
 TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) set ass. type PACCH [prev CCCH:0, PACCH:0]
 TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) starting timer T0 [assignment (PACCH)] with 2 sec. 0 microsec, cur_fn=0
-MS (IMSI 0011223344): Link quality 12dB (old 12dB) left window [0, 0], modifying uplink CS level: CS-3 -> CS-4
+MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 1/0, UL DL) Link quality 12dB (old 12dB) left window [0, 0], modifying uplink CS level: CS-3 -> CS-4
 Received RTS for PDCH: TRX=0 TS=7 FN=2654400 block_nr=2 scheduling USF=0 for required uplink resource of UL TFI=0
 TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH)
 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++