add LOG_TRANS, proper context for all transactions

Change-Id: I2e60964d7a3c06d051debd1c707051a0eb3101ba
diff --git a/tests/msc_vlr/msc_vlr_test_no_authen.err b/tests/msc_vlr/msc_vlr_test_no_authen.err
index b21e3fc..6f5adb6 100644
--- a/tests/msc_vlr/msc_vlr_test_no_authen.err
+++ b/tests/msc_vlr/msc_vlr_test_no_authen.err
@@ -176,17 +176,17 @@
 DREF VLR subscr IMSI-901700000004620:MSISDN-46071 + test_no_authen: now used by 2 (attached,test_no_authen)
   llist_count(&vsub->cs.requests) == 0
 DREF VLR subscr IMSI-901700000004620:MSISDN-46071 + SMS-receiver: now used by 3 (attached,test_no_authen,SMS-receiver)
-DLSMS Going to send a MT SMS
-DCC (ti 00 sub IMSI-901700000004620:MSISDN-46071 callref 40000001) New transaction
 DREF VLR subscr IMSI-901700000004620:MSISDN-46071 + SMS: now used by 4 (attached,test_no_authen,SMS-receiver,SMS)
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071 callref-0x40000001 tid-0) New transaction
 DLSMS SMC(0) instance created for network
 DLSMS SMR(0) instance created for network.
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071 callref-0x40000001 tid-0) Going to send a MT SMS
 DLSMS SMR(0) message SM-RL-DATA_REQ received in state IDLE
 DLSMS SMR(0) TX SMS RP-DATA
 DLSMS SMR(0) new RP state IDLE -> WAIT_FOR_RP_ACK
 DLSMS SMC(0) message MNSMS-EST-REQ received in state IDLE
 DLSMS SMC(0) new CP state IDLE -> MM_CONN_PENDING
-DLSMS Initiating Paging procedure for IMSI-901700000004620:MSISDN-46071 due to MMSMS_EST_REQ
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071 callref-0x40000001 tid-0) Initiating Paging due to MMSMS_EST_REQ
 DMM Subscriber IMSI-901700000004620:MSISDN-46071 not paged yet, start paging.
   GERAN-A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
   strcmp(paging_expecting_imsi, imsi) == 0
@@ -227,13 +227,13 @@
 DMM RAN_conn(IMSI-901700000004620:MSISDN-46071:GERAN-A-0:PAGING_RESP){RAN_CONN_S_NEW}: Received Event RAN_CONN_E_ACCEPTED
 DPAG Paging success for IMSI-901700000004620:MSISDN-46071 (event=0)
 DPAG Calling paging cbfn.
-DLSMS paging_cb_mmsms_est_req(hooknum=1, event=0)
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071 callref-0x40000001 tid-0,PAGING) paging_cb_mmsms_est_req(success)
 DREF IMSI-901700000004620:MSISDN-46071: MSC conn use + trans_sms == 2 (0x21: compl_l3,trans_sms)
 DLSMS SMC(0) message MMSMS-EST-CNF received in state MM_CONN_PENDING
 DLSMS SMC(0) send CP data
 DLSMS SMC(0) new CP state MM_CONN_PENDING -> WAIT_CP_ACK
-DLSMS sending CP message (trans=0)
-DLSMS GSM4.11 TX 09 01 58 01 00 07 91 44 77 58 10 06 50 00 4c 00 05 80 64 70 f1 00 00 07 10 10 00 00 00 00 44 50 79 da 1e 1e e7 41 69 37 48 5e 9e a7 c9 65 37 3d 1d 66 83 c2 70 38 3b 3d 0e d3 d3 6f f7 1c 94 9e 83 c2 20 72 79 9e 96 87 c5 ec 32 a8 1d 96 af cb f4 b4 fb 0c 7a c3 e9 e9 b7 db 05 
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:GERAN-A-0:PAGING_RESP callref-0x40000001 tid-0) sending CP message (trans=0)
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:GERAN-A-0:PAGING_RESP callref-0x40000001 tid-0) GSM4.11 TX 09 01 58 01 00 07 91 44 77 58 10 06 50 00 4c 00 05 80 64 70 f1 00 00 07 10 10 00 00 00 00 44 50 79 da 1e 1e e7 41 69 37 48 5e 9e a7 c9 65 37 3d 1d 66 83 c2 70 38 3b 3d 0e d3 d3 6f f7 1c 94 9e 83 c2 20 72 79 9e 96 87 c5 ec 32 a8 1d 96 af cb f4 b4 fb 0c 7a c3 e9 e9 b7 db 05 
 DMSC msc_tx 91 bytes to IMSI-901700000004620:MSISDN-46071 via GERAN-A
 - DTAP --GERAN-A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
 - DTAP matches expected message
