On Sat, 7 Aug 2004, Alexander Malysh wrote: > > On Thu, 2004-08-05 at 23:54, Peter Beckman wrote: > > > >> In 1.3.1 I'm seeing that when the remote connection disconnects without > >> an unbind, and then reconnects, messages stop getting sent until either > >> one side or I restart the gateway. > >> > >> Anyone else see this? > > which smsc module? more details with debug logs please...
SMSC SMPP module. The problem is transient (or at least seemingly so). The remote SMPP server sends an unbind and disconnects. Kannel attempts to reconnect every 10 seconds. Once the remote SMPP server opens for business again, Kannel can connect (or at least it looks that way), but does not send messages. A restart on either end will begin sending the messages again. Ok, here's what happens: The last message is successfully sent to smpphost 2004-07-16 21:30:00 [7] DEBUG: Looking for DLR smsc=smpphost, ts=17869084, dst=12125551213, type=12 A few seconds later the remote SMPP host disconnects, sending an unbind for both TX and RX. 2004-07-16 21:30:14 [8] DEBUG: SMPP PDU 0xac803c90 dump: 2004-07-16 21:30:14 [8] DEBUG: type_name: unbind 2004-07-16 21:30:14 [8] DEBUG: command_id: 6 = 0x00000006 2004-07-16 21:30:14 [8] DEBUG: command_status: 0 = 0x00000000 2004-07-16 21:30:14 [8] DEBUG: sequence_number: 624 = 0x00000270 2004-07-16 21:30:14 [8] DEBUG: SMPP PDU dump ends. 2004-07-16 21:30:15 [8] ERROR: SMPP[smpphost]: I/O error or other error. Re-connecting. 2004-07-16 21:30:15 [8] ERROR: connect failed 2004-07-16 21:30:15 [8] ERROR: System error 111: Connection refused 2004-07-16 21:30:15 [8] ERROR: error connecting to server `12.34.56.78' at port `8202' 2004-07-16 21:30:15 [8] ERROR: SMPP[smpphost]: Couldn't connect to server. 2004-07-16 21:30:15 [8] ERROR: SMPP[smpphost]: Couldn't connect to SMS center (retrying in 10 seconds). 2004-07-16 21:30:19 [7] DEBUG: SMPP[smpphost]: Got PDU: 2004-07-16 21:30:19 [7] DEBUG: SMPP PDU 0x873bfe0 dump: 2004-07-16 21:30:19 [7] DEBUG: type_name: unbind 2004-07-16 21:30:19 [7] DEBUG: command_id: 6 = 0x00000006 2004-07-16 21:30:19 [7] DEBUG: command_status: 0 = 0x00000000 2004-07-16 21:30:19 [7] DEBUG: sequence_number: 625 = 0x00000271 2004-07-16 21:30:19 [7] DEBUG: SMPP PDU dump ends. 2004-07-16 21:30:34 [7] DEBUG: SMPP[smpphost]: Sending enquire link: 2004-07-16 21:30:34 [7] DEBUG: SMPP PDU 0x873bfe0 dump: 2004-07-16 21:30:34 [7] DEBUG: type_name: enquire_link 2004-07-16 21:30:34 [7] DEBUG: command_id: 21 = 0x00000015 2004-07-16 21:30:34 [7] DEBUG: command_status: 0 = 0x00000000 2004-07-16 21:30:34 [7] DEBUG: sequence_number: 21266 = 0x00005312 2004-07-16 21:30:34 [7] DEBUG: SMPP PDU dump ends. 2004-07-16 21:30:34 [7] DEBUG: SMPP[smpphost]: Got PDU: 2004-07-16 21:30:34 [7] DEBUG: SMPP PDU 0x873bfe0 dump: 2004-07-16 21:30:34 [7] DEBUG: type_name: enquire_link_resp 2004-07-16 21:30:34 [7] DEBUG: command_id: 2147483669 = 0x80000015 2004-07-16 21:30:34 [7] DEBUG: command_status: 0 = 0x00000000 2004-07-16 21:30:34 [7] DEBUG: sequence_number: 21266 = 0x00005312 2004-07-16 21:30:34 [7] DEBUG: SMPP PDU dump ends. 2004-07-16 21:30:34 [7] ERROR: SMPP[smpphost]: I/O error or other error. Re-connecting. 2004-07-16 21:30:34 [7] ERROR: connect failed 2004-07-16 21:30:34 [7] ERROR: System error 111: Connection refused 2004-07-16 21:30:34 [7] ERROR: error connecting to server `12.34.56.78' at port `8203' 2004-07-16 21:30:34 [7] ERROR: SMPP[smpphost]: Couldn't connect to server. 2004-07-16 21:30:34 [7] ERROR: SMPP[smpphost]: Couldn't connect to SMS center (retrying in 10 seconds). Hmmmm. I get an unbind for the TX session #7, yet the system is still connected enough to do an enquire_link and get a response, then it dies. So it stays offline for a little bit then comes back up. 2004-07-16 21:30:44 [7] DEBUG: SMPP[smpphost]: Sending PDU: 2004-07-16 21:30:44 [7] DEBUG: SMPP PDU 0x8744fe8 dump: 2004-07-16 21:30:44 [7] DEBUG: type_name: bind_transmitter 2004-07-16 21:30:44 [7] DEBUG: command_id: 2 = 0x00000002 2004-07-16 21:30:44 [7] DEBUG: command_status: 0 = 0x00000000 2004-07-16 21:30:44 [7] DEBUG: sequence_number: 21267 = 0x00005313 2004-07-16 21:30:44 [7] DEBUG: system_id: "xxxxx" 2004-07-16 21:30:44 [7] DEBUG: password: "yyyyy" 2004-07-16 21:30:44 [7] DEBUG: system_type: "VMA" 2004-07-16 21:30:44 [7] DEBUG: interface_version: 52 = 0x00000034 2004-07-16 21:30:44 [7] DEBUG: addr_ton: 0 = 0x00000000 2004-07-16 21:30:44 [7] DEBUG: addr_npi: 0 = 0x00000000 2004-07-16 21:30:44 [7] DEBUG: address_range: "" 2004-07-16 21:30:44 [7] DEBUG: SMPP PDU dump ends. 2004-07-16 21:30:45 [7] DEBUG: SMPP[smpphost]: Got PDU: 2004-07-16 21:30:45 [7] DEBUG: SMPP PDU 0x8744fe8 dump: 2004-07-16 21:30:45 [7] DEBUG: type_name: bind_transmitter_resp 2004-07-16 21:30:45 [7] DEBUG: command_id: 2147483650 = 0x80000002 2004-07-16 21:30:45 [7] DEBUG: command_status: 0 = 0x00000000 2004-07-16 21:30:45 [7] DEBUG: sequence_number: 21267 = 0x00005313 2004-07-16 21:30:45 [7] DEBUG: system_id: "SMPPHOST" 2004-07-16 21:30:45 [7] DEBUG: SMPP PDU dump ends. 2004-07-16 21:30:46 [8] DEBUG: SMPP[smpphost]: Sending PDU: 2004-07-16 21:30:46 [8] DEBUG: SMPP PDU 0xac803ce0 dump: 2004-07-16 21:30:46 [8] DEBUG: type_name: bind_receiver 2004-07-16 21:30:46 [8] DEBUG: command_id: 1 = 0x00000001 2004-07-16 21:30:46 [8] DEBUG: command_status: 0 = 0x00000000 2004-07-16 21:30:46 [8] DEBUG: sequence_number: 21268 = 0x00005314 2004-07-16 21:30:46 [8] DEBUG: system_id: "xxxxx" 2004-07-16 21:30:46 [8] DEBUG: password: "yyyyy" 2004-07-16 21:30:46 [8] DEBUG: system_type: "VMA" 2004-07-16 21:30:46 [8] DEBUG: interface_version: 52 = 0x00000034 2004-07-16 21:30:46 [8] DEBUG: addr_ton: 0 = 0x00000000 2004-07-16 21:30:46 [8] DEBUG: addr_npi: 0 = 0x00000000 2004-07-16 21:30:46 [8] DEBUG: address_range: "" 2004-07-16 21:30:46 [8] DEBUG: SMPP PDU dump ends. 2004-07-16 21:30:46 [8] DEBUG: SMPP[smpphost]: Got PDU: 2004-07-16 21:30:46 [8] DEBUG: SMPP PDU 0xac803ce0 dump: 2004-07-16 21:30:46 [8] DEBUG: type_name: bind_receiver_resp 2004-07-16 21:30:46 [8] DEBUG: command_id: 2147483649 = 0x80000001 2004-07-16 21:30:46 [8] DEBUG: command_status: 0 = 0x00000000 2004-07-16 21:30:46 [8] DEBUG: sequence_number: 21268 = 0x00005314 2004-07-16 21:30:46 [8] DEBUG: system_id: "SMPPHOST" 2004-07-16 21:30:46 [8] DEBUG: SMPP PDU dump ends. So it seems the connection is up, as I continue to get these: 2004-07-16 21:31:14 [7] DEBUG: SMPP[smpphost]: Sending enquire link: 2004-07-16 21:31:14 [7] DEBUG: SMPP PDU 0x8744fe8 dump: 2004-07-16 21:31:14 [7] DEBUG: type_name: enquire_link 2004-07-16 21:31:14 [7] DEBUG: command_id: 21 = 0x00000015 2004-07-16 21:31:14 [7] DEBUG: command_status: 0 = 0x00000000 2004-07-16 21:31:14 [7] DEBUG: sequence_number: 21269 = 0x00005315 2004-07-16 21:31:14 [7] DEBUG: SMPP PDU dump ends. 2004-07-16 21:31:14 [7] DEBUG: SMPP[smpphost]: Got PDU: 2004-07-16 21:31:14 [7] DEBUG: SMPP PDU 0x8744fe8 dump: 2004-07-16 21:31:14 [7] DEBUG: type_name: enquire_link_resp 2004-07-16 21:31:14 [7] DEBUG: command_id: 2147483669 = 0x80000015 2004-07-16 21:31:14 [7] DEBUG: command_status: 0 = 0x00000000 2004-07-16 21:31:14 [7] DEBUG: sequence_number: 21269 = 0x00005315 2004-07-16 21:31:14 [7] DEBUG: SMPP PDU dump ends. 2004-07-16 21:31:16 [8] DEBUG: SMPP[smpphost]: Sending enquire link: 2004-07-16 21:31:16 [8] DEBUG: SMPP PDU 0xac803ce0 dump: 2004-07-16 21:31:16 [8] DEBUG: type_name: enquire_link 2004-07-16 21:31:16 [8] DEBUG: command_id: 21 = 0x00000015 2004-07-16 21:31:16 [8] DEBUG: command_status: 0 = 0x00000000 2004-07-16 21:31:16 [8] DEBUG: sequence_number: 21270 = 0x00005316 2004-07-16 21:31:16 [8] DEBUG: SMPP PDU dump ends. 2004-07-16 21:31:16 [8] DEBUG: SMPP[smpphost]: Got PDU: 2004-07-16 21:31:16 [8] DEBUG: SMPP PDU 0xac803ce0 dump: 2004-07-16 21:31:16 [8] DEBUG: type_name: enquire_link_resp 2004-07-16 21:31:16 [8] DEBUG: command_id: 2147483669 = 0x80000015 2004-07-16 21:31:16 [8] DEBUG: command_status: 0 = 0x00000000 2004-07-16 21:31:16 [8] DEBUG: sequence_number: 21270 = 0x00005316 2004-07-16 21:31:16 [8] DEBUG: SMPP PDU dump ends. But I get an SMS in from the smsbox according to sms-access.log: 2004-07-16 21:32:53 send-SMS request added - sender:smpphost:1234567890 222.22.222.222 target:12125551212 request: 'blah blah blah' And junk in the bearerbox.log to back it up: 2004-07-16 21:32:53 [18] DEBUG: send_msg: sending msg to boxc: <default> 2004-07-16 21:32:53 [18] DEBUG: boxc_sender: sent message to <127.0.0.1> 2004-07-16 21:32:53 [17] DEBUG: boxc_receiver: got ack 2004-07-16 21:32:53 [17] DEBUG: boxc_receiver: sms received 2004-07-16 21:32:53 [9] DEBUG: sms_router: time to sleep 2004-07-16 21:32:53 [9] DEBUG: sms_router: list_len = 1 2004-07-16 21:32:53 [9] DEBUG: sms_router: time to sleep But the message isn't sent by the bearerbox to the connection until kannel is stopped and restarted (the same thing has been seen to be fixed by having the remote smpp server connect stopped and restarted): 2004-07-16 22:41:32 [0] DEBUG: Shutting down Kannel... 2004-07-16 22:41:32 [0] DEBUG: shutting down smsc 2004-07-16 22:41:32 [1] DEBUG: Dumping 136 messages and 0 acks to store 2004-07-16 22:41:32 [0] PANIC: gwlib/thread.c:82: mutex_lock_real: Managed to lock the mutex twice! (Called from gwlib/list.c:426:lock.) oooh is this bad? 2004-07-16 22:41:32 [0] INFO: Kannel bearerbox II version 1.3.1 starting [...] smpphost connection is made and immediately delivers the messages that were stored... 2004-07-16 22:41:35 [9] DEBUG: sms_router: list_len = 17 2004-07-16 22:41:35 [7] DEBUG: SMPP[smpphost]: Sending PDU: 2004-07-16 22:41:35 [7] DEBUG: SMPP PDU 0x81143f8 dump: 2004-07-16 22:41:35 [7] DEBUG: type_name: submit_sm 2004-07-16 22:41:35 [7] DEBUG: command_id: 4 = 0x00000004 2004-07-16 22:41:35 [7] DEBUG: command_status: 0 = 0x00000000 2004-07-16 22:41:35 [7] DEBUG: sequence_number: 2 = 0x00000002 2004-07-16 22:41:35 [7] DEBUG: service_type: NULL 2004-07-16 22:41:35 [7] DEBUG: source_addr_ton: 2 = 0x00000002 2004-07-16 22:41:35 [7] DEBUG: source_addr_npi: 1 = 0x00000001 2004-07-16 22:41:35 [7] DEBUG: source_addr: "1234578900" 2004-07-16 22:41:35 [7] DEBUG: dest_addr_ton: 2 = 0x00000002 2004-07-16 22:41:35 [7] DEBUG: dest_addr_npi: 1 = 0x00000001 2004-07-16 22:41:35 [7] DEBUG: destination_addr: "12125551212" 2004-07-16 22:41:35 [7] DEBUG: esm_class: 3 = 0x00000003 2004-07-16 22:41:35 [7] DEBUG: protocol_id: 0 = 0x00000000 2004-07-16 22:41:35 [7] DEBUG: priority_flag: 0 = 0x00000000 2004-07-16 22:41:35 [7] DEBUG: schedule_delivery_time: NULL 2004-07-16 22:41:35 [7] DEBUG: validity_period: NULL 2004-07-16 22:41:35 [7] DEBUG: registered_delivery: 1 = 0x00000001 2004-07-16 22:41:35 [7] DEBUG: replace_if_present_flag: 0 = 0x00000000 2004-07-16 22:41:35 [7] DEBUG: data_coding: 0 = 0x00000000 2004-07-16 22:41:35 [7] DEBUG: sm_default_msg_id: 0 = 0x00000000 2004-07-16 22:41:35 [7] DEBUG: sm_length: 98 = 0x00000062 2004-07-16 22:41:35 [7] DEBUG: short_message: 2004-07-16 22:41:35 [7] DEBUG: Octet string at 0xad200790: 2004-07-16 22:41:35 [7] DEBUG: len: 98 2004-07-16 22:41:35 [7] DEBUG: size: 99 2004-07-16 22:41:35 [7] DEBUG: immutable: 0 2004-07-16 22:41:35 [7] DEBUG: data: 59 6f 75 72 20 73 65 63 blah bla 2004-07-16 22:41:35 [7] DEBUG: Octet string dump ends. 2004-07-16 22:41:35 [7] DEBUG: SMPP PDU dump ends. Hopefully that gives a better picture of what I'm talking about. Beckman --------------------------------------------------------------------------- Peter Beckman Internet Guy [EMAIL PROTECTED] http://www.purplecow.com/ ---------------------------------------------------------------------------
