1 files changed, 28 insertions, 22 deletions

diff --git a/openbsc/src/gprs_ns.c b/openbsc/src/gprs_ns.c
index 0db06c3f..619a8290 100644
--- a/openbsc/src/gprs_ns.c
+++ b/openbsc/src/gprs_ns.c
@@ -223,7 +223,8 @@ static int gprs_ns_tx_reset_ack(struct gprs_nsvc *nsvc)
 
 	nsh->pdu_type = NS_PDUT_RESET_ACK;
 
-	DEBUGP(DGPRS, "nsvci=%u, nsei=%u\n", nsvc->nsvci, nsvc->nsei);
+	DEBUGP(DGPRS, "NSEI=%u Tx NS RESET ACK (NSVCI=%u)\n",
+		nsvc->nsei, nsvc->nsvci);
 
 	msgb_tvlv_put(msg, NS_IE_VCI, 2, (uint8_t *)&nsvci);
 	msgb_tvlv_put(msg, NS_IE_NSEI, 2, (uint8_t *)&nsei);
@@ -240,13 +241,14 @@ int gprs_ns_sendmsg(struct gprs_ns_inst *nsi, struct msgb *msg)
 
 	nsvc = nsvc_by_nsei(nsi, msgb_nsei(msg));
 	if (!nsvc) {
-		DEBUGP(DGPRS, "Unable to resolve NSEI %u to NS-VC!\n", msgb_nsei(msg));
+		LOGP(DGPRS, LOGL_ERROR, "Unable to resolve NSEI %u "
+			"to NS-VC!\n", msgb_nsei(msg));
 		return -EINVAL;
 	}
 
 	nsh = (struct gprs_ns_hdr *) msgb_push(msg, sizeof(*nsh) + 3);
 	if (!nsh) {
-		DEBUGP(DGPRS, "Not enough headroom for NS header\n");
+		LOGP(DGPRS, LOGL_ERROR, "Not enough headroom for NS header\n");
 		return -EIO;
 	}
 
@@ -281,7 +283,7 @@ static int gprs_ns_rx_status(struct gprs_nsvc *nsvc, struct msgb *msg)
 	uint8_t cause;
 	int rc;
 
-	DEBUGP(DGPRS, "NS STATUS ");
+	DEBUGP(DGPRS, "NSEI=%u NS STATUS ", nsvc->nsei);
 
 	rc = tlv_parse(&tp, &ns_att_tlvdef, nsh->data, msgb_l2len(msg), 0, 0);
 
@@ -305,15 +307,13 @@ static int gprs_ns_rx_reset(struct gprs_nsvc *nsvc, struct msgb *msg)
 	uint16_t *nsvci, *nsei;
 	int rc;
 
-	DEBUGP(DGPRS, "NS RESET ");
-
 	rc = tlv_parse(&tp, &ns_att_tlvdef, nsh->data, msgb_l2len(msg), 0, 0);
 
 	if (!TLVP_PRESENT(&tp, NS_IE_CAUSE) ||
 	    !TLVP_PRESENT(&tp, NS_IE_VCI) ||
 	    !TLVP_PRESENT(&tp, NS_IE_NSEI)) {
 		/* FIXME: respond with NS_CAUSE_MISSING_ESSENT_IE */
-		DEBUGPC(DGPRS, "Missing mandatory IE\n");
+		LOGP(DGPRS, LOGL_ERROR, "NS RESET Missing mandatory IE\n");
 		return -EINVAL;
 	}
 
@@ -321,13 +321,13 @@ static int gprs_ns_rx_reset(struct gprs_nsvc *nsvc, struct msgb *msg)
 	nsvci = (uint16_t *) TLVP_VAL(&tp, NS_IE_VCI);
 	nsei = (uint16_t *) TLVP_VAL(&tp, NS_IE_NSEI);
 
+	DEBUGP(DGPRS, "NSEI=%u NS RESET (NSVCI=%u, cause=%s)\n",
+		nsvc->nsvci, nsvc->nsei, gprs_ns_cause_str(*cause));
+
 	nsvc->state = NSE_S_BLOCKED | NSE_S_ALIVE;
 	nsvc->nsei = ntohs(*nsei);
 	nsvc->nsvci = ntohs(*nsvci);
 
-	DEBUGPC(DGPRS, "cause=%s, NSVCI=%u, NSEI=%u\n",
-		gprs_ns_cause_str(*cause), nsvc->nsvci, nsvc->nsei);
-
 	/* mark the NS-VC as blocked and alive */
 	/* start the test procedure */
 	nsvc->alive_timer.cb = gprs_ns_alive_cb;
