Extra whitespace on IP parameters causes crash about ics-openconnect HOT 13 CLOSED

@cernekee
Thanks you so much for helping troubleshooting! I finally identified the root cause. The DNS address accidentally appended with a whitespace (in fact, a space), but I think the app can improve itself as Cisco Anyconnect can handle this case intelligently and gracefully.

06-07 10:53:41.253 17869 17869 D ACRA    : Looking for error files in /data/user/0/app.openconnect/files
06-07 10:53:41.254 17869 17869 D ACRA    : Deleting file 1496803989000.stacktrace
06-07 10:53:57.568 17869 17869 E ActionBarOverlayLayout: Requested split action bar with incompatible window decor! Ignoring request.
06-07 10:53:57.625 17869 17869 D OpenConnect: file not found reading /data/user/0/app.openconnect/cache/logdata.ser
06-07 10:53:57.691  1051  1401 I ActivityManager: Displayed app.openconnect/.MainActivity: +176ms
06-07 10:54:02.129  1051  3986 I ActivityManager: START u0 {act=android.intent.action.MAIN cmp=app.openconnect/.api.GrantPermissionsActivity
 (has extras)} from uid 10121 on display 0
06-07 10:54:02.201 17869 17869 W OpenConnect: removing bogus profile 'profile-b12703bc-a412-40d1-b76a-29183125a43b.xml.bak'
06-07 10:54:02.220 17869 17996 D OpenConnect: AssetExtractor: skipping /data/user/0/app.openconnect/files/android_csd.sh
06-07 10:54:02.221 17869 17996 D OpenConnect: AssetExtractor: skipping /data/user/0/app.openconnect/files/run_pie
06-07 10:54:02.227 17869 17996 D OpenConnect: AssetExtractor: skipping /data/user/0/app.openconnect/files/curl-bin
06-07 10:54:03.857 17869 17996 E ACRA    : ACRA caught a IllegalArgumentException exception for app.openconnect. Building report.
06-07 10:54:03.861 17869 17996 D ACRA    : Using default Report Fields
06-07 10:54:03.942 17869 17996 W Settings: Setting button_backlight_timeout has moved from android.provider.Settings.System to android.provi
der.Settings.Secure, returning read-only value.
06-07 10:54:03.944 17869 17996 W Settings: Setting button_brightness has moved from android.provider.Settings.System to android.provider.Set
tings.Secure, returning read-only value.
06-07 10:54:03.948 17869 17996 W Settings: Setting keyboard_brightness has moved from android.provider.Settings.System to android.provider.S
ettings.Secure, returning read-only value.
06-07 10:54:04.168 17869 17996 I ACRA    : READ_LOGS granted! ACRA can include LogCat and DropBox data.
06-07 10:54:04.176 17869 17996 D ACRA    : Retrieving logcat output...
06-07 10:54:04.208 17869 17996 D ACRA    : Writing crash report file 1496804044000.stacktrace.
06-07 10:54:04.226 17869 18023 D ACRA    : Waiting for Toast + worker...
06-07 10:54:04.226 17869 18023 D ACRA    : About to create DIALOG from #handleException
06-07 10:54:04.226 17869 18023 D ACRA    : Creating Dialog for 1496804044000.stacktrace
06-07 10:54:04.227  1051 19257 I ActivityManager: START u0 {flg=0x10000000 cmp=app.openconnect/org.acra.CrashReportDialog (has extras)} from
 uid 10121 on display 0
