cosmetic: add debug log to msc_subscr_conn_close()

Adjust test expectations.

Note: this marks all the places where we are so far failing to send a
Clear/Release, where during an IMSI Detach the log now says "no conn fsm,
ignore".

In msc_vlr_test_reject_concurrency, the places are marked "already in release"
because these tests for simplicity have a rather peculiar sequence of sending
an IMSI Detach right after a CM Service Request, on an open connection.

Change-Id: I1c4dc4e5afce3bcb98237e3506300c78d7e4584f

7 files changed, 35 insertions, 3 deletions

diff --git a/openbsc/src/libmsc/osmo_msc.c b/openbsc/src/libmsc/osmo_msc.c
index 8bb7c1f4a..2b91f010e 100644
--- a/openbsc/src/libmsc/osmo_msc.c
+++ b/openbsc/src/libmsc/osmo_msc.c
@@ -271,12 +271,24 @@ void msc_subscr_conn_close(struct gsm_subscriber_connection *conn,
 {
 	if (!conn)
 		return;
-	if (conn->in_release)
+	if (conn->in_release) {
+		DEBUGP(DMM, "msc_subscr_conn_close(vsub=%s, cause=%u):"
+		       " already dispatching release, ignore.\n",
+		       vlr_subscr_name(conn->vsub), cause);
 		return;
-	if (!conn->conn_fsm)
+	}
+	if (!conn->conn_fsm) {
+		DEBUGP(DMM, "msc_subscr_conn_close(vsub=%s, cause=%u): no conn fsm,"
+		       " ignore.\n",
+		       vlr_subscr_name(conn->vsub), cause);
 		return;
-	if (conn->conn_fsm->state == SUBSCR_CONN_S_RELEASED)
+	}
+	if (conn->conn_fsm->state == SUBSCR_CONN_S_RELEASED) {
+		DEBUGP(DMM, "msc_subscr_conn_close(vsub=%s, cause=%u):"
+		       " conn fsm already releasing, ignore.\n",
+		       vlr_subscr_name(conn->vsub), cause);
 		return;
+	}
 	osmo_fsm_inst_dispatch(conn->conn_fsm, SUBSCR_CONN_E_CN_CLOSE, &cause);
 }
 
diff --git a/openbsc/tests/msc_vlr/msc_vlr_test_gsm_authen.err b/openbsc/tests/msc_vlr/msc_vlr_test_gsm_authen.err
index 6ad931637..2cff2981c 100644
--- a/openbsc/tests/msc_vlr/msc_vlr_test_gsm_authen.err
+++ b/openbsc/tests/msc_vlr/msc_vlr_test_gsm_authen.err
@@ -431,6 +431,7 @@ DMM IMSI DETACH for MSISDN:46071
 DREF VLR subscr MSISDN:46071 usage decreases to: 1
 DREF VLR subscr MSISDN:46071 usage decreases to: 0
 DREF freeing VLR subscr MSISDN:46071
+DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, ignore.
 DREF unknown: MSC conn use - 1 == 0
 DRLL Freeing subscriber connection with NULL subscriber
   llist_count(&net->subscr_conns) == 0
@@ -1074,6 +1075,7 @@ DMM IMSI DETACH for MSISDN:46071
 DREF VLR subscr MSISDN:46071 usage decreases to: 1
 DREF VLR subscr MSISDN:46071 usage decreases to: 0
 DREF freeing VLR subscr MSISDN:46071
+DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, ignore.
 DREF unknown: MSC conn use - 1 == 0
 DRLL Freeing subscriber connection with NULL subscriber
   llist_count(&net->subscr_conns) == 0
@@ -1289,6 +1291,7 @@ DMM IMSI DETACH for MSISDN:46071
 DREF VLR subscr MSISDN:46071 usage decreases to: 1
 DREF VLR subscr MSISDN:46071 usage decreases to: 0
 DREF freeing VLR subscr MSISDN:46071
+DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, ignore.
 DREF unknown: MSC conn use - 1 == 0
 DRLL Freeing subscriber connection with NULL subscriber
   llist_count(&net->subscr_conns) == 0
@@ -1535,6 +1538,7 @@ DMM IMSI DETACH for MSISDN:46071
 DREF VLR subscr MSISDN:46071 usage decreases to: 1
 DREF VLR subscr MSISDN:46071 usage decreases to: 0
 DREF freeing VLR subscr MSISDN:46071
+DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, ignore.
 DREF unknown: MSC conn use - 1 == 0
 DRLL Freeing subscriber connection with NULL subscriber
   llist_count(&net->subscr_conns) == 0
@@ -1957,6 +1961,7 @@ DMM IMSI DETACH for MSISDN:42342
 DREF VLR subscr MSISDN:42342 usage decreases to: 1
 DREF VLR subscr MSISDN:42342 usage decreases to: 0
 DREF freeing VLR subscr MSISDN:42342
+DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, ignore.
 DREF unknown: MSC conn use - 1 == 0
 DRLL Freeing subscriber connection with NULL subscriber
   llist_count(&net->subscr_conns) == 0
diff --git a/openbsc/tests/msc_vlr/msc_vlr_test_gsm_ciph.err b/openbsc/tests/msc_vlr/msc_vlr_test_gsm_ciph.err
index faf97a158..da8c5fe16 100644
--- a/openbsc/tests/msc_vlr/msc_vlr_test_gsm_ciph.err
+++ b/openbsc/tests/msc_vlr/msc_vlr_test_gsm_ciph.err
@@ -465,6 +465,7 @@ DMM IMSI DETACH for MSISDN:46071
 DREF VLR subscr MSISDN:46071 usage decreases to: 1
 DREF VLR subscr MSISDN:46071 usage decreases to: 0
 DREF freeing VLR subscr MSISDN:46071
+DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, ignore.
 DREF unknown: MSC conn use - 1 == 0
 DRLL Freeing subscriber connection with NULL subscriber
   llist_count(&net->subscr_conns) == 0
@@ -977,6 +978,7 @@ DMM IMSI DETACH for MSISDN:46071
 DREF VLR subscr MSISDN:46071 usage decreases to: 1
 DREF VLR subscr MSISDN:46071 usage decreases to: 0
 DREF freeing VLR subscr MSISDN:46071
+DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, ignore.
 DREF unknown: MSC conn use - 1 == 0
 DRLL Freeing subscriber connection with NULL subscriber
   llist_count(&net->subscr_conns) == 0
@@ -1192,6 +1194,7 @@ DMM IMSI DETACH for MSISDN:46071
 DREF VLR subscr MSISDN:46071 usage decreases to: 1
 DREF VLR subscr MSISDN:46071 usage decreases to: 0
 DREF freeing VLR subscr MSISDN:46071
+DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, ignore.
 DREF unknown: MSC conn use - 1 == 0
 DRLL Freeing subscriber connection with NULL subscriber
   llist_count(&net->subscr_conns) == 0
@@ -1406,6 +1409,7 @@ DMM IMSI DETACH for MSISDN:46071
 DREF VLR subscr MSISDN:46071 usage decreases to: 1
 DREF VLR subscr MSISDN:46071 usage decreases to: 0
 DREF freeing VLR subscr MSISDN:46071
+DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, ignore.
 DREF unknown: MSC conn use - 1 == 0
 DRLL Freeing subscriber connection with NULL subscriber
   llist_count(&net->subscr_conns) == 0
@@ -1652,6 +1656,7 @@ DMM IMSI DETACH for MSISDN:46071
 DREF VLR subscr MSISDN:46071 usage decreases to: 1
 DREF VLR subscr MSISDN:46071 usage decreases to: 0
 DREF freeing VLR subscr MSISDN:46071
+DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, ignore.
 DREF unknown: MSC conn use - 1 == 0
 DRLL Freeing subscriber connection with NULL subscriber
   llist_count(&net->subscr_conns) == 0
diff --git a/openbsc/tests/msc_vlr/msc_vlr_test_no_authen.err b/openbsc/tests/msc_vlr/msc_vlr_test_no_authen.err
index 9eda3fc9d..2940318a4 100644
--- a/openbsc/tests/msc_vlr/msc_vlr_test_no_authen.err
+++ b/openbsc/tests/msc_vlr/msc_vlr_test_no_authen.err
@@ -307,6 +307,7 @@ DMM IMSI DETACH for MSISDN:46071
 DREF VLR subscr MSISDN:46071 usage decreases to: 1
 DREF VLR subscr MSISDN:46071 usage decreases to: 0
 DREF freeing VLR subscr MSISDN:46071
+DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, ignore.
 DREF unknown: MSC conn use - 1 == 0
 DRLL Freeing subscriber connection with NULL subscriber
   llist_count(&net->subscr_conns) == 0
@@ -809,6 +810,7 @@ DMM IMSI DETACH for MSISDN:46071
 DREF VLR subscr MSISDN:46071 usage decreases to: 1
 DREF VLR subscr MSISDN:46071 usage decreases to: 0
 DREF freeing VLR subscr MSISDN:46071
+DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, ignore.
 DREF unknown: MSC conn use - 1 == 0
 DRLL Freeing subscriber connection with NULL subscriber
   llist_count(&net->subscr_conns) == 0
@@ -977,6 +979,7 @@ DMM IMSI DETACH for MSISDN:46071
 DREF VLR subscr MSISDN:46071 usage decreases to: 1
 DREF VLR subscr MSISDN:46071 usage decreases to: 0
 DREF freeing VLR subscr MSISDN:46071
+DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, ignore.
 DREF unknown: MSC conn use - 1 == 0
 DRLL Freeing subscriber connection with NULL subscriber
   llist_count(&net->subscr_conns) == 0
@@ -1170,6 +1173,7 @@ DMM IMSI DETACH for MSISDN:46071
 DREF VLR subscr MSISDN:46071 usage decreases to: 1
 DREF VLR subscr MSISDN:46071 usage decreases to: 0
 DREF freeing VLR subscr MSISDN:46071
+DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, ignore.
 DREF unknown: MSC conn use - 1 == 0
 DRLL Freeing subscriber connection with NULL subscriber
   llist_count(&net->subscr_conns) == 0
diff --git a/openbsc/tests/msc_vlr/msc_vlr_test_reject_concurrency.err b/openbsc/tests/msc_vlr/msc_vlr_test_reject_concurrency.err
index 0f08ce8ed..a6ff7261b 100644
--- a/openbsc/tests/msc_vlr/msc_vlr_test_reject_concurrency.err
+++ b/openbsc/tests/msc_vlr/msc_vlr_test_reject_concurrency.err
@@ -706,6 +706,7 @@ DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
 DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
 DREF VLR subscr MSISDN:46071 usage decreases to: 2
 DREF VLR subscr MSISDN:46071 usage decreases to: 1
+DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=0): already dispatching release, ignore.
 DREF MSISDN:46071: MSC conn use - 1 == 0
 DRLL subscr MSISDN:46071: Freeing subscriber connection
 DREF VLR subscr MSISDN:46071 usage decreases to: 0