@@ -349,14 +349,18 @@ int gprs_ns_rcvmsg(struct gprs_ns_inst *nsi, struct msgb *msg,
 	nsvc = nsvc_by_rem_addr(nsi, saddr);
 	if (!nsvc) {
 		/* Only the RESET procedure creates a new NSVC */
-		if (nsh->pdu_type != NS_PDUT_RESET)
+		if (nsh->pdu_type != NS_PDUT_RESET) {
+			LOGP(DGPRS, LOGL_INFO, "Ignoring NS PDU type 0x%0x "
+				"from %s for non-existing NS-VC\n",
+				nsh->pdu_type, inet_ntoa(saddr->sin_addr));
 			return -EIO;
+		}
+		LOGP(DGPRS, LOGL_INFO, "Creating NS-VC for BSS at %s:%u\n",
+			inet_ntoa(saddr->sin_addr), ntohs(saddr->sin_port));
 		nsvc = nsvc_create(nsi, 0xffff);
 		nsvc->ip.bts_addr = *saddr;
-		rc = gprs_ns_rx_reset(nsvc, msg);
-		return rc;
-	}
-	msgb_nsei(msg) = nsvc->nsei;
+	} else
+		msgb_nsei(msg) = nsvc->nsei;
 
 	switch (nsh->pdu_type) {
 	case NS_PDUT_ALIVE:
@@ -382,33 +386,34 @@ int gprs_ns_rcvmsg(struct gprs_ns_inst *nsi, struct msgb *msg,
 		rc = gprs_ns_rx_reset(nsvc, msg);
 		break;
 	case NS_PDUT_RESET_ACK:
-		DEBUGP(DGPRS, "NS RESET ACK\n");
+		DEBUGP(DGPRS, "NSEI=%u Rx NS RESET ACK\n", nsvc->nsei);
 		/* mark remote NS-VC as blocked + active */
 		nsvc->remote_state = NSE_S_BLOCKED | NSE_S_ALIVE;
 		break;
 	case NS_PDUT_UNBLOCK:
 		/* Section 7.2: unblocking procedure */
-		DEBUGP(DGPRS, "NS UNBLOCK\n");
+		DEBUGP(DGPRS, "NSEI=%u Rx NS UNBLOCK\n", nsvc->nsei);
 		nsvc->state &= ~NSE_S_BLOCKED;
 		rc = gprs_ns_tx_simple(nsvc, NS_PDUT_UNBLOCK_ACK);
 		break;
 	case NS_PDUT_UNBLOCK_ACK:
-		DEBUGP(DGPRS, "NS UNBLOCK ACK\n");
+		DEBUGP(DGPRS, "NSEI=%u Rx NS UNBLOCK ACK\n", nsvc->nsei);
 		/* mark remote NS-VC as unblocked + active */
 		nsvc->remote_state = NSE_S_ALIVE;
 		break;
 	case NS_PDUT_BLOCK:
-		DEBUGP(DGPRS, "NS BLOCK\n");
+		DEBUGP(DGPRS, "NSEI=%u Rx NS BLOCK\n", nsvc->nsei);
 		nsvc->state |= NSE_S_BLOCKED;
 		rc = gprs_ns_tx_simple(nsvc, NS_PDUT_UNBLOCK_ACK);
 		break;
 	case NS_PDUT_BLOCK_ACK:
-		DEBUGP(DGPRS, "NS BLOCK ACK\n");
+		DEBUGP(DGPRS, "NSEI=%u Rx NS BLOCK ACK\n", nsvc->nsei);
 		/* mark remote NS-VC as blocked + active */
 		nsvc->remote_state = NSE_S_BLOCKED | NSE_S_ALIVE;
 		break;
 	default:
-		DEBUGP(DGPRS, "Unknown NS PDU type 0x%02x\n", nsh->pdu_type);
+		DEBUGP(DGPRS, "NSEI=%u Rx Unknown NS PDU type 0x%02x\n",
+			nsvc->nsei, nsh->pdu_type);
 		rc = -EINVAL;
 		break;
 	}
@@ -453,7 +458,8 @@ static struct msgb *read_nsip_msg(struct bsc_fd *bfd, int *error,
 	ret = recvfrom(bfd->fd, msg->data, NS_ALLOC_SIZE, 0,
 			(struct sockaddr *)saddr, &saddr_len);
 	if (ret < 0) {
-		fprintf(stderr, "recv error  %s\n", strerror(errno));
+		LOGP(DGPRS, LOGL_ERROR, "recv error %s during NSIP recv\n",
+			strerror(errno));
 		msgb_free(msg);
 		*error = ret;
 		return NULL;