@@ -255,7 +255,7 @@
   MSC <--GERAN-A-- MS: SMS:0x04
 DREF IMSI-901700000004620:MSISDN-46071: MSC conn use + dtap == 2 (0x22: dtap,trans_sms)
 DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
-DLSMS receiving data (trans_id=0, msg_type=SMS:0x04)
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:GERAN-A-0:PAGING_RESP callref-0x40000001 tid-0) receiving SMS message SMS:0x04
 DMM RAN_conn(IMSI-901700000004620:MSISDN-46071:GERAN-A-0:PAGING_RESP){RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_COMMUNICATING
 DMM RAN_conn(IMSI-901700000004620:MSISDN-46071:GERAN-A-0:PAGING_RESP){RAN_CONN_S_ACCEPTED}: state_chg to RAN_CONN_S_COMMUNICATING
 DLSMS SMC(0) message MMSMS-DATA-IND (CP ACK) received in state WAIT_CP_ACK
@@ -267,25 +267,26 @@
   MSC <--GERAN-A-- MS: SMS:0x01
 DREF IMSI-901700000004620:MSISDN-46071: MSC conn use + dtap == 2 (0x22: dtap,trans_sms)
 DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
-DLSMS receiving data (trans_id=0, msg_type=SMS:0x01)
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:GERAN-A-0:PAGING_RESP callref-0x40000001 tid-0) receiving SMS message SMS:0x01
 DMM RAN_conn(IMSI-901700000004620:MSISDN-46071:GERAN-A-0:PAGING_RESP){RAN_CONN_S_COMMUNICATING}: Received Event RAN_CONN_E_COMMUNICATING
 DLSMS SMC(0) message MMSMS-DATA-IND (CP DATA) received in state MM_ESTABLISHED
 DLSMS SMC(0) received CP-DATA
-DLSMS sending CP message (trans=0)
-DLSMS GSM4.11 TX 09 04 
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:GERAN-A-0:PAGING_RESP callref-0x40000001 tid-0) sending CP message (trans=0)
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:GERAN-A-0:PAGING_RESP callref-0x40000001 tid-0) GSM4.11 TX 09 04 
 DMSC msc_tx 2 bytes to IMSI-901700000004620:MSISDN-46071 via GERAN-A
 - DTAP --GERAN-A--> MS: SMS:0x04: 0904
 - DTAP matches expected message
-DLSMS MNSMS-DATA/EST-IND
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:GERAN-A-0:PAGING_RESP callref-0x40000001 tid-0) MNSMS-DATA/EST-IND
 DLSMS SMR(0) message MNSMS-DATA-IND received in state WAIT_FOR_RP_ACK
 DLSMS SMR(0) RX SMS RP-ACK
 DLSMS SMR(0) new RP state WAIT_FOR_RP_ACK -> IDLE
-DLSMS RX SMS RP-ACK (MO)
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:GERAN-A-0:PAGING_RESP callref-0x40000001 tid-0) RX SMS RP-ACK (MO)
 DREF VLR subscr IMSI-901700000004620:MSISDN-46071 - SMS-receiver: now used by 3 (attached,SMS,conn)
 DLSMS SMR(0) TX: MNSMS-REL-REQ
 DLSMS SMC(0) message MNSMS-REL-REQ received in state MM_ESTABLISHED
 DLSMS SMC(0) new CP state MM_ESTABLISHED -> IDLE
