search

schwabe / ics-openvpn

OpenVPN for Android
3.34k stars 1.2k forks source link

Logs show's connected however the device not connected #429

Closed AlmogBaku closed 8 years ago

AlmogBaku commented 8 years ago

After rebooting the logs says that the connection established, however the "key icon" not appearing.

Jan 06, 00:26:57] [INFO] started Socket Thread
[Jan 06, 00:26:58] [INFO] Current Parameter Settings:
[Jan 06, 00:26:58] [INFO]   config = '/data/data/net.rimoto.android/cache/android.conf'
[Jan 06, 00:26:58] [INFO]   mode = 0
[Jan 06, 00:26:58] [INFO]   show_ciphers = DISABLED
[Jan 06, 00:26:58] [INFO]   show_digests = DISABLED
[Jan 06, 00:26:58] [INFO]   show_engines = DISABLED
[Jan 06, 00:26:58] [INFO]   genkey = DISABLED
[Jan 06, 00:26:58] [INFO]   key_pass_file = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   show_tls_ciphers = DISABLED
[Jan 06, 00:26:58] [INFO]   connect_retry_max = 5
[Jan 06, 00:26:58] [INFO] Connection profiles [0]:
[Jan 06, 00:26:58] [INFO]   proto = udp
[Jan 06, 00:26:58] [INFO] Log (no context) resid 2131230834CONNECTED HSPA+ to MOBILE internet.golantelecom.net.il
[Jan 06, 00:26:58] [INFO]   local = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   local_port = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   remote = 'node4.rimoto.net'
[Jan 06, 00:26:58] [INFO]   remote_port = '2194'
[Jan 06, 00:26:58] [INFO]   remote_float = DISABLED
[Jan 06, 00:26:58] [INFO]   bind_defined = DISABLED
[Jan 06, 00:26:58] [INFO]   bind_local = DISABLED
[Jan 06, 00:26:58] [INFO]   bind_ipv6_only = DISABLED
[Jan 06, 00:26:58] [INFO]   connect_retry_seconds = 5
[Jan 06, 00:26:58] [INFO]   connect_timeout = 120
[Jan 06, 00:26:58] [INFO]   socks_proxy_server = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   socks_proxy_port = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   socks_proxy_retry = DISABLED
[Jan 06, 00:26:58] [INFO]   tun_mtu = 1500
[Jan 06, 00:26:58] [INFO]   tun_mtu_defined = ENABLED
[Jan 06, 00:26:58] [INFO]   link_mtu = 1500
[Jan 06, 00:26:58] [INFO]   link_mtu_defined = DISABLED
[Jan 06, 00:26:58] [INFO]   tun_mtu_extra = 0
[Jan 06, 00:26:58] [INFO]   tun_mtu_extra_defined = DISABLED
[Jan 06, 00:26:58] [INFO]   mtu_discover_type = -1
[Jan 06, 00:26:58] [INFO]   fragment = 0
[Jan 06, 00:26:58] [INFO]   mssfix = 1450
[Jan 06, 00:26:58] [INFO]   explicit_exit_notification = 0
[Jan 06, 00:26:58] [INFO] Connection profiles END
[Jan 06, 00:26:58] [INFO]   remote_random = DISABLED
[Jan 06, 00:26:58] [INFO]   ipchange = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   dev = 'tun'
[Jan 06, 00:26:58] [INFO]   dev_type = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   dev_node = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   lladdr = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   topology = 1
[Jan 06, 00:26:58] [INFO]   tun_ipv6 = DISABLED
[Jan 06, 00:26:58] [INFO]   ifconfig_local = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   ifconfig_remote_netmask = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   ifconfig_noexec = DISABLED
[Jan 06, 00:26:58] [INFO]   ifconfig_nowarn = ENABLED
[Jan 06, 00:26:58] [INFO]   ifconfig_ipv6_local = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   ifconfig_ipv6_netbits = 0
[Jan 06, 00:26:58] [INFO]   ifconfig_ipv6_remote = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   shaper = 0
[Jan 06, 00:26:58] [INFO]   mtu_test = 0
[Jan 06, 00:26:58] [INFO]   mlock = DISABLED
[Jan 06, 00:26:58] [INFO]   keepalive_ping = 0
[Jan 06, 00:26:58] [INFO]   keepalive_timeout = 0
[Jan 06, 00:26:58] [INFO]   inactivity_timeout = 0
[Jan 06, 00:26:58] [INFO]   ping_send_timeout = 0
[Jan 06, 00:26:58] [INFO]   ping_rec_timeout = 0
[Jan 06, 00:26:58] [INFO]   ping_rec_timeout_action = 0
[Jan 06, 00:26:58] [INFO]   ping_timer_remote = DISABLED
[Jan 06, 00:26:58] [INFO]   remap_sigusr1 = 0
[Jan 06, 00:26:58] [INFO]   persist_tun = ENABLED
[Jan 06, 00:26:58] [INFO]   persist_local_ip = DISABLED
[Jan 06, 00:26:58] [INFO]   persist_remote_ip = DISABLED
[Jan 06, 00:26:58] [INFO]   persist_key = DISABLED
[Jan 06, 00:26:58] [INFO]   passtos = DISABLED
[Jan 06, 00:26:58] [INFO]   resolve_retry_seconds = 1000000000
[Jan 06, 00:26:58] [INFO]   resolve_in_advance = ENABLED
[Jan 06, 00:26:58] [INFO]   username = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   groupname = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   chroot_dir = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   cd_dir = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   writepid = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   up_script = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   down_script = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   down_pre = DISABLED
[Jan 06, 00:26:58] [INFO]   up_restart = DISABLED
[Jan 06, 00:26:58] [INFO]   up_delay = DISABLED
[Jan 06, 00:26:58] [INFO]   daemon = DISABLED
[Jan 06, 00:26:58] [INFO]   inetd = 0
[Jan 06, 00:26:58] [INFO]   log = DISABLED
[Jan 06, 00:26:58] [INFO]   suppress_timestamps = DISABLED
[Jan 06, 00:26:58] [INFO]   machine_readable_output = ENABLED
[Jan 06, 00:26:58] [INFO]   nice = 0
[Jan 06, 00:26:58] [INFO]   verbosity = 4
[Jan 06, 00:26:58] [INFO]   mute = 0
[Jan 06, 00:26:58] [INFO]   gremlin = 0
[Jan 06, 00:26:58] [INFO]   status_file = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   status_file_version = 1
[Jan 06, 00:26:58] [INFO]   status_file_update_freq = 60
[Jan 06, 00:26:58] [INFO]   occ = ENABLED
[Jan 06, 00:26:58] [INFO]   rcvbuf = 0
[Jan 06, 00:26:58] [INFO]   sndbuf = 0
[Jan 06, 00:26:58] [INFO]   sockflags = 0
[Jan 06, 00:26:58] [INFO]   fast_io = DISABLED
[Jan 06, 00:26:58] [INFO]   comp.alg = 2
[Jan 06, 00:26:58] [INFO]   comp.flags = 1
[Jan 06, 00:26:58] [INFO]   route_script = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   route_default_gateway = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   route_default_metric = 0
[Jan 06, 00:26:58] [INFO]   route_noexec = DISABLED
[Jan 06, 00:26:58] [INFO]   route_delay = 0
[Jan 06, 00:26:58] [INFO]   route_delay_window = 30
[Jan 06, 00:26:58] [INFO]   route_delay_defined = DISABLED
[Jan 06, 00:26:58] [INFO]   route_nopull = DISABLED
[Jan 06, 00:26:58] [INFO]   route_gateway_via_dhcp = DISABLED
[Jan 06, 00:26:58] [INFO]   allow_pull_fqdn = DISABLED
[Jan 06, 00:26:58] [INFO]   management_addr = '/data/data/net.rimoto.android/cache/mgmtsocket'
[Jan 06, 00:26:58] [INFO]   management_port = 'unix'
[Jan 06, 00:26:58] [INFO]   management_user_pass = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   management_log_history_cache = 250
[Jan 06, 00:26:58] [INFO]   management_echo_buffer_size = 100
[Jan 06, 00:26:58] [INFO]   management_write_peer_info_file = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   management_client_user = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   management_client_group = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   management_flags = 4390
[Jan 06, 00:26:58] [INFO]   shared_secret_file = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   key_direction = 2
[Jan 06, 00:26:58] [INFO]   ciphername_defined = ENABLED
[Jan 06, 00:26:58] [INFO]   ciphername = 'BF-CBC'
[Jan 06, 00:26:58] [INFO]   authname_defined = ENABLED
[Jan 06, 00:26:58] [INFO]   authname = 'SHA1'
[Jan 06, 00:26:58] [INFO]   prng_hash = 'SHA1'
[Jan 06, 00:26:58] [INFO]   prng_nonce_secret_len = 16
[Jan 06, 00:26:58] [INFO]   keysize = 0
[Jan 06, 00:26:58] [INFO]   engine = DISABLED
[Jan 06, 00:26:58] [INFO]   replay = ENABLED
[Jan 06, 00:26:58] [INFO]   mute_replay_warnings = DISABLED
[Jan 06, 00:26:58] [INFO]   replay_window = 64
[Jan 06, 00:26:58] [INFO]   replay_time = 15
[Jan 06, 00:26:58] [INFO]   packet_id_file = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   use_iv = ENABLED
[Jan 06, 00:26:58] [INFO]   test_crypto = DISABLED
[Jan 06, 00:26:58] [INFO]   tls_server = DISABLED
[Jan 06, 00:26:58] [INFO]   tls_client = ENABLED
[Jan 06, 00:26:58] [INFO]   key_method = 2
[Jan 06, 00:26:58] [INFO]   ca_file = '[[INLINE]]'
[Jan 06, 00:26:58] [INFO]   ca_path = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   dh_file = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   cert_file = '[[INLINE]]'
[Jan 06, 00:26:58] [INFO]   extra_certs_file = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   priv_key_file = '[[INLINE]]'
[Jan 06, 00:26:58] [INFO]   pkcs12_file = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   cipher_list = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   tls_verify = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   tls_export_cert = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   verify_x509_type = 0
[Jan 06, 00:26:58] [INFO]   verify_x509_name = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   crl_file = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   ns_cert_type = 0
[Jan 06, 00:26:58] [INFO]   remote_cert_ku[i] = 0
[Jan 06, 00:26:58] [INFO]   remote_cert_ku[i] = 0
[Jan 06, 00:26:58] [INFO]   remote_cert_ku[i] = 0
[Jan 06, 00:26:58] [INFO]   remote_cert_ku[i] = 0
[Jan 06, 00:26:58] [INFO]   remote_cert_ku[i] = 0
[Jan 06, 00:26:58] [INFO]   remote_cert_ku[i] = 0
[Jan 06, 00:26:58] [INFO]   remote_cert_ku[i] = 0
[Jan 06, 00:26:58] [INFO]   remote_cert_ku[i] = 0
[Jan 06, 00:26:58] [INFO]   remote_cert_ku[i] = 0
[Jan 06, 00:26:58] [INFO]   remote_cert_ku[i] = 0
[Jan 06, 00:26:58] [INFO]   remote_cert_ku[i] = 0
[Jan 06, 00:26:58] [INFO]   remote_cert_ku[i] = 0
[Jan 06, 00:26:58] [INFO]   remote_cert_ku[i] = 0
[Jan 06, 00:26:58] [INFO]   remote_cert_ku[i] = 0
[Jan 06, 00:26:58] [INFO]   remote_cert_ku[i] = 0
[Jan 06, 00:26:58] [INFO]   remote_cert_ku[i] = 0
[Jan 06, 00:26:58] [INFO]   remote_cert_eku = '[UNDEF]'
[Jan 06, 00:26:58] [INFO]   ssl_flags = 0
[Jan 06, 00:26:58] [INFO]   tls_timeout = 2
[Jan 06, 00:26:58] [INFO]   renegotiate_bytes = 0
[Jan 06, 00:26:58] [INFO]   renegotiate_packets = 0
[Jan 06, 00:26:58] [INFO]   renegotiate_seconds = 3600
[Jan 06, 00:26:58] [INFO]   handshake_window = 60
[Jan 06, 00:26:58] [INFO]   transition_window = 3600
[Jan 06, 00:26:58] [INFO]   single_session = DISABLED
[Jan 06, 00:26:58] [INFO]   push_peer_info = DISABLED
[Jan 06, 00:26:58] [INFO]   tls_exit = DISABLED
[Jan 06, 00:26:58] [INFO]   tls_auth_file = '[[INLINE]]'
[Jan 06, 00:26:58] [INFO]   client = ENABLED
[Jan 06, 00:26:58] [INFO]   pull = ENABLED
[Jan 06, 00:26:58] [INFO]   auth_user_pass_file = '[UNDEF]'
[Jan 06, 00:26:58] [INFO] OpenVPN 2.4-icsopenvpn [git:HEAD-31df9c7c9789981f] android-14-armeabi-v7a [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH] [IPv6] built on Nov 21 2015
[Jan 06, 00:26:58] [INFO] library versions: OpenSSL 1.0.2d 9 Jul 2015, LZO 2.09
[Jan 06, 00:26:58] [INFO] MANAGEMENT: Connected to management server at /data/data/net.rimoto.android/cache/mgmtsocket
[Jan 06, 00:26:58] [INFO] MANAGEMENT: CMD 'hold release'
[Jan 06, 00:26:59] [INFO] MANAGEMENT: CMD 'bytecount 2'
[Jan 06, 00:26:59] [INFO] MANAGEMENT: CMD 'state on'
[Jan 06, 00:26:59] [INFO] MANAGEMENT: CMD 'proxy NONE'
[Jan 06, 00:27:00] [INFO] WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
[Jan 06, 00:27:00] [INFO] Control Channel Authentication: tls-auth using INLINE static key file
[Jan 06, 00:27:00] [INFO] Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
[Jan 06, 00:27:00] [INFO] Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
[Jan 06, 00:27:00] [INFO] LZO compression initializing
[Jan 06, 00:27:00] [INFO] Control Channel MTU parms [ L:1542 D:1184 EF:66 EB:0 ET:0 EL:3 ]
[Jan 06, 00:27:00] [INFO] Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:393 ET:0 EL:3 ]
[Jan 06, 00:27:00] [INFO] Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-client'
[Jan 06, 00:27:00] [INFO] Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-server'
[Jan 06, 00:27:00] [INFO] TCP/UDP: Preserving recently used remote address: [AF_INET]54.93.213.75:2194
[Jan 06, 00:27:00] [INFO] Socket Buffers: R=[163840->163840] S=[163840->163840]
[Jan 06, 00:27:00] [INFO] MANAGEMENT: CMD 'needok 'PROTECTFD' ok'
[Jan 06, 00:27:00] [INFO] UDP link local: (not bound)
[Jan 06, 00:27:00] [INFO] UDP link remote: [AF_INET]54.93.213.75:2194
[Jan 06, 00:27:00] [INFO] MANAGEMENT: >STATE:1452032820,WAIT,,,
[Jan 06, 00:27:00] [INFO] MANAGEMENT: >STATE:1452032820,AUTH,,,
[Jan 06, 00:27:00] [INFO] TLS: Initial packet from [AF_INET]54.93.213.75:2194, sid=189ef8ff 2d970843
[Jan 06, 00:27:01] [INFO] VERIFY OK: depth=1, C=IL, ST=Merkaz, O=Rimoto, OU=R&D, CN=Rimoto CORE Certificate Authority, emailAddress=dev@rimotosoftware.com
[Jan 06, 00:27:01] [INFO] VERIFY OK: depth=0, C=IL, ST=Merkaz, O=Rimoto, OU=Users, CN=54.93.213.75
[Jan 06, 00:27:02] [INFO] Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
[Jan 06, 00:27:02] [INFO] Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
[Jan 06, 00:27:02] [INFO] Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
[Jan 06, 00:27:02] [INFO] Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
[Jan 06, 00:27:02] [INFO] Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
[Jan 06, 00:27:02] [INFO] [54.93.213.75] Peer Connection Initiated with [AF_INET]54.93.213.75:2194
[Jan 06, 00:27:03] [INFO] MANAGEMENT: >STATE:1452032823,GET_CONFIG,,,
[Jan 06, 00:27:03] [INFO] SENT CONTROL [54.93.213.75]: 'PUSH_REQUEST' (status=1)
[Jan 06, 00:27:03] [INFO] PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1,dhcp-option DNS 10.7.1.1,route 10.50.0.1,topology net30,ping 10,ping-restart 30,ifconfig 10.50.0.10 10.50.0.9'
[Jan 06, 00:27:03] [INFO] OPTIONS IMPORT: timers and/or timeouts modified
[Jan 06, 00:27:03] [INFO] OPTIONS IMPORT: --ifconfig/up options modified
[Jan 06, 00:27:03] [INFO] OPTIONS IMPORT: route options modified
[Jan 06, 00:27:03] [INFO] OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
[Jan 06, 00:27:03] [INFO] ROUTE_GATEWAY 127.100.103.119/255.0.0.0 IFACE=lo HWADDR=00:00:00:00:00:00
[Jan 06, 00:27:03] [INFO] do_ifconfig, tt->ipv6=0, tt->did_ifconfig_ipv6_setup=0
[Jan 06, 00:27:03] [INFO] MANAGEMENT: >STATE:1452032823,ASSIGN_IP,,10.50.0.10,
[Jan 06, 00:27:03] [INFO] MANAGEMENT: CMD 'needok 'IFCONFIG' ok'
[Jan 06, 00:27:03] [INFO] MANAGEMENT: CMD 'needok 'ROUTE' ok'
[Jan 06, 00:27:03] [INFO] MANAGEMENT: >STATE:1452032823,ADD_ROUTES,,,
[Jan 06, 00:27:03] [INFO] MANAGEMENT: CMD 'needok 'ROUTE' ok'
[Jan 06, 00:27:03] [INFO] MANAGEMENT: CMD 'needok 'DNSSERVER' ok'
[Jan 06, 00:27:03] [INFO] MANAGEMENT: CMD 'needok 'PERSIST_TUN_ACTION' OPEN_BEFORE_CLOSE'
[Jan 06, 00:27:03] [INFO] Log (no context) resid 2131230989
[Jan 06, 00:27:03] [INFO] Log (no context) resid 213123099110.50.0.10|30|null|1500
[Jan 06, 00:27:03] [INFO] Log (no context) resid 213123093310.7.1.1|null
[Jan 06, 00:27:03] [INFO] Log (no context) resid 21312310480.0.0.0/0, 10.50.0.1/32, 10.50.0.8/30|
[Jan 06, 00:27:03] [INFO] Log (no context) resid 2131231047|
[Jan 06, 00:27:03] [DEBUG] Log (no context) resid 21312310460.0.0.0/0|
[Jan 06, 00:27:03] [DEBUG] Log (no context) resid 2131230889null, com.microsoft.office.officehub, com.sec.android.app.sbrowser, net.rimoto.android, com.android.captiveportallogin, com.android.settings, com.google.android.gms, com.android.chrome, com.google.android.apps.maps, com.google.android.gm, com.ubercab, com.waze, fake.bundle.id.nan, com.google.android.browser, com.whatsapp
[Jan 06, 00:27:03] [INFO] MANAGEMENT: CMD 'needok 'OPENTUN' ok'
[Jan 06, 00:27:03] [INFO] Initialization Sequence Completed
[Jan 06, 00:27:03] [INFO] MANAGEMENT: >STATE:1452032823,CONNECTED,SUCCESS,10.50.0.10,54.93.213.75
null
schwabe commented 8 years ago

That is really strange. From the client point of view everything went fine.

AlmogBaku commented 8 years ago

I know.. maybe there is a thing I can add to the VpnStatus to log?

(btw, did you received my emails? :) I wanna move forward with my proposal)

AlmogBaku commented 8 years ago

Manually disconnecting and connecting established a valid connection, so it's not a bug with "misconfigured network config"(that required a reboot).

It's really weird, especially since I can't reproduce it..

TaranTii commented 5 years ago

Hi @AlmogBaku

Hope you doing well I want to print these logs. Please help me out https://github.com/schwabe/ics-openvpn/issues/429#issue-125068024

AlmogBaku commented 4 years ago

@TaranTii sorry, I don't remember...