Change in osmo-msc[master]: libmsc/gsm_04_11.c: refactor MT SMS message handling

Vadim Yanitskiy gerrit-no-reply at lists.osmocom.org
Thu Nov 29 11:33:04 UTC 2018


Vadim Yanitskiy has submitted this change and it was merged. ( https://gerrit.osmocom.org/11916 )

Change subject: libmsc/gsm_04_11.c: refactor MT SMS message handling
......................................................................

libmsc/gsm_04_11.c: refactor MT SMS message handling

According to GSM TS 04.11, the SMC (Short Message Control) state
machine is a part of CM-sublayer of L3, that is responsible for
connection management (establisment and releasing), and SM-RP
(Relay Protocol) message delivery.

For some reason, the connection establisment request from SMC
(GSM411_MMSMS_EST_REQ) was not handled properly - it was
always assumed that connection is already established.

This is why the code initiating a MT (Mobile Terminated) SMS
transfer had to establish a radio connection with subscriber
manually.

Let's benefit from having the SMC state machine, and offload
connection establishment to it. This change makes the local
implementation closer to GSM TS 04.11, and facilitates the
further integration of GSUP transport.

NOTE: the expected unit test output is changed, because now we
always allocate a transaction first, and then establish a
connection, not vice versa.

Change-Id: I4a07ece80d8dd40b23da6bb1ffc9d3d745b54092
---
M include/osmocom/msc/gsm_04_11.h
M src/libmsc/gsm_04_11.c
M src/libmsc/msc_vty.c
M src/libmsc/smpp_openbsc.c
M src/libmsc/sms_queue.c
M tests/msc_vlr/msc_vlr_test_gsm_authen.err
M tests/msc_vlr/msc_vlr_test_gsm_ciph.err
M tests/msc_vlr/msc_vlr_test_ms_timeout.err
M tests/msc_vlr/msc_vlr_test_no_authen.err
M tests/msc_vlr/msc_vlr_test_reject_concurrency.err
M tests/msc_vlr/msc_vlr_test_umts_authen.err
M tests/msc_vlr/msc_vlr_tests.c
12 files changed, 337 insertions(+), 291 deletions(-)

Approvals:
  Jenkins Builder: Verified
  Harald Welte: Looks good to me, approved



diff --git a/include/osmocom/msc/gsm_04_11.h b/include/osmocom/msc/gsm_04_11.h
index 0b9639f..a368d46 100644
--- a/include/osmocom/msc/gsm_04_11.h
+++ b/include/osmocom/msc/gsm_04_11.h
@@ -27,6 +27,7 @@
 	uint8_t *smsc;
 };
 
+struct gsm_network;
 struct msgb;
 
 int gsm0411_rcv_sms(struct gsm_subscriber_connection *conn, struct msgb *msg);
@@ -37,9 +38,8 @@
 			      const char *sender_msisdn,
 			      int dcs, const char *text);
 
-int gsm411_send_sms_subscr(struct vlr_subscr *vsub,
-			   struct gsm_sms *sms);
-int gsm411_send_sms(struct gsm_subscriber_connection *conn,
+int gsm411_send_sms(struct gsm_network *net,
+		    struct vlr_subscr *vsub,
 		    struct gsm_sms *sms);
 void gsm411_sapi_n_reject(struct gsm_subscriber_connection *conn);
 
diff --git a/src/libmsc/gsm_04_11.c b/src/libmsc/gsm_04_11.c
index 14f9f57..88dc433 100644
--- a/src/libmsc/gsm_04_11.c
+++ b/src/libmsc/gsm_04_11.c
@@ -127,6 +127,87 @@
 	return msc_tx_dtap(conn, msg);
 }
 
+/* Paging callback for MT SMS (Paging is triggered by SMC) */
+static int paging_cb_mmsms_est_req(unsigned int hooknum, unsigned int event,
+				   struct msgb *msg, void *_conn, void *_trans)
+{
+	struct gsm_subscriber_connection *conn = _conn;
+	struct gsm_trans *trans = _trans;
+	struct gsm_sms *sms = trans->sms.sms;
+	int rc = 0;
+
+	DEBUGP(DLSMS, "paging_cb_mmsms_est_req(hooknum=%u, event=%u, "
+		"conn=%p, trans=%p)\n", hooknum, event, conn, trans);
+
+	if (hooknum != GSM_HOOK_RR_PAGING)
+		return -EINVAL;
+
+	/* Paging procedure has finished */
+	trans->paging_request = NULL;
+
+	switch (event) {
+	case GSM_PAGING_SUCCEEDED:
+		/* Associate transaction with established connection */
+		trans->conn = msc_subscr_conn_get(conn, MSC_CONN_USE_TRANS_SMS);
+		/* FIXME: specify SACCH in case we already have active TCH */
+		trans->dlci = 0x03;
+		/* Confirm successful connection establishment */
+		gsm411_smc_recv(&trans->sms.smc_inst,
+			GSM411_MMSMS_EST_CNF, NULL, 0);
+		break;
+	case GSM_PAGING_EXPIRED:
+	case GSM_PAGING_BUSY:
+		/* Inform SMC about channel establishment failure */
+		gsm411_smc_recv(&trans->sms.smc_inst,
+			GSM411_MMSMS_REL_IND, NULL, 0);
+
+		/* Notify the SMSqueue and free stored SMS */
+		send_signal(S_SMS_UNKNOWN_ERROR, NULL, sms, event);
+		trans->sms.sms = NULL;
+		sms_free(sms);
+
+		/* Destroy this transaction */
+		trans_free(trans);
+		rc = -ETIMEDOUT;
+		break;
+	default:
+		LOGP(DLSMS, LOGL_ERROR, "Unhandled paging event: %d\n", event);
+	}
+
+	return rc;
+}
+
+static int gsm411_mmsms_est_req(struct gsm_trans *trans)
+{
+	/* Subscriber's data shall be associated */
+	OSMO_ASSERT(trans->vsub != NULL);
+
+	/* Check if connection is already established */
+	if (trans->conn != NULL) {
+		LOGP(DLSMS, LOGL_DEBUG, "Using an existing connection "
+			"for %s\n", vlr_subscr_name(trans->vsub));
+		return gsm411_smc_recv(&trans->sms.smc_inst,
+			GSM411_MMSMS_EST_CNF, NULL, 0);
+	}
+
+	/* Initiate Paging procedure */
+	LOGP(DLSMS, LOGL_DEBUG, "Initiating Paging procedure "
+		"for %s due to MMSMS_EST_REQ\n", vlr_subscr_name(trans->vsub));
+	trans->paging_request = subscr_request_conn(trans->vsub,
+		paging_cb_mmsms_est_req, trans, "MT SMS");
+	if (!trans->paging_request) {
+		LOGP(DLSMS, LOGL_ERROR, "Failed to initiate Paging "
+			"procedure for %s\n", vlr_subscr_name(trans->vsub));
+		/* Inform SMC about channel establishment failure */
+		gsm411_smc_recv(&trans->sms.smc_inst,
+			GSM411_MMSMS_REL_IND, NULL, 0);
+		trans_free(trans);
+		return -EIO;
+	}
+
+	return 0;
+}
+
 /* Prefix msg with a 04.08/04.11 CP header */
 static int gsm411_cp_sendmsg(struct msgb *msg, struct gsm_trans *trans,
 			     uint8_t msg_type)
@@ -154,8 +235,7 @@
 
 	switch (msg_type) {
 	case GSM411_MMSMS_EST_REQ:
-		/* recycle msg */
-		rc = gsm411_smc_recv(inst, GSM411_MMSMS_EST_CNF, msg, 0);
+		rc = gsm411_mmsms_est_req(trans);
 		msgb_free(msg); /* upper layer does not free msg */
 		break;
 	case GSM411_MMSMS_DATA_REQ:
@@ -899,6 +979,120 @@
 	return rc;
 }
 
