problems with TLS offload - unexpected CSTP length

[Claudio Luck]

Hi

Can you double check all clocks are running correctly on the server?

I had the same errors without offloading involved and they went away 
about the same time when NTP was installed and running. This may or may 
not be it, I've postponed a deeper analysis.

Best regards
Claudio Luck


On 12/09/2015 02:33 PM, Eugene Istomin wrote:
> Nikos,
>
> #/usr/sbin/ocserv --version
> ocserv 0.10.9
>
> Compiled with PAM, PKCS#11, AnyConnect,
> GnuTLS version: 3.2.18
>
>
> It happens at first connection after ~ 30-50 packets:
> ....
> ocserv[16802]: main[VPN]: {IP}:60661 assigning tun device oc_vpn0
> ocserv[16802]: main[VPN]: {IP}:60661 user of group 'VPN' authenticated (using cookie)
> ocserv[16802]: main[VPN]: {IP}:60661 sending (socket) message 2 to worker
> ocserv[16802]: main[VPN]: {IP}:60661 user logged in
> ocserv[16828]: worker: {IP} received auth reply message (value: 1)
> ocserv[16828]: worker[VPN]: {IP} suggesting DPD of 1800 secs
> ocserv[16828]: worker[VPN]: {IP} peer's base MTU is 1440
> ocserv[16828]: worker[VPN]: {IP} CSTP Base MTU is 1440 bytes
> ocserv[16828]: worker[VPN]: {IP} sending IPv4 192.168.23.136
> ocserv[16828]: worker[VPN]: {IP} adding custom header 'X-My-Header: user:VPN group:VPN'
> ocserv[16828]: worker[VPN]: {IP} DTLS ciphersuite: AES128-SHA
> ocserv[16828]: worker[VPN]: {IP} DTLS overhead is 114
> ocserv[16828]: worker[VPN]: {IP} suggesting DTLS MTU 1326
> ocserv[16828]: worker[VPN]: {IP} setsockopt(SO_PRIORITY) to 3, failed.
> ocserv[16828]: worker[VPN]: {IP} sending message 'tun mtu change' to main
> ocserv[16828]: worker[VPN]: {IP} setting MTU to 1326
> ocserv[16802]: main[VPN]: {IP}:60661 main received message 'tun mtu change' of 3 bytes
> ocserv[16802]: main[VPN]: {IP}:60661 setting oc_vpn0 MTU to 1326
> ocserv[16828]: worker[VPN]: {IP} received 467 byte(s) (TLS)
> ocserv[16828]: worker[VPN]: {IP} writing 459 byte(s) to TUN
> ocserv[16828]: worker[VPN]: {IP} sending 40 byte(s)
> ocserv[16828]: worker[VPN]: {IP} received 467 byte(s) (TLS)
> ocserv[16828]: worker[VPN]: {IP} writing 459 byte(s) to TUN
> ocserv[16828]: worker[VPN]: {IP} sending 40 byte(s)
> ocserv[16828]: worker[VPN]: {IP} received 467 byte(s) (TLS)
> ocserv[16828]: worker[VPN]: {IP} writing 459 byte(s) to TUN
> ocserv[16828]: worker[VPN]: {IP} sending 52 byte(s)
> ocserv[16828]: worker[VPN]: {IP} sending 226 byte(s)
> ocserv[16828]: worker[VPN]: {IP} received 991 byte(s) (TLS)
> ocserv[16828]: worker[VPN]: {IP} writing 983 byte(s) to TUN
> ocserv[16828]: worker[VPN]: {IP} received 467 byte(s) (TLS)
> ocserv[16828]: worker[VPN]: {IP} writing 459 byte(s) to TUN
> ocserv[16828]: worker[VPN]: {IP} sending 40 byte(s)
> ocserv[16828]: worker[VPN]: {IP} received 1334 byte(s) (TLS)
> ocserv[16828]: worker[VPN]: {IP} writing 1326 byte(s) to TUN
> ocserv[16828]: worker[VPN]: {IP} received 467 byte(s) (TLS)
> ocserv[16828]: worker[VPN]: {IP} writing 459 byte(s) to TUN
> ocserv[16828]: worker[VPN]: {IP} sending 40 byte(s)
> ocserv[16828]: worker[VPN]: {IP} sending 40 byte(s)
> ocserv[16828]: worker[VPN]: {IP} received 467 byte(s) (TLS)
> ocserv[16828]: worker[VPN]: {IP} writing 459 byte(s) to TUN
> ocserv[16828]: worker[VPN]: {IP} received 991 byte(s) (TLS)
> ocserv[16828]: worker[VPN]: {IP} writing 983 byte(s) to TUN
> ocserv[16828]: worker[VPN]: {IP} sending 40 byte(s)
> ocserv[16828]: worker[VPN]: {IP} received 467 byte(s) (TLS)
> ocserv[16828]: worker[VPN]: {IP} writing 459 byte(s) to TUN
> ocserv[16828]: worker[VPN]: {IP} sending 40 byte(s)
> ocserv[16828]: worker[VPN]: {IP} sending 64 byte(s)
> ocserv[16828]: worker[VPN]: {IP} received 68 byte(s) (TLS)
> ocserv[16828]: worker[VPN]: {IP} writing 60 byte(s) to TUN
> ocserv[16828]: worker[VPN]: {IP} received 68 byte(s) (TLS)
> ocserv[16828]: worker[VPN]: {IP} writing 60 byte(s) to TUN
> ocserv[16828]: worker[VPN]: {IP} received 272 byte(s) (TLS)
> ocserv[16828]: worker[VPN]: {IP} unexpected CSTP length (have 60, should be 264)
> ocserv[16828]: worker[VPN]: {IP} worker-vpn.c:1094: error parsing CSTP data
> ...
>
>
>> tests/docker-ocserv/Dockerfile-fedora-proxyproto-unix.
> Already tested, seems like the same behaviour.
>
>
>
>
> ---
> Best regards,
> Eugene Istomin
>
> On Wednesday, December 09, 2015 02:10:57 PM  Mavrogiannopoulos wrote:
>> On Wed, Dec 9, 2015 at 12:13 PM, Eugene Istomin <E.Istomin at edss.ee> wrote:
>>> Hello,
>>> we have a problems with TLS offload using HaProxy:
>>>
>>> ocserv[64521]: worker[vpn_name]: [SOME_IP] sending 440 byte(s)
>>> ocserv[64521]: worker[vpn_name]: [SOME_IP] sending 56 byte(s)
>>> ocserv[64521]: worker[vpn_name]: [SOME_IP] sending 440 byte(s)
>>> ocserv[64521]: worker[vpn_name]: [SOME_IP] sending 56 byte(s)
>>> ocserv[64521]: worker[vpn_name]: [SOME_IP] received 60 byte(s) (TLS)
>>> ocserv[64521]: worker[vpn_name]: [SOME_IP] writing 52 byte(s) to TUN
>>> ocserv[64521]: worker[vpn_name]: [SOME_IP] received 1070 byte(s) (TLS)
>>> ocserv[64521]: worker[vpn_name]: [SOME_IP] unexpected CSTP length (have 52, should be 1062)
>>> ocserv[64521]: worker[vpn_name]: [SOME_IP] worker-vpn.c:1094: error parsing CSTP data
>>> ocserv[64521]: worker[vpn_name]: [SOME_IP] sending message 'sm: cli stats' to secmod
>>> ocserv[64521]: worker[vpn_name]: [SOME_IP] sent periodic stats (in: 52, out: 1984) to sec-mod
>>
>> Which version of ocserv is that? Is that a random failure or happens
>> consistently at a certain point. Please provide more info.
>>
>> For configuration I'd refer you to check the files used by
>> tests/docker-ocserv/Dockerfile-fedora-proxyproto-unix. It uses proxy
>> protocol over unix sockets and includes a traffic check so I would
>> expect that it fully covers your scenario.
>>
>> regards,
>> Nikos
>>
>> _______________________________________________
>> openconnect-devel mailing list
>> openconnect-devel at lists.infradead.org
>> http://lists.infradead.org/mailman/listinfo/openconnect-devel
>>
>>
>> _______________________________________________
>> openconnect-devel mailing list
>> openconnect-devel at lists.infradead.org
>> http://lists.infradead.org/mailman/listinfo/openconnect-devel