unlocked_try_write returning 1: OK or not OK (wrong sequence number issue)
spameden <[email protected]>
| Newsgroups | gmane.comp.mobile.kannel.devel |
|---|---|
| Message-ID | <CAHCALey4vZsknqDg71=nOhR5QrND3xc7zFoj5Vmt7f_kuJk6Jw@mail.gmail.com> |
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=4722submitted 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.