+static struct gsm_trans *gsm411_alloc_mt_trans(struct gsm_network *net,
+					       struct vlr_subscr *vsub)
+{
+	struct gsm_subscriber_connection *conn;
+	struct gsm_trans *trans;
+	int tid;
+
+	LOGP(DLSMS, LOGL_INFO, "Going to send a MT SMS\n");
+
+	/* Generate a new transaction ID */
+	tid = trans_assign_trans_id(net, vsub, GSM48_PDISC_SMS, 0);
+	if (tid == -1) {
+		LOGP(DLSMS, LOGL_ERROR, "No available transaction IDs\n");
+		return NULL;
+	}
+
+	/* Allocate a new transaction */
+	trans = trans_alloc(net, vsub, GSM48_PDISC_SMS, tid, new_callref++);
+	if (!trans) {
+		LOGP(DLSMS, LOGL_ERROR, "No memory for trans\n");
+		return NULL;
+	}
+
+	/* Init both SMC and SMR state machines */
+	gsm411_smc_init(&trans->sms.smc_inst, 0, 1,
+		gsm411_mn_recv, gsm411_mm_send);
+	gsm411_smr_init(&trans->sms.smr_inst, 0, 1,
+		gsm411_rl_recv, gsm411_mn_send);
+
+	/* Attempt to find an existing connection */
+	conn = connection_for_subscr(vsub);
+	if (conn) {
+		/* Associate transaction with connection */
+		trans->conn = msc_subscr_conn_get(conn, MSC_CONN_USE_TRANS_SMS);
+		/* Generate unique RP Message Reference */
+		trans->sms.sm_rp_mr = conn->next_rp_ref++;
+	}
+
+	return trans;
+}
+
+/* High-level function to send an SMS to a given subscriber */
+int gsm411_send_sms(struct gsm_network *net,
+		    struct vlr_subscr *vsub,
+		    struct gsm_sms *sms)
+{
+	uint8_t *data, *rp_ud_len;
+	struct gsm_trans *trans;
+	struct msgb *msg;
+	int rc;
+
+	/* Allocate a new transaction for MT SMS */
+	trans = gsm411_alloc_mt_trans(net, vsub);
+	if (!trans) {
+		send_signal(S_SMS_UNKNOWN_ERROR, NULL, sms, 0);
+		sms_free(sms);
+		return -ENOMEM;
+	}
+
+	/* Allocate a message buffer for to be encoded SMS */
+	msg = gsm411_msgb_alloc();
+	if (!msg) {
+		send_signal(S_SMS_UNKNOWN_ERROR, NULL, sms, 0);
+		trans_free(trans);
+		sms_free(sms);
+		return -ENOMEM;
+	}
+
+	/* Hardcode SMSC Originating Address for now */
+	data = (uint8_t *)msgb_put(msg, 8);
+	data[0] = 0x07;	/* originator length == 7 */
+	data[1] = 0x91; /* type of number: international, ISDN */
+	data[2] = 0x44; /* 447785016005 */
+	data[3] = 0x77;
+	data[4] = 0x58;
+	data[5] = 0x10;
+	data[6] = 0x06;
+	data[7] = 0x50;
+
+	/* Hardcoded Destination Address */
+	data = (uint8_t *)msgb_put(msg, 1);
+	data[0] = 0;	/* destination length == 0 */
+
+	/* obtain a pointer for the rp_ud_len, so we can fill it later */
+	rp_ud_len = (uint8_t *)msgb_put(msg, 1);
+
+	if (sms->is_report) {
+		/* generate the 03.40 SMS-STATUS-REPORT TPDU */
+		rc = gsm340_gen_sms_status_report_tpdu(msg, sms);
+	} else {
+		/* generate the 03.40 SMS-DELIVER TPDU */
+		rc = gsm340_gen_sms_deliver_tpdu(msg, sms);
+	}
+	if (rc < 0) {
+		send_signal(S_SMS_UNKNOWN_ERROR, trans, sms, 0);
+		sms_free(sms);
+		trans_free(trans);
+		msgb_free(msg);
+		return rc;
+	}
+
+	*rp_ud_len = rc;
+
+	/* Store a pointer to abstract SMS representation */
+	trans->sms.sms = sms;
+
+	rate_ctr_inc(&net->msc_ctrs->ctr[MSC_CTR_SMS_DELIVERED]);
+	db_sms_inc_deliver_attempts(trans->sms.sms);
+
+	return gsm411_rp_sendmsg(&trans->sms.smr_inst, msg,
+		GSM411_MT_RP_DATA_MT, trans->sms.sm_rp_mr,
+		GSM411_SM_RL_DATA_REQ);
+}
+
 /* Entry point for incoming GSM48_PDISC_SMS from abis_rsl.c */
 int gsm0411_rcv_sms(struct gsm_subscriber_connection *conn,
 		    struct msgb *msg)
@@ -985,159 +1179,6 @@
 	return rc;
 }
 
-/* Take a SMS in gsm_sms structure and send it through an already
- * existing conn. We also assume that the caller ensured this conn already
- * has a SAPI3 RLL connection! */
-int gsm411_send_sms(struct gsm_subscriber_connection *conn, struct gsm_sms *sms)
-{
-	struct msgb *msg = gsm411_msgb_alloc();
-	struct gsm_trans *trans;
-	uint8_t *data, *rp_ud_len;
-	uint8_t msg_ref = conn->next_rp_ref++;
-	int transaction_id;
-	int rc;
-
-	transaction_id =
-		trans_assign_trans_id(conn->network, conn->vsub,
-				      GSM48_PDISC_SMS, 0);
-	if (transaction_id == -1) {
-		LOGP(DLSMS, LOGL_ERROR, "No available transaction ids\n");
-		send_signal(S_SMS_UNKNOWN_ERROR, NULL, sms, 0);
-		sms_free(sms);
-		msgb_free(msg);
-		return -EBUSY;
-	}
-
-	DEBUGP(DLSMS, "%s()\n", __func__);
-
-	/* FIXME: allocate transaction with message reference */
-	trans = trans_alloc(conn->network, conn->vsub,
-			    GSM48_PDISC_SMS,
-			    transaction_id, new_callref++);
-	if (!trans) {
-		LOGP(DLSMS, LOGL_ERROR, "No memory for trans\n");
-		send_signal(S_SMS_UNKNOWN_ERROR, NULL, sms, 0);
-		sms_free(sms);
-		msgb_free(msg);
-		/* FIXME: send some error message */
-		return -ENOMEM;
-	}
-	gsm411_smc_init(&trans->sms.smc_inst, sms->id, 1,
-		gsm411_mn_recv, gsm411_mm_send);
-	gsm411_smr_init(&trans->sms.smr_inst, sms->id, 1,
-		gsm411_rl_recv, gsm411_mn_send);
-	trans->sms.sms = sms;
-
-	trans->conn = msc_subscr_conn_get(conn, MSC_CONN_USE_TRANS_SMS);
-	trans->dlci = 0x03;
-	/* FIXME: specify SACCH in case we already have active TCH */
-
-	/* Hardcode SMSC Originating Address for now */
-	data = (uint8_t *)msgb_put(msg, 8);
-	data[0] = 0x07;	/* originator length == 7 */
-	data[1] = 0x91; /* type of number: international, ISDN */
-	data[2] = 0x44; /* 447785016005 */
-	data[3] = 0x77;
-	data[4] = 0x58;
-	data[5] = 0x10;
-	data[6] = 0x06;
-	data[7] = 0x50;
-
-	/* Hardcoded Destination Address */
-	data = (uint8_t *)msgb_put(msg, 1);
-	data[0] = 0;	/* destination length == 0 */
-
-	/* obtain a pointer for the rp_ud_len, so we can fill it later */
-	rp_ud_len = (uint8_t *)msgb_put(msg, 1);
-
-	if (sms->is_report) {
-		/* generate the 03.40 SMS-STATUS-REPORT TPDU */
-		rc = gsm340_gen_sms_status_report_tpdu(msg, sms);
-	} else {
-		/* generate the 03.40 SMS-DELIVER TPDU */
-		rc = gsm340_gen_sms_deliver_tpdu(msg, sms);
-	}
-	if (rc < 0) {
-		send_signal(S_SMS_UNKNOWN_ERROR, trans, sms, 0);
-		sms_free(sms);
-		trans->sms.sms = NULL;
-		trans_free(trans);
-		msgb_free(msg);
-		return rc;
-	}
-
-	*rp_ud_len = rc;
-
-	DEBUGP(DLSMS, "TX: SMS DELIVER\n");
-
-	rate_ctr_inc(&conn->network->msc_ctrs->ctr[MSC_CTR_SMS_DELIVERED]);
-	db_sms_inc_deliver_attempts(trans->sms.sms);
-
-	return gsm411_rp_sendmsg(&trans->sms.smr_inst, msg,
-		GSM411_MT_RP_DATA_MT, msg_ref, GSM411_SM_RL_DATA_REQ);
-}
-
-/* paging callback. Here we get called if paging a subscriber has
- * succeeded or failed. */
-static int paging_cb_send_sms(unsigned int hooknum, unsigned int event,
-			      struct msgb *msg, void *_conn, void *_sms)
-{
-	struct gsm_subscriber_connection *conn = _conn;
-	struct gsm_sms *sms = _sms;
-	int rc = 0;
-
-	DEBUGP(DLSMS, "paging_cb_send_sms(hooknum=%u, event=%u, msg=%p,"
-		"conn=%p, sms=%p/id: %llu)\n", hooknum, event, msg, conn, sms, sms->id);
-
-	if (hooknum != GSM_HOOK_RR_PAGING)
-		return -EINVAL;
-
-	switch (event) {
-	case GSM_PAGING_SUCCEEDED:
-		gsm411_send_sms(conn, sms);
-		break;
-	case GSM_PAGING_EXPIRED:
-	case GSM_PAGING_BUSY:
-		send_signal(S_SMS_UNKNOWN_ERROR, NULL, sms, event);
-		sms_free(sms);
-		rc = -ETIMEDOUT;
-		break;
-	default:
-		LOGP(DLSMS, LOGL_ERROR, "Unhandled paging event: %d\n", event);
-	}
-
-	return rc;
-}
-
-/* high-level function to send a SMS to a given subscriber. The function
- * will take care of paging the subscriber, establishing the RLL SAPI3
- * connection, etc. */
-int gsm411_send_sms_subscr(struct vlr_subscr *vsub,
-			   struct gsm_sms *sms)
-{
-	struct gsm_subscriber_connection *conn;
-	void *res;
-
-	/* check if we already have an open conn to the subscriber.
-	 * if yes, send the SMS this way */
-	conn = connection_for_subscr(vsub);
-	if (conn) {
-		LOGP(DLSMS, LOGL_DEBUG, "Sending SMS via already open connection %p to %s\n",
-		     conn, vlr_subscr_name(vsub));
-		return gsm411_send_sms(conn, sms);
-	}
-
-	/* if not, we have to start paging */
-	LOGP(DLSMS, LOGL_DEBUG, "Sending SMS: no connection open, start paging %s\n",
-	     vlr_subscr_name(vsub));
-	res = subscr_request_conn(vsub, paging_cb_send_sms, sms, "send SMS");
-	if (!res) {
-		send_signal(S_SMS_UNKNOWN_ERROR, NULL, sms, GSM_PAGING_BUSY);
-		sms_free(sms);
-	}
-	return 0;
-}
-
 void _gsm411_sms_trans_free(struct gsm_trans *trans)
 {
 	/* cleanup SMS instance */
diff --git a/src/libmsc/msc_vty.c b/src/libmsc/msc_vty.c
index cdf3184..4f3ac04 100644
--- a/src/libmsc/msc_vty.c
+++ b/src/libmsc/msc_vty.c
@@ -680,7 +680,7 @@
 			break;
 
 		if (sms->receiver)
-			gsm411_send_sms_subscr(sms->receiver, sms);
+			gsm411_send_sms(gsmnet, sms->receiver, sms);
 
 		sms_id = sms->id + 1;
 	}
