The latest ocserv cannot work well with IOS Anyconnect using profile.xml

Yick Xie yick.xie at gmail.com
Mon Dec 21 10:57:02 PST 2015


Hi Nikos,

Sorry for the size of the log I sent before, please check my log
without --leak-check=full option.

valgrind ocserv -c /etc/ocserv/config -d 4 -f
==9640== Memcheck, a memory error detector
==9640== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==9640== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==9640== Command: ocserv -c /etc/ocserv/config -d 4 -f
==9640==
Setting 'radius' as primary authentication method
Enabling 'certificate' as authentication method
listening (TCP) on 0.0.0.0:443...
listening (UDP) on 0.0.0.0:443...
ocserv[9640]: main: initializing control unix socket: /var/run/occtl.socket
ocserv[9640]: main: initialized ocserv 0.11.0
ocserv[9641]: sec-mod: reading supplemental config from radius
ocserv[9641]: sec-mod: sec-mod initialized (socket: /var/run/ocserv-socket.9640)
ocserv[9641]: sec-mod: received request from pid 9640 and uid 0
ocserv[9641]: sec-mod: cmd [size=55] sm: sign
ocserv[9640]: main: processed 1 CA certificate(s)
ocserv[9642]: worker:  accepted connection
ocserv[9642]: worker:  client certificate verification succeeded
ocserv[9641]: sec-mod: received request from pid 9642 and uid 65534
ocserv[9641]: sec-mod: cmd [size=261] sm: decrypt
ocserv[9641]: sec-mod: received request from pid 9642 and uid 65534
ocserv[9642]: worker:  sending message 'resume data store request' to secmod
ocserv[9641]: sec-mod: cmd [size=1220] resume data store request
ocserv[9642]: worker:  TLS handshake completedocserv[9641]: sec-mod:
TLS session DB storing
f7318441530b6e4848498d29fba7e37a29d66b2c5b3f86ae44c1b8d4b16c3589
ocserv[9642]: worker:  sending message 'session info' to main
ocserv[9640]: main: 1xx.9x.1x.7x:49624 main received message 'session
info' of 6 bytes

