| Newsgroups |
gmane.comp.mobile.kannel.user |
| Message-ID |
<[email protected]> |
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.