@@ -819,7 +819,7 @@
 
 	sms = db_sms_get_unsent_for_subscr(vsub, UINT_MAX);
 	if (sms)
-		gsm411_send_sms_subscr(sms->receiver, sms);
+		gsm411_send_sms(gsmnet, sms->receiver, sms);
 
 	vlr_subscr_put(vsub);
 
diff --git a/src/libmsc/smpp_openbsc.c b/src/libmsc/smpp_openbsc.c
index c12db5f..051372c 100644
--- a/src/libmsc/smpp_openbsc.c
+++ b/src/libmsc/smpp_openbsc.c
@@ -268,7 +268,7 @@
 		LOGP(DLSMS, LOGL_DEBUG, "SMPP SUBMIT-SM: Forwarding in "
 			"real time (Transaction/Forward mode)\n");
 		sms->smpp.transaction_mode = 1;
-		gsm411_send_sms_subscr(sms->receiver, sms);
+		gsm411_send_sms(net, sms->receiver, sms);
 		rc = 1; /* don't send any response yet */
 		break;
 	}
diff --git a/src/libmsc/sms_queue.c b/src/libmsc/sms_queue.c
index 252e529..9907f4f 100644
--- a/src/libmsc/sms_queue.c
+++ b/src/libmsc/sms_queue.c
@@ -186,7 +186,7 @@
 			sms_queue_trigger(smsq);
 		} else {
 			pending->resend = 0;
-			gsm411_send_sms_subscr(sms->receiver, sms);
+			gsm411_send_sms(smsq->network, sms->receiver, sms);
 		}
 	}
 }
@@ -311,7 +311,7 @@
 		attempted += 1;
 		smsq->pending += 1;
 		llist_add_tail(&pending->entry, &smsq->pending_sms);
-		gsm411_send_sms_subscr(sms->receiver, sms);
+		gsm411_send_sms(smsq->network, sms->receiver, sms);
 	} while (attempted < attempts && rounds < 1000);
 
 	LOGP(DLSMS, LOGL_DEBUG, "SMSqueue added %d messages in %d rounds\n", attempted, rounds);
@@ -349,7 +349,7 @@
 
 	smsq->pending += 1;
 	llist_add_tail(&pending->entry, &smsq->pending_sms);
-	gsm411_send_sms_subscr(sms->receiver, sms);
+	gsm411_send_sms(smsq->network, sms->receiver, sms);
 	return;
 
 no_pending_sms:
@@ -398,7 +398,6 @@
 {
 	struct gsm_sms *sms;
 	struct gsm_sms_pending *pending;
-	struct gsm_subscriber_connection *conn;
 
 	/*
 	 * The code used to be very clever and tried to submit
@@ -423,15 +422,12 @@
 		return 0;
 	}
 
-	conn = connection_for_subscr(vsub);
-	if (!conn)
-		return -1;
-
 	/* Now try to deliver any pending SMS to this sub */
 	sms = db_sms_get_unsent_for_subscr(vsub, UINT_MAX);
 	if (!sms)
 		return -1;
-	gsm411_send_sms(conn, sms);
+
+	gsm411_send_sms(net, vsub, sms);
 	return 0;
 }
 
diff --git a/tests/msc_vlr/msc_vlr_test_gsm_authen.err b/tests/msc_vlr/msc_vlr_test_gsm_authen.err
index 51f7367..fc701b2 100644
--- a/tests/msc_vlr/msc_vlr_test_gsm_authen.err
+++ b/tests/msc_vlr/msc_vlr_test_gsm_authen.err
@@ -275,18 +275,20 @@
 DREF VLR subscr MSISDN:46071 usage increases to: 2
   llist_count(&vsub->cs.requests) == 0
 DREF VLR subscr MSISDN:46071 usage increases to: 3
+DCC (ti 00 sub MSISDN:46071 callref 40000001) New transaction
+DREF VLR subscr MSISDN:46071 usage increases to: 4
 DMM Subscriber MSISDN:46071 not paged yet, start paging.
   RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
   strcmp(paging_expecting_imsi, imsi) == 0
-DREF VLR subscr MSISDN:46071 usage increases to: 4
+DREF VLR subscr MSISDN:46071 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:46071 usage decreases to: 3
+DREF VLR subscr MSISDN:46071 usage decreases to: 4
   paging_sent == 1
   paging_stopped == 0
 - the subscriber and its pending request should remain
-DREF VLR subscr MSISDN:46071 usage increases to: 4
+DREF VLR subscr MSISDN:46071 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:46071 usage decreases to: 3
+DREF VLR subscr MSISDN:46071 usage decreases to: 4
 - MS replies with Paging Response, and VLR sends Auth Request with third key
   MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
   new conn
@@ -299,8 +301,8 @@
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000004620)
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
-DREF VLR subscr MSISDN:46071 usage increases to: 4
 DREF VLR subscr MSISDN:46071 usage increases to: 5
