Intermediate SMPP DLR is considered as final in kannel

Paulo Correia

2018-10-18 16:22:44 UTC

Hello,

We have a connection to a carrier using SMPP and some intermediate DLRs
are considered by kannel as final.

The typical message sent is:

2018-10-18 15:30:49 [13585] [9] DEBUG: SMPP PDU 0x7f8c3c0052a0 dump:
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â type_name: submit_sm
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â command_id: 4 = 0x00000004
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â command_status: 0 = 0x00000000
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â sequence_number: 282995 =
0x00045173
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â service_type: NULL
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â source_addr_ton: 2 = 0x00000002
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â source_addr_npi: 1 = 0x00000001
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â source_addr: "*****"
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â dest_addr_ton: 1 = 0x00000001
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â dest_addr_npi: 1 = 0x00000001
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â destination_addr:
"244*********"
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â esm_class: 3 = 0x00000003
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â protocol_id: 0 = 0x00000000
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â priority_flag: 2 = 0x00000002
2018-10-18 15:30:49 [13585] [9] DEBUG: schedule_delivery_time: NULL
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â validity_period:
"181021143149000+"
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â registered_delivery: 17 =
0x00000011
2018-10-18 15:30:49 [13585] [9] DEBUG: replace_if_present_flag: 0 =
0x00000000
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â data_coding: 0 = 0x00000000
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â sm_default_msg_id: 0 =
0x00000000
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â sm_length: 159 = 0x0000009f
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â short_message:
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â Â Octet string at
0x7f8c3c0009a0:
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â Â Â Â len:Â 159
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â Â Â Â size: 160
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â Â Â Â immutable: 0
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â Â Â Â data: 42 65 6d 2d 76 69
6e 64 6f 20 61 6f 20 55 6e 69Â Â Bem-vindo ao Uni
...<snip>...
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â Â Octet string dump ends.
2018-10-18 15:30:49 [13585] [9] DEBUG: SMPP PDU dump ends.
...
2018-10-18 15:30:49 [13585] [9] DEBUG: SMPP PDU 0x7f8c3c0052a0 dump:
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â type_name: submit_sm_resp
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â command_id: 2147483652 =
0x80000004
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â command_status: 0 = 0x00000000
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â sequence_number: 282995 =
0x00045173
2018-10-18 15:30:49 [13585] [9] DEBUG:Â Â message_id: "2FD40AC9"
2018-10-18 15:30:49 [13585] [9] DEBUG: SMPP PDU dump ends.

Then we receive a first DLR:

2018-10-18 15:31:02 [13585] [9] DEBUG: SMPP PDU 0x7f8c3c0052a0 dump:
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â type_name: deliver_sm
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â command_id: 5 = 0x00000005
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â command_status: 0 = 0x00000000
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â sequence_number: 440922 =
0x0006ba5a
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â service_type: NULL
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â source_addr_ton: 1 = 0x00000001
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â source_addr_npi: 1 = 0x00000001
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â source_addr: "244*********"
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â dest_addr_ton: 2 = 0x00000002
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â dest_addr_npi: 1 = 0x00000001
2018-10-18 15:31:02 [13585] [9] DEBUG: destination_addr: "*****"
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â esm_class: 32 = 0x00000020
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â protocol_id: 0 = 0x00000000
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â priority_flag: 0 = 0x00000000
2018-10-18 15:31:02 [13585] [9] DEBUG: schedule_delivery_time: NULL
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â validity_period: NULL
2018-10-18 15:31:02 [13585] [9] DEBUG: registered_delivery: 0 =
0x00000000
2018-10-18 15:31:02 [13585] [9] DEBUG: replace_if_present_flag: 0 =
0x00000000
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â data_coding: 0 = 0x00000000
2018-10-18 15:31:02 [13585] [9] DEBUG: sm_default_msg_id: 0 = 0x00000000
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â sm_length: 122 = 0x0000007a
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â short_message:
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Octet string at
0x7f8c3c0051d0:
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â len:Â 122
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â size: 123
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â immutable: 0
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â data: 69 64 3a 30 38 30
32 34 32 35 35 34 35 20 73 75Â Â id:0802425545 su
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â data: 62 3a 30 30 31 20
64 6c 76 72 64 3a 30 30 30 20Â Â b:001 dlvrd:000
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â data: 73 75 62 6d 69 74
20 64 61 74 65 3a 31 38 31 30Â Â submit date:1810
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â data: 31 38 31 35 33 30
20 64 6f 6e 65 20 64 61 74 65Â Â 181530 done date
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â data: 3a 31 38 31 30 31
38 31 35 33 31 20 73 74 61 74Â Â :1810181531 stat
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â data: 3a 55 4e 4b 4e 4f
57 4e 20 65 72 72 3a 30 30 36Â Â :UNKNOWN err:006
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â data: 20 74 65 78 74 3a
42 65 6d 2d 76 69 6e 64 6f 20Â Â Â text:Bem-vindo
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â data: 61 6f 20 55 6e 69
74 65 6c 20Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â ao Unitel
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Octet string dump ends.
2018-10-18 15:31:02 [13585] [9] DEBUG: network_error_code:
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Octet string at
0x7f8c3c000ce0:
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â len:Â 3
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â size: 4
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â immutable: 0
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â data: 03 00
06Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â ...
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Octet string dump ends.
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â message_state: 7 = 0x00000007
2018-10-18 15:31:02 [13585] [9] DEBUG: receipted_message_id: "2FD40AC9"
2018-10-18 15:31:02 [13585] [9] DEBUG: SMPP PDU dump ends.

And this causes the message to be considered in final status (type=2),
and the DLR is deleted from the DB:

2018-10-18 15:31:02 [13585] [9] DEBUG: DLR[pgsql]: Looking for DLR
smsc=UNI.AO-FUT, ts=2FD40AC9, dst=244*********, type=2
2018-10-18 15:31:02 [13585] [9] DEBUG: sql: SELECT "mask",
"service", "url", "source", "destination", "boxc" FROM
"deliveryreport" WHERE "smsc"='UNI.AO-FUT' AND "ts"='2FD40AC9' LIMIT 1;
2018-10-18 15:31:02 [13585] [9] DEBUG: Found entry, col1=31,
col2=UNIAOFUTUSER,
col3=http://192.168.41.40:30060/receive-dlr?type=%d&mtMsgId=1734641907&reply=%A&error=%B&dispatchId=%F&meta=%D&timestamp=%T&sendMtUsername=%n,
col4=19152, col5=+ccol6=
2018-10-18 15:31:02 [13585] [9] DEBUG: DLR[pgsql]: created DLR
message for URL
<http://192.168.41.40:30060/receive-dlr?type=%d&mtMsgId=1734641907&reply=%A&error=%B&dispatchId=%F&meta=%D&timestamp=%T&sendMtUsername=%n>
2018-10-18 15:31:02 [13585] [9] DEBUG: removing DLR from database
2018-10-18 15:31:02 [13585] [9] DEBUG: sql: DELETE FROM
"deliveryreport" WHERE oid = (SELECT oid FROM "deliveryreport" WHERE
"smsc"='UNI.AO-FUT' AND "ts"='2FD40AC9'Â LIMIT 1);

So some minutes later when we receive a new DLR with a DELIVRD status
(type=1):

2018-10-18 15:31:02 [13585] [9] DEBUG: SMPP PDU 0x7f8c3c0052a0 dump:
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â type_name: deliver_sm
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â command_id: 5 = 0x00000005
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â command_status: 0 = 0x00000000
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â sequence_number: 440923 =
0x0006ba5b
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â service_type: NULL
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â source_addr_ton: 1 = 0x00000001
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â source_addr_npi: 1 = 0x00000001
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â source_addr: "244*********"
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â dest_addr_ton: 2 = 0x00000002
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â dest_addr_npi: 1 = 0x00000001
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â destination_addr: "*****"
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â esm_class: 32 = 0x00000020
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â protocol_id: 0 = 0x00000000
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â priority_flag: 0 = 0x00000000
2018-10-18 15:31:02 [13585] [9] DEBUG: schedule_delivery_time: NULL
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â validity_period: NULL
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â registered_delivery: 0 =
0x00000000
2018-10-18 15:31:02 [13585] [9] DEBUG: replace_if_present_flag: 0 =
0x00000000
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â data_coding: 0 = 0x00000000
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â sm_default_msg_id: 0 =
0x00000000
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â sm_length: 122 = 0x0000007a
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â short_message:
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Octet string at
0x7f8c3c0051d0:
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â len:Â 122
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â size: 123
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â immutable: 0
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â data: 69 64 3a 30 38 30
32 34 32 35 35 34 35 20 73 75Â Â id:0802425545 su
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â data: 62 3a 30 30 31 20
64 6c 76 72 64 3a 30 30 31 20Â Â b:001 dlvrd:001
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â data: 73 75 62 6d 69 74
20 64 61 74 65 3a 31 38 31 30Â Â submit date:1810
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â data: 31 38 31 35 33 30
20 64 6f 6e 65 20 64 61 74 65Â Â 181530 done date
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â data: 3a 31 38 31 30 31
38 31 35 33 31 20 73 74 61 74Â Â :1810181531 stat
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â data: 3a 44 45 4c 49 56
52 44 20 65 72 72 3a 30 30 30Â Â :DELIVRD err:000
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â data: 20 74 65 78 74 3a
42 65 6d 2d 76 69 6e 64 6f 20Â Â Â text:Bem-vindo
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Â Â data: 61 6f 20 55 6e 69
74 65 6c 20Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â Â ao Unitel
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â Â Octet string dump ends.
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â message_state: 2 = 0x00000002
2018-10-18 15:31:02 [13585] [9] DEBUG:Â Â receipted_message_id:
"2FD40AC9"
2018-10-18 15:31:02 [13585] [9] DEBUG: SMPP PDU dump ends.
2018-10-18 15:31:02 [13585] [9] DEBUG: SMPP[UNI.AO-FUT] handle_pdu,
got DLR
2018-10-18 15:31:02 [13585] [9] DEBUG: DLR[pgsql]: Looking for DLR
smsc=UNI.AO-FUT, ts=2FD40AC9, dst=244*********, type=1
2018-10-18 15:31:02 [13585] [9] DEBUG: sql: SELECT "mask",
"service", "url", "source", "destination", "boxc" FROM
"deliveryreport" WHERE "smsc"='UNI.AO-FUT' AND "ts"='2FD40AC9' LIMIT 1;
2018-10-18 15:31:02 [13585] [9] DEBUG: no rows found
2018-10-18 15:31:02 [13585] [9] WARNING: DLR[pgsql]: DLR from
SMSC<UNI.AO-FUT> for DST<244*********> not found.
2018-10-18 15:31:02 [13585] [9] ERROR: SMPP[UNI.AO-FUT]: got DLR but
could not find message or was not interested in it id<2FD40AC9>
dst<244*********>, type<1>

But as there is no longer a DLR on the database, it is ignored.

Is this a common issue? Is there a problem on the first DLR sent by the
carrier?

Kind regards,

--
*Paulo Correia*
Head of Development

*telephone:*+351210337760*fax:* +351210337761
*email:* ***@go4mobility.com
<mailto:***@go4mobility.com> skype: pcorreia.g4m
<skype://pcorreia.g4m?chat>**
Go4Mobility <https://go4mobility.com/en>