Intermediate SMPP DLR is considered as final in kannel
Paulo Correia <[email protected]>
| Newsgroups | gmane.comp.mobile.kannel.user |
|---|---|
| Organization | Go4Mobility |
| Message-ID | <[email protected]> |
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×tamp=%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×tamp=%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:* [email protected]
<mailto:[email protected]> skype: pcorreia.g4m
<skype://pcorreia.g4m?chat>**
Go4Mobility <https://go4mobility.com/en>