06-07 10:54:04.239 17869 18023 D ACRA    : Wait for Toast + worker ended. Kill Application ? true
06-07 10:54:04.240 17869 18023 E ACRA    : app.openconnect fatal error : Not a numeric address: 8.8.8.8
06-07 10:54:04.240 17869 18023 E ACRA    : java.lang.IllegalArgumentException: Not a numeric address: 8.8.8.8
06-07 10:54:04.240 17869 18023 E ACRA    :      at java.net.InetAddress.parseNumericAddress(InetAddress.java:933)
06-07 10:54:04.240 17869 18023 E ACRA    :      at android.net.VpnService$Builder.addDnsServer(VpnService.java:558)
06-07 10:54:04.240 17869 18023 E ACRA    :      at app.openconnect.core.OpenConnectManagementThread.setIPInfo(OpenConnectManagementThread.ja
va:636)
06-07 10:54:04.240 17869 18023 E ACRA    :      at app.openconnect.core.OpenConnectManagementThread.runVPN(OpenConnectManagementThread.java:
731)
06-07 10:54:04.240 17869 18023 E ACRA    :      at app.openconnect.core.OpenConnectManagementThread.run(OpenConnectManagementThread.java:282
)
06-07 10:54:04.240 17869 18023 E ACRA    :      at java.lang.Thread.run(Thread.java:761)
06-07 10:54:04.240 17869 18023 I ACRA    : Finishing the last Activity prior to killing the Process
06-07 10:54:04.241 17869 18023 I ACRA    : Finished class app.openconnect.api.GrantPermissionsActivity
06-07 10:54:04.241 17869 18023 I Process : Sending signal. PID: 17869 SIG: 9
06-07 10:54:04.257  1051 18760 I WindowManager: WIN DEATH: Window{a724724 u0 app.openconnect/app.openconnect.MainActivity}
06-07 10:54:04.257  1051  3969 D GraphicsStats: Buffer count: 7
06-07 10:54:04.258  1051  3969 I ActivityManager: Process app.openconnect (pid 17869) has died
06-07 10:54:04.258  1051  3969 D ActivityManager: cleanUpApplicationRecord -- 17869
06-07 10:54:04.258  1051  3969 W ActivityManager: Scheduling restart of crashed service app.openconnect/.core.OpenVpnService in 1000ms
06-07 10:54:04.259  1051  3969 W ActivityManager: Force removing ActivityRecord{5ce9e3a u0 app.openconnect/.MainActivity t1406}: app died, n
o saved state
06-07 10:54:04.277  1051  3969 I ActivityManager: Start proc 18029:app.openconnect/u0a121 for activity app.openconnect/org.acra.CrashReportD
ialog
06-07 10:54:04.332 18029 18029 D ACRA    : ACRA is enabled for app.openconnect, intializing...
06-07 10:54:04.341 18029 18029 D ACRA    : Looking for error files in /data/user/0/app.openconnect/files
06-07 10:54:04.341 18029 18029 D ACRA    : Looking for error files in /data/user/0/app.openconnect/files
06-07 10:54:04.342 18029 18029 D ACRA    : Looking for error files in /data/user/0/app.openconnect/files
06-07 10:54:04.350 18029 18029 W linker  : /data/app/app.openconnect-1/lib/arm/libopenconnect.so has text relocations. This is wasting memor
y and prevents security hardening. Please fix.
06-07 10:54:04.352 18029 18029 W linker  : /data/app/app.openconnect-1/lib/arm/libstoken.so has text relocations. This is wasting memory and
 prevents security hardening. Please fix.
06-07 10:54:04.359 18029 18029 D ACRA    : Opening CrashReportDialog for 1496804044000.stacktrace
06-07 10:54:04.515  1051  1401 I ActivityManager: Displayed app.openconnect/org.acra.CrashReportDialog: +249ms (total +2s376ms)

from ics-openconnect.

from ics-openconnect.

On Android, before the app dies, it spits such info:
"An unexpected error occurred forcing the application to stop. You can help us fix this by sending us error data.

Please describe what was happening when the problem occurred:
[blank
txt
box]
"

from ics-openconnect.

Ocserv exposes weird 'GnuTLS error' in its log:

sudo ocserv -fd 9 -c /etc/ocserv/ocserv.conf

