search

cernekee / ics-openconnect

Android UI for OpenConnect VPN client
GNU General Public License v2.0
358 stars 130 forks source link

Extra whitespace on IP parameters causes crash #19

Closed moralrebuild closed 6 years ago

moralrebuild commented 7 years ago

The crash happen just when setup the connection and authentication pass, this client crashed immediately. It's an issue existing for more than 2 years, the server side is ocserv with latest version. In fact, the Cisco Anyconnect works perfect for the same VPN server. Could somebody take a serious look? I knew most people use the anyconnect, but I don't want to use it for its poor user friendness.

ildar commented 7 years ago
  1. Clear app data
  2. get the logcat
moralrebuild commented 7 years ago

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] "

moralrebuild commented 7 years ago

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)

moralrebuild commented 7 years ago

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
moralrebuild commented 7 years ago

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

ildar commented 7 years ago

Em, sorry. I'm not a developer actually, just a user. I think that logcat would haste a problem resolution. Generally. Although this particular upstream doesn't move for a long time...

cernekee commented 7 years ago

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.

moralrebuild commented 7 years ago

@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.

cernekee commented 7 years ago

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.

moralrebuild commented 7 years ago

@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.

moralrebuild commented 7 years ago

@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!

cernekee commented 7 years ago

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

moralrebuild commented 7 years ago

@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)