Re: unlocked_try_write returning 1: OK or not OK (wrong sequence number issue)
Alexander Malysh <[email protected]>
| Newsgroups | gmane.comp.mobile.kannel.devel |
|---|---|
| Message-ID | <[email protected]> |
Hi, I don't see how my patch is related to you issue. As far as I see ,this is not Kannel issue. Kannel does what you ask... This is SMSC issue because I see in your logs that Kannel was able to send messages without any error and SMSC doesn't answer in time. Then SMSC sent submit_sm_resp and even DLR _without_ noticing that ESME already closed connection. In order to avoid such situations try to increase: wait-ack timeout to say 5 minutes and see if this helps. Alex Am 15.11.2012 um 18:36 schrieb spameden <[email protected]>: > Hi, I've experienced today the similar issue when there was a problem with one of the SMSCs and some of the MT's were re-submitted for sending. > > Here is a link to the original issue: > > http://www.kannel.org/pipermail/devel/2009-April/002368.html > > http://www.kannel.org/pipermail/users/2009-March/006567.html > > The fix is https://redmine.kannel.org/projects/kannel/repository/diff?rev=4723&rev_to=4722 submitted by Alexander. > > I'm using r5001 revision from SVN. > > I believe the issue is still here, because I'm judging on the SMSC logs and there was 3 messages submitted instead of 1 while there was some problems with smsc. > > Basically we have multiple connections to the same server with different logins (login, login:6, login:8). > > If kannel picks up a message and tries to send it through login link it fails for some reason it sleeps for wait-ack interval (60 sec by default) and resends message again. > > Because we are using load-balancing (i.e. we have allowed-smsc-id=mysmsc, preferred-smsc-id=mysmsc set for all three links) message is being queued to other link (login:6). > > After it fails 2nd time on login:6 it's being queued on the third link (login:8). After smsc starts working we are getting 3 submitted messages instead of 1. Correct me if I'm wrong in my explanation. > > Here are logs from smsc: > [2012-11-15 12:27:06.371] INFO - [login] client request: (submit: (pdu: 206 4 0 142) > [2012-11-15 12:27:06.526] INFO - [login] server response: (submit_resp: (pdu: 0 80000004 0 142) 170336247 ) > [2012-11-15 12:27:32.205] INFO - [login:6] client request: (submit: (pdu: 206 4 0 1664) (addr: 5 0 Pomosh) (addr: 1 1 1234567) > [2012-11-15 12:27:32.273] INFO - [login:6] server response: (submit_resp: (pdu: 0 80000004 0 1664) 170387537 ) > [2012-11-15 12:29:05.431] INFO - [login:8] client request: (submit: (pdu: 206 4 0 194745) (addr: 5 0 Pomosh) (addr: 1 1 1234567) > [2012-11-15 12:29:05.495] INFO - [login:8] server response: (submit_resp: (pdu: 0 80000004 0 194745) 170566615 ) > > 142 is the seq number submitted to login link. > 170336247 -- smsc message ID for login link > sender is Pomosh, receiver is 1234567 > > 1664 seq number for login:6 > 170387537 - message ID for login:6 > > 194745 seq number for login:8 > 170566615 - message ID for login:8 > > Here are logs from kannel: > > login link: > > First time we send through login link: > 2012-11-15 12:20:43 [20481] [6] DEBUG: SMPP[login]: Sending PDU: > 2012-11-15 12:20:43 [20481] [6] DEBUG: SMPP PDU 0xc437d20 dump: > 2012-11-15 12:20:43 [20481] [6] DEBUG: type_name: submit_sm > 2012-11-15 12:20:43 [20481] [6] DEBUG: command_id: 4 = 0x00000004 > 2012-11-15 12:20:43 [20481] [6] DEBUG: command_status: 0 = 0x00000000 > 2012-11-15 12:20:43 [20481] [6] DEBUG: sequence_number: 694418 = 0x000a9892 > 2012-11-15 12:20:43 [20481] [6] DEBUG: service_type: NULL > 2012-11-15 12:20:43 [20481] [6] DEBUG: source_addr_ton: 5 = 0x00000005 > 2012-11-15 12:20:43 [20481] [6] DEBUG: source_addr_npi: 0 = 0x00000000 > 2012-11-15 12:20:43 [20481] [6] DEBUG: source_addr: "Pomosh" > 2012-11-15 12:20:43 [20481] [6] DEBUG: dest_addr_ton: 1 = 0x00000001 > 2012-11-15 12:20:43 [20481] [6] DEBUG: dest_addr_npi: 1 = 0x00000001 > 2012-11-15 12:20:43 [20481] [6] DEBUG: destination_addr: "1234567" > 2012-11-15 12:20:43 [20481] [6] DEBUG: esm_class: 3 = 0x00000003 > 2012-11-15 12:20:43 [20481] [6] DEBUG: protocol_id: 0 = 0x00000000 > 2012-11-15 12:20:43 [20481] [6] DEBUG: priority_flag: 0 = 0x00000000 > 2012-11-15 12:20:43 [20481] [6] DEBUG: schedule_delivery_time: NULL > 2012-11-15 12:20:43 [20481] [6] DEBUG: validity_period: "121115092043000+" > 2012-11-15 12:20:43 [20481] [6] DEBUG: registered_delivery: 1 = 0x00000001 > 2012-11-15 12:20:43 [20481] [6] DEBUG: replace_if_present_flag: 0 = 0x00000000 > 2012-11-15 12:20:43 [20481] [6] DEBUG: data_coding: 8 = 0x00000008 > 2012-11-15 12:20:43 [20481] [6] DEBUG: sm_default_msg_id: 0 = 0x00000000 > 2012-11-15 12:20:43 [20481] [6] DEBUG: sm_length: 140 = 0x0000008c > 2012-11-15 12:20:43 [20481] [6] DEBUG: short_message: > 2012-11-15 12:20:43 [20481] [6] DEBUG: Octet string at 0xc201730: > 2012-11-15 12:20:43 [20481] [6] DEBUG: len: 140 > 2012-11-15 12:20:43 [20481] [6] DEBUG: size: 141 > 2012-11-15 12:20:43 [20481] [6] DEBUG: immutable: 0 > 2012-11-15 12:20:43 [20481] [6] DEBUG: data: 04 10 04 32 04 42 04 3e 04 4e 04 40 04 38 04 41 ...2.B.>[email protected] > 2012-11-15 12:20:43 [20481] [6] DEBUG: data: 04 42 00 2e 04 1f 04 3e 04 3c 04 3e 04 49 04 4c .B.....>.<.>.I.L > 2012-11-15 12:20:43 [20481] [6] DEBUG: data: 00 20 04 3f 04 40 04 38 00 20 04 14 04 22 04 1f . [email protected]. ...".. > 2012-11-15 12:20:43 [20481] [6] DEBUG: data: 00 2e 04 12 04 3e 04 37 04 32 04 40 04 30 04 42 .....>[email protected] > 2012-11-15 12:20:43 [20481] [6] DEBUG: data: 00 20 04 32 04 3e 04 34 04 38 04 42 00 2e 00 2d . .2.>.4.8.B...- > 2012-11-15 12:20:43 [20481] [6] DEBUG: data: 04 45 00 20 04 3f 04 40 04 30 04 32 00 2e 04 21 .E. [email protected]...! > 2012-11-15 12:20:43 [20481] [6] DEBUG: data: 04 42 04 40 04 30 04 45 04 3e 04 32 04 4b 04 35 [email protected].>.2.K.5 > 2012-11-15 12:20:43 [20481] [6] DEBUG: data: 00 20 04 41 04 3f 04 3e 04 40 04 4b 00 2e 00 32 . .A.?.>[email protected] > 2012-11-15 12:20:43 [20481] [6] DEBUG: data: 00 30 00 31 00 38 00 30 00 31 00 38 .0.1.8.0.1.8 > 2012-11-15 12:20:43 [20481] [6] DEBUG: Octet string dump ends. > 2012-11-15 12:20:43 [20481] [6] DEBUG: SMPP PDU dump ends. > > We had no ACK message from SMSC so kannel warns about this: > 2012-11-15 12:21:45 [20481] [6] WARNING: SMPP[login]: Not ACKED message found, will retransmit. SENT<62>sec. ago, SEQ<694418>, DST<1234567> > > Resends the message (because of the queue): > 2012-11-15 12:24:46 [17068] [6] DEBUG: SMPP[login]: Sending PDU: > 2012-11-15 12:24:46 [17068] [6] DEBUG: SMPP PDU 0x7fe15c056f00 dump: > 2012-11-15 12:24:46 [17068] [6] DEBUG: type_name: submit_sm > 2012-11-15 12:24:46 [17068] [6] DEBUG: command_id: 4 = 0x00000004 > 2012-11-15 12:24:46 [17068] [6] DEBUG: command_status: 0 = 0x00000000 > 2012-11-15 12:24:46 [17068] [6] DEBUG: sequence_number: 142 = 0x0000008e > 2012-11-15 12:24:46 [17068] [6] DEBUG: service_type: NULL > 2012-11-15 12:24:46 [17068] [6] DEBUG: source_addr_ton: 5 = 0x00000005 > 2012-11-15 12:24:46 [17068] [6] DEBUG: source_addr_npi: 0 = 0x00000000 > 2012-11-15 12:24:46 [17068] [6] DEBUG: source_addr: "Pomosh" > 2012-11-15 12:24:46 [17068] [6] DEBUG: dest_addr_ton: 1 = 0x00000001 > 2012-11-15 12:24:46 [17068] [6] DEBUG: dest_addr_npi: 1 = 0x00000001 > 2012-11-15 12:24:46 [17068] [6] DEBUG: destination_addr: "1234567" > 2012-11-15 12:24:46 [17068] [6] DEBUG: esm_class: 3 = 0x00000003 > 2012-11-15 12:24:46 [17068] [6] DEBUG: protocol_id: 0 = 0x00000000 > 2012-11-15 12:24:46 [17068] [6] DEBUG: priority_flag: 0 = 0x00000000 > 2012-11-15 12:24:46 [17068] [6] DEBUG: schedule_delivery_time: NULL > 2012-11-15 12:24:46 [17068] [6] DEBUG: validity_period: "121115092446000+" > 2012-11-15 12:24:46 [17068] [6] DEBUG: registered_delivery: 1 = 0x00000001 > 2012-11-15 12:24:46 [17068] [6] DEBUG: replace_if_present_flag: 0 = 0x00000000 > 2012-11-15 12:24:46 [17068] [6] DEBUG: data_coding: 8 = 0x00000008 > 2012-11-15 12:24:46 [17068] [6] DEBUG: sm_default_msg_id: 0 = 0x00000000 > 2012-11-15 12:24:46 [17068] [6] DEBUG: sm_length: 140 = 0x0000008c > 2012-11-15 12:24:46 [17068] [6] DEBUG: short_message: > 2012-11-15 12:24:46 [17068] [6] DEBUG: Octet string at 0x7fe15c05bf30: > 2012-11-15 12:24:46 [17068] [6] DEBUG: len: 140 > 2012-11-15 12:24:46 [17068] [6] DEBUG: size: 141 > 2012-11-15 12:24:46 [17068] [6] DEBUG: immutable: 0 > 2012-11-15 12:24:46 [17068] [6] DEBUG: data: 04 10 04 32 04 42 04 3e 04 4e 04 40 04 38 04 41 ...2.B.>[email protected] > 2012-11-15 12:24:46 [17068] [6] DEBUG: data: 04 42 00 2e 04 1f 04 3e 04 3c 04 3e 04 49 04 4c .B.....>.<.>.I.L > 2012-11-15 12:24:46 [17068] [6] DEBUG: data: 00 20 04 3f 04 40 04 38 00 20 04 14 04 22 04 1f . [email protected]. ...".. > 2012-11-15 12:24:46 [17068] [6] DEBUG: data: 00 2e 04 12 04 3e 04 37 04 32 04 40 04 30 04 42 .....>[email protected] > 2012-11-15 12:24:46 [17068] [6] DEBUG: data: 00 20 04 32 04 3e 04 34 04 38 04 42 00 2e 00 2d . .2.>.4.8.B...- > 2012-11-15 12:24:46 [17068] [6] DEBUG: data: 04 45 00 20 04 3f 04 40 04 30 04 32 00 2e 04 21 .E. [email protected]...! > 2012-11-15 12:24:46 [17068] [6] DEBUG: data: 04 42 04 40 04 30 04 45 04 3e 04 32 04 4b 04 35 [email protected].>.2.K.5 > 2012-11-15 12:24:46 [17068] [6] DEBUG: data: 00 20 04 41 04 3f 04 3e 04 40 04 4b 00 2e 00 32 . .A.?.>[email protected] > 2012-11-15 12:24:46 [17068] [6] DEBUG: data: 00 30 00 31 00 38 00 30 00 31 00 38 .0.1.8.0.1.8 > 2012-11-15 12:24:46 [17068] [6] DEBUG: Octet string dump ends. > 2012-11-15 12:24:46 [17068] [6] DEBUG: SMPP PDU dump ends. > 2012-11-15 12:26:46 [17068] [6] WARNING: SMPP[login]: Not ACKED message found, will retransmit. SENT<120>sec. ago, SEQ<142>, DST<1234567> > > The weird thing I do not see submit_sm on 2012-11-15 12:27:06 through login, only submit_sm_resp for that message: > 2012-11-15 12:27:06 [17068] [6] DEBUG: SMPP PDU dump ends. > 2012-11-15 12:27:06 [17068] [6] DEBUG: SMPP[login]: Got PDU: > 2012-11-15 12:27:06 [17068] [6] DEBUG: SMPP PDU 0x4ee9300 dump: > 2012-11-15 12:27:06 [17068] [6] DEBUG: type_name: submit_sm_resp > 2012-11-15 12:27:06 [17068] [6] DEBUG: command_id: 2147483652 = 0x80000004 > 2012-11-15 12:27:06 [17068] [6] DEBUG: command_status: 0 = 0x00000000 > 2012-11-15 12:27:06 [17068] [6] DEBUG: sequence_number: 142 = 0x0000008e > 2012-11-15 12:27:06 [17068] [6] DEBUG: message_id: "170336247" > 2012-11-15 12:27:06 [17068] [6] DEBUG: SMPP PDU dump ends. > > That's probably the reason why kannel warns about wrong sequence number, because there was no submit_sm with that sequence: > 2012-11-15 12:27:06 [17068] [6] WARNING: SMPP[login]: SMSC sent submit_sm_resp with wrong sequence number 0x0000008e > > DELIVERY report for login link for that message: > 2012-11-15 12:34:52 [17068] [6] DEBUG: SMPP[login]: Got PDU: > 2012-11-15 12:34:52 [17068] [6] DEBUG: SMPP PDU 0x7fe1245759c0 dump: > 2012-11-15 12:34:52 [17068] [6] DEBUG: type_name: deliver_sm > 2012-11-15 12:34:52 [17068] [6] DEBUG: command_id: 5 = 0x00000005 > 2012-11-15 12:34:52 [17068] [6] DEBUG: command_status: 0 = 0x00000000 > 2012-11-15 12:34:52 [17068] [6] DEBUG: sequence_number: 3685058 = 0x00383ac2 > 2012-11-15 12:34:52 [17068] [6] DEBUG: service_type: NULL > 2012-11-15 12:34:52 [17068] [6] DEBUG: source_addr_ton: 0 = 0x00000000 > 2012-11-15 12:34:52 [17068] [6] DEBUG: source_addr_npi: 0 = 0x00000000 > 2012-11-15 12:34:52 [17068] [6] DEBUG: source_addr: "1234567" > 2012-11-15 12:34:52 [17068] [6] DEBUG: dest_addr_ton: 0 = 0x00000000 > 2012-11-15 12:34:52 [17068] [6] DEBUG: dest_addr_npi: 0 = 0x00000000 > 2012-11-15 12:34:52 [17068] [6] DEBUG: destination_addr: "Pomosh" > 2012-11-15 12:34:52 [17068] [6] DEBUG: esm_class: 4 = 0x00000004 > 2012-11-15 12:34:52 [17068] [6] DEBUG: protocol_id: 0 = 0x00000000 > 2012-11-15 12:34:52 [17068] [6] DEBUG: priority_flag: 0 = 0x00000000 > 2012-11-15 12:34:52 [17068] [6] DEBUG: schedule_delivery_time: NULL > 2012-11-15 12:34:52 [17068] [6] DEBUG: validity_period: NULL > 2012-11-15 12:34:52 [17068] [6] DEBUG: registered_delivery: 0 = 0x00000000 > 2012-11-15 12:34:52 [17068] [6] DEBUG: replace_if_present_flag: 0 = 0x00000000 > 2012-11-15 12:34:52 [17068] [6] DEBUG: data_coding: 0 = 0x00000000 > 2012-11-15 12:34:52 [17068] [6] DEBUG: sm_default_msg_id: 0 = 0x00000000 > 2012-11-15 12:34:52 [17068] [6] DEBUG: sm_length: 119 = 0x00000077 > 2012-11-15 12:34:52 [17068] [6] DEBUG: short_message: > 2012-11-15 12:34:52 [17068] [6] DEBUG: Octet string at 0x7fe12430e000: > 2012-11-15 12:34:52 [17068] [6] DEBUG: len: 119 > 2012-11-15 12:34:52 [17068] [6] DEBUG: size: 120 > 2012-11-15 12:34:52 [17068] [6] DEBUG: immutable: 0 > 2012-11-15 12:34:52 [17068] [6] DEBUG: data: 69 64 3a 31 37 30 33 33 36 32 34 37 20 73 75 62 id:170336247 sub > 2012-11-15 12:34:52 [17068] [6] DEBUG: data: 3a 30 30 31 20 64 6c 76 72 64 3a 30 30 31 20 73 :001 dlvrd:001 s > 2012-11-15 12:34:52 [17068] [6] DEBUG: data: 75 62 6d 69 74 20 64 61 74 65 3a 31 32 31 31 31 ubmit date:12111 > 2012-11-15 12:34:52 [17068] [6] DEBUG: data: 35 31 32 32 37 20 64 6f 6e 65 20 64 61 74 65 3a 51227 done date: > 2012-11-15 12:34:52 [17068] [6] DEBUG: data: 31 32 31 31 31 35 31 32 33 34 20 73 74 61 74 3a 1211151234 stat: > 2012-11-15 12:34:52 [17068] [6] DEBUG: data: 44 45 4c 49 56 52 44 20 65 72 72 3a 30 20 74 65 DELIVRD err:0 te > 2012-11-15 12:34:52 [17068] [6] DEBUG: data: 78 74 3a 04 10 04 32 04 42 04 3e 04 4e 04 40 04 xt:...2.B.>.N.@. > 2012-11-15 12:34:52 [17068] [6] DEBUG: data: 38 04 41 04 42 00 2e 8.A.B.. > 2012-11-15 12:34:52 [17068] [6] DEBUG: Octet string dump ends. > 2012-11-15 12:34:52 [17068] [6] DEBUG: message_state: 2 = 0x00000002 > 2012-11-15 12:34:52 [17068] [6] DEBUG: receipted_message_id: "170336247" > 2012-11-15 12:34:52 [17068] [6] DEBUG: SMPP PDU dump ends. > 2012-11-15 12:34:52 [17068] [6] DEBUG: SMPP PDU dump ends. > 2012-11-15 12:34:52 [17068] [6] DEBUG: SMPP[login] handle_pdu, got DLR > 2012-11-15 12:34:52 [17068] [6] DEBUG: DLR[mysql]: Looking for DLR smsc=login, ts=170336247, dst=1234567, type=1 > 2012-11-15 12:34:52 [17068] [6] DEBUG: sql: SELECT `mask`, `service`, `url`, `source`, `destination`, `boxc`, `parts_num` FROM `dlr` WHERE `smsc`=? AND `ts`=? LIMIT 1 > 2012-11-15 12:34:52 [17068] [6] DEBUG: column=mask buffer_type=3 max_length=0 length=10 > 2012-11-15 12:34:52 [17068] [6] DEBUG: column=service buffer_type=253 max_length=0 length=120 > 2012-11-15 12:34:52 [17068] [6] DEBUG: column=url buffer_type=253 max_length=0 length=765 > 2012-11-15 12:34:52 [17068] [6] DEBUG: column=source buffer_type=253 max_length=0 length=120 > 2012-11-15 12:34:52 [17068] [6] DEBUG: column=destination buffer_type=253 max_length=0 length=120 > 2012-11-15 12:34:52 [17068] [6] DEBUG: column=boxc buffer_type=253 max_length=0 length=120 > 2012-11-15 12:34:52 [17068] [6] DEBUG: column=parts_num buffer_type=1 max_length=0 length=1 > 2012-11-15 12:34:52 [17068] [6] WARNING: DLR[mysql]: DLR from SMSC<login> for DST<1234567> not found. > 2012-11-15 12:34:52 [17068] [6] ERROR: SMPP[login]: got DLR but could not find message or was not interested in it id<170336247> dst<1234567>, type<1> > 2012-11-15 12:34:52 [17068] [6] DEBUG: SMPP[login]: Sending PDU: > 2012-11-15 12:34:52 [17068] [6] DEBUG: SMPP PDU 0x7fe124574f50 dump: > 2012-11-15 12:34:52 [17068] [6] DEBUG: type_name: deliver_sm_resp > 2012-11-15 12:34:52 [17068] [6] DEBUG: command_id: 2147483653 = 0x80000005 > 2012-11-15 12:34:52 [17068] [6] DEBUG: command_status: 0 = 0x00000000 > 2012-11-15 12:34:52 [17068] [6] DEBUG: sequence_number: 3685058 = 0x00383ac2 > 2012-11-15 12:34:52 [17068] [6] DEBUG: message_id: NULL > 2012-11-15 12:34:52 [17068] [6] DEBUG: SMPP PDU dump ends. > > login:6 link: > 2012-11-15 12:27:16 [17068] [8] DEBUG: SMPP PDU 0x7fe16088c450 dump: > 2012-11-15 12:27:16 [17068] [8] DEBUG: type_name: submit_sm > 2012-11-15 12:27:16 [17068] [8] DEBUG: command_id: 4 = 0x00000004 > 2012-11-15 12:27:16 [17068] [8] DEBUG: command_status: 0 = 0x00000000 > 2012-11-15 12:27:16 [17068] [8] DEBUG: sequence_number: 1664 = 0x00000680 > 2012-11-15 12:27:16 [17068] [8] DEBUG: service_type: NULL > 2012-11-15 12:27:16 [17068] [8] DEBUG: source_addr_ton: 5 = 0x00000005 > 2012-11-15 12:27:16 [17068] [8] DEBUG: source_addr_npi: 0 = 0x00000000 > 2012-11-15 12:27:16 [17068] [8] DEBUG: source_addr: "Pomosh" > 2012-11-15 12:27:16 [17068] [8] DEBUG: dest_addr_ton: 1 = 0x00000001 > 2012-11-15 12:27:16 [17068] [8] DEBUG: dest_addr_npi: 1 = 0x00000001 > 2012-11-15 12:27:16 [17068] [8] DEBUG: destination_addr: "1234567" > 2012-11-15 12:27:16 [17068] [8] DEBUG: esm_class: 3 = 0x00000003 > 2012-11-15 12:27:16 [17068] [8] DEBUG: protocol_id: 0 = 0x00000000 > 2012-11-15 12:27:16 [17068] [8] DEBUG: priority_flag: 0 = 0x00000000 > 2012-11-15 12:27:16 [17068] [8] DEBUG: schedule_delivery_time: NULL > 2012-11-15 12:27:16 [17068] [8] DEBUG: validity_period: "121115092716000+" > 2012-11-15 12:27:16 [17068] [8] DEBUG: registered_delivery: 1 = 0x00000001 > 2012-11-15 12:27:16 [17068] [8] DEBUG: replace_if_present_flag: 0 = 0x00000000 > 2012-11-15 12:27:16 [17068] [8] DEBUG: data_coding: 8 = 0x00000008 > 2012-11-15 12:27:16 [17068] [8] DEBUG: sm_default_msg_id: 0 = 0x00000000 > 2012-11-15 12:27:16 [17068] [8] DEBUG: sm_length: 140 = 0x0000008c > 2012-11-15 12:27:16 [17068] [8] DEBUG: short_message: > 2012-11-15 12:27:16 [17068] [8] DEBUG: Octet string at 0x7fe16109d0b0: > 2012-11-15 12:27:16 [17068] [8] DEBUG: len: 140 > 2012-11-15 12:27:16 [17068] [8] DEBUG: size: 141 > 2012-11-15 12:27:16 [17068] [8] DEBUG: immutable: 0 > 2012-11-15 12:27:16 [17068] [8] DEBUG: data: 04 10 04 32 04 42 04 3e 04 4e 04 40 04 38 04 41 ...2.B.>[email protected] > 2012-11-15 12:27:16 [17068] [8] DEBUG: data: 04 42 00 2e 04 1f 04 3e 04 3c 04 3e 04 49 04 4c .B.....>.<.>.I.L > 2012-11-15 12:27:16 [17068] [8] DEBUG: data: 00 20 04 3f 04 40 04 38 00 20 04 14 04 22 04 1f . [email protected]. ...".. > 2012-11-15 12:27:16 [17068] [8] DEBUG: data: 00 2e 04 12 04 3e 04 37 04 32 04 40 04 30 04 42 .....>[email protected] > 2012-11-15 12:27:16 [17068] [8] DEBUG: data: 00 20 04 32 04 3e 04 34 04 38 04 42 00 2e 00 2d . .2.>.4.8.B...- > 2012-11-15 12:27:16 [17068] [8] DEBUG: data: 04 45 00 20 04 3f 04 40 04 30 04 32 00 2e 04 21 .E. [email protected]...! > 2012-11-15 12:27:16 [17068] [8] DEBUG: data: 04 42 04 40 04 30 04 45 04 3e 04 32 04 4b 04 35 [email protected].>.2.K.5 > 2012-11-15 12:27:16 [17068] [8] DEBUG: data: 00 20 04 41 04 3f 04 3e 04 40 04 4b 00 2e 00 32 . .A.?.>[email protected] > 2012-11-15 12:27:16 [17068] [8] DEBUG: data: 00 30 00 31 00 38 00 30 00 31 00 38 .0.1.8.0.1.8 > 2012-11-15 12:27:16 [17068] [8] DEBUG: Octet string dump ends. > 2012-11-15 12:27:16 [17068] [8] DEBUG: SMPP PDU dump ends. > 2012-11-15 12:27:16 [17068] [8] DEBUG: SMPP[login6]: Got PDU: > 2012-11-15 12:27:16 [17068] [8] DEBUG: SMPP PDU 0x7fe1610c5780 dump: > 2012-11-15 12:27:16 [17068] [8] DEBUG: type_name: submit_sm_resp > 2012-11-15 12:27:16 [17068] [8] DEBUG: command_id: 2147483652 = 0x80000004 > 2012-11-15 12:27:16 [17068] [8] DEBUG: command_status: 0 = 0x00000000 > 2012-11-15 12:27:16 [17068] [8] DEBUG: sequence_number: 1103 = 0x0000044f > 2012-11-15 12:27:16 [17068] [8] DEBUG: message_id: "170357193" > 2012-11-15 12:27:16 [17068] [8] DEBUG: SMPP PDU dump ends. > 2012-11-15 12:27:32 [17068] [8] DEBUG: SMPP PDU 0x7fe160032300 dump: > 2012-11-15 12:27:32 [17068] [8] DEBUG: type_name: submit_sm_resp > 2012-11-15 12:27:32 [17068] [8] DEBUG: command_id: 2147483652 = 0x80000004 > 2012-11-15 12:27:32 [17068] [8] DEBUG: command_status: 0 = 0x00000000 > 2012-11-15 12:27:32 [17068] [8] DEBUG: sequence_number: 1664 = 0x00000680 > 2012-11-15 12:27:32 [17068] [8] DEBUG: message_id: "170387537" > 2012-11-15 12:27:32 [17068] [8] DEBUG: SMPP PDU dump ends. > 2012-11-15 12:27:32 [17068] [8] DEBUG: DLR[mysql]: Adding DLR smsc=login6, ts=170387537, src=Pomosh, dst=1234567, mask=31, boxc=sqlbox, parts_num=1 > > DELIVERY report for login6 link for that message: > 2012-11-15 12:33:20 [17068] [8] DEBUG: SMPP[login6]: Got PDU: > 2012-11-15 12:33:20 [17068] [8] DEBUG: SMPP PDU 0x7fe124546c90 dump: > 2012-11-15 12:33:20 [17068] [8] DEBUG: type_name: deliver_sm > 2012-11-15 12:33:20 [17068] [8] DEBUG: command_id: 5 = 0x00000005 > 2012-11-15 12:33:20 [17068] [8] DEBUG: command_status: 0 = 0x00000000 > 2012-11-15 12:33:20 [17068] [8] DEBUG: sequence_number: 3670150 = 0x00380086 > 2012-11-15 12:33:20 [17068] [8] DEBUG: service_type: NULL > 2012-11-15 12:33:20 [17068] [8] DEBUG: source_addr_ton: 0 = 0x00000000 > 2012-11-15 12:33:20 [17068] [8] DEBUG: source_addr_npi: 0 = 0x00000000 > 2012-11-15 12:33:20 [17068] [8] DEBUG: source_addr: "1234567" > 2012-11-15 12:33:20 [17068] [8] DEBUG: dest_addr_ton: 0 = 0x00000000 > 2012-11-15 12:33:20 [17068] [8] DEBUG: dest_addr_npi: 0 = 0x00000000 > 2012-11-15 12:33:20 [17068] [8] DEBUG: destination_addr: "Pomosh" > 2012-11-15 12:33:20 [17068] [8] DEBUG: esm_class: 4 = 0x00000004 > 2012-11-15 12:33:20 [17068] [8] DEBUG: protocol_id: 0 = 0x00000000 > 2012-11-15 12:33:20 [17068] [8] DEBUG: priority_flag: 0 = 0x00000000 > 2012-11-15 12:33:20 [17068] [8] DEBUG: schedule_delivery_time: NULL > 2012-11-15 12:33:20 [17068] [8] DEBUG: validity_period: NULL > 2012-11-15 12:33:20 [17068] [8] DEBUG: registered_delivery: 0 = 0x00000000 > 2012-11-15 12:33:20 [17068] [8] DEBUG: replace_if_present_flag: 0 = 0x00000000 > 2012-11-15 12:33:20 [17068] [8] DEBUG: data_coding: 0 = 0x00000000 > 2012-11-15 12:33:20 [17068] [8] DEBUG: sm_default_msg_id: 0 = 0x00000000 > 2012-11-15 12:33:20 [17068] [8] DEBUG: sm_length: 119 = 0x00000077 > 2012-11-15 12:33:20 [17068] [8] DEBUG: short_message: > 2012-11-15 12:33:20 [17068] [8] DEBUG: Octet string at 0x7fe124031c70: > 2012-11-15 12:33:20 [17068] [8] DEBUG: len: 119 > 2012-11-15 12:33:20 [17068] [8] DEBUG: size: 120 > 2012-11-15 12:33:20 [17068] [8] DEBUG: immutable: 0 > 2012-11-15 12:33:20 [17068] [8] DEBUG: data: 69 64 3a 31 37 30 33 38 37 35 33 37 20 73 75 62 id:170387537 sub > 2012-11-15 12:33:20 [17068] [8] DEBUG: data: 3a 30 30 31 20 64 6c 76 72 64 3a 30 30 30 20 73 :001 dlvrd:000 s > 2012-11-15 12:33:20 [17068] [8] DEBUG: data: 75 62 6d 69 74 20 64 61 74 65 3a 31 32 31 31 31 ubmit date:12111 > 2012-11-15 12:33:20 [17068] [8] DEBUG: data: 35 31 32 32 37 20 64 6f 6e 65 20 64 61 74 65 3a 51227 done date: > 2012-11-15 12:33:20 [17068] [8] DEBUG: data: 31 32 31 31 31 35 31 32 33 33 20 73 74 61 74 3a 1211151233 stat: > 2012-11-15 12:33:20 [17068] [8] DEBUG: data: 52 45 4a 45 43 54 44 20 65 72 72 3a 30 20 74 65 REJECTD err:0 te > 2012-11-15 12:33:20 [17068] [8] DEBUG: data: 78 74 3a 04 10 04 32 04 42 04 3e 04 4e 04 40 04 xt:...2.B.>.N.@. > 2012-11-15 12:33:20 [17068] [8] DEBUG: data: 38 04 41 04 42 00 2e 8.A.B.. > 2012-11-15 12:33:20 [17068] [8] DEBUG: Octet string dump ends. > 2012-11-15 12:33:20 [17068] [8] DEBUG: message_state: 8 = 0x00000008 > 2012-11-15 12:33:20 [17068] [8] DEBUG: receipted_message_id: "170387537" > 2012-11-15 12:33:20 [17068] [8] DEBUG: SMPP PDU dump ends. > 2012-11-15 12:33:20 [17068] [8] DEBUG: SMPP[login6] handle_pdu, got DLR > 2012-11-15 12:33:20 [17068] [8] DEBUG: DLR[mysql]: Looking for DLR smsc=login6, ts=170387537, dst=1234567, type=2 > 2012-11-15 12:33:20 [17068] [8] DEBUG: sql: SELECT `mask`, `service`, `url`, `source`, `destination`, `boxc`, `parts_num` FROM `dlr` WHERE `smsc`=? AND `ts`=? LIMIT 1 > 2012-11-15 12:33:20 [17068] [8] DEBUG: column=mask buffer_type=3 max_length=0 length=10 > 2012-11-15 12:33:20 [17068] [8] DEBUG: column=service buffer_type=253 max_length=0 length=120 > 2012-11-15 12:33:20 [17068] [8] DEBUG: column=url buffer_type=253 max_length=0 length=765 > 2012-11-15 12:33:20 [17068] [8] DEBUG: column=source buffer_type=253 max_length=0 length=120 > 2012-11-15 12:33:20 [17068] [8] DEBUG: column=url buffer_type=253 max_length=0 length=765 > 2012-11-15 12:33:20 [17068] [8] DEBUG: column=source buffer_type=253 max_length=0 length=120 > 2012-11-15 12:33:20 [17068] [8] DEBUG: column=destination buffer_type=253 max_length=0 length=120 > 2012-11-15 12:33:20 [17068] [8] DEBUG: column=boxc buffer_type=253 max_length=0 length=120 > 2012-11-15 12:33:20 [17068] [8] DEBUG: column=parts_num buffer_type=1 max_length=0 length=1 > 2012-11-15 12:33:20 [17068] [8] DEBUG: DLR[mysql]: created DLR message for URL <50A4A5AC008751C1> > 2012-11-15 12:33:20 [17068] [8] DEBUG: removing DLR from database > 2012-11-15 12:33:20 [17068] [8] DEBUG: sql: DELETE FROM `dlr` WHERE `smsc`=? AND `ts`=? LIMIT 1 > 2012-11-15 12:33:20 [17068] [8] DEBUG: new group created `smpp' > 2012-11-15 12:33:20 [17068] [8] DEBUG: group=`smpp' key=`dlr_err' value=`^C' > 2012-11-15 12:33:20 [17068] [8] DEBUG: SMPP[login6]: Sending PDU: > 2012-11-15 12:33:20 [17068] [8] DEBUG: SMPP PDU 0x7fe124547f00 dump: > 2012-11-15 12:33:20 [17068] [8] DEBUG: type_name: deliver_sm_resp > 2012-11-15 12:33:20 [17068] [8] DEBUG: command_id: 2147483653 = 0x80000005 > 2012-11-15 12:33:20 [17068] [8] DEBUG: command_status: 0 = 0x00000000 > 2012-11-15 12:33:20 [17068] [8] DEBUG: sequence_number: 3670150 = 0x00380086 > 2012-11-15 12:33:20 [17068] [8] DEBUG: message_id: NULL > 2012-11-15 12:33:20 [17068] [8] DEBUG: SMPP PDU dump ends. > > login8 link: > 2012-11-15 12:22:11 [20481] [10] DEBUG: SMPP PDU dump ends. > 2012-11-15 12:22:11 [20481] [10] DEBUG: SMPP[login8]: throughput (71.00,90.00) > 2012-11-15 12:22:11 [20481] [10] DEBUG: SMPP[login8]: Manually forced source addr ton = 5, source add npi = 1 > 2012-11-15 12:22:11 [20481] [10] DEBUG: SMPP[login8]: Manually forced dest addr ton = 1, dest add npi = 1 > 2012-11-15 12:22:11 [20481] [10] DEBUG: SMPP[login8]: Sending PDU: > 2012-11-15 12:22:11 [20481] [10] DEBUG: SMPP PDU 0xc26e7c0 dump: > 2012-11-15 12:22:11 [20481] [10] DEBUG: type_name: submit_sm > 2012-11-15 12:22:11 [20481] [10] DEBUG: command_id: 4 = 0x00000004 > 2012-11-15 12:22:11 [20481] [10] DEBUG: command_status: 0 = 0x00000000 > 2012-11-15 12:22:11 [20481] [10] DEBUG: sequence_number: 194745 = 0x0002f8b9 > 2012-11-15 12:22:11 [20481] [10] DEBUG: service_type: NULL > 2012-11-15 12:22:11 [20481] [10] DEBUG: source_addr_ton: 5 = 0x00000005 > 2012-11-15 12:22:11 [20481] [10] DEBUG: source_addr_npi: 0 = 0x00000000 > 2012-11-15 12:22:11 [20481] [10] DEBUG: source_addr: "Pomosh" > 2012-11-15 12:22:11 [20481] [10] DEBUG: dest_addr_ton: 1 = 0x00000001 > 2012-11-15 12:22:11 [20481] [10] DEBUG: dest_addr_npi: 1 = 0x00000001 > 2012-11-15 12:22:11 [20481] [10] DEBUG: destination_addr: "1234567" > 2012-11-15 12:22:11 [20481] [10] DEBUG: esm_class: 3 = 0x00000003 > 2012-11-15 12:22:11 [20481] [10] DEBUG: protocol_id: 0 = 0x00000000 > 2012-11-15 12:22:11 [20481] [10] DEBUG: priority_flag: 0 = 0x00000000 > 2012-11-15 12:22:11 [20481] [10] DEBUG: schedule_delivery_time: NULL > 2012-11-15 12:22:11 [20481] [10] DEBUG: validity_period: "121115092211000+" > 2012-11-15 12:22:11 [20481] [10] DEBUG: registered_delivery: 1 = 0x00000001 > 2012-11-15 12:22:11 [20481] [10] DEBUG: replace_if_present_flag: 0 = 0x00000000 > 2012-11-15 12:22:11 [20481] [10] DEBUG: data_coding: 8 = 0x00000008 > 2012-11-15 12:22:11 [20481] [10] DEBUG: sm_default_msg_id: 0 = 0x00000000 > 2012-11-15 12:22:11 [20481] [10] DEBUG: sm_length: 140 = 0x0000008c > 2012-11-15 12:22:11 [20481] [10] DEBUG: short_message: > 2012-11-15 12:22:11 [20481] [10] DEBUG: Octet string at 0xc370420: > 2012-11-15 12:22:11 [20481] [10] DEBUG: len: 140 > 2012-11-15 12:22:11 [20481] [10] DEBUG: size: 141 > 2012-11-15 12:22:11 [20481] [10] DEBUG: immutable: 0 > 2012-11-15 12:22:11 [20481] [10] DEBUG: data: 04 10 04 32 04 42 04 3e 04 4e 04 40 04 38 04 41 ...2.B.>[email protected] > 2012-11-15 12:22:11 [20481] [10] DEBUG: data: 04 42 00 2e 04 1f 04 3e 04 3c 04 3e 04 49 04 4c .B.....>.<.>.I.L > 2012-11-15 12:22:11 [20481] [10] DEBUG: data: 00 20 04 3f 04 40 04 38 00 20 04 14 04 22 04 1f . [email protected]. ...".. > 2012-11-15 12:22:11 [20481] [10] DEBUG: data: 00 2e 04 12 04 3e 04 37 04 32 04 40 04 30 04 42 .....>[email protected] > 2012-11-15 12:22:11 [20481] [10] DEBUG: data: 00 20 04 32 04 3e 04 34 04 38 04 42 00 2e 00 2d . .2.>.4.8.B...- > 2012-11-15 12:22:11 [20481] [10] DEBUG: data: 04 45 00 20 04 3f 04 40 04 30 04 32 00 2e 04 21 .E. [email protected]...! > 2012-11-15 12:22:11 [20481] [10] DEBUG: data: 04 42 04 40 04 30 04 45 04 3e 04 32 04 4b 04 35 [email protected].>.2.K.5 > 2012-11-15 12:22:11 [20481] [10] DEBUG: data: 00 20 04 41 04 3f 04 3e 04 40 04 4b 00 2e 00 32 . .A.?.>[email protected] > 2012-11-15 12:22:11 [20481] [10] DEBUG: data: 00 30 00 31 00 38 00 30 00 31 00 38 .0.1.8.0.1.8 > 2012-11-15 12:22:11 [20481] [10] DEBUG: Octet string dump ends. > 2012-11-15 12:22:11 [20481] [10] DEBUG: SMPP PDU dump ends. > 2012-11-15 12:24:12 [20481] [10] WARNING: SMPP[login8]: Not ACKED message found, will retransmit. SENT<121>sec. ago, SEQ<194745>, DST<1234567> > > There is no re-submit as well in the logs for some reason.. > > DELIVERY report for login8 link for that message: > 2012-11-15 13:04:32 [17068] [10] DEBUG: SMPP PDU 0x15714e0 dump: > 2012-11-15 13:04:32 [17068] [10] DEBUG: type_name: deliver_sm > 2012-11-15 13:04:32 [17068] [10] DEBUG: command_id: 5 = 0x00000005 > 2012-11-15 13:04:32 [17068] [10] DEBUG: command_status: 0 = 0x00000000 > 2012-11-15 13:04:32 [17068] [10] DEBUG: sequence_number: 3956116 = 0x003c5d94 > 2012-11-15 13:04:32 [17068] [10] DEBUG: service_type: NULL > 2012-11-15 13:04:32 [17068] [10] DEBUG: source_addr_ton: 0 = 0x00000000 > 2012-11-15 13:04:32 [17068] [10] DEBUG: source_addr_npi: 0 = 0x00000000 > 2012-11-15 13:04:32 [17068] [10] DEBUG: source_addr: "1234567" > 2012-11-15 13:04:32 [17068] [10] DEBUG: dest_addr_ton: 0 = 0x00000000 > 2012-11-15 13:04:32 [17068] [10] DEBUG: dest_addr_npi: 0 = 0x00000000 > 2012-11-15 13:04:32 [17068] [10] DEBUG: destination_addr: "Pomosh" > 2012-11-15 13:04:32 [17068] [10] DEBUG: esm_class: 4 = 0x00000004 > 2012-11-15 13:04:32 [17068] [10] DEBUG: protocol_id: 0 = 0x00000000 > 2012-11-15 13:04:32 [17068] [10] DEBUG: priority_flag: 0 = 0x00000000 > 2012-11-15 13:04:32 [17068] [10] DEBUG: schedule_delivery_time: NULL > 2012-11-15 13:04:32 [17068] [10] DEBUG: validity_period: NULL > 2012-11-15 13:04:32 [17068] [10] DEBUG: registered_delivery: 0 = 0x00000000 > 2012-11-15 13:04:32 [17068] [10] DEBUG: replace_if_present_flag: 0 = 0x00000000 > 2012-11-15 13:04:32 [17068] [10] DEBUG: data_coding: 0 = 0x00000000 > 2012-11-15 13:04:32 [17068] [10] DEBUG: sm_default_msg_id: 0 = 0x00000000 > 2012-11-15 13:04:32 [17068] [10] DEBUG: sm_length: 119 = 0x00000077 > 2012-11-15 13:04:32 [17068] [10] DEBUG: short_message: > 2012-11-15 13:04:32 [17068] [10] DEBUG: Octet string at 0x23c66b0: > 2012-11-15 13:04:32 [17068] [10] DEBUG: len: 119 > 2012-11-15 13:04:32 [17068] [10] DEBUG: size: 120 > 2012-11-15 13:04:32 [17068] [10] DEBUG: immutable: 0 > 2012-11-15 13:04:32 [17068] [10] DEBUG: data: 69 64 3a 31 37 30 35 36 36 36 31 35 20 73 75 62 id:170566615 sub > 2012-11-15 13:04:32 [17068] [10] DEBUG: data: 3a 30 30 31 20 64 6c 76 72 64 3a 30 30 31 20 73 :001 dlvrd:001 s > 2012-11-15 13:04:32 [17068] [10] DEBUG: data: 75 62 6d 69 74 20 64 61 74 65 3a 31 32 31 31 31 ubmit date:12111 > 2012-11-15 13:04:32 [17068] [10] DEBUG: data: 35 31 32 32 39 20 64 6f 6e 65 20 64 61 74 65 3a 51229 done date: > 2012-11-15 13:04:32 [17068] [10] DEBUG: data: 31 32 31 31 31 35 31 33 30 34 20 73 74 61 74 3a 1211151304 stat: > 2012-11-15 13:04:32 [17068] [10] DEBUG: data: 44 45 4c 49 56 52 44 20 65 72 72 3a 30 20 74 65 DELIVRD err:0 te > 2012-11-15 13:04:32 [17068] [10] DEBUG: data: 78 74 3a 04 10 04 32 04 42 04 3e 04 4e 04 40 04 xt:...2.B.>.N.@. > 2012-11-15 13:04:32 [17068] [10] DEBUG: data: 38 04 41 04 42 00 2e 8.A.B.. > 2012-11-15 13:04:32 [17068] [10] DEBUG: Octet string dump ends. > 2012-11-15 13:04:32 [17068] [10] DEBUG: message_state: 2 = 0x00000002 > 2012-11-15 13:04:32 [17068] [10] DEBUG: receipted_message_id: "170566615" > 2012-11-15 13:04:32 [17068] [10] DEBUG: SMPP PDU dump ends. > 2012-11-15 13:04:32 [17068] [10] DEBUG: SMPP[login8] handle_pdu, got DLR > 2012-11-15 13:04:32 [17068] [10] DEBUG: DLR[mysql]: Looking for DLR smsc=login8, ts=170566615, dst=1234567, type=1 > 2012-11-15 13:04:32 [17068] [10] DEBUG: sql: SELECT `mask`, `service`, `url`, `source`, `destination`, `boxc`, `parts_num` FROM `dlr` WHERE `smsc`=? AND `ts`=? LIMIT 1 > 2012-11-15 13:04:32 [17068] [10] DEBUG: column=mask buffer_type=3 max_length=0 length=10 > 2012-11-15 13:04:32 [17068] [10] DEBUG: column=service buffer_type=253 max_length=0 length=120 > 2012-11-15 13:04:32 [17068] [10] DEBUG: column=url buffer_type=253 max_length=0 length=765 > 2012-11-15 13:04:32 [17068] [10] DEBUG: column=source buffer_type=253 max_length=0 length=120 > 2012-11-15 13:04:32 [17068] [10] DEBUG: column=destination buffer_type=253 max_length=0 length=120 > 2012-11-15 13:04:32 [17068] [10] DEBUG: column=boxc buffer_type=253 max_length=0 length=120 > 2012-11-15 13:04:32 [17068] [10] DEBUG: column=parts_num buffer_type=1 max_length=0 length=1 > 2012-11-15 13:04:32 [17068] [10] WARNING: DLR[mysql]: DLR from SMSC<login8> for DST<1234567> not found. > 2012-11-15 13:04:32 [17068] [10] ERROR: SMPP[login8]: got DLR but could not find message or was not interested in it id<170566615> dst<1234567>, type<1> > 2012-11-15 13:04:32 [17068] [10] DEBUG: SMPP[login8]: Sending PDU: > 2012-11-15 13:04:32 [17068] [10] DEBUG: SMPP PDU 0x2ce3e50 dump: > 2012-11-15 13:04:32 [17068] [10] DEBUG: type_name: deliver_sm_resp > 2012-11-15 13:04:32 [17068] [10] DEBUG: command_id: 2147483653 = 0x80000005 > 2012-11-15 13:04:32 [17068] [10] DEBUG: command_status: 0 = 0x00000000 > 2012-11-15 13:04:32 [17068] [10] DEBUG: sequence_number: 3956116 = 0x003c5d94 > 2012-11-15 13:04:32 [17068] [10] DEBUG: message_id: NULL > 2012-11-15 13:04:32 [17068] [10] DEBUG: SMPP PDU dump ends. > > > Because we wanted to send only 1 MT message we hit DLR only once, other two times were unsuccessful. > > Also from what I can see there is an issue if you're load-balancing between multiple links if message is queued through another link it won't be matched against DLR. > > I know you can use same SMSCID for all links, but it's not a good idea if you have 1000 uplinks and you want to load balance between them with allowed-smsc-id, preferred-smsc-id parameters. > > i.e. smsc1, smsc2 in group mysmsc, smsc2, smsc3 in group mysmsc3, etc.. > > If I wasn't clear in any part please let me know. > > >