bts-trx: Detect duplicated responses for retransmitted commands

It was detected that under some conditions, osmo-trx (with limesdr)
may take a long time to answer to CMDs, which means trx_ctrl_timer will
trigger re-transmitting the last sent but yet unacked CMD. Due to the
high latency in osmo-trx, the original AND the rentrasnmited CMD are
handled after a while and RSP messages are sent for both. When
osmo-bts-trx receives the first RSP, it was marking the CMD as acked and
carried on with next one. Then, when the RSP from the retransmited CMD
arrives, it already lost state and doesn't know where does that come
from. As a result, osmo-bts-trx shutdowns.

The issue can be seen in the following truncated log from osmo-bts-trx
with TRX category enabled:
20180117135228175 Enqueuing TRX control command 'CMD RXTUNE 1782000'
20180117135228175 Enqueuing TRX control command 'CMD TXTUNE 1877000'
20180117135228175 Enqueuing TRX control command 'CMD SETTSC 7'
20180117135228175 Enqueuing TRX control command 'CMD POWERON'
20180117135228175 Enqueuing TRX control command 'CMD SETRXGAIN 1'
20180117135228175 Enqueuing TRX control command 'CMD SETPOWER 20'
20180117135228175 Enqueuing TRX control command 'CMD SETSLOT 0 5'
...
20180117135249829 Response message: 'RSP POWEROFF 0'
20180117135249855 Response message: 'RSP RXTUNE 0 1782000'
20180117135249876 Response message: 'RSP TXTUNE 0 1877000'
20180117135249876 Response message: 'RSP SETTSC 0 7'
20180117135250648 Response message: 'RSP POWERON 0'
20180117135251150 Response message: 'RSP SETRXGAIN 0 0'
20180117135253151 No response from transceiver for phy0.0 (CMD SETPOWER 20)
20180117135253777 Response message: 'RSP SETPOWER 0 20'
20180117135254535 Clock indication: fn=2018878
20180117135255777 No response from transceiver for phy0.0 (CMD SETSLOT 0 5)
...
20180117135256858 Response message: 'RSP SETPOWER 0 20'
20180117135256858 Discarding duplicated RSP from old CMD 'RSP SETPOWER 0 20'
20180117135256858 Response message: 'RSP SETSLOT 0 0 5'
20180117135256858 Response message: 'RSP SETSLOT 0 0 5'
20180117135256858 Discarding duplicated RSP from old CMD 'RSP SETSLOT 0 0 5'

Change-Id: I3633cba212edde878f83ed36aef922aaca6f503a

1 files changed, 16 insertions, 2 deletions

diff --git a/src/osmo-bts-trx/trx_if.c b/src/osmo-bts-trx/trx_if.c
index a8026d49..35698ef5 100644
--- a/src/osmo-bts-trx/trx_if.c
+++ b/src/osmo-bts-trx/trx_if.c
@@ -455,6 +455,12 @@ static int trx_ctrl_read_cb(struct osmo_fd *ofd, unsigned int what)
 
 	/* get command for response message */
 	if (llist_empty(&l1h->trx_ctrl_list)) {
+		/* RSP from a retransmission, skip it */
+		if (l1h->last_acked && cmd_matches_rsp(l1h->last_acked, cmdname, params)) {
+			LOGP(DTRX, LOGL_NOTICE, "Discarding duplicated RSP "
+				"from old CMD '%s'\n", buf);
+			return 0;
+		}
 		LOGP(DTRX, LOGL_NOTICE, "Response message without "
 			"command\n");
 		return -EINVAL;
@@ -464,6 +470,12 @@ static int trx_ctrl_read_cb(struct osmo_fd *ofd, unsigned int what)
 
 	/* check if response matches command */
 	if (!cmd_matches_rsp(tcm, cmdname, params)) {
+		/* RSP from a retransmission, skip it */
+		if (l1h->last_acked && cmd_matches_rsp(l1h->last_acked, cmdname, params)) {
+			LOGP(DTRX, LOGL_NOTICE, "Discarding duplicated RSP "
+				"from old CMD '%s'\n", buf);
+			return 0;
+		}
 		LOGP(DTRX, (tcm->critical) ? LOGL_FATAL : LOGL_NOTICE,
 			"Response message '%s' does not match command "
 			"message 'CMD %s%s%s'\n",
@@ -481,9 +493,10 @@ static int trx_ctrl_read_cb(struct osmo_fd *ofd, unsigned int what)
 			goto rsp_error;
 	}
 
-	/* remove command from list */
+	/* remove command from list, save it to last_acked and removed previous last_acked */
 	llist_del(&tcm->list);
-	talloc_free(tcm);
+	talloc_free(l1h->last_acked);
+	l1h->last_acked = tcm;
 
 	trx_ctrl_send(l1h);
 
@@ -621,6 +634,7 @@ void trx_if_flush(struct trx_l1h *l1h)
 		llist_del(&tcm->list);
 		talloc_free(tcm);
 	}
+	talloc_free(l1h->last_acked);
 }
 
 /*! close the TRX for given handle (data + control socket) */