Share your configuration will be good to localize the possible problem. Pada tanggal Rab, 1 Apr 2020 08.39, lbrezs...@gmx.co.uk <lbrezs...@gmx.co.uk> 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. > > > >