-DLSMS Got MMSMS_REL_REQ, destroying transaction.
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:GERAN-A-0:PAGING_RESP callref-0x40000001 tid-0) Got MMSMS_REL_REQ, destroying transaction.
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:GERAN-A-0:PAGING_RESP callref-0x40000001 tid-0) Freeing transaction
 DLSMS SMR(0) clearing SMR instance
 DLSMS SMC(0) clearing instance
 DREF VLR subscr IMSI-901700000004620:MSISDN-46071 - SMS: now used by 2 (attached,conn)
@@ -561,17 +562,17 @@
 DREF VLR subscr IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100 + test_no_authen_tmsi: now used by 2 (attached,test_no_authen_tmsi)
   llist_count(&vsub->cs.requests) == 0
 DREF VLR subscr IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100 + SMS-receiver: now used by 3 (attached,test_no_authen_tmsi,SMS-receiver)
-DLSMS Going to send a MT SMS
-DCC (ti 00 sub IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100 callref 40000002) New transaction
 DREF VLR subscr IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100 + SMS: now used by 4 (attached,test_no_authen_tmsi,SMS-receiver,SMS)
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100 callref-0x40000002 tid-0) New transaction
 DLSMS SMC(0) instance created for network
 DLSMS SMR(0) instance created for network.
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100 callref-0x40000002 tid-0) Going to send a MT SMS
 DLSMS SMR(0) message SM-RL-DATA_REQ received in state IDLE
 DLSMS SMR(0) TX SMS RP-DATA
 DLSMS SMR(0) new RP state IDLE -> WAIT_FOR_RP_ACK
 DLSMS SMC(0) message MNSMS-EST-REQ received in state IDLE
 DLSMS SMC(0) new CP state IDLE -> MM_CONN_PENDING
-DLSMS Initiating Paging procedure for IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100 due to MMSMS_EST_REQ
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100 callref-0x40000002 tid-0) Initiating Paging due to MMSMS_EST_REQ
 DMM Subscriber IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100 not paged yet, start paging.
   GERAN-A sends out paging request to IMSI 901700000004620, TMSI 0x03020100, LAC 23
   paging_expecting_tmsi == 0x03020100
@@ -612,13 +613,13 @@
 DMM RAN_conn(IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100:GERAN-A-0:PAGING_RESP){RAN_CONN_S_NEW}: Received Event RAN_CONN_E_ACCEPTED
 DPAG Paging success for IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100 (event=0)
 DPAG Calling paging cbfn.
-DLSMS paging_cb_mmsms_est_req(hooknum=1, event=0)
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100 callref-0x40000002 tid-0,PAGING) paging_cb_mmsms_est_req(success)
 DREF IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100: MSC conn use + trans_sms == 2 (0x21: compl_l3,trans_sms)
 DLSMS SMC(0) message MMSMS-EST-CNF received in state MM_CONN_PENDING
 DLSMS SMC(0) send CP data
 DLSMS SMC(0) new CP state MM_CONN_PENDING -> WAIT_CP_ACK
-DLSMS sending CP message (trans=0)
-DLSMS GSM4.11 TX 09 01 58 01 00 07 91 44 77 58 10 06 50 00 4c 00 05 80 64 70 f1 00 00 07 10 10 00 00 00 00 44 50 79 da 1e 1e e7 41 69 37 48 5e 9e a7 c9 65 37 3d 1d 66 83 c2 70 38 3b 3d 0e d3 d3 6f f7 1c 94 9e 83 c2 20 72 79 9e 96 87 c5 ec 32 a8 1d 96 af cb f4 b4 fb 0c 7a c3 e9 e9 b7 db 05 
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100:GERAN-A-0:PAGING_RESP callref-0x40000002 tid-0) sending CP message (trans=0)
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100:GERAN-A-0:PAGING_RESP callref-0x40000002 tid-0) GSM4.11 TX 09 01 58 01 00 07 91 44 77 58 10 06 50 00 4c 00 05 80 64 70 f1 00 00 07 10 10 00 00 00 00 44 50 79 da 1e 1e e7 41 69 37 48 5e 9e a7 c9 65 37 3d 1d 66 83 c2 70 38 3b 3d 0e d3 d3 6f f7 1c 94 9e 83 c2 20 72 79 9e 96 87 c5 ec 32 a8 1d 96 af cb f4 b4 fb 0c 7a c3 e9 e9 b7 db 05 
 DMSC msc_tx 91 bytes to IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100 via GERAN-A
 - DTAP --GERAN-A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
 - DTAP matches expected message