+DREF VLR subscr MSISDN:46071 usage increases to: 6
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
 DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
@@ -311,7 +313,7 @@
 - sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=2 auth_types=0x1 and...
 - ...rand=e7c03ba7cf0e2fde82b2dc4d63077d42
 - ...expecting sres=a29514ae
-DREF VLR subscr MSISDN:46071 usage decreases to: 4
+DREF VLR subscr MSISDN:46071 usage decreases to: 5
 DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
 DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
 DREF MSISDN:46071: MSC conn use - compl_l3 == 0 (0x0: )
@@ -356,8 +358,6 @@
 DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
 DPAG Paging success for MSISDN:46071 (event=0)
 DPAG Calling paging cbfn.
-DCC (ti 00 sub MSISDN:46071 callref 40000001) New transaction
-DREF VLR subscr MSISDN:46071 usage increases to: 5
 DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x22: dtap,trans_sms)
 DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
 - DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
@@ -762,18 +762,20 @@
 DREF VLR subscr MSISDN:46071 usage increases to: 2
   llist_count(&vsub->cs.requests) == 0
 DREF VLR subscr MSISDN:46071 usage increases to: 3
+DCC (ti 00 sub MSISDN:46071 callref 40000002) New transaction
+DREF VLR subscr MSISDN:46071 usage increases to: 4
 DMM Subscriber MSISDN:46071 not paged yet, start paging.
   RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0x03020100, LAC 23
   paging_expecting_tmsi == 0x03020100
-DREF VLR subscr MSISDN:46071 usage increases to: 4
+DREF VLR subscr MSISDN:46071 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:46071 usage decreases to: 3
+DREF VLR subscr MSISDN:46071 usage decreases to: 4
   paging_sent == 1
   paging_stopped == 0
 - the subscriber and its pending request should remain
-DREF VLR subscr MSISDN:46071 usage increases to: 4
+DREF VLR subscr MSISDN:46071 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:46071 usage decreases to: 3
+DREF VLR subscr MSISDN:46071 usage decreases to: 4
 - MS replies with Paging Response using TMSI, and VLR sends Auth Request with third key
   MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
   new conn
