rohc

iprohc_client disconnect after short time

Asked by intizar

Hi,
i have iprohc_server running on CentOS release 6.4 (Final) and client also on CentOS release 6.3 , my problem is that iprohc_clients doesn't stay connected with server for more than a minute. the client keeps disconnecting within a minute . all i can see this in my log on client
"timeout reached while waiting to message on TCP connection, give up "

i can ping the server and the client both ways, but client exit itself within a mint , network connectivity is reliable , there is no problem in connectivity .

thanks

Question information

Language:
English Edit question
Status:
Expired
For:
rohc Edit question
Assignee:
No assignee Edit question
Last query:
Last reply:

This question was reopened

Revision history for this message
intizar (intizar57) said : 		#1

here is the log of iprohc_client side .

Sep 2 16:27:13 localhost iprohc_client[5589]: local address 192.168.245.139:43396 is used to contact server
Sep 2 16:27:14 localhost iprohc_client[5589]: TLS handshake succeeded
Sep 2 16:27:14 localhost iprohc_client[5589]: client certificate accepted
Sep 2 16:27:14 localhost iprohc_client[5589]: send connect message to server
Sep 2 16:27:14 localhost iprohc_client[5589]: wait for connect answer from server
Sep 2 16:27:15 localhost iprohc_client[5589]: MTU of underlying interface 'eth0' set to 1500 bytes
Sep 2 16:27:15 localhost iprohc_client[5589]: MTU of tunnel interface 'rohc' set to 1458 bytes
Sep 2 16:27:15 localhost iprohc_client[5589]: run tunnel thread for new client
Sep 2 16:27:15 localhost kernel: rohc: Disabled Privacy Extensions
Sep 2 16:27:15 localhost iprohc_client[5589]: ROHC compressor[65535] : [rohc_comp.c:471 rohc_comp_get_random_default()] please define a callback for random numbers
Sep 2 16:27:21 localhost iprohc_client[5589]: ROHC compressor[65535] : [rohc_comp.c:471 rohc_comp_get_random_default()] please define a callback for random numbers
Sep 2 16:28:36 localhost iprohc_client[5589]: timeout reached while waiting to message on TCP connection, give up

Revision history for this message
Didier Barvaux (didier-barvaux) said : 		#2

Hello,

There is a keepalive message sent on the TCP connection in order to detect network disconnection. It seems as if keepalive messages are not received, so connection is reset.

Could you please run both the client and the server in debug mode (--debug on command line for both of them) ? Send me the full logs.

Regards,
Didier

Revision history for this message
intizar (intizar57) said : 		#3

Thanks, Didier for giving me the hint ,i figured out that i have had set KeepAlive time to 300 secs in server configurations and client doesn't wait for 300 secs to receive keep alive mesg , , now i have set it back to default 30 secs and it's working fine , no more disconnects . rsyslogd kind of sucks on centos , thats why i couldn't give the detail logs. i had to run the client on ubuntu and now i can see that the client is receiving keep alive message in syslogs.
warm thanks . :) ..

Revision history for this message
Didier Barvaux (didier-barvaux) said : 		#4

Hello,

Could you please create a bug report for this? There is a bug to my opinion. You should either not be able to put 300 seconds as keepalive interval or it should work.

Regards,
Didier

Revision history for this message
intizar (intizar57) said : 		#5

Hi ,
yes , sure i will reproduce it on client and server (both running centos) . syslogd on centos don't show the logs except i posted above , even with --debug , i need to configure syslogd properly , then i'll report it .

thanks,

Revision history for this message
intizar (intizar57) said : 		#6

sorry for late reply .
i tried to set syslogd on centos but don't know what is wrong with it . so i switched iprohcserver to ubuntu and client to centos so that i can get some debug log . here they are . :