ocserv[9642]: worker: 1xx.9x.1x.7x HTTP processing: User-Agent:
AnyConnect AppleSSLVPN_Darwin_ARM (iPhone) 4.0.03016
ocserv[9642]: worker: 1xx.9x.1x.7x User-agent: 'AnyConnect
AppleSSLVPN_Darwin_ARM (iPhone) 4.0.'
ocserv[9642]: worker: 1xx.9x.1x.7x HTTP processing: Host: 1**.8*.1*.2**:443
ocserv[9642]: worker: 1xx.9x.1x.7x HTTP processing: Accept: */*
ocserv[9642]: worker: 1xx.9x.1x.7x HTTP processing: Accept-Encoding: identity
ocserv[9642]: worker: 1xx.9x.1x.7x HTTP processing: X-Transcend-Version: 1
ocserv[9642]: worker: 1xx.9x.1x.7x HTTP processing: X-Transcend-Version: 1
ocserv[9642]: worker: 1xx.9x.1x.7x HTTP processing:
X-AnyConnect-Identifier-ClientVersion: 4.0.03016
ocserv[9642]: worker: 1xx.9x.1x.7x HTTP processing:
X-AnyConnect-Identifier-Platform: apple-ios
ocserv[9642]: worker: 1xx.9x.1x.7x HTTP processing:
X-AnyConnect-Identifier-PlatformVersion: 7.1.2
ocserv[9642]: worker: 1xx.9x.1x.7x HTTP processing:
X-AnyConnect-Identifier-DeviceType: iPhone4,1
ocserv[9642]: worker: 1xx.9x.1x.7x HTTP processing:
X-AnyConnect-Identifier-Device-UniqueID:
55307d20b7d8b69b04f3d9a99f5d06d72e3b384b
ocserv[9642]: worker: 1xx.9x.1x.7x HTTP processing:
X-AnyConnect-Identifier-Device-MacAddress: unknown
ocserv[9642]: worker: 1xx.9x.1x.7x HTTP processing:
X-AnyConnect-Identifier-Device-Imei: UNKNOWN:unknown
ocserv[9642]: worker: 1xx.9x.1x.7x HTTP processing: X-Aggregate-Auth: 1
ocserv[9642]: worker: 1xx.9x.1x.7x HTTP processing: Connection: close
ocserv[9642]: worker: 1xx.9x.1x.7x HTTP processing: Content-Length: 476
ocserv[9642]: worker: 1xx.9x.1x.7x HTTP processing: Content-Type:
application/x-www-form-urlencoded
ocserv[9642]: worker: 1xx.9x.1x.7x HTTP POST /
ocserv[9642]: worker: 1xx.9x.1x.7x POST body: '<?xml version="1.0"
encoding="UTF-8"?>
<config-auth client="vpn" type="init">
<device-id platform-version="7.1.2" device-type="iPhone4,1"
unique-id="55307d20b7d8b69b04f3d9a99f5d06d72e3b384b">apple-ios</device-id>
<phone-id>UNKNOWN:unknown</phone-id>
<mac-address-list>
<mac-address>unknown</mac-address></mac-address-list>
<version who="vpn">4.0.03016</version>
<group-select>admin-global</group-select>
<group-access>https://1**.8*.1*.2**:443/</group-access>
</config-auth>
'
ocserv[9641]: sec-mod: received request from pid 9642 and uid 65534
ocserv[9642]: worker: 1xx.9x.1x.7x sending message 'sm: auth init' to secmod
ocserv[9641]: sec-mod: cmd [size=59] sm: auth init
ocserv[9641]: sec-mod: using 'certificate' authentication to
authenticate user (session: liM8X)
ocserv[9641]: sec-mod: auth init (with cert) for user 'admin'
(session: liM8X) of group: '' from '1xx.9x.1x.7x'
ocserv[9642]: worker: 1xx.9x.1x.7x received auth reply message (value: 1)
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x user 'admin' obtained cookie
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x HTTP sending: 200 OK
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x sent sid: liM8X7y454gA4Kg4Codojw==
ocserv[9643]: worker:  accepted connection
ocserv[9643]: worker:  tlslib.c:379: no certificate was found
ocserv[9641]: sec-mod: received request from pid 9643 and uid 65534
ocserv[9641]: sec-mod: cmd [size=261] sm: decrypt
ocserv[9641]: sec-mod: received request from pid 9643 and uid 65534
ocserv[9643]: worker:  sending message 'resume data store request' to secmod
ocserv[9641]: sec-mod: cmd [size=355] resume data store request
ocserv[9641]: sec-mod: TLS session DB storing
0f5a834200c917a189a122fcf832da481d6d71922fe2083ef9cb49fa345d002f
ocserv[9643]: worker:  TLS handshake completed
ocserv[9643]: worker:  sending message 'session info' to main
ocserv[9640]: main: 1xx.9x.1x.7x:49625 main received message 'session
info' of 6 bytes
ocserv[9643]: worker: 1xx.9x.1x.7x HTTP processing: User-Agent:
AnyConnect ERROR_NOT_USED 4.0.03016
ocserv[9643]: worker: 1xx.9x.1x.7x User-agent: 'AnyConnect
ERROR_NOT_USED 4.0.03016'
ocserv[9643]: worker: 1xx.9x.1x.7x HTTP processing: Host: 1**.8*.1*.2**:443
ocserv[9643]: worker: 1xx.9x.1x.7x HTTP processing: Accept: */*
ocserv[9643]: worker: 1xx.9x.1x.7x HTTP processing: Cookie: (censored)
ocserv[9643]: worker: 1xx.9x.1x.7x HTTP GET /profiles//etc/ocserv/profile.xml
ocserv[9643]: worker: 1xx.9x.1x.7x requested config:
/profiles//etc/ocserv/profile.xml
==9643== Invalid read of size 8
==9643==    at 0x42671B: get_config_handler (worker-http-handlers.c:51)
==9643==    by 0x40C26A: vpn_server (worker-vpn.c:534)
==9643==    by 0x40910D: listen_watcher_cb (main.c:1061)
==9643==    by 0x6227E44: ev_invoke_pending (in
/usr/lib/x86_64-linux-gnu/libev.so.4.0.0)
==9643==    by 0x622AFE6: ev_run (in /usr/lib/x86_64-linux-gnu/libev.so.4.0.0)
==9643==    by 0x409DB4: main (main.c:1342)
==9643==  Address 0xa0 is not stack'd, malloc'd or (recently) free'd
==9643==
==9643==
==9643== Process terminating with default action of signal 11 (SIGSEGV)
==9643==  Access not within mapped region at address 0xA0
==9643==    at 0x42671B: get_config_handler (worker-http-handlers.c:51)
==9643==    by 0x40C26A: vpn_server (worker-vpn.c:534)
==9643==    by 0x40910D: listen_watcher_cb (main.c:1061)
==9643==    by 0x6227E44: ev_invoke_pending (in
/usr/lib/x86_64-linux-gnu/libev.so.4.0.0)
==9643==    by 0x622AFE6: ev_run (in /usr/lib/x86_64-linux-gnu/libev.so.4.0.0)
==9643==    by 0x409DB4: main (main.c:1342)
==9643==  If you believe this happened as a result of a stack
==9643==  overflow in your program's main thread (unlikely but
==9643==  possible), you can try to increase the size of the
==9643==  main thread stack using the --main-stacksize= flag.
==9643==  The main thread stack size used in this run was 8388608.
==9643== Invalid free() / delete / delete[] / realloc()
==9643==    at 0x4C2BD57: free (vg_replace_malloc.c:530)
==9643==    by 0x679B5AB: __libc_freeres (in /lib/x86_64-linux-gnu/libc-2.19.so)
==9643==    by 0x4A256B1: _vgnU_freeres (vg_preloaded.c:65)
==9643==    by 0xFFEFFFA3F: ???
==9643==    by 0x40C26A: vpn_server (worker-vpn.c:534)
==9643==    by 0x40910D: listen_watcher_cb (main.c:1061)
==9643==    by 0x6227E44: ev_invoke_pending (in
/usr/lib/x86_64-linux-gnu/libev.so.4.0.0)
==9643==    by 0x622AFE6: ev_run (in /usr/lib/x86_64-linux-gnu/libev.so.4.0.0)
==9643==    by 0x409DB4: main (main.c:1342)
==9643==  Address 0x69f43c0 is 0 bytes inside data symbol "noai6ai_cached"
==9643==
==9643==
==9643== HEAP SUMMARY:
==9643==     in use at exit: 203,277 bytes in 1,041 blocks
==9643==   total heap usage: 3,370 allocs, 2,330 frees, 1,123,308
bytes allocated
==9643==
==9643== LEAK SUMMARY:
==9643==    definitely lost: 8,192 bytes in 1 blocks
==9643==    indirectly lost: 0 bytes in 0 blocks
==9643==      possibly lost: 63,755 bytes in 230 blocks
==9643==    still reachable: 131,330 bytes in 810 blocks
==9643==         suppressed: 0 bytes in 0 blocks
==9643== Rerun with --leak-check=full to see details of leaked memory
==9643==
==9643== For counts of detected and suppressed errors, rerun with: -v
==9643== ERROR SUMMARY: 2 errors from 2 contexts (suppressed: 0 from 0)
ocserv[9640]: main: 1xx.9x.1x.7x:49625 command socket closed
ocserv[9640]: main: 1xx.9x.1x.7x:49625 user disconnected (reason:
unspecified, rx: 0, tx: 0)
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x HTTP processing: User-Agent:
AnyConnect AppleSSLVPN_Darwin_ARM (iPhone) 4.0.03016
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x User-agent: 'AnyConnect
AppleSSLVPN_Darwin_ARM (iPhone) 4.0.'
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x HTTP processing: Host:
1**.8*.1*.2**:443
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x HTTP processing: Accept: */*
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x HTTP processing:
Accept-Encoding: identity
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x HTTP processing: Cookie: (censored)
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x received sid: liM8X7y454gA4Kg4Codojw==
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x HTTP processing:
X-Transcend-Version: 1
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x HTTP processing:
X-Transcend-Version: 1
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x HTTP processing:
X-AnyConnect-Identifier-ClientVersion: 4.0.03016
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x HTTP processing:
X-AnyConnect-Identifier-Platform: apple-ios
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x HTTP processing:
X-AnyConnect-Identifier-PlatformVersion: 7.1.2
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x HTTP processing:
X-AnyConnect-Identifier-DeviceType: iPhone4,1
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x HTTP processing:
X-AnyConnect-Identifier-Device-UniqueID:
55307d20b7d8b69b04f3d9a99f5d06d72e3b384b
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x HTTP processing:
X-AnyConnect-Identifier-Device-MacAddress: unknown
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x HTTP processing:
X-AnyConnect-Identifier-Device-Imei: UNKNOWN:unknown
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x HTTP processing: X-Aggregate-Auth: 1
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x HTTP processing: Cookie: (censored)
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x HTTP GET //logout
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x HTTP sending: 200 OK
ocserv[9642]: worker[admin]: 1xx.9x.1x.7x sent sid: liM8X7y454gA4Kg4Codojw==
==9642== Invalid free() / delete / delete[] / realloc()
==9642==    at 0x4C2BD57: free (vg_replace_malloc.c:530)
==9642==    by 0x679B5AB: __libc_freeres (in /lib/x86_64-linux-gnu/libc-2.19.so)
==9642==    by 0x4A256B1: _vgnU_freeres (vg_preloaded.c:65)
==9642==    by 0x667221A: __run_exit_handlers (exit.c:97)
==9642==    by 0x66722A4: exit (exit.c:104)
==9642==    by 0x409117: listen_watcher_cb (main.c:1062)
==9642==    by 0x6227E44: ev_invoke_pending (in
/usr/lib/x86_64-linux-gnu/libev.so.4.0.0)
==9642==    by 0x622AFE6: ev_run (in /usr/lib/x86_64-linux-gnu/libev.so.4.0.0)
==9642==    by 0x409DB4: main (main.c:1342)
==9642==  Address 0x69f43c0 is 0 bytes inside data symbol "noai6ai_cached"
==9642==
==9642==
==9642== HEAP SUMMARY:
==9642==     in use at exit: 196,616 bytes in 1,028 blocks
==9642==   total heap usage: 5,075 allocs, 4,048 frees, 1,915,720
bytes allocated
==9642==
==9642== LEAK SUMMARY:
==9642==    definitely lost: 8,192 bytes in 1 blocks
==9642==    indirectly lost: 0 bytes in 0 blocks
==9642==      possibly lost: 64,850 bytes in 232 blocks
==9642==    still reachable: 123,574 bytes in 795 blocks
==9642==         suppressed: 0 bytes in 0 blocks
==9642== Rerun with --leak-check=full to see details of leaked memory
==9642==
==9642== For counts of detected and suppressed errors, rerun with: -v
==9642== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 0 from 0)
ocserv[9640]: main: 1xx.9x.1x.7x:49624 command socket closed
ocserv[9640]: main: 1xx.9x.1x.7x:49624 user disconnected (reason:
unspecified, rx: 0, tx: 0)

2015-12-21 15:36 GMT+08:00 Nikos Mavrogiannopoulos
<n.mavrogiannopoulos at gmail.com>:
> On Sun, Dec 20, 2015 at 10:02 PM, Yick Xie <yick.xie at gmail.com> wrote:
>> Hi Nikos,
>>
>> Sorry, I don't know how to use valgrind 3.11.0, which always showed
>> some errors even as I just ran safe ocserv 0.10.8 .
>> GCC version is:
>> gcc (Ubuntu 4.8.4-2ubuntu1~14.04) 4.8.4
>> valgrind ocserv -c /etc/ocserv/config -f
>> ==5112== Memcheck, a memory error detector
>> ==5112== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
>> ==5112== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
>> ==5112== Command: ocserv -c /etc/ocserv/config -f
>
> I forgot to mention that you need to set isolate-workers to false to
> be able to run valgrind. After setting that, it should run normally.
>
> regards,
> Nikos



More information about the openconnect-devel mailing list