ocserv[21154]: worker[gfw]: 111.222.111.222 HTTP processing: Host: my.example.com
ocserv[21154]: worker[gfw]: 111.222.111.222 HTTP processing: User-Agent: OpenConnect VPN Agent (Java) v7.04-unknown
ocserv[21154]: worker[gfw]: 111.222.111.222 User-agent: 'OpenConnect VPN Agent (Java) v7.04-unknown'
ocserv[21154]: worker[gfw]: 111.222.111.222 HTTP processing: Cookie: webvpn=iXGDC8tdx5ugcxGqhEdO5E7r8YZS9fx6rXTv+TIh36o=
ocserv[21154]: worker[gfw]: 111.222.111.222 HTTP processing: X-CSTP-Version: 1
ocserv[21154]: worker[gfw]: 111.222.111.222 HTTP processing: X-CSTP-Hostname: localhost
ocserv[21154]: worker[gfw]: 111.222.111.222 HTTP processing: X-AnyConnect-Identifier-ClientVersion: v7.04-unknown
ocserv[21154]: worker[gfw]: 111.222.111.222 HTTP processing: X-AnyConnect-Identifier-Platform: android
ocserv[21154]: worker[gfw]: 111.222.111.222 Platform: 'android' (mobile)
ocserv[21154]: worker[gfw]: 111.222.111.222 HTTP processing: X-AnyConnect-Identifier-PlatformVersion: 1.0
ocserv[21154]: worker[gfw]: 111.222.111.222 HTTP processing: X-AnyConnect-Identifier-DeviceType: android
ocserv[21154]: worker[gfw]: 111.222.111.222 Device-type: 'android'
ocserv[21154]: worker[gfw]: 111.222.111.222 HTTP processing: X-AnyConnect-Identifier-Device-UniqueID: AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
ocserv[21154]: worker[gfw]: 111.222.111.222 HTTP processing: X-CSTP-Accept-Encoding: oc-lz4,lzs
ocserv[21154]: worker[gfw]: 111.222.111.222 HTTP processing: X-CSTP-MTU: 1406
ocserv[21154]: worker[gfw]: 111.222.111.222 HTTP processing: X-CSTP-Address-Type: IPv6,IPv4
ocserv[21154]: worker[gfw]: 111.222.111.222 HTTP processing: X-CSTP-Full-IPv6-Capability: true
ocserv[21154]: worker[gfw]: 111.222.111.222 HTTP processing: X-DTLS-Master-Secret: E50A18B04ED8DB4D5B599221CCCD3B722A64B113A947280AE6C52DB616DCE8F39DBC5D6C01A38E7B5786D6760A44C563
ocserv[21154]: worker[gfw]: 111.222.111.222 HTTP processing: X-DTLS-CipherSuite: OC-DTLS1_2-AES256-GCM:OC-DTLS1_2-AES128-GCM:AES256-SHA:AES128-SHA:DES-CBC3-SHA:DES-CBC-SHA
ocserv[21154]: worker[gfw]: 111.222.111.222 HTTP processing: X-DTLS-Accept-Encoding: oc-lz4,lzs
ocserv[21154]: worker[gfw]: 111.222.111.222 HTTP CONNECT /CSCOSSLC/tunnel
ocserv[21154]: worker[gfw]: 111.222.111.222 sending message 'auth cookie request' to main
ocserv[21152]: main: 111.222.111.222:58998 main received worker's message 'auth cookie request' of 34 bytes
ocserv[21152]: main: 111.222.111.222:58998 sending msg sm: session open to sec-mod
ocserv[21153]: sec-mod: received request sm: session open
ocserv[21153]: sec-mod: cmd [size=34] sm: session open
ocserv[21153]: sec-mod: initiating session for user 'gfw' (session: Ft63uJ)
ocserv[21152]: main[gfw]: 111.222.111.222:58998 new user session
ocserv[21152]: main[gfw]: 111.222.111.222:58998 selected IP: 10.0.0.12
ocserv[21152]: main[gfw]: 111.222.111.222:58998 assigned IPv4: 10.0.0.12
ocserv[21152]: main[gfw]: 111.222.111.222:58998 assigning tun device octun0
ocserv[21152]: main[gfw]: 111.222.111.222:58998 user of group '*' authenticated (using cookie)
ocserv[21152]: main[gfw]: 111.222.111.222:58998 sending (socket) message 2 to worker
ocserv[21154]: worker[gfw]: 111.222.111.222 received auth reply message (value: 1)
ocserv[21154]: worker[gfw]: 111.222.111.222 suggesting DPD of 1800 secs
ocserv[21154]: worker[gfw]: 111.222.111.222 configured link MTU is 1500
ocserv[21154]: worker[gfw]: 111.222.111.222 peer's data MTU is 1406 / link is 1500
ocserv[21154]: worker[gfw]: 111.222.111.222 DTLS overhead is 66
ocserv[21154]: worker[gfw]: 111.222.111.222 sending IPv4 10.0.0.12
ocserv[21154]: worker[gfw]: 111.222.111.222 adding DNS 8.8.8.8
ocserv[21154]: worker[gfw]: 111.222.111.222 adding DNS 8.8.4.4
ocserv[21154]: worker[gfw]: 111.222.111.222 DTLS ciphersuite: OC-DTLS1_2-AES128-GCM
ocserv[21154]: worker[gfw]: 111.222.111.222 DTLS data MTU 1434
ocserv[21154]: worker[gfw]: 111.222.111.222 Link MTU is 1500 bytes
ocserv[21154]: worker[gfw]: 111.222.111.222 sending message 'tun mtu change' to main
ocserv[21154]: worker[gfw]: 111.222.111.222 setting data MTU to 1434
ocserv[21154]: worker[gfw]: 111.222.111.222 selected DTLS compression method oc-lz4
ocserv[21154]: worker[gfw]: 111.222.111.222 selected CSTP compression method oc-lz4
ocserv[21154]: TLS[<5>]: REC[0x1c13010]: Preparing Packet Application Data(23) with length: 908 and min pad: 0
ocserv[21154]: TLS[<9>]: ENC[0x1c13010]: cipher: AES-128-GCM, MAC: AEAD, Epoch: 1
ocserv[21154]: TLS[<5>]: REC[0x1c13010]: Sent Packet[5] Application Data(23) in epoch 1 and length: 937
ocserv[21152]: main[gfw]: 111.222.111.222:58998 user logged in
ocserv[21152]: main[gfw]: 111.222.111.222:58998 main received worker's message 'tun mtu change' of 3 bytes
ocserv[21152]: main[gfw]: 111.222.111.222:58998 setting octun0 MTU to 1434
ocserv[21154]: TLS[<3>]: ASSERT: gnutls_buffers.c:551
ocserv[21154]: TLS[<3>]: ASSERT: gnutls_record.c:1064
ocserv[21154]: TLS[<3>]: ASSERT: gnutls_record.c:1185
ocserv[21154]: TLS[<3>]: ASSERT: gnutls_record.c:1447
ocserv[21154]: worker[gfw]: 111.222.111.222 worker-vpn.c:1261: GnuTLS error (at worker-vpn.c:1261): The TLS connection was non-properly terminated.
ocserv[21154]: worker[gfw]: 111.222.111.222 sending message 'sm: worker cli stats' to secmod
ocserv[21153]: sec-mod: received request from pid 21154 and uid 65534
ocserv[21153]: sec-mod: cmd [size=69] sm: worker cli stats
ocserv[21154]: worker[gfw]: 111.222.111.222 sent periodic stats (in: 0, out: 0) to sec-mod
ocserv[21152]: main[gfw]: 111.222.111.222:58998 worker terminated
ocserv[21152]: main[gfw]: 111.222.111.222:58998 sending msg sm: session close to sec-mod
ocserv[21153]: sec-mod: received request sm: session close
ocserv[21153]: sec-mod: cmd [size=40] sm: session close
ocserv[21153]: sec-mod: temporarily closing session for gfw (session: Ft63uJ)
ocserv[21152]: main[gfw]: 111.222.111.222:58998 user disconnected (reason: unspecified error, rx: 0, tx: 0)

