Using Fakesmsc and Opensmppbox for load testing of an SMPP application I notice strange behavior of Kannel (surrely bad configuration, I hope)
Fakesmsc <--> Bearerbox <--> Opensmppbox <--> Smpp client Config file at the end: Test: When I send 1 SMS from Fakesmsc (5656) to my SMPP application (1065) this application answer back with a SMS to the original sender. ie for 1 SMS sent from fakesmsc 1 should be received. >From fakesmsc I send 50 SMS with this command: *# /usr/bin/fakesmsc -r 10001 -H 127.0.0.1 -i 0.2 -m 50 "5656 1065 text 50 SMS"* Below output from a script that parse the log file under /var/log: So I see exactly the 50 SMS sent to my smpp application (50 SMS also on its side) *# /usr/bin/fakesmsc -r 10001 -H 127.0.0.1 -i 0.2 -m 50 "5656 1065 text 50 SMS" 2010-10-13 14:31:08 [29344] [0] INFO: Debug_lvl = -1, log_file = <none>, log_lvl = 0 2010-10-13 14:31:08 [29344] [0] INFO: Host 127.0.0.1 Port 10001 interval 0.200 max-messages 50 2010-10-13 14:31:08 [29344] [0] INFO: fakesmsc starting 2010-10-13 14:31:08 [29344] [0] DEBUG: Connecting to <127.0.0.1> 2010-10-13 14:31:08 [29344] [0] DEBUG: fakesmsc: sent message 1 2010-10-13 14:31:08 [29344] [0] DEBUG: fakesmsc: sent message 2* ... 2010-10-13 14:31:18 [29344] [0] DEBUG: fakesmsc: sent message 49 2010-10-13 14:31:18 [29344] [0] INFO: fakesmsc: sent message 50 2010-10-13 14:31:19 [29344] [0] DEBUG: Got message 1: <1065 5656 text 50 SMS> 2010-10-13 14:31:20 [29344] [0] DEBUG: Got message 2: <1065 5656 text 50 SMS> ... 2010-10-13 14:32:07 [29344] [0] DEBUG: Got message 49: <1065 5656 text 50 SMS> 2010-10-13 14:32:08 [29344] [0] INFO: Got message 50: <1065 5656 text 50 SMS> # ./stat.sh Bearerbox - Received SMS: 50 (cat bearerbox.log | grep "new message" | wc -l) Bearerbox - Sent SMS: 50 (cat bearerbox.log | grep "sending message" | wc -l) Access - Receive SMS: 50 (cat access.log | grep "Receive SMS" | wc -l) Access - Sent SMS: 50 (cat access.log | grep "Sent SMS" | wc -l) Smppbox - Deliver_sm: 50 (cat opensmppbox.log | grep "deliver_sm" | wc -l) Smppbox - Submit_sm: 50 (cat opensmppbox.log | grep "submit_sm" | wc -l) But some minutes after I see new messages sent from kannel (not from fakesmsc), 31 more !! ... 2010-10-13 14:37:31 [29344] [0] DEBUG: Got message 51: <1065 5656 text 50 SMS> 2010-10-13 14:37:32 [29344] [0] DEBUG: Got message 52: <1065 5656 text 50 SMS> ... 2010-10-13 14:38:00 [29344] [0] DEBUG: Got message 80: <1065 5656 text 50 SMS> 2010-10-13 14:38:01 [29344] [0] DEBUG: Got message 81: <1065 5656 text 50 SMS> I close fakesmsc: *^C2010-10-13 14:55:59 [29344] [0] INFO: fakesmsc: 50 messages sent and 81 received 2010-10-13 14:55:59 [29344] [0] INFO: fakesmsc: total running time 1490.5 seconds 2010-10-13 14:55:59 [29344] [0] INFO: fakesmsc: from first to last sent message 9.8 s, 5.0 msgs/s 2010-10-13 14:55:59 [29344] [0] INFO: fakesmsc: from first to last received message 402.0 s, 0.2 msgs/s 2010-10-13 14:55:59 [29344] [0] INFO: fakesmsc: terminating #* logs parsed by the script stat.sh # ./stat.sh Bearerbox - Received SMS: 50 Bearerbox - Sent SMS: 81 --> bearerbox sent 31 new messages to fakesmsc !!!! Access - Receive SMS: 50 Access - Sent SMS: 81 --> 31 new messages logged in access.log Smppbox - Deliver_sm: 81 --> smppbox received these 31 new messages forward them to smpp client Smppbox - Submit_sm: 81 --> and smppclient answer back with 31 new message going to fakesmsc *From where comes theses messages ? It seems it is smppbox that seems to receive 31 new messages but from where ????!* I check in detail opensmppbox.log: Ifound that smppbox shutdown and restarted after the 50 messages have been sent at 14:32, 4 minutes later it restarted: *2010-10-13 14:32:08 [25805] [267] DEBUG: message_id: "b91ac635" 2010-10-13 14:32:08 [25805] [267] DEBUG: SMPP PDU dump ends. 2010-10-13 14:36:21 [25805] [266] DEBUG: Thread 266 (opensmppbox.c:smpp_to_bearerbox) terminates. 2010-10-13 14:36:21 [25805] [265] DEBUG: Thread 265 (opensmppbox.c:function) terminates. 2010-10-13 14:36:21 [25805] [0] DEBUG: Started thread 269 (opensmppbox.c:function) 2010-10-13 14:36:21 [25805] [269] DEBUG: Thread 269 (opensmppbox.c:function) maps to pid 25805. 2010-10-13 14:36:21 [25805] [269] INFO: Client connected from <163.176.17.238> 2010-10-13 14:36:21 [25805] [269] DEBUG: Connecting to <127.0.0.1> 2010-10-13 14:36:21 [25805] [269] INFO: Connected to bearerbox at localhost port 13001. 2010-10-13 14:36:21 [25805] [269] DEBUG: Started thread 270 (opensmppbox.c:smpp_to_bearerbox) 2010-10-13 14:36:21 [25805] [270] DEBUG: Thread 270 (opensmppbox.c:smpp_to_bearerbox) maps to pid 25805. 2010-10-13 14:36:26 [25805] [270] DEBUG: SMPP[smppbox]: Got PDU: 2010-10-13 14:36:26 [25805] [270] DEBUG: SMPP PDU 0xb2f814b0 dump: 2010-10-13 14:36:26 [25805] [270] DEBUG: type_name: bind_receiver 2010-10-13 14:36:26 [25805] [270] DEBUG: command_id: 1 = 0x00000001 2010-10-13 14:36:26 [25805] [270] DEBUG: command_status: 0 = 0x00000000 2010-10-13 14:36:26 [25805] [270] DEBUG: sequence_number: 1 = 0x00000001 2010-10-13 14:36:26 [25805] [270] DEBUG: system_id: "mmg" 2010-10-13 14:36:26 [25805] [270] DEBUG: password: "mmg" 2010-10-13 14:36:26 [25805] [270] DEBUG: system_type: "mmg" 2010-10-13 14:36:26 [25805] [270] DEBUG: interface_version: 52 = 0x00000034 2010-10-13 14:36:26 [25805] [270] DEBUG: addr_ton: 0 = 0x00000000 2010-10-13 14:36:26 [25805] [270] DEBUG: addr_npi: 0 = 0x00000000 2010-10-13 14:36:26 [25805] [270] DEBUG: address_range: NULL 2010-10-13 14:36:26 [25805] [270] DEBUG: SMPP PDU dump ends. 2010-10-13 14:36:26 [25805] [270] DEBUG: SMPP[mmg]: Sending PDU: 2010-10-13 14:36:26 [25805] [270] DEBUG: SMPP PDU 0xb2f82258 dump: 2010-10-13 14:36:26 [25805] [270] DEBUG: type_name: bind_receiver_resp 2010-10-13 14:36:26 [25805] [270] DEBUG: command_id: 2147483649 = 0x80000001 2010-10-13 14:36:26 [25805] [270] DEBUG: command_status: 0 = 0x00000000 2010-10-13 14:36:26 [25805] [270] DEBUG: sequence_number: 1 = 0x00000001 2010-10-13 14:36:26 [25805] [270] DEBUG: system_id: "opensmppbox" 2010-10-13 14:36:26 [25805] [270] DEBUG: SMPP PDU dump ends. 2010-10-13 14:37:10 [25805] [268] DEBUG: Thread 268 (opensmppbox.c:smpp_to_bearerbox) terminates. 2010-10-13 14:37:10 [25805] [267] DEBUG: Thread 267 (opensmppbox.c:function) terminates. 2010-10-13 14:37:10 [25805] [269] INFO: We received an SMS message. 2010-10-13 14:37:10 [25805] [269] DEBUG: message length 6, sending 1 message 2010-10-13 14:37:10 [25805] [269] DEBUG: SMPP[mmg]: Sending PDU: 2010-10-13 14:37:10 [25805] [269] DEBUG: SMPP PDU 0xb2f855d0 dump: 2010-10-13 14:37:10 [25805] [269] DEBUG: type_name: deliver_sm 2010-10-13 14:37:10 [25805] [269] DEBUG: command_id: 5 = 0x00000005 2010-10-13 14:37:10 [25805] [269] DEBUG: command_status: 0 = 0x00000000 2010-10-13 14:37:10 [25805] [269] DEBUG: sequence_number: 0 = 0x00000000 2010-10-13 14:37:10 [25805] [269] DEBUG: service_type: NULL 2010-10-13 14:37:10 [25805] [269] DEBUG: source_addr_ton: 2 = 0x00000002 2010-10-13 14:37:10 [25805] [269] DEBUG: source_addr_npi: 1 = 0x00000001 2010-10-13 14:37:10 [25805] [269] DEBUG: source_addr: "5656" 2010-10-13 14:37:10 [25805] [269] DEBUG: dest_addr_ton: 2 = 0x00000002 2010-10-13 14:37:10 [25805] [269] DEBUG: dest_addr_npi: 1 = 0x00000001 2010-10-13 14:37:10 [25805] [269] DEBUG: destination_addr: "1065" * *Config file:* *kannel;conf:* ... *# SMSC Fake group = smsc smsc = fake smsc-id = "FakeSMSC-1" allowed-smsc-id = "FakeSMSC-1" host = localhost port = 10001* group = smsbox-route smsbox-id = mmg smsc-id = FakeSMSC-1 *opensmppbox.conf:* ...* group = core dlr-storage = mysql # this group defines your opensmppbox group = opensmppbox # our boxc type opensmppbox-id = smppbox # the port to listen on for smpp connections opensmppbox-port = 6201 # we connect to the following host as a box bearerbox-host = localhost bearerbox-port = 13001 log-level = 0 log-file = /var/log/kannel/opensmppbox.log our-system-id = opensmppbox route-to-smsc = FakeSMSC-1 # see sample smpplogins.txt smpp-logins = "/etc/kannel/smpplogins.txt"* *smpplogins.txt* mmg mmg mmg Regards, Emmanuel
