Hi all, I'm seeing some strangeness with DLR handling of concatenated messages sent via SMPP in Kannel 1.5.0.
I'm using MySQL for DLR storage and only the first message of the set generates a DLR in the database. My provider, however, follows the specs and returns a DLR for each part. Kannel recognizes the first DLR and updates the database. When the DLRs for the remaining parts arrive, Kannel tries to find them in the database and fails, spitting out an error (see below). Specifically: 1. When the submit_sm_resp PDU for the first message part arrives, Kannel happily creates the DLR in the database: 2011-03-25 02:03:37 [5106] [10] DEBUG: SMPP PDU 0xc8ad960 dump: 2011-03-25 02:03:37 [5106] [10] DEBUG: type_name: submit_sm_resp 2011-03-25 02:03:37 [5106] [10] DEBUG: command_id: 2147483652 = 0x80000004 2011-03-25 02:03:37 [5106] [10] DEBUG: command_status: 0 = 0x00000000 2011-03-25 02:03:37 [5106] [10] DEBUG: sequence_number: 17 = 0x00000011 2011-03-25 02:03:37 [5106] [10] DEBUG: message_id: 2011-03-25 02:03:37 [5106] [10] DEBUG: Octet string at 0xc8cbc50: 2011-03-25 02:03:37 [5106] [10] DEBUG: len: 20 2011-03-25 02:03:37 [5106] [10] DEBUG: size: 21 2011-03-25 02:03:37 [5106] [10] DEBUG: immutable: 0 2011-03-25 02:03:37 [5106] [10] DEBUG: data: 31 33 30 30 39 38 39 38 31 37 36 36 36 31 38 33 1300989817666183 2011-03-25 02:03:37 [5106] [10] DEBUG: data: 30 34 30 32 0402 2011-03-25 02:03:37 [5106] [10] DEBUG: Octet string dump ends. 2011-03-25 02:03:37 [5106] [10] DEBUG: SMPP PDU dump ends. 2011-03-25 02:03:37 [5106] [10] DEBUG: DLR[mysql]: Adding DLR smsc=MY-SMPP-CONNECTION, ts=13009898176661830402, src=test, dst=999999999, mask=31, boxc=smsbox 2011-03-25 02:03:37 [5106] [10] DEBUG: adding DLR entry into database 2011-03-25 02:03:37 [5106] [10] DEBUG: sql: INSERT INTO `smsgw_kannel_sms_dlr` (`smsc`, `timestamp`, `source`, `destination`, `service`, `url`, `mask`, `boxc_id`, `status`) VALUES (?, ?, ?, ?, ?, ?, ?, ?, 0) 2. When the submit_sm_resp PDU for the subsequent message parts arrive, Kannel doesn't create a database DLR but instead appears to create one in memory (note the missing SQL): 2011-03-25 02:03:38 [5106] [10] DEBUG: SMPP PDU 0xc8ad960 dump: 2011-03-25 02:03:38 [5106] [10] DEBUG: type_name: submit_sm_resp 2011-03-25 02:03:38 [5106] [10] DEBUG: command_id: 2147483652 = 0x80000004 2011-03-25 02:03:38 [5106] [10] DEBUG: command_status: 0 = 0x00000000 2011-03-25 02:03:38 [5106] [10] DEBUG: sequence_number: 18 = 0x00000012 2011-03-25 02:03:38 [5106] [10] DEBUG: message_id: 2011-03-25 02:03:38 [5106] [10] DEBUG: Octet string at 0xc8d1d80: 2011-03-25 02:03:38 [5106] [10] DEBUG: len: 20 2011-03-25 02:03:38 [5106] [10] DEBUG: size: 21 2011-03-25 02:03:38 [5106] [10] DEBUG: immutable: 0 2011-03-25 02:03:38 [5106] [10] DEBUG: data: 31 33 30 30 39 38 39 38 31 37 39 33 34 31 38 34 1300989817934184 2011-03-25 02:03:38 [5106] [10] DEBUG: data: 30 34 30 32 0402 2011-03-25 02:03:38 [5106] [10] DEBUG: Octet string dump ends. 2011-03-25 02:03:38 [5106] [10] DEBUG: SMPP PDU dump ends. 2011-03-25 02:03:38 [5106] [10] DEBUG: SMSC[MY-SMPP-CONNECTION]: creating DLR message 2011-03-25 02:03:38 [5106] [10] DEBUG: SMSC[MY-SMPP-CONNECTION]: DLR = 3. When the deliver_sm PDU arrives for the first message part, it's correctly matched against the database, processed and deleted: 2011-03-25 02:03:48 [5106] [10] DEBUG: SMPP PDU 0xc8ad960 dump: 2011-03-25 02:03:48 [5106] [10] DEBUG: type_name: deliver_sm 2011-03-25 02:03:48 [5106] [10] DEBUG: command_id: 5 = 0x00000005 2011-03-25 02:03:48 [5106] [10] DEBUG: command_status: 0 = 0x00000000 2011-03-25 02:03:48 [5106] [10] DEBUG: sequence_number: 8 = 0x00000008 2011-03-25 02:03:48 [5106] [10] DEBUG: service_type: NULL 2011-03-25 02:03:48 [5106] [10] DEBUG: source_addr_ton: 0 = 0x00000000 2011-03-25 02:03:48 [5106] [10] DEBUG: source_addr_npi: 0 = 0x00000000 2011-03-25 02:03:48 [5106] [10] DEBUG: source_addr: "999999999" 2011-03-25 02:03:48 [5106] [10] DEBUG: dest_addr_ton: 0 = 0x00000000 2011-03-25 02:03:48 [5106] [10] DEBUG: dest_addr_npi: 0 = 0x00000000 2011-03-25 02:03:48 [5106] [10] DEBUG: destination_addr: "test" 2011-03-25 02:03:48 [5106] [10] DEBUG: esm_class: 4 = 0x00000004 2011-03-25 02:03:48 [5106] [10] DEBUG: protocol_id: 0 = 0x00000000 2011-03-25 02:03:48 [5106] [10] DEBUG: priority_flag: 0 = 0x00000000 2011-03-25 02:03:48 [5106] [10] DEBUG: schedule_delivery_time: NULL 2011-03-25 02:03:48 [5106] [10] DEBUG: validity_period: NULL 2011-03-25 02:03:48 [5106] [10] DEBUG: registered_delivery: 0 = 0x00000000 2011-03-25 02:03:48 [5106] [10] DEBUG: replace_if_present_flag: 0 = 0x00000000 2011-03-25 02:03:48 [5106] [10] DEBUG: data_coding: 0 = 0x00000000 2011-03-25 02:03:48 [5106] [10] DEBUG: sm_default_msg_id: 0 = 0x00000000 2011-03-25 02:03:48 [5106] [10] DEBUG: sm_length: 165 = 0x000000a5 2011-03-25 02:03:48 [5106] [10] DEBUG: short_message: 2011-03-25 02:03:48 [5106] [10] DEBUG: Octet string at 0xc8b00e0: 2011-03-25 02:03:48 [5106] [10] DEBUG: len: 165 2011-03-25 02:03:48 [5106] [10] DEBUG: size: 166 2011-03-25 02:03:48 [5106] [10] DEBUG: immutable: 0 2011-03-25 02:03:48 [5106] [10] DEBUG: data: 69 64 3a 31 33 30 30 39 38 39 38 31 37 36 36 36 id:1300989817666 2011-03-25 02:03:48 [5106] [10] DEBUG: data: 31 38 33 30 34 30 32 20 73 75 62 3a 30 30 31 20 1830402 sub:001 2011-03-25 02:03:48 [5106] [10] DEBUG: data: 64 6c 76 72 64 3a 30 30 31 20 73 75 62 6d 69 74 dlvrd:001 submit 2011-03-25 02:03:48 [5106] [10] DEBUG: data: 20 64 61 74 65 3a 31 31 30 33 32 34 31 39 30 33 date:1103241903 2011-03-25 02:03:48 [5106] [10] DEBUG: data: 20 64 6f 6e 65 20 64 61 74 65 3a 31 31 30 33 32 done date:11032 2011-03-25 02:03:48 [5106] [10] DEBUG: data: 34 31 39 30 33 20 73 74 61 74 3a 44 45 4c 49 56 41903 stat:DELIV 2011-03-25 02:03:48 [5106] [10] DEBUG: data: 52 44 20 65 72 72 3a 30 30 30 20 74 65 78 74 3a RD err:000 text: 2011-03-25 02:03:48 [5106] [10] DEBUG: data: 20 4d 43 43 3a 35 32 35 20 4d 4e 43 3a 30 31 0a MCC:525 MNC:01. 2011-03-25 02:03:48 [5106] [10] DEBUG: data: 53 4d 53 43 52 65 63 65 69 70 74 4d 73 67 49 64 SMSCReceiptMsgId 2011-03-25 02:03:48 [5106] [10] DEBUG: data: 3a 31 33 30 30 39 38 39 38 31 37 36 36 36 31 38 :130098981766618 2011-03-25 02:03:48 [5106] [10] DEBUG: data: 33 30 34 30 32 30402 2011-03-25 02:03:48 [5106] [10] DEBUG: Octet string dump ends. 2011-03-25 02:03:48 [5106] [10] DEBUG: SMPP PDU dump ends. 2011-03-25 02:03:48 [5106] [10] DEBUG: SMPP[MY-SMPP-CONNECTION] handle_pdu, got DLR 2011-03-25 02:03:48 [5106] [10] DEBUG: DLR[mysql]: Looking for DLR smsc= MY-SMPP-CONNECTION, ts=13009898176661830402, dst=999999999, type=1 2011-03-25 02:03:48 [5106] [10] DEBUG: sql: SELECT `mask`, `service`, `url`, `source`, `destination`, `boxc_id` FROM `smsgw_kannel_sms_dlr` WHERE `smsc`=? AND `timestamp`=? LIMIT 1 2011-03-25 02:03:48 [5106] [10] DEBUG: column=mask buffer_type=253 max_length=0 length=10 2011-03-25 02:03:48 [5106] [10] DEBUG: column=service buffer_type=253 max_length=0 length=50 2011-03-25 02:03:48 [5106] [10] DEBUG: column=url buffer_type=253 max_length=0 length=255 2011-03-25 02:03:48 [5106] [10] DEBUG: column=source buffer_type=253 max_length=0 length=16 2011-03-25 02:03:48 [5106] [10] DEBUG: column=destination buffer_type=253 max_length=0 length=16 2011-03-25 02:03:48 [5106] [10] DEBUG: column=boxc_id buffer_type=253 max_length=0 length=50 2011-03-25 02:03:48 [5106] [10] DEBUG: DLR[mysql]: created DLR message for URL <> 2011-03-25 02:03:48 [5106] [10] DEBUG: removing DLR from database 2011-03-25 02:03:48 [5106] [10] DEBUG: sql: DELETE FROM `smsgw_kannel_sms_dlr` WHERE `smsc`=? AND `timestamp`=? LIMIT 1 2011-03-25 02:03:48 [5106] [10] DEBUG: new group created `smpp' 2011-03-25 02:03:48 [5106] [10] DEBUG: group=`smpp' key=`dlr_err' value=`000' 3. When the deliver_sm PDU arrives for the first subsequent message parts, they're not found in the database (as they weren't created there in the first place!) and Kannel throws an error: 2011-03-25 02:03:56 [5106] [10] DEBUG: SMPP[MY-SMPP-CONNECTION]: Got PDU: 2011-03-25 02:03:56 [5106] [10] DEBUG: SMPP PDU 0xc8ad960 dump: 2011-03-25 02:03:56 [5106] [10] DEBUG: type_name: deliver_sm 2011-03-25 02:03:56 [5106] [10] DEBUG: command_id: 5 = 0x00000005 2011-03-25 02:03:56 [5106] [10] DEBUG: command_status: 0 = 0x00000000 2011-03-25 02:03:56 [5106] [10] DEBUG: sequence_number: 9 = 0x00000009 2011-03-25 02:03:56 [5106] [10] DEBUG: service_type: NULL 2011-03-25 02:03:56 [5106] [10] DEBUG: source_addr_ton: 0 = 0x00000000 2011-03-25 02:03:56 [5106] [10] DEBUG: source_addr_npi: 0 = 0x00000000 2011-03-25 02:03:56 [5106] [10] DEBUG: source_addr: "999999999" 2011-03-25 02:03:56 [5106] [10] DEBUG: dest_addr_ton: 0 = 0x00000000 2011-03-25 02:03:56 [5106] [10] DEBUG: dest_addr_npi: 0 = 0x00000000 2011-03-25 02:03:56 [5106] [10] DEBUG: destination_addr: "test" 2011-03-25 02:03:56 [5106] [10] DEBUG: esm_class: 4 = 0x00000004 2011-03-25 02:03:56 [5106] [10] DEBUG: protocol_id: 0 = 0x00000000 2011-03-25 02:03:56 [5106] [10] DEBUG: priority_flag: 0 = 0x00000000 2011-03-25 02:03:56 [5106] [10] DEBUG: schedule_delivery_time: NULL 2011-03-25 02:03:56 [5106] [10] DEBUG: validity_period: NULL 2011-03-25 02:03:56 [5106] [10] DEBUG: registered_delivery: 0 = 0x00000000 2011-03-25 02:03:56 [5106] [10] DEBUG: replace_if_present_flag: 0 = 0x00000000 2011-03-25 02:03:56 [5106] [10] DEBUG: data_coding: 0 = 0x00000000 2011-03-25 02:03:56 [5106] [10] DEBUG: sm_default_msg_id: 0 = 0x00000000 2011-03-25 02:03:56 [5106] [10] DEBUG: sm_length: 165 = 0x000000a5 2011-03-25 02:03:56 [5106] [10] DEBUG: short_message: 2011-03-25 02:03:56 [5106] [10] DEBUG: Octet string at 0xc8d0c80: 2011-03-25 02:03:56 [5106] [10] DEBUG: len: 165 2011-03-25 02:03:56 [5106] [10] DEBUG: size: 166 2011-03-25 02:03:56 [5106] [10] DEBUG: immutable: 0 2011-03-25 02:03:56 [5106] [10] DEBUG: data: 69 64 3a 31 33 30 30 39 38 39 38 31 37 39 33 34 id:1300989817934 2011-03-25 02:03:56 [5106] [10] DEBUG: data: 31 38 34 30 34 30 32 20 73 75 62 3a 30 30 31 20 1840402 sub:001 2011-03-25 02:03:56 [5106] [10] DEBUG: data: 64 6c 76 72 64 3a 30 30 31 20 73 75 62 6d 69 74 dlvrd:001 submit 2011-03-25 02:03:56 [5106] [10] DEBUG: data: 20 64 61 74 65 3a 31 31 30 33 32 34 31 39 30 33 date:1103241903 2011-03-25 02:03:56 [5106] [10] DEBUG: data: 20 64 6f 6e 65 20 64 61 74 65 3a 31 31 30 33 32 done date:11032 2011-03-25 02:03:56 [5106] [10] DEBUG: data: 34 31 39 30 33 20 73 74 61 74 3a 44 45 4c 49 56 41903 stat:DELIV 2011-03-25 02:03:56 [5106] [10] DEBUG: data: 52 44 20 65 72 72 3a 30 30 30 20 74 65 78 74 3a RD err:000 text: 2011-03-25 02:03:56 [5106] [10] DEBUG: data: 20 4d 43 43 3a 35 32 35 20 4d 4e 43 3a 30 31 0a MCC:525 MNC:01. 2011-03-25 02:03:56 [5106] [10] DEBUG: data: 53 4d 53 43 52 65 63 65 69 70 74 4d 73 67 49 64 SMSCReceiptMsgId 2011-03-25 02:03:56 [5106] [10] DEBUG: data: 3a 31 33 30 30 39 38 39 38 31 37 39 33 34 31 38 :130098981793418 2011-03-25 02:03:56 [5106] [10] DEBUG: data: 34 30 34 30 32 40402 2011-03-25 02:03:56 [5106] [10] DEBUG: Octet string dump ends. 2011-03-25 02:03:56 [5106] [10] DEBUG: SMPP PDU dump ends. 2011-03-25 02:03:56 [5106] [10] DEBUG: SMPP[MY-SMPP-CONNECTION] handle_pdu, got DLR 2011-03-25 02:03:56 [5106] [10] DEBUG: DLR[mysql]: Looking for DLR smsc= MY-SMPP-CONNECTION, ts=13009898179341840402, dst=999999999, type=1 2011-03-25 02:03:56 [5106] [10] DEBUG: sql: SELECT `mask`, `service`, `url`, `source`, `destination`, `boxc_id` FROM ` smsgw_kannel_sms_dlr` WHERE `smsc`=? AND `timestamp`=? LIMIT 1 2011-03-25 02:03:56 [5106] [10] DEBUG: column=mask buffer_type=253 max_length=0 length=10 2011-03-25 02:03:56 [5106] [10] DEBUG: column=service buffer_type=253 max_length=0 length=50 2011-03-25 02:03:56 [5106] [10] DEBUG: column=url buffer_type=253 max_length=0 length=255 2011-03-25 02:03:56 [5106] [10] DEBUG: column=source buffer_type=253 max_length=0 length=16 2011-03-25 02:03:56 [5106] [10] DEBUG: column=destination buffer_type=253 max_length=0 length=16 2011-03-25 02:03:56 [5106] [10] DEBUG: column=boxc_id buffer_type=253 max_length=0 length=50 2011-03-25 02:03:56 [5106] [10] WARNING: DLR[mysql]: DLR from SMSC<MY-SMPP-CONNECTION > for DST<999999999> not found. 2011-03-25 02:03:56 [5106] [10] ERROR: SMPP[MY-SMPP-CONNECTION]: got DLR but could not find message or was not interested in it id<13009898179341840402> dst<999999999>, type<1> Can anyone shed some light on this behaviour? I've tried this with messages injected via sqlbox and via smsbox/sendsms and both exhibit exactly the same issue. There's another thread on a similar topic (http://www.mail-archive.com/users@kannel.org/msg20976.html) but it seems that my issue is slightly different in that Kannel isn't even creating the second and subsequent message DLRs for matching, so it gets upset when they arrive. Thanks, Toby.
