Re: Interesting issue with DLRs
Ben Suffolk <[email protected]>
| Newsgroups | gmane.comp.mobile.kannel.devel |
|---|---|
| Message-ID | <[email protected]> |
Stipe, > I had assumed that the deliver_sm would come in on the RX bind, and > the submit_sm_resp as the reply on the TX bind. Are you saying the > same thread handles both these binds? If so is it possible that the > SMSC did in fact deliver the submit_sm_resp fractionally before the > deliver_sm but the thread was processing the RX at the time (say > several deliver_sm PDUs were coming in at the same time - which > given the nature of my app happens a lot as the message flow is > pretty bursty like that) and so got to the deliver_sm before the > submit_sm_resp. However its more than possible that the SMSC could > be to blame. I have looked at the relevant logs (attached here as a text file, with my notes and a lot removed to make it readable with just the relevant parts in), and it seems to bear out my initial thoughts that the DLR is coming in on a different thread, and so has the opportunity to be processed before the response in the tx thread. You will note from the logs that the message responses are asynchronous to the submissions. Thats because this operator uses an smpp load balancer in front of the SMSCs so that although you have only one connection, they share the messages across multiple SMSCs, and as different SMSCs are under different loads some are able to respond quicker than others. Regards Ben
smsc.log
(application/octet-stream, 7.9 KB)
Looks like the message was timed with one of the regular enquire linkes 2006-10-16 18:40:45 [83654] [7] DEBUG: SMPP[smsc1]: Sending enquire link: 2006-10-16 18:40:45 [83654] [7] DEBUG: SMPP PDU 0x854cb00 dump: 2006-10-16 18:40:45 [83654] [7] DEBUG: type_name: enquire_link 2006-10-16 18:40:45 [83654] [7] DEBUG: sequence_number: 21526 = 0x00005416 2006-10-16 18:40:45 [83654] [7] DEBUG: SMPP PDU dump ends. 6 messages go out 2006-10-16 18:40:45 [83654] [7] DEBUG: SMPP[smsc1]: Sending PDU: 2006-10-16 18:40:45 [83654] [7] DEBUG: SMPP PDU 0x854cb00 dump: 2006-10-16 18:40:45 [83654] [7] DEBUG: type_name: submit_sm 2006-10-16 18:40:45 [83654] [7] DEBUG: sequence_number: 21527 = 0x00005417 2006-10-16 18:40:45 [83654] [7] DEBUG: SMPP PDU dump ends. 2006-10-16 18:40:45 [83654] [7] DEBUG: SMPP[smsc1]: Sending PDU: 2006-10-16 18:40:45 [83654] [7] DEBUG: SMPP PDU 0x854cb00 dump: 2006-10-16 18:40:45 [83654] [7] DEBUG: type_name: submit_sm 2006-10-16 18:40:45 [83654] [7] DEBUG: sequence_number: 21528 = 0x00005418 2006-10-16 18:40:45 [83654] [7] DEBUG: SMPP PDU dump ends. 2006-10-16 18:40:45 [83654] [7] DEBUG: SMPP[smsc1]: Sending PDU: 2006-10-16 18:40:45 [83654] [7] DEBUG: SMPP PDU 0x84b7000 dump: 2006-10-16 18:40:45 [83654] [7] DEBUG: type_name: submit_sm 2006-10-16 18:40:45 [83654] [7] DEBUG: sequence_number: 21529 = 0x00005419 2006-10-16 18:40:45 [83654] [7] DEBUG: SMPP PDU dump ends. 2006-10-16 18:40:45 [83654] [7] DEBUG: SMPP[smsc1]: Sending PDU: 2006-10-16 18:40:45 [83654] [7] DEBUG: SMPP PDU 0x84b7000 dump: 2006-10-16 18:40:45 [83654] [7] DEBUG: type_name: submit_sm 2006-10-16 18:40:45 [83654] [7] DEBUG: sequence_number: 21530 = 0x0000541a 2006-10-16 18:40:45 [83654] [7] DEBUG: SMPP PDU dump ends. 2006-10-16 18:40:45 [83654] [7] DEBUG: SMPP[smsc1]: Sending PDU: 2006-10-16 18:40:45 [83654] [7] DEBUG: SMPP PDU 0x84b7000 dump: 2006-10-16 18:40:45 [83654] [7] DEBUG: type_name: submit_sm 2006-10-16 18:40:45 [83654] [7] DEBUG: sequence_number: 21531 = 0x0000541b 2006-10-16 18:40:45 [83654] [7] DEBUG: SMPP PDU dump ends. 2006-10-16 18:40:45 [83654] [7] DEBUG: SMPP[smsc1]: Sending PDU: 2006-10-16 18:40:45 [83654] [7] DEBUG: SMPP PDU 0x84b7000 dump: 2006-10-16 18:40:45 [83654] [7] DEBUG: type_name: submit_sm 2006-10-16 18:40:45 [83654] [7] DEBUG: sequence_number: 21532 = 0x0000541c 2006-10-16 18:40:45 [83654] [7] DEBUG: SMPP PDU dump ends. We get the enquire link respone back 2006-10-16 18:40:46 [83654] [7] DEBUG: SMPP[smsc1]: Got PDU: 2006-10-16 18:40:46 [83654] [7] DEBUG: SMPP PDU 0x84b7000 dump: 2006-10-16 18:40:46 [83654] [7] DEBUG: type_name: enquire_link_resp 2006-10-16 18:40:46 [83654] [7] DEBUG: sequence_number: 21526 = 0x00005416 2006-10-16 18:40:46 [83654] [7] DEBUG: SMPP PDU dump ends. 1st message response 2006-10-16 18:40:47 [83654] [7] DEBUG: SMPP[smsc1]: Got PDU: 2006-10-16 18:40:47 [83654] [7] DEBUG: SMPP PDU 0x84b7000 dump: 2006-10-16 18:40:47 [83654] [7] DEBUG: type_name: submit_sm_resp 2006-10-16 18:40:47 [83654] [7] DEBUG: sequence_number: 21527 = 0x00005417 2006-10-16 18:40:47 [83654] [7] DEBUG: message_id: "26F2C10E" 2006-10-16 18:40:47 [83654] [7] DEBUG: SMPP PDU dump ends. 4th message DLR 2006-10-16 18:40:48 [83654] [8] DEBUG: SMPP[smsc1]: Got PDU: 2006-10-16 18:40:48 [83654] [8] DEBUG: SMPP PDU 0x84b7100 dump: 2006-10-16 18:40:48 [83654] [8] DEBUG: type_name: deliver_sm 2006-10-16 18:40:48 [83654] [8] DEBUG: data: 69 64 3a 30 35 33 34 36 38 32 39 39 32 20 73 75 id:0534682992 su 2006-10-16 18:40:48 [83654] [8] DEBUG: data: 62 3a 30 30 31 20 64 6c 76 72 64 3a 30 30 30 20 b:001 dlvrd:000 2006-10-16 18:40:48 [83654] [8] DEBUG: SMPP PDU dump ends. 4th message response 2006-10-16 18:40:48 [83654] [7] DEBUG: SMPP[smsc1]: Got PDU: 2006-10-16 18:40:48 [83654] [7] DEBUG: SMPP PDU 0x84b7000 dump: 2006-10-16 18:40:48 [83654] [7] DEBUG: type_name: submit_sm_resp 2006-10-16 18:40:48 [83654] [7] DEBUG: sequence_number: 21530 = 0x0000541a 2006-10-16 18:40:48 [83654] [7] DEBUG: message_id: "1FDE9D70" 2006-10-16 18:40:48 [83654] [7] DEBUG: SMPP PDU dump ends. 2nd message response 2006-10-16 18:40:48 [83654] [7] DEBUG: SMPP[smsc1]: Got PDU: 2006-10-16 18:40:48 [83654] [7] DEBUG: SMPP PDU 0x84b7000 dump: 2006-10-16 18:40:48 [83654] [7] DEBUG: type_name: submit_sm_resp 2006-10-16 18:40:48 [83654] [7] DEBUG: sequence_number: 21528 = 0x00005418 2006-10-16 18:40:48 [83654] [7] DEBUG: message_id: "27E61946" 2006-10-16 18:40:48 [83654] [7] DEBUG: SMPP PDU dump ends. 5th message response 2006-10-16 18:40:48 [83654] [7] DEBUG: SMPP PDU 0x84b7000 dump: 2006-10-16 18:40:48 [83654] [7] DEBUG: type_name: submit_sm_resp 2006-10-16 18:40:48 [83654] [7] DEBUG: sequence_number: 21531 = 0x0000541b 2006-10-16 18:40:48 [83654] [7] DEBUG: message_id: "2D8DAEBA" 2006-10-16 18:40:48 [83654] [7] DEBUG: SMPP PDU dump ends. 3rd Message response 2006-10-16 18:40:48 [83654] [7] DEBUG: SMPP[smsc1]: Got PDU: 2006-10-16 18:40:48 [83654] [7] DEBUG: SMPP PDU 0x84b7000 dump: 2006-10-16 18:40:48 [83654] [7] DEBUG: type_name: submit_sm_resp 2006-10-16 18:40:48 [83654] [7] DEBUG: sequence_number: 21529 = 0x00005419 2006-10-16 18:40:48 [83654] [7] DEBUG: message_id: "2A32B246" 2006-10-16 18:40:48 [83654] [7] DEBUG: SMPP PDU dump ends. 6th message response 2006-10-16 18:40:48 [83654] [7] DEBUG: SMPP PDU 0x84b7000 dump: 2006-10-16 18:40:48 [83654] [7] DEBUG: type_name: submit_sm_resp 2006-10-16 18:40:48 [83654] [7] DEBUG: sequence_number: 21532 = 0x0000541c 2006-10-16 18:40:48 [83654] [7] DEBUG: message_id: "26F2C113" 2006-10-16 18:40:48 [83654] [7] DEBUG: SMPP PDU dump ends. 3rd Message response 2006-10-16 18:40:51 [83654] [8] DEBUG: SMPP[smsc1]: Got PDU: 2006-10-16 18:40:51 [83654] [8] DEBUG: SMPP PDU 0x8421100 dump: 2006-10-16 18:40:51 [83654] [8] DEBUG: type_name: deliver_sm 2006-10-16 18:40:51 [83654] [8] DEBUG: data: 69 64 3a 30 37 30 37 39 36 35 35 31 30 20 73 75 id:0707965510 su 2006-10-16 18:40:51 [83654] [8] DEBUG: data: 62 3a 30 30 31 20 64 6c 76 72 64 3a 30 30 31 20 b:001 dlvrd:001 2006-10-16 18:40:51 [83654] [8] DEBUG: SMPP PDU dump ends. 1st Message DLR 2006-10-16 18:40:52 [83654] [8] DEBUG: SMPP[smsc1]: Got PDU: 2006-10-16 18:40:52 [83654] [8] DEBUG: SMPP PDU 0x8421100 dump: 2006-10-16 18:40:52 [83654] [8] DEBUG: type_name: deliver_sm 2006-10-16 18:40:52 [83654] [8] DEBUG: data: 69 64 3a 30 36 35 33 34 34 33 33 34 32 20 73 75 id:0653443342 su 2006-10-16 18:40:52 [83654] [8] DEBUG: data: 62 3a 30 30 31 20 64 6c 76 72 64 3a 30 30 31 20 b:001 dlvrd:001 2006-10-16 18:40:52 [83654] [8] DEBUG: SMPP PDU dump ends. 2nd Message DLR 2006-10-16 18:40:52 [83654] [8] DEBUG: SMPP[smsc1]: Got PDU: 2006-10-16 18:40:52 [83654] [8] DEBUG: SMPP PDU 0x8421100 dump: 2006-10-16 18:40:52 [83654] [8] DEBUG: type_name: deliver_sm 2006-10-16 18:40:52 [83654] [8] DEBUG: data: 69 64 3a 30 36 36 39 33 39 31 31 37 34 20 73 75 id:0669391174 su 2006-10-16 18:40:52 [83654] [8] DEBUG: data: 62 3a 30 30 31 20 64 6c 76 72 64 3a 30 30 31 20 b:001 dlvrd:001 2006-10-16 18:40:52 [83654] [8] DEBUG: SMPP PDU dump ends. 5th Message DLR 2006-10-16 18:40:53 [83654] [8] DEBUG: SMPP[smsc1]: Got PDU: 2006-10-16 18:40:53 [83654] [8] DEBUG: SMPP PDU 0x8421100 dump: 2006-10-16 18:40:53 [83654] [8] DEBUG: type_name: deliver_sm 2006-10-16 18:40:53 [83654] [8] DEBUG: data: 69 64 3a 30 37 36 34 32 36 30 30 32 36 20 73 75 id:0764260026 su 2006-10-16 18:40:53 [83654] [8] DEBUG: data: 62 3a 30 30 31 20 64 6c 76 72 64 3a 30 30 31 20 b:001 dlvrd:001 2006-10-16 18:40:53 [83654] [8] DEBUG: SMPP PDU dump ends. 6th Message DLR 2006-10-16 18:40:55 [83654] [8] DEBUG: SMPP[smsc1]: Got PDU: 2006-10-16 18:40:55 [83654] [8] DEBUG: SMPP PDU 0x8421100 dump: 2006-10-16 18:40:55 [83654] [8] DEBUG: type_name: deliver_sm 2006-10-16 18:40:55 [83654] [8] DEBUG: data: 69 64 3a 30 36 35 33 34 34 33 33 34 37 20 73 75 id:0653443347 su 2006-10-16 18:40:55 [83654] [8] DEBUG: data: 62 3a 30 30 31 20 64 6c 76 72 64 3a 30 30 31 20 b:001 dlvrd:001 2006-10-16 18:40:55 [83654] [8] DEBUG: SMPP PDU dump ends.