Hi Alvaro, Thanks for the feedback. Any insight into why it was implemented this way? i.e. is there reason why each of the submit_sm_resp PDUs shouldn't generate a separate DLR in the DB? The only reason I can come up with offhand is that the current way probably handles misbehaving SMPP servers better - servers that send one DLR per concatenated message rather than per part. However, the current (broken, IMHO) behaviour could easily be maintained with a config parameter.
Before I scope a patch to address this, any comments or disagreements? Also, I haven't tried this with memory-only DLRs - is this an issue limited to SQL DLR storage? From looking at my logs, it seems that a DLR is indeed created in memory for the second and subsequent message parts, just not written to the DB. Thanks, Toby -----Original Message----- From: Alvaro Cornejo [mailto:cornejo.alv...@gmail.com] Sent: Friday, March 25, 2011 1:47 AM To: Toby Phipps Cc: users@kannel.org Subject: Re: DLRs for concatenated messages 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 <toby.phi...@nexmedia.com.sg> 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/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. > > > >
