DLR Routing failure in Kannel in a situation where there is a separate receiver and transceiver bind

I have a Kannel gateway with multiple SMPP binds ( one operator requires separate transmitter and receiver binds while another permits transceiver binds ). The transceiver binds do not display this problem, so I will not delve into more detail on those.

In the separate receiver / transmitter bind scenario, most ( but not all ) DLRs fail with "got DLR but could not find message or was not interested in it ", as shown in the log file extract below: ( some light anonymization has been done )

2011-10-28 08:41:24 [6182] [9] DEBUG: SMPP[tx_bind]: Sending PDU:
2011-10-28 08:41:24 [6182] [9] DEBUG: SMPP PDU 0x12d76c0 dump:
2011-10-28 08:41:24 [6182] [9] DEBUG:   type_name: submit_sm
2011-10-28 08:41:24 [6182] [9] DEBUG:   command_id: 4 = 0x00000004
2011-10-28 08:41:24 [6182] [9] DEBUG:   command_status: 0 = 0x00000000
2011-10-28 08:41:24 [6182] [9] DEBUG:   sequence_number: 108 = 0x0000006c
2011-10-28 08:41:24 [6182] [9] DEBUG:   service_type: "SHORT_CODE_REMOVED"
2011-10-28 08:41:24 [6182] [9] DEBUG:   source_addr_ton: 0 = 0x00000000
2011-10-28 08:41:24 [6182] [9] DEBUG:   source_addr_npi: 1 = 0x00000001
2011-10-28 08:41:24 [6182] [9] DEBUG:   source_addr: "SHORT_CODE_REMOVED"
2011-10-28 08:41:24 [6182] [9] DEBUG:   dest_addr_ton: 1 = 0x00000001
2011-10-28 08:41:24 [6182] [9] DEBUG:   dest_addr_npi: 1 = 0x00000001
2011-10-28 08:41:24 [6182] [9] DEBUG:   destination_addr: "PHONE_NUMBER_REMOVED"
2011-10-28 08:41:24 [6182] [9] DEBUG:   esm_class: 3 = 0x00000003
2011-10-28 08:41:24 [6182] [9] DEBUG:   protocol_id: 0 = 0x00000000
2011-10-28 08:41:24 [6182] [9] DEBUG:   priority_flag: 0 = 0x00000000
2011-10-28 08:41:24 [6182] [9] DEBUG:   schedule_delivery_time: NULL
2011-10-28 08:41:24 [6182] [9] DEBUG:   validity_period: NULL
2011-10-28 08:41:24 [6182] [9] DEBUG:   registered_delivery: 1 = 0x00000001
2011-10-28 08:41:24 [6182] [9] DEBUG:   replace_if_present_flag: 0 = 0x00000000
2011-10-28 08:41:24 [6182] [9] DEBUG:   data_coding: 0 = 0x00000000
2011-10-28 08:41:24 [6182] [9] DEBUG:   sm_default_msg_id: 0 = 0x00000000
2011-10-28 08:41:24 [6182] [9] DEBUG:   sm_length: 9 = 0x00000009
2011-10-28 08:41:24 [6182] [9] DEBUG:   short_message: "test test"
2011-10-28 08:41:24 [6182] [9] DEBUG: SMPP PDU dump ends.
2011-10-28 08:41:26 [6182] [19] DEBUG: Dumping 47 messages to store
2011-10-28 08:41:28 [6182] [9] DEBUG: SMPP[tx_bind]: Got PDU:
2011-10-28 08:41:28 [6182] [9] DEBUG: SMPP PDU 0x12a6590 dump:
2011-10-28 08:41:28 [6182] [9] DEBUG:   type_name: submit_sm_resp
2011-10-28 08:41:28 [6182] [9] DEBUG:   command_id: 2147483652 = 0x80000004
2011-10-28 08:41:28 [6182] [9] DEBUG:   command_status: 0 = 0x00000000
2011-10-28 08:41:28 [6182] [9] DEBUG:   sequence_number: 108 = 0x0000006c
2011-10-28 08:41:28 [6182] [9] DEBUG:   message_id: "1673716701"
2011-10-28 08:41:28 [6182] [9] DEBUG: SMPP PDU dump ends.
2011-10-28 08:41:28 [6182] [9] DEBUG: DLR[mysql]: Adding DLR smsc=tx_bind, ts=1673716701, src=SHORT_CODE_REMOVED, dst=PHONE_NUMBER_REMOVED, mask=1, boxc=
2011-10-28 08:41:28 [6182] [9] DEBUG: sql: INSERT INTO dlr (smsc, ts, source, destination, service, url, mask, boxc, status) VALUES ('tx_bind', '1673716701', 'SHORT_CODE_REMOVED', 'PHONE_NUMBER_REMOVED', 'SHORT_CODE_REMOVED', 'DLR_CALLBACK_URL_REMOVED', '1', '', '0');
2011-10-28 08:41:30 [6182] [19] DEBUG: Dumping 46 messages to store
2011-10-28 08:41:30 [6182] [6] DEBUG: SMPP[saf_7777]: Sending enquire link:
2011-10-28 08:41:33 [6182] [16] DEBUG: Optional parameter tag (0x001e)
2011-10-28 08:41:33 [6182] [16] DEBUG: Optional parameter length read as 11
2011-10-28 08:41:33 [6182] [16] DEBUG: Optional parameter tag (0x0427)
2011-10-28 08:41:33 [6182] [16] DEBUG: Optional parameter length read as 1
2011-10-28 08:41:33 [6182] [16] DEBUG: Optional parameter tag (0x1501)
2011-10-28 08:41:33 [6182] [16] DEBUG: Optional parameter length read as 13
2011-10-28 08:41:33 [6182] [16] WARNING: SMPP: Unknown TLV(0x1501,0x000d,32353437323235303036303900) for PDU type (deliver_sm) received!
2011-10-28 08:41:33 [6182] [16] DEBUG: SMPP[saf_receiver]: Got PDU:
2011-10-28 08:41:33 [6182] [16] DEBUG: SMPP PDU 0x1275cc0 dump:
2011-10-28 08:41:33 [6182] [16] DEBUG:   type_name: deliver_sm
2011-10-28 08:41:33 [6182] [16] DEBUG:   command_id: 5 = 0x00000005
2011-10-28 08:41:33 [6182] [16] DEBUG:   command_status: 0 = 0x00000000
2011-10-28 08:41:33 [6182] [16] DEBUG:   sequence_number: 49 = 0x00000031
2011-10-28 08:41:33 [6182] [16] DEBUG:   service_type: "SHORT_CODE_REMOVED"
2011-10-28 08:41:33 [6182] [16] DEBUG:   source_addr_ton: 1 = 0x00000001
2011-10-28 08:41:33 [6182] [16] DEBUG:   source_addr_npi: 1 = 0x00000001
2011-10-28 08:41:33 [6182] [16] DEBUG:   source_addr: "PHONE_NUMBER_REMOVED"
2011-10-28 08:41:33 [6182] [16] DEBUG:   dest_addr_ton: 0 = 0x00000000
2011-10-28 08:41:33 [6182] [16] DEBUG:   dest_addr_npi: 1 = 0x00000001
2011-10-28 08:41:33 [6182] [16] DEBUG:   destination_addr: "SHORT_CODE_REMOVED"
2011-10-28 08:41:33 [6182] [16] DEBUG:   esm_class: 4 = 0x00000004
2011-10-28 08:41:33 [6182] [16] DEBUG:   protocol_id: 0 = 0x00000000
2011-10-28 08:41:33 [6182] [16] DEBUG:   priority_flag: 0 = 0x00000000
2011-10-28 08:41:33 [6182] [16] DEBUG:   schedule_delivery_time: NULL
2011-10-28 08:41:33 [6182] [16] DEBUG:   validity_period: NULL
2011-10-28 08:41:33 [6182] [16] DEBUG:   registered_delivery: 0 = 0x00000000
2011-10-28 08:41:33 [6182] [16] DEBUG:   replace_if_present_flag: 0 = 0x00000000
2011-10-28 08:41:33 [6182] [16] DEBUG:   data_coding: 0 = 0x00000000
2011-10-28 08:41:33 [6182] [16] DEBUG:   sm_default_msg_id: 0 = 0x00000000
2011-10-28 08:41:33 [6182] [16] DEBUG:   sm_length: 111 = 0x0000006f
2011-10-28 08:41:33 [6182] [16] DEBUG:   short_message:
2011-10-28 08:41:33 [6182] [16] DEBUG:    Octet string at 0x12e2da0:
2011-10-28 08:41:33 [6182] [16] DEBUG:      len:  111
2011-10-28 08:41:33 [6182] [16] DEBUG:      size: 112
2011-10-28 08:41:33 [6182] [16] DEBUG:      immutable: 0
2011-10-28 08:41:33 [6182] [16] DEBUG:      data: 69 64 3a 31 36 37 33 37 31 36 37 30 31 20 73 75   id:1673716701 su
2011-10-28 08:41:33 [6182] [16] DEBUG:      data: 62 3a 30 30 31 20 64 6c 76 72 64 3a 30 30 31 20   b:001 dlvrd:001
2011-10-28 08:41:33 [6182] [16] DEBUG:      data: 73 75 62 6d 69 74 20 64 61 74 65 3a 31 31 31 30   submit date:1110
2011-10-28 08:41:33 [6182] [16] DEBUG:      data: 32 38 30 38 34 31 20 64 6f 6e 65 20 64 61 74 65   280841 done date
2011-10-28 08:41:33 [6182] [16] DEBUG:      data: 3a 31 31 31 30 32 38 30 38 34 31 20 73 74 61 74   :1110280841 stat
2011-10-28 08:41:33 [6182] [16] DEBUG:      data: 3a 44 45 4c 49 56 52 44 20 65 72 72 3a 30 30 30   :DELIVRD err:000
2011-10-28 08:41:33 [6182] [16] DEBUG:      data: 20 74 65 78 74 3a 74 65 73 74 20 74 65 73 74       text:test test
2011-10-28 08:41:33 [6182] [16] DEBUG:    Octet string dump ends.
2011-10-28 08:41:33 [6182] [16] DEBUG:   message_state: 2 = 0x00000002
2011-10-28 08:41:33 [6182] [16] DEBUG:   receipted_message_id: "1673716701"
2011-10-28 08:41:33 [6182] [16] DEBUG: SMPP PDU dump ends.
2011-10-28 08:41:33 [6182] [16] DEBUG: SMPP[rx_bind] handle_pdu, got DLR
2011-10-28 08:41:33 [6182] [16] DEBUG: DLR[mysql]: Looking for DLR smsc=tx_bind, ts=1673716701, dst=PHONE_NUMBER_REMOVED, type=1
2011-10-28 08:41:33 [6182] [16] DEBUG: sql: SELECT mask, service, url, source, destination, boxc FROM dlr WHERE smsc='rx_bind' AND ts='1673716701';
2011-10-28 08:41:33 [6182] [16] DEBUG: no rows found
2011-10-28 08:41:33 [6182] [16] WARNING: DLR[mysql]: DLR from SMSC<rx_bind> for DST<PHONE_NUMBER_REMOVED> not found.
2011-10-28 08:41:33 [6182] [16] ERROR: SMPP[rx_bind]: got DLR but could not find message or was not interested in it id<1673716701> dst<PHONE_NUMBER_REMOVED>, type<1>

