This is a useful log. Key interesting parts below.
1. Initial tunnel config looks fine:
- Idle timeout is 180 minutes
- Rekey interval is 180 minutes
- Cookie lifetime is 30 days (meaning we should be able to keep
rekeying for 30 days, unless there's an idle timeout)
[2020-04-13 21:20:20] > POST /ssl-vpn/getconfig.esp HTTP/1.1
[2020-04-13 21:20:20] > Host: foo.bar.baz
[2020-04-13 21:20:20] > User-Agent: PAN GlobalProtect
[2020-04-13 21:20:20] > Cookie: PHPSESSID=PHP_SESSION_ID_COOKIE
[2020-04-13 21:20:20] > X-Pad:
00000000000000000000000000000000000000000000000000000
[2020-04-13 21:20:20] > Content-Type: application/x-www-form-urlencoded
[2020-04-13 21:20:20] > Content-Length: 267
[2020-04-13 21:20:20] >
[2020-04-13 21:20:20] >
client-type=1&protocol-version=p1&app-version=4.0.5-8&clientos=Linux&os-version=linux-64&hmac-algo=sha1%2cmd5%2csha256&enc-algo=aes-128-cbc%2caes-256-cbc&authcookie=AUTHCOOKIE&portal=FOOBAR-GP-Gate-N&user=foobar_user&domain=bar.baz&computer=origin
[2020-04-13 21:20:20] Got HTTP response: HTTP/1.1 200 OK
[2020-04-13 21:20:20] Date: Tue, 14 Apr 2020 01:20:20 GMT
[2020-04-13 21:20:20] Content-Type: application/xml; charset=UTF-8
[2020-04-13 21:20:20] Content-Length: 1673
[2020-04-13 21:20:20] Connection: keep-alive
[2020-04-13 21:20:20] ETag: "1f35da11d19"
[2020-04-13 21:20:20] Pragma: no-cache
[2020-04-13 21:20:20] Cache-Control: no-store, no-cache,
must-revalidate, post-check=0, pre-check=0
[2020-04-13 21:20:20] Expires: Thu, 19 Nov 1981 08:52:00 GMT
[2020-04-13 21:20:20] X-FRAME-OPTIONS: DENY
[2020-04-13 21:20:20] Strict-Transport-Security: max-age=31536000;
[2020-04-13 21:20:20] X-XSS-Protection: 1; mode=block;
[2020-04-13 21:20:20] X-Content-Type-Options: nosniff
[2020-04-13 21:20:20] Content-Security-Policy: default-src 'self';
script-src 'self' 'unsafe-inline'; img-src * data:; style-src 'self'
'unsafe-inline';
[2020-04-13 21:20:20] HTTP body length: (1673)
[2020-04-13 21:20:20] <
[2020-04-13 21:20:20] < <response status="success">
[2020-04-13 21:20:20] < <need-tunnel>yes</need-tunnel>
[2020-04-13 21:20:20] <
<ssl-tunnel-url>/ssl-tunnel-connect.sslvpn</ssl-tunnel-url>
[2020-04-13 21:20:20] < <portal>FOOBAR-GP-Gate-N</portal>
[2020-04-13 21:20:20] < <user>foobar_user</user>
[2020-04-13 21:20:20] < <lifetime>2592000</lifetime>
[2020-04-13 21:20:20] < <timeout>10800</timeout>
[2020-04-13 21:20:20] < <disconnect-on-idle>10800</disconnect-on-idle>
[2020-04-13 21:20:20] < <bw-c2s>1000</bw-c2s>
[2020-04-13 21:20:20] < <bw-s2c>1000</bw-s2c>
[2020-04-13 21:20:20] < <gw-address>VPN_PORTAL_IPV4</gw-address>
[2020-04-13 21:20:20] < <ip-address>10.9.6.2</ip-address>
[2020-04-13 21:20:20] < <netmask>255.255.255.255</netmask>
[2020-04-13 21:20:20] < <ip-address-preferred>yes</ip-address-preferred>
[2020-04-13 21:20:20] < <dns>
[2020-04-13 21:20:20] < <member>10.20.0.82</member>
[2020-04-13 21:20:20] < <member>10.20.0.13</member>
[2020-04-13 21:20:20] < </dns>
[2020-04-13 21:20:20] < <wins>
[2020-04-13 21:20:20] < </wins>
[2020-04-13 21:20:20] < <dns-suffix>
[2020-04-13 21:20:20] < <member>bar.baz</member>
[2020-04-13 21:20:20] < <member>ad.bar.baz</member>
[2020-04-13 21:20:20] < </dns-suffix>
[2020-04-13 21:20:20] < <default-gateway>10.9.6.2</default-gateway>
[2020-04-13 21:20:20] < <mtu>0</mtu>
[2020-04-13 21:20:20] <
<no-direct-access-to-local-network>no</no-direct-access-to-local-network>
[2020-04-13 21:20:20] < <access-routes>
[2020-04-13 21:20:20] < <member>0.0.0.0/0</member>
[2020-04-13 21:20:20] < <member>10.20.0.82/32</member>
[2020-04-13 21:20:20] < <member>10.20.0.13/32</member>
[2020-04-13 21:20:20] < </access-routes>
[2020-04-13 21:20:20] < <exclude-access-routes>
[2020-04-13 21:20:20] < </exclude-access-routes>
[2020-04-13 21:20:20] < <ipsec>
[2020-04-13 21:20:20] < <udp-port>4501</udp-port>
[2020-04-13 21:20:20] < <ipsec-mode>esp-tunnel</ipsec-mode>
[2020-04-13 21:20:20] < <enc-algo>aes-128-cbc</enc-algo>
[2020-04-13 21:20:20] < <hmac-algo>sha1</hmac-algo>
[2020-04-13 21:20:20] < <c2s-spi>ESP_OUTGOINGSPI</c2s-spi>
[2020-04-13 21:20:20] < <s2c-spi>ESP_INCOMINGSPI</s2c-spi>
[2020-04-13 21:20:20] < <akey-s2c>
[2020-04-13 21:20:20] < <bits>160</bits>
[2020-04-13 21:20:20] < <val>AKEY_S2C_160</val>
[2020-04-13 21:20:20] < </akey-s2c>
[2020-04-13 21:20:20] < <ekey-s2c>
[2020-04-13 21:20:20] < <bits>128</bits>
[2020-04-13 21:20:20] < <val>EKEY_S2C_128</val>
[2020-04-13 21:20:20] < </ekey-s2c>
[2020-04-13 21:20:20] < <akey-c2s>
[2020-04-13 21:20:20] < <bits>160</bits>
[2020-04-13 21:20:20] < <val>AKEY_C2S_160</val>
[2020-04-13 21:20:20] < </akey-c2s>
[2020-04-13 21:20:20] < <ekey-c2s>
[2020-04-13 21:20:20] < <bits>128</bits>
[2020-04-13 21:20:20] < <val>EKEY_C2S_128</val>
[2020-04-13 21:20:20] < </ekey-c2s>
[2020-04-13 21:20:20] < </ipsec>
[2020-04-13 21:20:20] < </response>
[2020-04-13 21:20:20] Session will expire after 43200 minutes.
[2020-04-13 21:20:20] Tunnel timeout (rekey interval) is 180 minutes.
[2020-04-13 21:20:20] Idle timeout is 180 minutes.
[2020-04-13 21:20:20] TCP_INFO rcv mss 1460, snd mss 1460, adv mss
1460, pmtu 1500
2. Initial connection setup. ESP is working normally:
[2020-04-13 21:20:20] Send ESP probes
[2020-04-13 21:20:20] Connected as 10.9.6.2, using SSL, with ESP in progress
[2020-04-13 21:20:20] Received ESP packet of 84 bytes
[2020-04-13 21:20:20] Accepting later-than-expected ESP packet with
seq 1 (expected 0)
[2020-04-13 21:20:20] ESP session established with server
[2020-04-13 21:20:20] Received ESP packet of 84 bytes
[2020-04-13 21:20:20] Accepting expected ESP packet with seq 2
[2020-04-13 21:20:20] Received ESP packet of 84 bytes
[2020-04-13 21:20:20] Accepting expected ESP packet with seq 3
[2020-04-13 21:20:20] ESP tunnel connected; exiting HTTPS mainloop.
[2020-04-13 21:20:20] Sent ESP packet of 100 bytes
[2020-04-13 21:20:20] No work to do; sleeping for 10000 ms...
[2020-04-13 21:20:24] Sent ESP packet of 100 bytes
3. Exactly 179 minutes later, OpenConnect attempts to rekey by
reconnecting to HTTPS and re-fetching the config. This *appears* to go
off without a hitch:
[2020-04-14 00:19:20] GlobalProtect rekey due
[2020-04-14 00:19:20] POST https://foo.bar.baz/ssl-vpn/getconfig.esp
…
[2020-04-14 00:19:20] Session will expire after 43020 minutes.
[2020-04-14 00:19:20] Tunnel timeout (rekey interval) is 180 minutes.
[2020-04-14 00:19:20] Idle timeout is 180 minutes.
…
[2020-04-14 00:19:20] Send ESP probes
[2020-04-14 00:19:20] No work to do; sleeping for 5000 ms...
[2020-04-14 00:19:20] Received ESP packet of 84 bytes
[2020-04-14 00:19:20] Accepting later-than-expected ESP packet with
seq 1 (expected 0)
[2020-04-14 00:19:20] ESP session established with server
[2020-04-14 00:19:20] Received ESP packet of 84 bytes
[2020-04-14 00:19:20] Accepting expected ESP packet with seq 2
[2020-04-14 00:19:20] Received ESP packet of 84 bytes
[2020-04-14 00:19:20] Accepting expected ESP packet with seq 3
[2020-04-14 00:19:20] ESP tunnel connected; exiting HTTPS mainloop.
4. But then, exactly 180 minutes after the initial connection (at
00:20:20), the server appears to stop sending packets via ESP:
[2020-04-14 00:20:13] Received ESP packet of 84 bytes
[2020-04-14 00:20:13] Accepting expected ESP packet with seq 10
[2020-04-14 00:20:13] No work to do; sleeping for 10000 ms...
[2020-04-14 00:20:23] Send ESP probes for DPD
[2020-04-14 00:20:23] Sent ESP packet of 132 bytes
[2020-04-14 00:20:23] No work to do; sleeping for 5000 ms...
[2020-04-14 00:20:28] Send ESP probes for DPD
[2020-04-14 00:20:28] No work to do; sleeping for 5000 ms...
[2020-04-14 00:20:33] Send ESP probes for DPD
[2020-04-14 00:20:33] No work to do; sleeping for 5000 ms...
[2020-04-14 00:20:38] No work to do; sleeping for 5000 ms...
5. This suggests a server misconfiguration. The server has sent new
ESP keys and started using them, but then it gets confused and
invalidates the ESP connection after the original interval elapses.
That's annoying, and we've seen it before… but what OpenConnect should
do to workaround it here is that it should give up on ESP and attempt
to fallback to HTTPS. Which it appears to do:
[2020-04-14 00:20:43] Connecting to HTTPS tunnel endpoint ...
[2020-04-14 00:20:43] SSL negotiation with foo.bar.baz
[2020-04-14 00:20:43] Connected to HTTPS on foo.bar.baz with
ciphersuite (TLS1.2)-(RSA)-(AES-256-GCM)
[2020-04-14 00:20:43] > GET
/ssl-tunnel-connect.sslvpn?authcookie=AUTHCOOKIE&user=foobar_user
HTTP/1.1
[2020-04-14 00:20:43] >
… but what's completely puzzling here is that we don't see either of
the following messages prior to this attempted failover to HTTPS:
ESP detected dead peer
Failed to connect ESP tunnel; using HTTPS instead.
There is no codepath in OpenConnect v8.08 where you can go from a
working GP ESP connection to HTTPS fallback *without* printing the
second message (see
https://gitlab.com/openconnect/openconnect/blob/v8.08/gpst.c#L1102-1116).
IIRC correctly, I had all of this tricky ESP-to-HTTPS handoff "tap
dance" nailed down prior to v8.0, but in case it hasn't changed
recently.
6. Finally, one more strange thing in your log. Something (????)
causes it to attempt a logout immediately after trying to fallback to
HTTPS, but the logout *fails* (POST
https://foo.bar.baz/ssl-vpn/logout.esp -> "Invalid user name").
As I have in the past, I just tried to torture-test the rekey and
ESP-HTTPS fallback by building v8.08 with an artificially-short
hardcoded rekey interval (2 minutes), and then blocking UDP packets
with iptables for long enough that OpenConnect thinks the ESP
connection is dead, and falls back to ESP. As expected, I get both of
the aforementioned messages ("ESP detected dead peer" and "Failed to
connect ESP tunnel; using HTTPS instead.") prior to fallback from ESP
to HTTPS, and then the HTTPS connection works fine. If I then unblock
UDP, it will detect this on the next rekey and resume using ESP.
Basically… I can't reproduce your issue, and I'm having trouble
understanding how it's even possible to get the sequence of log output
that you show. You're 100% sure that this output comes from invoking
OpenConnect v8.08 from the command line?
-Dan
On Fri, Apr 17, 2020 at 8:17 AM The Wanderer <wanderer@xxxxxxxxxxx> wrote:
>
> On 2020-04-16 at 18:22, The Wanderer wrote:
>
> > My first attempt at sending the below mail seems to have been held up
> > in moderation, because the attachment is slightly too large. While I
> > wait for it to be noticed and released (or bounced, so that I can try
> > again, with a compressed version if necessary), I want to at least
> > make it visible that I haven't dropped this.
>
> As I've now been (informally and non-authoritatively) informed that -
> contrary to the wording of the moderation-notice message which I
> received - basically nothing ever gets released from moderation (or, I
> gather, formally rejected) on this mailing list, here's the
> previously-attached file in compressed form.
>
> If this gets held for moderation for some reason (opaque binary
> attachment?), I'll have to see what else I can try.
>
> --
> The Wanderer
>
> The reasonable man adapts himself to the world; the unreasonable one
> persists in trying to adapt the world to himself. Therefore all
> progress depends on the unreasonable man. -- George Bernard Shaw
> _______________________________________________
> openconnect-devel mailing list
> openconnect-devel@xxxxxxxxxxxxxxxxxxx
> http://lists.infradead.org/mailman/listinfo/openconnect-devel
_______________________________________________
openconnect-devel mailing list
openconnect-devel@xxxxxxxxxxxxxxxxxxx
http://lists.infradead.org/mailman/listinfo/openconnect-devel
