Hi Peter, as I see now, you have described problem with 1.3.1 release and it not with 1.3.2... so please get 1.3.2. a try and if this is still happens, tell us.
P.S. 1.3.1 is over a year old and 1.3.2 is more stable (IMO) ;) Peter Beckman wrote: > 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/ > --------------------------------------------------------------------------- -- Thanks, Alex