server log :

Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: Debugging enabled
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: underlying interface: eth2
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: Using file : /home/ali/iprohcserver/server.conf
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: Conf [general] port => 3126
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: Conf [general] pidfile => /var/run/iprohc_server.pid
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: Conf [general] p12file => /etc/pki/tls/misc/iprohcserver/newcert.p12
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: Conf [tunnel] ipaddr => 192.168.42.1
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: Conf [tunnel] packing => 5
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: Conf [tunnel] maxcid => 15
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: Conf [tunnel] unidirectional => 1
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: Conf [tunnel] keepalive => 600
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: Port : 3126
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: P12 file : /etc/pki/tls/misc/iprohcserver/newcert.p12
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: Pidfile : /var/run/iprohc_server.pid
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: Tunnel params :
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: . Local IP : 192.168.42.1
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: . Packing : 5
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: . Max cid : 15
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: . Unid : 1
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: . Keepalive : 600
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: load server certificate from file '/etc/pki/tls/misc/iprohcserver/newcert.p12'
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: failed to open PKCS#12 file '/etc/pki/tls/misc/iprohcserver/newcert.p12': No such file or directory (2)
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: failed load server certificate from file '/etc/pki/tls/misc/iprohcserver/newcert.p12'
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: remove pidfile '/var/run/iprohc_server.pid'
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: server stops with exit code 1
Sep 18 12:44:46 ali-virtual-machine iprohc_server[3594]: close syslog session
al-machine iprohc_server[3765]: Debugging enabled
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: underlying interface: eth2
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: Using file : /home/ali/iprohcserver/server.conf
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: Conf [general] port => 3126
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: Conf [general] pidfile => /var/run/iprohc_server.pid
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: Conf [general] p12file => /home/ali/iprohcserver/newcert.p12
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: Conf [tunnel] ipaddr => 192.168.42.1
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: Conf [tunnel] packing => 5
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: Conf [tunnel] maxcid => 15
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: Conf [tunnel] unidirectional => 1
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: Conf [tunnel] keepalive => 600
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: Port : 3126
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: P12 file : /home/ali/iprohcserver/newcert.p12
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: Pidfile : /var/run/iprohc_server.pid
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: Tunnel params :
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: . Local IP : 192.168.42.1
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: . Packing : 5
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: . Max cid : 15
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: . Unid : 1
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: . Keepalive : 600
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: load server certificate from file '/home/ali/iprohcserver/newcert.p12'
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: bag count = 2
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: certificate found!
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: certificate found!
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: bag count = 1
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: key found!
Sep 18 12:46:46 ali-virtual-machine iprohc_server[3765]: generate Diffie–Hellman parameters (it takes a few seconds)
Sep 18 12:46:50 ali-virtual-machine iprohc_server[3765]: listen on TCP 0.0.0.0:3126
Sep 18 12:46:50 ali-virtual-machine iprohc_server[3765]: create TUN interface
Sep 18 12:46:50 ali-virtual-machine iprohc_server[3765]: MTU of underlying interface 'eth2' set to 1500 bytes
Sep 18 12:46:50 ali-virtual-machine iprohc_server[3765]: MTU of tunnel interface 'tun_ipip' set to 1458 bytes
Sep 18 12:46:50 ali-virtual-machine NetworkManager[838]: SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/tun_ipip, iface: tun_ipip)
Sep 18 12:46:50 ali-virtual-machine NetworkManager[838]: SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/tun_ipip, iface: tun_ipip): no ifupdown configuration found.
Sep 18 12:46:50 ali-virtual-machine iprohc_server[3765]: start TUN routing thread
Sep 18 12:46:50 ali-virtual-machine iprohc_server[3765]: create RAW socket
Sep 18 12:46:50 ali-virtual-machine iprohc_server[3765]: start RAW routing thread
Sep 18 12:46:50 ali-virtual-machine iprohc_server[3765]: server is now ready to accept requests from clients
Sep 18 12:46:50 ali-virtual-machine iprohc_server[3765]: Initializing routing thread
Sep 18 12:46:50 ali-virtual-machine iprohc_server[3765]: Initializing routing thread