@@ -640,7 +641,7 @@
   MSC <--GERAN-A-- MS: SMS:0x04
 DREF IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100: MSC conn use + dtap == 2 (0x22: dtap,trans_sms)
 DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
-DLSMS receiving data (trans_id=0, msg_type=SMS:0x04)
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100:GERAN-A-0:PAGING_RESP callref-0x40000002 tid-0) receiving SMS message SMS:0x04
 DMM RAN_conn(IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100:GERAN-A-0:PAGING_RESP){RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_COMMUNICATING
 DMM RAN_conn(IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100:GERAN-A-0:PAGING_RESP){RAN_CONN_S_ACCEPTED}: state_chg to RAN_CONN_S_COMMUNICATING
 DLSMS SMC(0) message MMSMS-DATA-IND (CP ACK) received in state WAIT_CP_ACK
@@ -652,25 +653,26 @@
   MSC <--GERAN-A-- MS: SMS:0x01
 DREF IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100: MSC conn use + dtap == 2 (0x22: dtap,trans_sms)
 DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
-DLSMS receiving data (trans_id=0, msg_type=SMS:0x01)
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100:GERAN-A-0:PAGING_RESP callref-0x40000002 tid-0) receiving SMS message SMS:0x01
 DMM RAN_conn(IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100:GERAN-A-0:PAGING_RESP){RAN_CONN_S_COMMUNICATING}: Received Event RAN_CONN_E_COMMUNICATING
 DLSMS SMC(0) message MMSMS-DATA-IND (CP DATA) received in state MM_ESTABLISHED
 DLSMS SMC(0) received CP-DATA
-DLSMS sending CP message (trans=0)
-DLSMS GSM4.11 TX 09 04 
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100:GERAN-A-0:PAGING_RESP callref-0x40000002 tid-0) sending CP message (trans=0)
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100:GERAN-A-0:PAGING_RESP callref-0x40000002 tid-0) GSM4.11 TX 09 04 
 DMSC msc_tx 2 bytes to IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100 via GERAN-A
 - DTAP --GERAN-A--> MS: SMS:0x04: 0904
 - DTAP matches expected message
-DLSMS MNSMS-DATA/EST-IND
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100:GERAN-A-0:PAGING_RESP callref-0x40000002 tid-0) MNSMS-DATA/EST-IND
 DLSMS SMR(0) message MNSMS-DATA-IND received in state WAIT_FOR_RP_ACK
 DLSMS SMR(0) RX SMS RP-ACK
 DLSMS SMR(0) new RP state WAIT_FOR_RP_ACK -> IDLE
-DLSMS RX SMS RP-ACK (MO)
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100:GERAN-A-0:PAGING_RESP callref-0x40000002 tid-0) RX SMS RP-ACK (MO)
 DREF VLR subscr IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100 - SMS-receiver: now used by 3 (attached,SMS,conn)
 DLSMS SMR(0) TX: MNSMS-REL-REQ
 DLSMS SMC(0) message MNSMS-REL-REQ received in state MM_ESTABLISHED
 DLSMS SMC(0) new CP state MM_ESTABLISHED -> IDLE
-DLSMS Got MMSMS_REL_REQ, destroying transaction.
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100:GERAN-A-0:PAGING_RESP callref-0x40000002 tid-0) Got MMSMS_REL_REQ, destroying transaction.
+DLSMS trans(SMS IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100:GERAN-A-0:PAGING_RESP callref-0x40000002 tid-0) Freeing transaction
 DLSMS SMR(0) clearing SMR instance
 DLSMS SMC(0) clearing instance
 DREF VLR subscr IMSI-901700000004620:MSISDN-46071:TMSI-0x03020100 - SMS: now used by 2 (attached,conn)