@@ -786,8 +788,8 @@
 DVLR Process_Access_Request_VLR(PAGING_RESP:50462976){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:50462976)
 DVLR Process_Access_Request_VLR(PAGING_RESP:50462976){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
 DVLR Process_Access_Request_VLR(PAGING_RESP:50462976){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
-DREF VLR subscr MSISDN:46071 usage increases to: 4
 DREF VLR subscr MSISDN:46071 usage increases to: 5
+DREF VLR subscr MSISDN:46071 usage increases to: 6
 DVLR Process_Access_Request_VLR(PAGING_RESP:50462976){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
 DVLR Process_Access_Request_VLR(PAGING_RESP:50462976){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
 DVLR VLR_Authenticate(PAGING_RESP:50462976){VLR_SUB_AS_NEEDS_AUTH}: Allocated
@@ -798,7 +800,7 @@
 - sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=2 auth_types=0x1 and...
 - ...rand=e7c03ba7cf0e2fde82b2dc4d63077d42
 - ...expecting sres=a29514ae
-DREF VLR subscr MSISDN:46071 usage decreases to: 4
+DREF VLR subscr MSISDN:46071 usage decreases to: 5
 DMM Subscr_Conn(PAGING_RESP:50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
 DMM Subscr_Conn(PAGING_RESP:50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
 DREF MSISDN:46071: MSC conn use - compl_l3 == 0 (0x0: )
@@ -843,8 +845,6 @@
 DMM Subscr_Conn(PAGING_RESP:50462976){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
 DPAG Paging success for MSISDN:46071 (event=0)
 DPAG Calling paging cbfn.
-DCC (ti 00 sub MSISDN:46071 callref 40000002) New transaction
-DREF VLR subscr MSISDN:46071 usage increases to: 5
 DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x22: dtap,trans_sms)
 DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
 - DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
@@ -1873,18 +1873,20 @@
 DREF VLR subscr MSISDN:42342 usage increases to: 2
   llist_count(&vsub->cs.requests) == 0
 DREF VLR subscr MSISDN:42342 usage increases to: 3
+DCC (ti 00 sub MSISDN:42342 callref 40000003) New transaction
+DREF VLR subscr MSISDN:42342 usage increases to: 4
 DMM Subscriber MSISDN:42342 not paged yet, start paging.
   RAN_GERAN_A sends out paging request to IMSI 901700000010650, TMSI 0xffffffff, LAC 23
   strcmp(paging_expecting_imsi, imsi) == 0
-DREF VLR subscr MSISDN:42342 usage increases to: 4
+DREF VLR subscr MSISDN:42342 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:42342 usage decreases to: 3
+DREF VLR subscr MSISDN:42342 usage decreases to: 4
   paging_sent == 1
   paging_stopped == 0
 - the subscriber and its pending request should remain
-DREF VLR subscr MSISDN:42342 usage increases to: 4
+DREF VLR subscr MSISDN:42342 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:42342 usage decreases to: 3
+DREF VLR subscr MSISDN:42342 usage decreases to: 4
 - MS replies with Paging Response, and VLR sends Auth Request with third key
   MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
   new conn
@@ -1897,8 +1899,8 @@
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000010650)
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
-DREF VLR subscr MSISDN:42342 usage increases to: 4
 DREF VLR subscr MSISDN:42342 usage increases to: 5
+DREF VLR subscr MSISDN:42342 usage increases to: 6
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
 DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
@@ -1909,7 +1911,7 @@
 - sending GSM Auth Request for MSISDN:42342: tuple use_count=1 key_seq=2 auth_types=0x3 and...
 - ...rand=efa9c29a9742148d5c9070348716e1bb
 - ...expecting sres=69d5f9fb
-DREF VLR subscr MSISDN:42342 usage decreases to: 4
+DREF VLR subscr MSISDN:42342 usage decreases to: 5
 DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
 DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
 DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: )
@@ -1954,8 +1956,6 @@
 DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
 DPAG Paging success for MSISDN:42342 (event=0)
 DPAG Calling paging cbfn.
-DCC (ti 00 sub MSISDN:42342 callref 40000003) New transaction
-DREF VLR subscr MSISDN:42342 usage increases to: 5
 DREF MSISDN:42342: MSC conn use + trans_sms == 2 (0x22: dtap,trans_sms)
 DMSC msc_tx 91 bytes to MSISDN:42342 via RAN_GERAN_A
 - DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005802443f2000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
diff --git a/tests/msc_vlr/msc_vlr_test_gsm_ciph.err b/tests/msc_vlr/msc_vlr_test_gsm_ciph.err
index cc8659c..9cc6387 100644
--- a/tests/msc_vlr/msc_vlr_test_gsm_ciph.err
+++ b/tests/msc_vlr/msc_vlr_test_gsm_ciph.err
@@ -303,18 +303,20 @@
 DREF VLR subscr MSISDN:46071 usage increases to: 2
   llist_count(&vsub->cs.requests) == 0
 DREF VLR subscr MSISDN:46071 usage increases to: 3
+DCC (ti 00 sub MSISDN:46071 callref 40000001) New transaction
+DREF VLR subscr MSISDN:46071 usage increases to: 4
 DMM Subscriber MSISDN:46071 not paged yet, start paging.
   RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
   strcmp(paging_expecting_imsi, imsi) == 0
-DREF VLR subscr MSISDN:46071 usage increases to: 4
+DREF VLR subscr MSISDN:46071 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:46071 usage decreases to: 3
+DREF VLR subscr MSISDN:46071 usage decreases to: 4
   paging_sent == 1
   paging_stopped == 0
 - the subscriber and its pending request should remain
-DREF VLR subscr MSISDN:46071 usage increases to: 4
+DREF VLR subscr MSISDN:46071 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:46071 usage decreases to: 3
+DREF VLR subscr MSISDN:46071 usage decreases to: 4
 - MS replies with Paging Response, and VLR sends Auth Request with third key
   MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
   new conn
@@ -327,8 +329,8 @@
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000004620)
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth+Ciph
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
-DREF VLR subscr MSISDN:46071 usage increases to: 4
 DREF VLR subscr MSISDN:46071 usage increases to: 5
+DREF VLR subscr MSISDN:46071 usage increases to: 6
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
 DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
@@ -339,7 +341,7 @@
 - sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=2 auth_types=0x1 and...
 - ...rand=e7c03ba7cf0e2fde82b2dc4d63077d42
 - ...expecting sres=a29514ae
-DREF VLR subscr MSISDN:46071 usage decreases to: 4
+DREF VLR subscr MSISDN:46071 usage decreases to: 5
 DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
 DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
 DREF MSISDN:46071: MSC conn use - compl_l3 == 0 (0x0: )
@@ -409,8 +411,6 @@
 DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
 DPAG Paging success for MSISDN:46071 (event=0)
 DPAG Calling paging cbfn.
-DCC (ti 00 sub MSISDN:46071 callref 40000001) New transaction
-DREF VLR subscr MSISDN:46071 usage increases to: 5
 DREF MSISDN:46071: MSC conn use + trans_sms == 1 (0x20: trans_sms)
 DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
 - DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
@@ -843,18 +843,20 @@
 DREF VLR subscr MSISDN:46071 usage increases to: 2
   llist_count(&vsub->cs.requests) == 0
 DREF VLR subscr MSISDN:46071 usage increases to: 3
+DCC (ti 00 sub MSISDN:46071 callref 40000002) New transaction
+DREF VLR subscr MSISDN:46071 usage increases to: 4
 DMM Subscriber MSISDN:46071 not paged yet, start paging.
   RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0x03020100, LAC 23
   paging_expecting_tmsi == 0x03020100
-DREF VLR subscr MSISDN:46071 usage increases to: 4
+DREF VLR subscr MSISDN:46071 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:46071 usage decreases to: 3
+DREF VLR subscr MSISDN:46071 usage decreases to: 4
   paging_sent == 1
   paging_stopped == 0
 - the subscriber and its pending request should remain
-DREF VLR subscr MSISDN:46071 usage increases to: 4
+DREF VLR subscr MSISDN:46071 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:46071 usage decreases to: 3
+DREF VLR subscr MSISDN:46071 usage decreases to: 4
 - MS replies with Paging Response using TMSI, and VLR sends Auth Request with third key
   MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
   new conn
@@ -867,8 +869,8 @@
 DVLR Process_Access_Request_VLR(PAGING_RESP:50462976){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:50462976)
 DVLR Process_Access_Request_VLR(PAGING_RESP:50462976){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth+Ciph
 DVLR Process_Access_Request_VLR(PAGING_RESP:50462976){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
-DREF VLR subscr MSISDN:46071 usage increases to: 4
 DREF VLR subscr MSISDN:46071 usage increases to: 5
+DREF VLR subscr MSISDN:46071 usage increases to: 6
 DVLR Process_Access_Request_VLR(PAGING_RESP:50462976){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
 DVLR Process_Access_Request_VLR(PAGING_RESP:50462976){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
 DVLR VLR_Authenticate(PAGING_RESP:50462976){VLR_SUB_AS_NEEDS_AUTH}: Allocated
@@ -879,7 +881,7 @@
 - sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=2 auth_types=0x1 and...
 - ...rand=e7c03ba7cf0e2fde82b2dc4d63077d42
 - ...expecting sres=a29514ae
-DREF VLR subscr MSISDN:46071 usage decreases to: 4
+DREF VLR subscr MSISDN:46071 usage decreases to: 5
 DMM Subscr_Conn(PAGING_RESP:50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
 DMM Subscr_Conn(PAGING_RESP:50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
 DREF MSISDN:46071: MSC conn use - compl_l3 == 0 (0x0: )
@@ -949,8 +951,6 @@
 DMM Subscr_Conn(PAGING_RESP:50462976){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
 DPAG Paging success for MSISDN:46071 (event=0)
 DPAG Calling paging cbfn.
-DCC (ti 00 sub MSISDN:46071 callref 40000002) New transaction
-DREF VLR subscr MSISDN:46071 usage increases to: 5
 DREF MSISDN:46071: MSC conn use + trans_sms == 1 (0x20: trans_sms)
 DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
 - DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
@@ -2069,18 +2069,20 @@
 DREF VLR subscr MSISDN:42342 usage increases to: 2
   llist_count(&vsub->cs.requests) == 0
 DREF VLR subscr MSISDN:42342 usage increases to: 3
+DCC (ti 00 sub MSISDN:42342 callref 40000003) New transaction
+DREF VLR subscr MSISDN:42342 usage increases to: 4
 DMM Subscriber MSISDN:42342 not paged yet, start paging.
   RAN_GERAN_A sends out paging request to IMSI 901700000010650, TMSI 0xffffffff, LAC 23
   strcmp(paging_expecting_imsi, imsi) == 0
-DREF VLR subscr MSISDN:42342 usage increases to: 4
+DREF VLR subscr MSISDN:42342 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:42342 usage decreases to: 3
+DREF VLR subscr MSISDN:42342 usage decreases to: 4
   paging_sent == 1
   paging_stopped == 0
 - the subscriber and its pending request should remain
-DREF VLR subscr MSISDN:42342 usage increases to: 4
+DREF VLR subscr MSISDN:42342 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:42342 usage decreases to: 3
+DREF VLR subscr MSISDN:42342 usage decreases to: 4
 - MS replies with Paging Response, and VLR sends *UMTS AKA* Auth Request with third key
   MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
   new conn
@@ -2093,8 +2095,8 @@
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000010650)
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: rev=R99 net=GERAN Auth+Ciph
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
-DREF VLR subscr MSISDN:42342 usage increases to: 4
 DREF VLR subscr MSISDN:42342 usage increases to: 5
+DREF VLR subscr MSISDN:42342 usage increases to: 6
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
 DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
@@ -2106,7 +2108,7 @@
 - ...rand=54d8f19778056666b41c8c25e52eb60c
 - ...autn=53f3e5632b3d00008865dd54d49663f2
 - ...expecting res=86e848a9e7ad8cd5
-DREF VLR subscr MSISDN:42342 usage decreases to: 4
+DREF VLR subscr MSISDN:42342 usage decreases to: 5
 DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
 DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
 DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: )
@@ -2165,8 +2167,6 @@
 DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
 DPAG Paging success for MSISDN:42342 (event=0)
 DPAG Calling paging cbfn.
-DCC (ti 00 sub MSISDN:42342 callref 40000003) New transaction
-DREF VLR subscr MSISDN:42342 usage increases to: 5
 DREF MSISDN:42342: MSC conn use + trans_sms == 1 (0x20: trans_sms)
 DMSC msc_tx 91 bytes to MSISDN:42342 via RAN_GERAN_A
 - DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005802443f2000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
@@ -2559,18 +2559,20 @@
 DREF VLR subscr MSISDN:42342 usage increases to: 2
   llist_count(&vsub->cs.requests) == 0
 DREF VLR subscr MSISDN:42342 usage increases to: 3
+DCC (ti 00 sub MSISDN:42342 callref 40000004) New transaction
+DREF VLR subscr MSISDN:42342 usage increases to: 4
 DMM Subscriber MSISDN:42342 not paged yet, start paging.
   RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
   strcmp(paging_expecting_imsi, imsi) == 0
-DREF VLR subscr MSISDN:42342 usage increases to: 4
+DREF VLR subscr MSISDN:42342 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:42342 usage decreases to: 3
+DREF VLR subscr MSISDN:42342 usage decreases to: 4
   paging_sent == 1
   paging_stopped == 0
 - the subscriber and its pending request should remain
-DREF VLR subscr MSISDN:42342 usage increases to: 4
+DREF VLR subscr MSISDN:42342 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:42342 usage decreases to: 3
+DREF VLR subscr MSISDN:42342 usage decreases to: 4
 - MS replies with Paging Response, and VLR sends Auth Request with third key
   MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
   new conn
@@ -2583,8 +2585,8 @@
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000004620)
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth+Ciph
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
-DREF VLR subscr MSISDN:42342 usage increases to: 4
 DREF VLR subscr MSISDN:42342 usage increases to: 5
+DREF VLR subscr MSISDN:42342 usage increases to: 6
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
 DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
@@ -2595,7 +2597,7 @@
 - sending GSM Auth Request for MSISDN:42342: tuple use_count=1 key_seq=2 auth_types=0x1 and...
 - ...rand=e7c03ba7cf0e2fde82b2dc4d63077d42
 - ...expecting sres=a29514ae
-DREF VLR subscr MSISDN:42342 usage decreases to: 4
+DREF VLR subscr MSISDN:42342 usage decreases to: 5
 DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
 DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
 DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: )
@@ -2665,8 +2667,6 @@
 DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
 DPAG Paging success for MSISDN:42342 (event=0)
 DPAG Calling paging cbfn.
-DCC (ti 00 sub MSISDN:42342 callref 40000004) New transaction
-DREF VLR subscr MSISDN:42342 usage increases to: 5
 DREF MSISDN:42342: MSC conn use + trans_sms == 1 (0x20: trans_sms)
 DMSC msc_tx 91 bytes to MSISDN:42342 via RAN_GERAN_A
 - DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005802443f2000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
@@ -3059,18 +3059,20 @@
 DREF VLR subscr MSISDN:42342 usage increases to: 2
   llist_count(&vsub->cs.requests) == 0
 DREF VLR subscr MSISDN:42342 usage increases to: 3
+DCC (ti 00 sub MSISDN:42342 callref 40000005) New transaction
+DREF VLR subscr MSISDN:42342 usage increases to: 4
 DMM Subscriber MSISDN:42342 not paged yet, start paging.
   RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
   strcmp(paging_expecting_imsi, imsi) == 0
-DREF VLR subscr MSISDN:42342 usage increases to: 4
+DREF VLR subscr MSISDN:42342 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:42342 usage decreases to: 3
+DREF VLR subscr MSISDN:42342 usage decreases to: 4
   paging_sent == 1
   paging_stopped == 0
 - the subscriber and its pending request should remain
-DREF VLR subscr MSISDN:42342 usage increases to: 4
+DREF VLR subscr MSISDN:42342 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:42342 usage decreases to: 3
+DREF VLR subscr MSISDN:42342 usage decreases to: 4
 - MS replies with Paging Response, and VLR sends Auth Request with third key
   MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
   new conn
@@ -3083,8 +3085,8 @@
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000004620)
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth+Ciph
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
-DREF VLR subscr MSISDN:42342 usage increases to: 4
 DREF VLR subscr MSISDN:42342 usage increases to: 5
+DREF VLR subscr MSISDN:42342 usage increases to: 6
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
 DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
@@ -3095,7 +3097,7 @@
 - sending GSM Auth Request for MSISDN:42342: tuple use_count=1 key_seq=2 auth_types=0x1 and...
 - ...rand=e7c03ba7cf0e2fde82b2dc4d63077d42
 - ...expecting sres=a29514ae
-DREF VLR subscr MSISDN:42342 usage decreases to: 4
+DREF VLR subscr MSISDN:42342 usage decreases to: 5
 DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
 DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
 DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: )
@@ -3104,8 +3106,8 @@
   auth_request_sent == 1
 ---
 - Fake a situation where Classmark 2 is unknown during proc_arq_fsm
-DREF VLR subscr MSISDN:42342 usage increases to: 5
-DREF VLR subscr MSISDN:42342 usage decreases to: 4
+DREF VLR subscr MSISDN:42342 usage increases to: 6
+DREF VLR subscr MSISDN:42342 usage decreases to: 5
 - MS sends Authen Response, VLR accepts and requests Ciphering
 - MS sends Authen Response, VLR accepts and requests Ciphering. Normally, we'd know Classmark 3, but this test removed it. Hence a Classmark Request is generated.
   MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
@@ -3156,8 +3158,6 @@
 DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
 DPAG Paging success for MSISDN:42342 (event=0)
 DPAG Calling paging cbfn.
-DCC (ti 00 sub MSISDN:42342 callref 40000005) New transaction
-DREF VLR subscr MSISDN:42342 usage increases to: 5
 DREF MSISDN:42342: MSC conn use + trans_sms == 1 (0x20: trans_sms)
 DMSC msc_tx 91 bytes to MSISDN:42342 via RAN_GERAN_A
 - DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005802443f2000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
diff --git a/tests/msc_vlr/msc_vlr_test_ms_timeout.err b/tests/msc_vlr/msc_vlr_test_ms_timeout.err
index d2b7ef3..4874f93 100644
--- a/tests/msc_vlr/msc_vlr_test_ms_timeout.err
+++ b/tests/msc_vlr/msc_vlr_test_ms_timeout.err
@@ -471,32 +471,38 @@
 DREF VLR subscr MSISDN:46071 usage increases to: 2
   llist_count(&vsub->cs.requests) == 0
 DREF VLR subscr MSISDN:46071 usage increases to: 3
+DCC (ti 00 sub MSISDN:46071 callref 40000001) New transaction
+DREF VLR subscr MSISDN:46071 usage increases to: 4
 DMM Subscriber MSISDN:46071 not paged yet, start paging.
   RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
   strcmp(paging_expecting_imsi, imsi) == 0
-DREF VLR subscr MSISDN:46071 usage increases to: 4
+DREF VLR subscr MSISDN:46071 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:46071 usage decreases to: 3
+DREF VLR subscr MSISDN:46071 usage decreases to: 4
   paging_sent == 1
   paging_stopped == 0
 - time passes and no paging result is received
 - Total time passed: 9.000000 s
 - the paging timeout has not yet expired
   paging_stopped == 0
-DREF VLR subscr MSISDN:46071 usage increases to: 4
+DREF VLR subscr MSISDN:46071 usage increases to: 5
   vsub->cs.is_paging == 1
 - another request is added to the list but does not cause another paging
-DREF VLR subscr MSISDN:46071 usage increases to: 5
+DREF VLR subscr MSISDN:46071 usage increases to: 6
+DCC (ti 01 sub MSISDN:46071 callref 40000002) New transaction
+DREF VLR subscr MSISDN:46071 usage increases to: 7
 DMM Subscriber MSISDN:46071 already paged.
   llist_count(&vsub->cs.requests) == 2
-DREF VLR subscr MSISDN:46071 usage decreases to: 4
+DREF VLR subscr MSISDN:46071 usage decreases to: 6
   paging_sent == 0
 - the paging timeout expires, the paging as well as the requests are canceled
 - Total time passed: 11.000000 s
 DPAG Paging failure for MSISDN:46071 (event=1)
 DPAG Calling paging cbfn.
-DREF VLR subscr MSISDN:46071 usage decreases to: 3
+DREF VLR subscr MSISDN:46071 usage decreases to: 5
+DREF VLR subscr MSISDN:46071 usage decreases to: 4
 DPAG Calling paging cbfn.
+DREF VLR subscr MSISDN:46071 usage decreases to: 3
 DREF VLR subscr MSISDN:46071 usage decreases to: 2
 DREF VLR subscr MSISDN:46071 usage decreases to: 1
   paging_stopped == 1
@@ -506,12 +512,14 @@
 ---
 - Now that the timeout has expired, another Paging is sent on request
 DREF VLR subscr MSISDN:46071 usage increases to: 3
+DCC (ti 00 sub MSISDN:46071 callref 40000003) New transaction
+DREF VLR subscr MSISDN:46071 usage increases to: 4
 DMM Subscriber MSISDN:46071 not paged yet, start paging.
   RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
   strcmp(paging_expecting_imsi, imsi) == 0
-DREF VLR subscr MSISDN:46071 usage increases to: 4
+DREF VLR subscr MSISDN:46071 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:46071 usage decreases to: 3
+DREF VLR subscr MSISDN:46071 usage decreases to: 4
   paging_sent == 1
   paging_stopped == 0
 ---
@@ -522,10 +530,11 @@
 DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
 DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
 DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
-DREF VLR subscr MSISDN:46071 usage increases to: 4
+DREF VLR subscr MSISDN:46071 usage increases to: 5
 DMM IMSI DETACH for MSISDN:46071
 DPAG Paging failure for MSISDN:46071 (event=1)
 DPAG Calling paging cbfn.
+DREF VLR subscr MSISDN:46071 usage decreases to: 4
 DREF VLR subscr MSISDN:46071 usage decreases to: 3
 DREF VLR subscr MSISDN:46071 usage decreases to: 2
 DREF VLR subscr MSISDN:46071 usage increases to: 3
diff --git a/tests/msc_vlr/msc_vlr_test_no_authen.err b/tests/msc_vlr/msc_vlr_test_no_authen.err
index fb0582b..e8c2927 100644
--- a/tests/msc_vlr/msc_vlr_test_no_authen.err
+++ b/tests/msc_vlr/msc_vlr_test_no_authen.err
@@ -187,18 +187,20 @@
 DREF VLR subscr MSISDN:46071 usage increases to: 2
   llist_count(&vsub->cs.requests) == 0
 DREF VLR subscr MSISDN:46071 usage increases to: 3
+DCC (ti 00 sub MSISDN:46071 callref 40000001) New transaction
+DREF VLR subscr MSISDN:46071 usage increases to: 4
 DMM Subscriber MSISDN:46071 not paged yet, start paging.
   RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
   strcmp(paging_expecting_imsi, imsi) == 0
-DREF VLR subscr MSISDN:46071 usage increases to: 4
+DREF VLR subscr MSISDN:46071 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:46071 usage decreases to: 3
+DREF VLR subscr MSISDN:46071 usage decreases to: 4
   paging_sent == 1
   paging_stopped == 0
 - the subscriber and its pending request should remain
-DREF VLR subscr MSISDN:46071 usage increases to: 4
+DREF VLR subscr MSISDN:46071 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:46071 usage decreases to: 3
+DREF VLR subscr MSISDN:46071 usage decreases to: 4
 - MS replies with Paging Response, we deliver the SMS
   MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
   new conn
@@ -211,8 +213,8 @@
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000004620)
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
-DREF VLR subscr MSISDN:46071 usage increases to: 4
 DREF VLR subscr MSISDN:46071 usage increases to: 5
+DREF VLR subscr MSISDN:46071 usage increases to: 6
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
@@ -226,8 +228,6 @@
 DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
 DPAG Paging success for MSISDN:46071 (event=0)
 DPAG Calling paging cbfn.
-DCC (ti 00 sub MSISDN:46071 callref 40000001) New transaction
-DREF VLR subscr MSISDN:46071 usage increases to: 6
 DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x21: compl_l3,trans_sms)
 DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
 - DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
@@ -546,18 +546,20 @@
 DREF VLR subscr MSISDN:46071 usage increases to: 2
   llist_count(&vsub->cs.requests) == 0
 DREF VLR subscr MSISDN:46071 usage increases to: 3
+DCC (ti 00 sub MSISDN:46071 callref 40000002) New transaction
+DREF VLR subscr MSISDN:46071 usage increases to: 4
 DMM Subscriber MSISDN:46071 not paged yet, start paging.
   RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0x03020100, LAC 23
   paging_expecting_tmsi == 0x03020100
-DREF VLR subscr MSISDN:46071 usage increases to: 4
+DREF VLR subscr MSISDN:46071 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:46071 usage decreases to: 3
+DREF VLR subscr MSISDN:46071 usage decreases to: 4
   paging_sent == 1
   paging_stopped == 0
 - the subscriber and its pending request should remain
-DREF VLR subscr MSISDN:46071 usage increases to: 4
+DREF VLR subscr MSISDN:46071 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:46071 usage decreases to: 3
+DREF VLR subscr MSISDN:46071 usage decreases to: 4
 - MS replies with Paging Response using TMSI, we deliver the SMS
   MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
   new conn
@@ -570,8 +572,8 @@
 DVLR Process_Access_Request_VLR(PAGING_RESP:50462976){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:50462976)
 DVLR Process_Access_Request_VLR(PAGING_RESP:50462976){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
 DVLR Process_Access_Request_VLR(PAGING_RESP:50462976){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
-DREF VLR subscr MSISDN:46071 usage increases to: 4
 DREF VLR subscr MSISDN:46071 usage increases to: 5
+DREF VLR subscr MSISDN:46071 usage increases to: 6
 DVLR Process_Access_Request_VLR(PAGING_RESP:50462976){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
 DVLR Process_Access_Request_VLR(PAGING_RESP:50462976){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
 DVLR Process_Access_Request_VLR(PAGING_RESP:50462976){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
@@ -585,8 +587,6 @@
 DMM Subscr_Conn(PAGING_RESP:50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
 DPAG Paging success for MSISDN:46071 (event=0)
 DPAG Calling paging cbfn.
-DCC (ti 00 sub MSISDN:46071 callref 40000002) New transaction
-DREF VLR subscr MSISDN:46071 usage increases to: 6
 DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x21: compl_l3,trans_sms)
 DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
 - DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
diff --git a/tests/msc_vlr/msc_vlr_test_reject_concurrency.err b/tests/msc_vlr/msc_vlr_test_reject_concurrency.err
index 0a964ac..cf90a1c 100644
--- a/tests/msc_vlr/msc_vlr_test_reject_concurrency.err
+++ b/tests/msc_vlr/msc_vlr_test_reject_concurrency.err
@@ -1260,12 +1260,14 @@
 DREF VLR subscr MSISDN:46071 usage increases to: 2
   llist_count(&vsub->cs.requests) == 0
 DREF VLR subscr MSISDN:46071 usage increases to: 3
+DCC (ti 00 sub MSISDN:46071 callref 40000001) New transaction
+DREF VLR subscr MSISDN:46071 usage increases to: 4
 DMM Subscriber MSISDN:46071 not paged yet, start paging.
   RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
   strcmp(paging_expecting_imsi, imsi) == 0
-DREF VLR subscr MSISDN:46071 usage increases to: 4
+DREF VLR subscr MSISDN:46071 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:46071 usage decreases to: 3
+DREF VLR subscr MSISDN:46071 usage decreases to: 4
   paging_sent == 1
   paging_stopped == 0
 - MS replies with Paging Response, we deliver the SMS
@@ -1280,8 +1282,8 @@
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000004620)
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
-DREF VLR subscr MSISDN:46071 usage increases to: 4
 DREF VLR subscr MSISDN:46071 usage increases to: 5
+DREF VLR subscr MSISDN:46071 usage increases to: 6
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
@@ -1295,8 +1297,6 @@
 DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
 DPAG Paging success for MSISDN:46071 (event=0)
 DPAG Calling paging cbfn.
-DCC (ti 00 sub MSISDN:46071 callref 40000001) New transaction
-DREF VLR subscr MSISDN:46071 usage increases to: 6
 DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x21: compl_l3,trans_sms)
 DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
 - DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
@@ -1487,12 +1487,14 @@
 DREF VLR subscr MSISDN:46071 usage increases to: 2
   llist_count(&vsub->cs.requests) == 0
 DREF VLR subscr MSISDN:46071 usage increases to: 3
+DCC (ti 00 sub MSISDN:46071 callref 40000002) New transaction
+DREF VLR subscr MSISDN:46071 usage increases to: 4
 DMM Subscriber MSISDN:46071 not paged yet, start paging.
   RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
   strcmp(paging_expecting_imsi, imsi) == 0
-DREF VLR subscr MSISDN:46071 usage increases to: 4
+DREF VLR subscr MSISDN:46071 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:46071 usage decreases to: 3
+DREF VLR subscr MSISDN:46071 usage decreases to: 4
   paging_sent == 1
   paging_stopped == 0
 - MS replies with Paging Response, we deliver the SMS
@@ -1507,8 +1509,8 @@
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000004620)
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
-DREF VLR subscr MSISDN:46071 usage increases to: 4
 DREF VLR subscr MSISDN:46071 usage increases to: 5
+DREF VLR subscr MSISDN:46071 usage increases to: 6
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
@@ -1522,8 +1524,6 @@
 DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
 DPAG Paging success for MSISDN:46071 (event=0)
 DPAG Calling paging cbfn.
-DCC (ti 00 sub MSISDN:46071 callref 40000002) New transaction
-DREF VLR subscr MSISDN:46071 usage increases to: 6
 DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x21: compl_l3,trans_sms)
 DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
 - DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
@@ -1734,12 +1734,14 @@
 DREF VLR subscr MSISDN:46071 usage increases to: 2
   llist_count(&vsub->cs.requests) == 0
 DREF VLR subscr MSISDN:46071 usage increases to: 3
+DCC (ti 00 sub MSISDN:46071 callref 40000003) New transaction
+DREF VLR subscr MSISDN:46071 usage increases to: 4
 DMM Subscriber MSISDN:46071 not paged yet, start paging.
   RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
   strcmp(paging_expecting_imsi, imsi) == 0
-DREF VLR subscr MSISDN:46071 usage increases to: 4
+DREF VLR subscr MSISDN:46071 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:46071 usage decreases to: 3
+DREF VLR subscr MSISDN:46071 usage decreases to: 4
   paging_sent == 1
   paging_stopped == 0
 - MS replies with Paging Response, we deliver the SMS
@@ -1754,8 +1756,8 @@
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000004620)
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
-DREF VLR subscr MSISDN:46071 usage increases to: 4
 DREF VLR subscr MSISDN:46071 usage increases to: 5
+DREF VLR subscr MSISDN:46071 usage increases to: 6
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
@@ -1769,8 +1771,6 @@
 DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
 DPAG Paging success for MSISDN:46071 (event=0)
 DPAG Calling paging cbfn.
-DCC (ti 00 sub MSISDN:46071 callref 40000003) New transaction
-DREF VLR subscr MSISDN:46071 usage increases to: 6
 DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x21: compl_l3,trans_sms)
 DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
 - DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
diff --git a/tests/msc_vlr/msc_vlr_test_umts_authen.err b/tests/msc_vlr/msc_vlr_test_umts_authen.err
index 538a3d9..fdd3b0c 100644
--- a/tests/msc_vlr/msc_vlr_test_umts_authen.err
+++ b/tests/msc_vlr/msc_vlr_test_umts_authen.err
@@ -288,18 +288,20 @@
 DREF VLR subscr MSISDN:42342 usage increases to: 2
   llist_count(&vsub->cs.requests) == 0
 DREF VLR subscr MSISDN:42342 usage increases to: 3
+DCC (ti 00 sub MSISDN:42342 callref 40000001) New transaction
+DREF VLR subscr MSISDN:42342 usage increases to: 4
 DMM Subscriber MSISDN:42342 not paged yet, start paging.
   RAN_GERAN_A sends out paging request to IMSI 901700000010650, TMSI 0x03020100, LAC 23
   strcmp(paging_expecting_imsi, imsi) == 0
-DREF VLR subscr MSISDN:42342 usage increases to: 4
+DREF VLR subscr MSISDN:42342 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:42342 usage decreases to: 3
+DREF VLR subscr MSISDN:42342 usage decreases to: 4
   paging_sent == 1
   paging_stopped == 0
 - the subscriber and its pending request should remain
-DREF VLR subscr MSISDN:42342 usage increases to: 4
+DREF VLR subscr MSISDN:42342 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:42342 usage decreases to: 3
+DREF VLR subscr MSISDN:42342 usage decreases to: 4
 - MS replies with Paging Response, and VLR sends Auth Request with third key
   MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
   new conn
@@ -312,8 +314,8 @@
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000010650)
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: rev=R99 net=GERAN Auth (no Ciph)
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
-DREF VLR subscr MSISDN:42342 usage increases to: 4
 DREF VLR subscr MSISDN:42342 usage increases to: 5