The respective binds are:

# The sender
group=smsc
smsc=smpp
smsc-id=tx_bind
allowed-smsc-id=tx_bind
preferred-smsc-id=SHORT_CODE_REMOVED
interface-version=34
host=SMSC_HOST_REMOVED
port=SMSC_PORT_REMOVED
system-id=SHORT_CODE_REMOVED
system-type=
service-type=SHORT_CODE_REMOVED
source-addr-ton=0
source-addr-npi=1
dest-addr-ton=1
dest-addr-npi=1
smsc-username=USERNAME_REMOVED
smsc-password=PASSWORD_REMOVED
log-level=0

# The receiver
group=smsc
smsc=smpp
smsc-id=rx_bind
interface-version=34
host=HOST_REMOVED
receive-port=PORT_REMOVED
system-type=
smsc-username=USERNAME_REMOVED
smsc-password=PASSWORD_REMOVED
log-level=0

My background research brought up these mailing list messages: - http://www.kannel.org/pipermail/users/2011-July/016183.html - http://old.nabble.com/Responsibility-for-inversion-of-source-and-destination-address-for-DLR-td32165725.html

It seems that Kannel saves the DLR immediately after the submit_sm with the smsc_id set to the tx_bind [ the sender's SMSC id ]. Then, when the deliver_sm is received [ for this operator, it will usually come in via the rx_bind [ the receiver bind ], it attempts to look for it using that smsc_id.

Does anyone know of a workaround for this?

As I can see from log and configuration file, you use different smsc sections for transmitter and receiver connections.

So when Kannel tries to find original message it use smsc and message-id parameters. In your case smsc will have different values on submit_sm and deliver_sm processing.

To resolve it just set-up single smsc group with:

1. both port and receive-port inside
2. transceiver-mode = 0 parameter (mean transmitter/receiver mode)

Note: this port may be the same and often is the same on SMSC.

Example (part of configuration):

group=smsc
smsc=smpp
smsc-id=rx_tx_bind
interface-version=34
transceiver-mode = 0
host=smsc.host.was.here
port=TX_PORT
receive-port=RX_PORT
# other parameters here