Hi That is the way kannel handles dlr for concatenated messages. There has been several threads regarding how to improve this but nothing has been done.
|-----------------------------------------------------------------------------------------------------------------| Envíe y Reciba Datos y mensajes de Texto (SMS) hacia y desde cualquier celular y Nextel en el Perú, México y en mas de 180 paises. Use aplicaciones 2 vias via SMS y GPRS online Visitenos en www.perusms.NET www.smsglobal.com.mx y www.pravcom.com On Thu, Mar 24, 2011 at 1:29 PM, Toby Phipps <[email protected]> wrote: > 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/[email protected]/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. > > > >