@@ -897,6 +898,7 @@ DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
 DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
 DREF VLR subscr MSISDN:46071 usage decreases to: 2
 DREF VLR subscr MSISDN:46071 usage decreases to: 1
+DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=0): already dispatching release, ignore.
 DREF MSISDN:46071: MSC conn use - 1 == 0
 DRLL subscr MSISDN:46071: Freeing subscriber connection
 DREF VLR subscr MSISDN:46071 usage decreases to: 0
@@ -1559,6 +1561,7 @@ DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
 DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
 DREF VLR subscr MSISDN:46071 usage decreases to: 2
 DREF VLR subscr MSISDN:46071 usage decreases to: 1
+DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=0): already dispatching release, ignore.
 DREF MSISDN:46071: MSC conn use - 1 == 0
 DRLL subscr MSISDN:46071: Freeing subscriber connection
 DREF VLR subscr MSISDN:46071 usage decreases to: 0
diff --git a/openbsc/tests/msc_vlr/msc_vlr_test_rest.err b/openbsc/tests/msc_vlr/msc_vlr_test_rest.err
index 1424361a4..18db13134 100644
--- a/openbsc/tests/msc_vlr/msc_vlr_test_rest.err
+++ b/openbsc/tests/msc_vlr/msc_vlr_test_rest.err
@@ -323,6 +323,7 @@ DMM IMSI DETACH for MSISDN:46071
 DREF VLR subscr MSISDN:46071 usage decreases to: 1
 DREF VLR subscr MSISDN:46071 usage decreases to: 0
 DREF freeing VLR subscr MSISDN:46071
+DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, ignore.
 DREF unknown: MSC conn use - 1 == 0
 DRLL Freeing subscriber connection with NULL subscriber
   llist_count(&net->subscr_conns) == 0
diff --git a/openbsc/tests/msc_vlr/msc_vlr_test_umts_authen.err b/openbsc/tests/msc_vlr/msc_vlr_test_umts_authen.err
index de0c430e9..791bc8cbe 100644
--- a/openbsc/tests/msc_vlr/msc_vlr_test_umts_authen.err
+++ b/openbsc/tests/msc_vlr/msc_vlr_test_umts_authen.err
@@ -445,6 +445,7 @@ DMM IMSI DETACH for MSISDN:42342
 DREF VLR subscr MSISDN:42342 usage decreases to: 1
 DREF VLR subscr MSISDN:42342 usage decreases to: 0
 DREF freeing VLR subscr MSISDN:42342
+DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, ignore.
 DREF unknown: MSC conn use - 1 == 0
 DRLL Freeing subscriber connection with NULL subscriber
   llist_count(&net->subscr_conns) == 0
@@ -932,6 +933,7 @@ DMM IMSI DETACH for MSISDN:42342
 DREF VLR subscr MSISDN:42342 usage decreases to: 1
 DREF VLR subscr MSISDN:42342 usage decreases to: 0
 DREF freeing VLR subscr MSISDN:42342
+DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, ignore.
 DREF unknown: MSC conn use - 1 == 0
 DRLL Freeing subscriber connection with NULL subscriber
   llist_count(&net->subscr_conns) == 0