praekelt/vumi — pull request #656 by jerith (2013-11-25 09:37:02+00:00)
Title: Sanity check message storage in the MTN NG transport

We've been seeing a lot of "Invalid reply to message" in the MTN Nigeria transport. After looking through the logs for GFM, it seems the issue is triggered when the remote side (MTN) preemptively terminates a session, right after the user has sent a message to us. It could be the case that the transport is not distinguishing between the messages, and is overwriting one message with the other in its local storage.

In the trace below, notice that both inbound messages (from the perspective of the http_api), have the same message_id, which is obviously an issue, and is a clue to the root cause.

```text
Trace in bridge_ng.log for session_id: 1859639643, msisdn: 2348135829645

The following events happened during a 1 second interval starting at 2013-11-19 09:36:10 UTC.

inbound msg: session_id=1859639643 message_id=408114897 session_event=resume

outbound msg: session_id=1859639643 message_id=c6fd5349361a46839d73bc9e49d1d5fe in_reply_to=408114897

inbound nack: user_message_id=c6fd5349361a46839d73bc9e49d1d5fe (invalid in_reply_to)

inbound msg: session_id=1859639643 message_id=408114897 session_event=close
```

Full log for the above trace:
```text
2013-11-19 09:36:10+0000 [HTTP11ClientProtocol,client] Processed inbound message for bridge_ng: {"transport_name": "mtn_nigeria_ussd_transport", "transport_metadata": {"mtn_nigeria_ussd": {"phase": "2", "clientId": "441", "dcs": "15", "session_id": "1859639643", "starCode": "759"}}, "group": null, "from_addr": "+2348135829645", "timestamp": "2013-11-19 09:36:10.505146", "helper_metadata": {"load_balancer": {"transport_names": ["mtn_nigeria_ussd_transport_1"]}, "go": {"conversation_type": "http_api", "user_account": "19b25b7ce2594e898bf9ae1d7cb20ed4", "conversation_key": "d917d8f8354a4efb92ca7148174704ae"}, "tag": {"tag": ["mtn_nigeria_ussd", "*759#"]}, "optout": {"optout": false}}, "to_addr": "*759#", "content": "1", "routing_metadata": {"go_hops": [[["TRANSPORT_TAG:mtn_nigeria_ussd:*759#", "default"], ["CONVERSATION:http_api:d917d8f8354a4efb92ca7148174704ae", "default"]]], "endpoint_name": "default"}, "message_version": "20110921", "transport_type": "ussd", "provider": "mtn_nigeria", "in_reply_to": null, "session_event": "resume", "message_id": "408114897", "message_type": "user_message"}

2013-11-19 09:36:10+0000 [WorkerAMQClient,client] Processed outbound message for bridge_ng: {"transport_name": "mtn_nigeria_ussd_transport", "in_reply_to": "408114897", "group": null, "from_addr": "*759#", "timestamp": "2013-11-19 09:36:10.707222", "to_addr": "+2348135829645", "content": "Guinness Football Manager\n\nCHE U FC\n\n1) Team Dashboard\n2) Manage Team\n3) Leagues\n4) EPL Fixtures\n5) About the Game\n", "routing_metadata": {"endpoint_name": "default"}, "message_version": "20110921", "transport_type": "ussd", "helper_metadata": {"load_balancer": {"transport_names": ["mtn_nigeria_ussd_transport_1"]}, "go": {"conversation_type": "http_api", "user_account": "19b25b7ce2594e898bf9ae1d7cb20ed4", "conversation_key": "d917d8f8354a4efb92ca7148174704ae"}, "tag": {"tag": ["mtn_nigeria_ussd", "*759#"]}, "optout": {"optout": false}}, "transport_metadata": {"mtn_nigeria_ussd": {"phase": "2", "clientId": "441", "dcs": "15", "session_id": "1859639643", "starCode": "759"}}, "session_event": null, "message_id": "c6fd5349361a46839d73bc9e49d1d5fe", "message_type": "user_message"}

2013-11-19 09:36:10+0000 [HTTP11ClientProtocol,client] Processed event message for bridge_ng: {"transport_name": "bridge_ng", "event_type": "nack", "nack_reason": "Unexpected status code: 400", "event_id": "dd32607ec38a424ab06506bc265d81a2", "message_type": "event", "helper_metadata": {}, "routing_metadata": {}, "message_version": "20110921", "timestamp": "2013-11-19 09:36:10.802169", "transport_metadata": {}, "user_message_id": "c6fd5349361a46839d73bc9e49d1d5fe"}

2013-11-19 09:36:10+0000 [HTTP11ClientProtocol,client] Processed inbound message for bridge_ng: {"transport_name": "mtn_nigeria_ussd_transport", "transport_metadata": {"mtn_nigeria_ussd": {"phase": "2", "clientId": "441", "dcs": "15", "session_id": "1859639643", "starCode": "759"}}, "group": null, "from_addr": "+2348135829645", "timestamp": "2013-11-19 09:36:10.693562", "helper_metadata": {"load_balancer": {"transport_names": ["mtn_nigeria_ussd_transport_1"]}, "go": {"conversation_type": "http_api", "user_account": "19b25b7ce2594e898bf9ae1d7cb20ed4", "conversation_key": "d917d8f8354a4efb92ca7148174704ae"}, "tag": {"tag": ["mtn_nigeria_ussd", "*759#"]}, "optout": {"optout": false}}, "to_addr": "*759#", "content": "Session closed due to cause 209", "routing_metadata": {"go_hops": [[["TRANSPORT_TAG:mtn_nigeria_ussd:*759#", "default"], ["CONVERSATION:http_api:d917d8f8354a4efb92ca7148174704ae", "default"]]], "endpoint_name": "default"}, "message_version": "20110921", "transport_type": "ussd", "provider": "mtn_nigeria", "in_reply_to": null, "session_event": "close", "message_id": "408114897", "message_type": "user_message"}
```