from ics-openconnect.

The ocserv configuration:

cat /etc/ocserv/ocserv.conf

auth = "plain[/etc/ocserv/ocpasswd]"
max-clients = 0
max-same-clients = 0
tcp-port = 443 
udp-port = 443
keepalive = 32400
dpd = 90
mobile-dpd = 1800
try-mtu-discovery = false
server-cert = /etc/letsencrypt/live/my.example.com/fullchain.pem
server-key = /etc/letsencrypt/live/my.example.com/privkey.pem
auth-timeout = 40
cookie-timeout = 300
deny-roaming = false
rekey-time = 172800
rekey-method = ssl
use-utmp = true
use-occtl = true
pid-file = /var/run/ocserv.pid
socket-file = /var/run/ocserv-socket
run-as-user = nobody
run-as-group = nogroup
device = octun
predictable-ips = true
ipv4-network = 10.0.0.0
ipv4-netmask = 255.255.255.0
dns = 8.8.8.8 
dns = 8.8.4.4
ping-leases = false
compression = true
output-buffer = 23000 
try-mtu-discovery = true

from ics-openconnect.

@ildar I believe you can reproduce the issue easily with above setting on your own test bed.

from ics-openconnect.

from ics-openconnect.

Please describe what was happening when the problem occurred

If you put some keywords in there (like "Bug19") I can try to search for the report to see where it's crashing. Otherwise, posting a logcat is probably your best bet.

from ics-openconnect.

@cernekee as long as you use this app on last two years' Android (6+) and connect to ocserv (open source alternative to Cisco SSL VPN) you should meet this issue. There is no magic scenario but a very common one. Since the last official release of this app was delivered 2.5 years before, I don't think any developers or even users take serious for the app. Very sorry to see this project dies in this way.

from ics-openconnect.

I'm running the app on Android 7.1, connected to an ocserv instance 24/7. Haven't had a problem in years.

It is likely that you're hitting a corner case. Posting the logcat (or giving me something to search for in the ACRA problem report database) would allow me to see what's breaking.

from ics-openconnect.

@cernekee if so, you can temporarily adjust your ocserv setting according to my above example to see the result.
B.T.W. don't use those ocserv release which more than 2 years old. Yes, I was happy to use both this app and ocserv 2 years before, but after first updating the ocserv and then Android to 6, the nightmare never goes away.

from ics-openconnect.

@cernekee can you elaborate how to capture the logcat? I'm not a developer of Android, but I think I would like to do what I can to give more traces on this issue. Thanks!

from ics-openconnect.

1. Install adb
2. Run adb logcat right before the problem occurs, and redirect/save to a file
3. Connect to the server and make the app crash
4. Stop adb

from ics-openconnect.