+DREF VLR subscr MSISDN:42342 usage increases to: 6
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
 DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
@@ -325,7 +327,7 @@
 - ...rand=efa9c29a9742148d5c9070348716e1bb
 - ...autn=f9375e6d41e1000096e7fe4ff1c27e39
 - ...expecting res=706f996719ba609c
-DREF VLR subscr MSISDN:42342 usage decreases to: 4
+DREF VLR subscr MSISDN:42342 usage decreases to: 5
 DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
 DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
 DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: )
@@ -370,8 +372,6 @@
 DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
 DPAG Paging success for MSISDN:42342 (event=0)
 DPAG Calling paging cbfn.
-DCC (ti 00 sub MSISDN:42342 callref 40000001) New transaction
-DREF VLR subscr MSISDN:42342 usage increases to: 5
 DREF MSISDN:42342: MSC conn use + trans_sms == 2 (0x22: dtap,trans_sms)
 DMSC msc_tx 91 bytes to MSISDN:42342 via RAN_GERAN_A
 - DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005802443f2000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
@@ -778,18 +778,20 @@
 DREF VLR subscr MSISDN:42342 usage increases to: 2
   llist_count(&vsub->cs.requests) == 0
 DREF VLR subscr MSISDN:42342 usage increases to: 3
+DCC (ti 00 sub MSISDN:42342 callref 40000002) New transaction
+DREF VLR subscr MSISDN:42342 usage increases to: 4
 DMM Subscriber MSISDN:42342 not paged yet, start paging.
   RAN_UTRAN_IU sends out paging request to IMSI 901700000010650, TMSI 0x03020100, LAC 23
   strcmp(paging_expecting_imsi, imsi) == 0