Sep 18 12:48:48 ali-virtual-machine dhclient: DHCPREQUEST of 192.168.164.131 on eth1 to 192.168.164.254 port 67
Sep 18 12:48:48 ali-virtual-machine dhclient: DHCPACK of 192.168.164.131 from 192.168.164.254
Sep 18 12:48:48 ali-virtual-machine dhclient: bound to 192.168.164.131 -- renewal in 828 seconds.
Sep 18 12:48:49 ali-virtual-machine iprohc_server[3765]: new connection from 192.168.133.1:52789
Sep 18 12:48:49 ali-virtual-machine iprohc_server[3765]: TLS handshake succeeded
Sep 18 12:48:49 ali-virtual-machine iprohc_server[3765]: Creation of client
Sep 18 12:48:49 ali-virtual-machine iprohc_server[3765]: Allocating 0x8283158
Sep 18 12:48:49 ali-virtual-machine iprohc_server[3765]: Created
Sep 18 12:48:49 ali-virtual-machine iprohc_server[3765]: [192.168.133.1] Received 10 bytes on TCP socket
Sep 18 12:48:49 ali-virtual-machine iprohc_server[3765]: [192.168.133.1] Connection asked, negotating parameters
Sep 18 12:48:49 ali-virtual-machine iprohc_server[3765]: Type : 9, length : 1,value : 0:
Sep 18 12:48:49 ali-virtual-machine iprohc_server[3765]: Type : a, length : 1,value : 1:
Sep 18 12:48:49 ali-virtual-machine iprohc_server[3765]: [192.168.133.1] Connection asked, negotating parameters (proto version 1, asked packing : 0)
Sep 18 12:48:49 ali-virtual-machine iprohc_server[3765]: Generating TLV
Sep 18 12:48:49 ali-virtual-machine iprohc_server[3765]: generate a 6-byte TLV option of type 1
Sep 18 12:48:49 ali-virtual-machine iprohc_server[3765]: generate a 3-byte TLV option of type 2
Sep 18 12:48:49 ali-virtual-machine iprohc_server[3765]: generate a 6-byte TLV option of type 3
Sep 18 12:48:49 ali-virtual-machine iprohc_server[3765]: generate a 3-byte TLV option of type 4
Sep 18 12:48:49 ali-virtual-machine iprohc_server[3765]: generate a 6-byte TLV option of type 5
Sep 18 12:48:49 ali-virtual-machine iprohc_server[3765]: generate a 6-byte TLV option of type 6
Sep 18 12:48:49 ali-virtual-machine iprohc_server[3765]: generate a 6-byte TLV option of type 7
Sep 18 12:48:49 ali-virtual-machine iprohc_server[3765]: generate a 3-byte TLV option of type 8
Sep 18 12:48:49 ali-virtual-machine iprohc_server[3765]: [192.168.133.1] Received 1 bytes on TCP socket
Sep 18 12:48:49 ali-virtual-machine iprohc_server[3765]: [192.168.133.1] Connection started by client
Sep 18 12:48:50 ali-virtual-machine iprohc_server[3765]: Keepalive !
Sep 18 12:48:50 ali-virtual-machine iprohc_server[3765]: [192.168.133.1] Received 1 bytes on TCP socket
Sep 18 12:48:50 ali-virtual-machine iprohc_server[3765]: [192.168.133.1] Received keepalive from client

Sep 18 12:50:10 ali-virtual-machine iprohc_server[3765]: [192.168.133.1] client #0 was disconnected, stop its thread
Sep 18 12:50:10 ali-virtual-machine iprohc_server[3765]: wait for client thread to stop
Sep 18 12:50:10 ali-virtual-machine iprohc_server[3765]: client thread was asked to stop
Sep 18 12:50:10 ali-virtual-machine iprohc_server[3765]: ROHC decompressor[65535] : [rohc_decomp.c:455 rohc_free_decompressor()] free decompressor
Sep 18 12:50:10 ali-virtual-machine iprohc_server[3765]: ROHC compressor[65535] : [rohc_comp.c:327 rohc_free_compressor()] free compressor
Sep 18 12:50:11 ali-virtual-machine iprohc_server[3765]: remove context of client #0
Sep 18 12:50:11 ali-virtual-machine iprohc_server[3765]: --------------------------------------------------
Sep 18 12:50:11 ali-virtual-machine iprohc_server[3765]: client 192.168.133.1
Sep 18 12:50:11 ali-virtual-machine iprohc_server[3765]: status: pending delete
Sep 18 12:50:11 ali-virtual-machine iprohc_server[3765]: --------------------------------------------------
################################################3

Client log ::
Sep 18 21:48:56 localhost iprohc_client[2759]: TLS handshake succeeded
Sep 18 21:48:56 localhost iprohc_client[2759]: client certificate accepted
Sep 18 21:48:56 localhost iprohc_client[2759]: send connect message to server
Sep 18 21:48:56 localhost iprohc_client[2759]: wait for connect answer from serv er
Sep 18 21:48:56 localhost kernel: rohtun: Disabled Privacy Extensions
Sep 18 21:48:56 localhost iprohc_client[2759]: MTU of underlying interface 'eth2 ' set to 1500 bytes
Sep 18 21:48:56 localhost iprohc_client[2759]: MTU of tunnel interface 'rohtun' set to 1458 bytes
Sep 18 21:48:56 localhost iprohc_client[2759]: run tunnel thread for new client
Sep 18 21:50:17 localhost iprohc_client[2759]: timeout reached while waiting to message on TCP connection, give up

Revision history for this message
intizar (intizar57) said : 		#7

one more thing i can't understand , when rohc tunnel server and client is working fine , ping reply time is huge about 1200 ms to 1400 ms , without iprohc tunnel i can ping both PC's at reply time of 1 ms .
is something wrong with my installation or is this a normal behaviour of iprohc tunnel ?

thanks

Revision history for this message
Launchpad Janitor (janitor) said : 		#8

This question was expired because it remained in the 'Open' state without activity for the last 15 days.