From d88bb2e825ec868a9634985fedad7a85f8e77944 Mon Sep 17 00:00:00 2001
From: Jacob Erlbeck <jerlbeck@sysmocom.de>
Date: Fri, 11 Dec 2015 14:53:29 +0100
Subject: rlc: Dump RLC data for debugging

Log incoming RLC data messages and RLC data units to LOGL_DEBUG.

Sponsored-by: On-Waves ehf
---
 src/bts.cpp           |  2 ++
 src/tbf_ul.cpp        |  3 +++
 tests/tbf/TbfTest.err | 18 ++++++++++++++++++
 3 files changed, 23 insertions(+)

diff --git a/src/bts.cpp b/src/bts.cpp
index d1d738c6..b7244aa5 100644
--- a/src/bts.cpp
+++ b/src/bts.cpp
@@ -1180,6 +1180,8 @@ int gprs_rlcmac_pdch::rcv_data_block(uint8_t *data, uint32_t fn,
 		}
 	}
 
+	LOGP(DRLCMACUL, LOGL_DEBUG, "  UL data: %s\n", osmo_hexdump(data, len));
+
 	rc = Decoding::rlc_parse_ul_data_header(&rlc_dec, data, cs);
 	if (rc < 0) {
 		LOGP(DRLCMACUL, LOGL_ERROR,
diff --git a/src/tbf_ul.cpp b/src/tbf_ul.cpp
index a133d3e7..271f87aa 100644
--- a/src/tbf_ul.cpp
+++ b/src/tbf_ul.cpp
@@ -242,6 +242,9 @@ int gprs_rlcmac_ul_tbf::rcv_data_block_acknowledged(
 			Decoding::rlc_copy_to_aligned_buffer(rlc, block_idx, data,
 				rlc_data);
 
+		LOGP(DRLCMACUL, LOGL_DEBUG,
+			"%s: data_length=%d, data=%s\n",
+			name(), block->len, osmo_hexdump(rlc_data, block->len));
 
 		/* TODO: Handle SPB != 0 -> set state to partly received
 		 * (upper/lower) and continue with the loop, unless the other
diff --git a/tests/tbf/TbfTest.err b/tests/tbf/TbfTest.err
index 27c5fe31..f5509d7e 100644
--- a/tests/tbf/TbfTest.err
+++ b/tests/tbf/TbfTest.err
@@ -1394,11 +1394,13 @@ TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) RX: [PCU <- BTS] RACH qbit-ta=31 ra
 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) TX: START Immediate Assignment Uplink (AGCH)
 Sending data request: trx=0 ts=0 sapi=2 arfcn=0 fn=0 block=0 data=2d 06 3f 10 0f 00 00 03 8b 29 07 00 c8 00 10 0b 2b 2b 2b 2b 2b 2b 2b 
 Got RLC block, coding scheme: CS-1, length: 23 (23))
+  UL data: 00 01 01 f1 22 33 44 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
 Got CS-1 RLC block: R=0, SI=0, TFI=0, CPS=0, RSB=0, rc=184
 UL DATA TFI=0 received (V(Q)=0 .. V(R)=0)
 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) restarting timer 3169 while old timer 3169 pending 
 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
 - BSN 0 storing in window (0..63)
+TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW): data_length=20, data=f1 22 33 44 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
 Decoded premier TLLI=0x00000000 of UL DATA TFI=0.
 Modifying MS object, UL TLLI: 0x00000000 -> 0xf1223344, not yet confirmed
 - Raising V(R) to 1
@@ -1485,11 +1487,13 @@ RX: [PCU <- BTS] TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) Packet Control A
 TBF: [DOWNLINK] UPLINK ASSIGNED TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN)
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) changes state from ASSIGN to FLOW
 Got RLC block, coding scheme: CS-1, length: 23 (23))
+  UL data: 3c 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
 Got CS-1 RLC block: R=0, SI=0, TFI=0, CPS=0, RSB=0, rc=184
 UL DATA TFI=0 received (V(Q)=0 .. V(R)=0)
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) restarting timer 3169 while old timer 3169 pending 
 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
 - BSN 0 storing in window (0..63)
+TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW): data_length=20, data=00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
 - Raising V(R) to 1
 - Taking block 0 out, raising V(Q) to 1
 - Assembling frames: (len=20)
@@ -1566,11 +1570,13 @@ RX: [PCU <- BTS] TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) Packet Control A
 TBF: [DOWNLINK] UPLINK ASSIGNED TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN)
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) changes state from ASSIGN to FLOW
 Got RLC block, coding scheme: CS-1, length: 23 (23))
+  UL data: 3c 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
 Got CS-1 RLC block: R=0, SI=0, TFI=0, CPS=0, RSB=0, rc=184
 UL DATA TFI=0 received (V(Q)=0 .. V(R)=0)
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) restarting timer 3169 while old timer 3169 pending 
 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
 - BSN 0 storing in window (0..63)
+TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW): data_length=20, data=00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
 - Raising V(R) to 1
 - Taking block 0 out, raising V(Q) to 1
 - Assembling frames: (len=20)
@@ -1693,11 +1699,13 @@ RX: [PCU <- BTS] TBF(TFI=1 TLLI=0xf5667788 DIR=UL STATE=ASSIGN) Packet Control A
 TBF: [DOWNLINK] UPLINK ASSIGNED TBF(TFI=1 TLLI=0xf5667788 DIR=UL STATE=ASSIGN)
 TBF(TFI=1 TLLI=0xf5667788 DIR=UL STATE=ASSIGN) changes state from ASSIGN to FLOW
 Got RLC block, coding scheme: CS-1, length: 23 (23))
+  UL data: 3c 02 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
 Got CS-1 RLC block: R=0, SI=0, TFI=1, CPS=0, RSB=0, rc=184
 UL DATA TFI=1 received (V(Q)=0 .. V(R)=0)
 TBF(TFI=1 TLLI=0xf5667788 DIR=UL STATE=FLOW) restarting timer 3169 while old timer 3169 pending 
 TBF(TFI=1 TLLI=0xf5667788 DIR=UL STATE=FLOW): Got CS-1 RLC data block: CV=15, BSN=0, SPB=0, PI=0, E=1, TI=0, bitoffs=24
 - BSN 0 storing in window (0..63)
+TBF(TFI=1 TLLI=0xf5667788 DIR=UL STATE=FLOW): data_length=20, data=00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
 - Raising V(R) to 1
 - Taking block 0 out, raising V(Q) to 1
 - Assembling frames: (len=20)
@@ -1760,11 +1768,13 @@ RX: [PCU <- BTS] TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) Packet Control A
 TBF: [DOWNLINK] UPLINK ASSIGNED TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN)
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) changes state from ASSIGN to FLOW
 Got RLC block, coding scheme: CS-1, length: 23 (23))
+  UL data: 3c 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
 Got CS-1 RLC block: R=0, SI=0, TFI=0, CPS=0, RSB=0, rc=184
 UL DATA TFI=0 received (V(Q)=0 .. V(R)=0)
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) restarting timer 3169 while old timer 3169 pending 
 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
 - BSN 0 storing in window (0..63)
+TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW): data_length=20, data=00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
 - Raising V(R) to 1
 - Taking block 0 out, raising V(Q) to 1
 - Assembling frames: (len=20)
@@ -1867,11 +1877,13 @@ Send dowlink assignment on PACCH, because TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE
 TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NULL) changes state from NULL to ASSIGN
 TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) starting timer 0.
 Got RLC block, coding scheme: CS-1, length: 23 (23))
+  UL data: 3c 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
 Got CS-1 RLC block: R=0, SI=0, TFI=0, CPS=0, RSB=0, rc=184
 UL DATA TFI=0 received (V(Q)=0 .. V(R)=0)
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) restarting timer 3169 while old timer 3169 pending 
 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
 - BSN 0 storing in window (0..63)
+TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW): data_length=20, data=00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
 - Raising V(R) to 1
 - Taking block 0 out, raising V(Q) to 1
 - Assembling frames: (len=20)
@@ -1925,11 +1937,13 @@ RX: [PCU <- BTS] TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) Packet Control A
 TBF: [DOWNLINK] UPLINK ASSIGNED TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN)
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) changes state from ASSIGN to FLOW
 Got RLC block, coding scheme: CS-1, length: 23 (23))
+  UL data: 3c 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
 Got CS-1 RLC block: R=0, SI=0, TFI=0, CPS=0, RSB=0, rc=184
 UL DATA TFI=0 received (V(Q)=0 .. V(R)=0)
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) restarting timer 3169 while old timer 3169 pending 
 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
 - BSN 0 storing in window (0..63)
+TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW): data_length=20, data=00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
 - Raising V(R) to 1
 - Taking block 0 out, raising V(Q) to 1
 - Assembling frames: (len=20)
@@ -1994,11 +2008,13 @@ TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) RX: [PCU <- BTS] RACH qbit-ta=31 ra
 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) TX: START Immediate Assignment Uplink (AGCH)
 Sending data request: trx=0 ts=0 sapi=2 arfcn=0 fn=0 block=0 data=2d 06 3f 10 0f 00 00 03 8b ed 07 00 c8 00 10 0b 2b 2b 2b 2b 2b 2b 2b 
 Got RLC block, coding scheme: CS-1, length: 23 (23))
+  UL data: 00 01 01 f1 22 33 44 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
 Got CS-1 RLC block: R=0, SI=0, TFI=0, CPS=0, RSB=0, rc=184
 UL DATA TFI=0 received (V(Q)=0 .. V(R)=0)
 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) restarting timer 3169 while old timer 3169 pending 
 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
 - BSN 0 storing in window (0..63)
+TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW): data_length=20, data=f1 22 33 44 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
 Decoded premier TLLI=0x00000000 of UL DATA TFI=0.
 Detaching TBF from MS object, TLLI = 0xf1223344, TBF = TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN)
 Attaching TBF to MS object, TLLI = 0x00000000, TBF = TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=ASSIGN)
@@ -2067,11 +2083,13 @@ RX: [PCU <- BTS] TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) Packet Control A
 TBF: [DOWNLINK] UPLINK ASSIGNED TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN)
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) changes state from ASSIGN to FLOW
 Got RLC block, coding scheme: CS-1, length: 23 (23))
+  UL data: 3c 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
 Got CS-1 RLC block: R=0, SI=0, TFI=0, CPS=0, RSB=0, rc=184
 UL DATA TFI=0 received (V(Q)=0 .. V(R)=0)
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) restarting timer 3169 while old timer 3169 pending 
 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
 - BSN 0 storing in window (0..63)
+TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW): data_length=20, data=00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
 - Raising V(R) to 1
 - Taking block 0 out, raising V(Q) to 1
 - Assembling frames: (len=20)
-- 
cgit v1.2.3