-DREF VLR subscr MSISDN:42342 usage increases to: 4
+DREF VLR subscr MSISDN:42342 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:42342 usage decreases to: 3
+DREF VLR subscr MSISDN:42342 usage decreases to: 4
   paging_sent == 1
   paging_stopped == 0
 - the subscriber and its pending request should remain
-DREF VLR subscr MSISDN:42342 usage increases to: 4
+DREF VLR subscr MSISDN:42342 usage increases to: 5
   llist_count(&vsub->cs.requests) == 1
-DREF VLR subscr MSISDN:42342 usage decreases to: 3
+DREF VLR subscr MSISDN:42342 usage decreases to: 4
 - MS replies with Paging Response, and VLR sends Auth Request with third key
   MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_RR_PAG_RESP
   new conn
@@ -802,8 +804,8 @@
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000010650)
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
-DREF VLR subscr MSISDN:42342 usage increases to: 4
 DREF VLR subscr MSISDN:42342 usage increases to: 5
+DREF VLR subscr MSISDN:42342 usage increases to: 6
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
 DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
 DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
@@ -815,7 +817,7 @@
 - ...rand=efa9c29a9742148d5c9070348716e1bb
 - ...autn=f9375e6d41e1000096e7fe4ff1c27e39
 - ...expecting res=706f996719ba609c
