Re: got DLR but could not find message, bug?

Share your configuration will be good to localize the possible problem.

Pada tanggal Rab, 1 Apr 2020 08.39, [email protected] <[email protected]>
menulis:

> 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.
>
>
>
>