Kannel 1.4.5 + redis is used to send sms via SMSC using smpp protocol.
When processing dlrs, once in a while we receive an ERROR similar to the following: ERROR: SMPP[XXXXX]: got DLR but could not find message or was not interested in it id<143914440> dst<XXXXXXX0842> If sms body is long, it becomes a real problem as almost every 2nd receipt can not be matched to the original submission. So let me explain what I believe is a serious bug: Kannel submits a request to send an sms to SMSC: smpp submit_sm 2020-03-31 22:53:43 [10846] [6] DEBUG: type_name: submit_sm 2020-03-31 22:53:43 [10846] [6] DEBUG: command_id: 4 = 0x00000004 2020-03-31 22:53:43 [10846] [6] DEBUG: sequence_number: 3305 = 0x00000ce9 2020-03-31 22:53:43 [10846] [6] DEBUG: destination_addr: "XXXXXXX0842" 2020-03-31 22:53:43 [10846] [6] DEBUG: sm_length: 159 = 0x0000009f 2020-03-31 22:53:43 [10846] [6] DEBUG: more_messages_to_send: 1 = 0x00000001 ... 2020-03-31 22:53:43 [10846] [6] DEBUG: type_name: submit_sm 2020-03-31 22:53:43 [10846] [6] DEBUG: command_id: 4 = 0x00000004 2020-03-31 22:53:43 [10846] [6] DEBUG: sequence_number: 3306 = 0x00000cea 2020-03-31 22:53:43 [10846] [6] DEBUG: destination_addr: "XXXXXXX0842" 2020-03-31 22:53:43 [10846] [6] DEBUG: sm_length: 48 = 0x00000030 It gets gets an ACK from the SMSC: smpp submit_sm_resp 2020-03-31 22:53:43 [10846] [6] DEBUG: type_name: submit_sm_resp 2020-03-31 22:53:43 [10846] [6] DEBUG: command_id: 2147483652 = 0x80000004 2020-03-31 22:53:43 [10846] [6] DEBUG: sequence_number: 3305 = 0x00000ce9 2020-03-31 22:53:43 [10846] [6] DEBUG: message_id: "0893F5C7" writes it to redis 2020-03-31 22:53:43 [10846] [6] DEBUG: DLR[redis]: Adding DLR smsc=smsc_123, ts=143914439, src=XXXXXXX8356, dst=XXXXXXX0842, mask=31, boxc= It converts it to fake DLR8 and posts (actually http get) to our API. So far so good, sms is going to the recipient and we have ACK (fake DLR8 as a proof). 2020-03-31 22:53:43 [10846] [6] DEBUG: type_name: submit_sm_resp 2020-03-31 22:53:43 [10846] [6] DEBUG: command_id: 2147483652 = 0x80000004 2020-03-31 22:53:43 [10846] [6] DEBUG: sequence_number: 3306 = 0x00000cea 2020-03-31 22:53:43 [10846] [6] DEBUG: message_id: "0893F5C8" 2020-03-31 22:53:43 [10846] [6] DEBUG: SMSC[smsc_123]: creating DLR message 2020-03-31 22:53:43 [10846] [6] DEBUG: SMSC[smsc_123]: DLR = http://XXXX Note message_id is +1 to what redis has ( we will need it later). Now, sms is delivered and our provider sends us a delivery receipt. 2020-03-31 22:53:43 [10846] [6] DEBUG: type_name: deliver_sm 2020-03-31 22:53:43 [10846] [6] DEBUG: command_id: 5 = 0x00000005 2020-03-31 22:53:43 [10846] [6] DEBUG: sequence_number: 1650 = 0x00000672 2020-03-31 22:53:43 [10846] [6] DEBUG: source_addr: "XXXXXXX0842" 2020-03-31 22:53:43 [10846] [6] DEBUG: sm_length: 102 = 0x00000066 Kannel goes to redis but could not find the key needed: 2020-03-31 22:53:43 [10846] [6] DEBUG: DLR[redis]: Looking for DLR smsc=smsc_123, ts=143914440, dst=XXXXXXX0842, type=2 2020-03-31 22:53:43 [10846] [6] WARNING: DLR[redis]: DLR from SMSC<smsc_123> for DST<XXXXXXX0842> not found. 2020-03-31 22:53:43 [10846] [6] ERROR: SMPP[smsc_123]: got DLR but could not find message or was not interested in it id<143914440> dst<XXXXXXX0842>, type<2> Manually examining the redis confirms that there is no key: Message_id converted from hex to int: 0893F5C8 => 143914440 redis-cli keys "dlr:smsc_123:143914440" (empty list or set) Now to revisit on what was written to redis: 2020-03-31 22:53:43 [10846] [6] DEBUG: DLR[redis]: Adding DLR smsc=smsc_123, ts=143914439, src=XXXXXXX8356, dst=XXXXXXX0842, mask=31, boxc= and compare to what is expected: 2020-03-31 22:53:43 [10846] [6] DEBUG: DLR[redis]: Looking for DLR smsc=smsc_123, ts=143914440, dst=XXXXXXX0842, type=2 Now we getting somewhere: 0893F5C7 (part 1) => 143914439 is written to redis 0893F5C8 (part 2) => 143914440 is used to create DLR8 0893F5C8 (part 2) => 143914440 is used on receiving deliver_sm to look-up in redis. But in fact we should be looking for 0893F5C7 (part 1) => 143914439? no? Correct: redis-cli keys "dlr:smsc_123:143914439" 1) "dlr:smsc_123:143914439" As you see kannel writes to redis ts = message_id from part 1, but on receiving a dlr it is looking for ts = message_id from part 2, could not find it, and as a result dlr is lost. The puzzling part, as bug is not consistent. As I mentioned before, some of the message(s) are Ok (???). Not sure what trips kannel to look for a wrong message_id though. Sometimes it matches message_id from part2 to part2, and everything is good.