-DREF VLR subscr MSISDN:42342 usage decreases to: 4
+DREF VLR subscr MSISDN:42342 usage decreases to: 5
 DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
 DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
 DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: )
@@ -875,8 +877,6 @@
 DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
 DPAG Paging success for MSISDN:42342 (event=0)
 DPAG Calling paging cbfn.
-DCC (ti 00 sub MSISDN:42342 callref 40000002) New transaction
-DREF VLR subscr MSISDN:42342 usage increases to: 5
 DREF MSISDN:42342: MSC conn use + trans_sms == 1 (0x20: trans_sms)
 DMSC msc_tx 91 bytes to MSISDN:42342 via RAN_UTRAN_IU
 - DTAP --RAN_UTRAN_IU--> MS: SMS:0x01: 09015801000791447758100650004c0005802443f2000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
diff --git a/tests/msc_vlr/msc_vlr_tests.c b/tests/msc_vlr/msc_vlr_tests.c
index 6cf927c..01f5974 100644
--- a/tests/msc_vlr/msc_vlr_tests.c
+++ b/tests/msc_vlr/msc_vlr_tests.c
@@ -319,7 +319,7 @@
 	      char *str)
 {
 	struct gsm_sms *sms = sms_from_text(receiver, sender->msisdn, 0, str);
-	gsm411_send_sms_subscr(receiver, sms);
+	gsm411_send_sms(net, receiver, sms);
 }
 
 unsigned char next_rand_byte = 0;

-- 
To view, visit https://gerrit.osmocom.org/11916
To unsubscribe, or for help writing mail filters, visit https://gerrit.osmocom.org/settings

Gerrit-Project: osmo-msc
Gerrit-Branch: master
Gerrit-MessageType: merged
Gerrit-Change-Id: I4a07ece80d8dd40b23da6bb1ffc9d3d745b54092
Gerrit-Change-Number: 11916
Gerrit-PatchSet: 5
Gerrit-Owner: Vadim Yanitskiy <axilirator at gmail.com>
Gerrit-Reviewer: Harald Welte <laforge at gnumonks.org>
Gerrit-Reviewer: Jenkins Builder (1000002)
Gerrit-Reviewer: Vadim Yanitskiy <axilirator at gmail.com>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.osmocom.org/pipermail/gerrit-log/attachments/20181129/aaed7745/attachment.html>


More information about the gerrit-log mailing list