Issues staying connected to Pulse Secure on OpenConnect v8.10

Mon Jan 11 20:11:23 EST 2021

This case seems remarkably similar to:
https://gitlab.com/openconnect/openconnect/-/issues/105#note_305217281
(Juniper NC protocol, key lifetime of 20 minutes, but ESP rekeys and
stops working after ~16 minutes)

Details:

On Mon, Jan 11, 2021 at 2:03 PM John Hannafin <john.hannafin at gmail.com> wrote:
> I'm running Fedora, and my work has a Pulse Secure VPN that I need to
> access our internal assets.  Sometime last year, we noticed that at
> some point between version 8.03 and 8.06, using openconnect would
> become unreliable.  Using 8.03, I can run the command "sudo
> openconnect --juniper --protocol=nc https://[REDACTED_HOSTNAME]", and
> the VPN will stay active and work for as long as I needed it.  I
> noticed with version 8.06 (perhaps earlier though?), that the VPN
> would run for, about 15 minutes before failing and I'd have to quit
> the VPN and resign in to get another 15 minutes or so of use.  This
> behavior still exists in 8.10 today.  I can no longer run 8.03 due to
> dependencies not existing for it in Fedora 33's repos, so I'm looking
> to try and solve my problem for newer versions.  Any guidance or help
> would be greatly appreciated.

Can you use git-bisect to isolate the specific commit where this
broke? My best guess would be:
https://gitlab.com/openconnect/openconnect/commits/347060a852832f622ca13784a83c7a9e7eb8d7c2

> I may be wrong, but it seems that the "Received ESP packet with
> invalid SPI 0xe615d345" is the beginning of the problems, which
> ultimately ends with "ESP detected dead peer", and then connectivity
> is dead at that point.
>
> I ran a verbose VPN, redacted DSIDs and hostnames.  It is pasted below:

You may want to add --timestamp to make this a bit clearer.

> jhannafin at raijin ~ $ sudo openconnect -v --juniper --protocol=nc
> https://[REDACTED_HOST]
> WARNING: Juniper Network Connect support is experimental.
> It will probably be superseded by Junos Pulse support.
> GET https://[REDACTED_HOST]/
> Attempting to connect to server [REDACTED_IP]:443
> Connected to [REDACTED_IP]:443
> SSL negotiation with [REDACTED_HOST]
> Connected to HTTPS on [REDACTED_HOST] with ciphersuite
> (TLS1.2)-(RSA)-(AES-128-GCM)
> Got HTTP response: HTTP/1.1 302 Found
> Location: /dana-na/auth/url_pYt8kE2M2C7u2FVR/welcome.cgi
> Content-Type: text/html; charset=utf-8
> Set-Cookie: DSSIGNIN=url_pYt8kE2M2C7u2FVR; path=/dana-na/;
> expires=Thu, 31-Dec-2037 00:00:00 GMT; secure
> Set-Cookie: DSIVS=; path=/; expires=Thu, 01 Jan 1970 22:00:00 GMT; secure
> Set-Cookie: DSSignInURL=/; path=/; secure
> Connection: close
> Content-Length: 0
> X-XSS-Protection: 1
> Strict-Transport-Security: max-age=31536000
> HTTP body length:  (0)
> GET https://[REDACTED_HOST]/dana-na/auth/url_pYt8kE2M2C7u2FVR/welcome.cgi
> SSL negotiation with [REDACTED_HOST]
> Connected to HTTPS on [REDACTED_HOST] with ciphersuite
> (TLS1.2)-(RSA)-(AES-128-GCM)
> Got HTTP response: HTTP/1.1 200 OK
> Content-Type: text/html; charset=utf-8
> Date: Mon, 11 Jan 2021 21:09:27 GMT
> x-frame-options: SAMEORIGIN
> Pragma: no-cache
> Cache-Control: no-store
> Expires: -1
> Transfer-Encoding: chunked
> X-XSS-Protection: 1
> Strict-Transport-Security: max-age=31536000
> HTTP body chunked (-2)
> frmLogin
> username:jhannafin
> password:
> POST https://[REDACTED_HOST]/dana-na/auth/url_pYt8kE2M2C7u2FVR/login.cgi
> Got HTTP response: HTTP/1.1 302 Moved
> Set-Cookie: DSASSERTREF=x; path=/; expires=Thu, 01 Jan 1970 22:00:00 GMT; secure
> Set-Cookie: DSID=[REDACTED]; path=/; secure
> Set-Cookie: DSDID=[REDACTED]; path=/; secure; HttpOnly
> Set-Cookie: DSFirstAccess=1610399373; path=/; secure
> Set-Cookie: DSSIGNIN=url_pYt8kE2M2C7u2FVR; path=/; secure
> Date: Mon, 11 Jan 2021 21:09:33 GMT
> location: /dana/home/index.cgi
> Content-Type: text/html; charset=utf-8
> Pragma: no-cache
> Cache-Control: no-store
> Expires: -1
> Content-Length: 0
> X-XSS-Protection: 1
> Strict-Transport-Security: max-age=31536000
> HTTP body length:  (0)
> GET https://[REDACTED_HOST]/dana/home/index.cgi
> Got HTTP response: HTTP/1.1 200 OK
> Content-Type: text/html; charset=utf-8
> Set-Cookie: DSLastAccess=1610399374; path=/; Secure
> Pragma: no-cache
> Cache-Control: no-store
> Expires: -1
> Transfer-Encoding: chunked
> X-Frame-Options: SAMEORIGIN
> X-XSS-Protection: 1
> Strict-Transport-Security: max-age=31536000
> HTTP body chunked (-2)
> Got HTTP response: HTTP/1.1 200 OK
> Content-type: application/octet-stream
> Pragma: no-cache
> NCP-Version: 3
> Set-Cookie: DSLastAccess=1610399374; path=/; Secure
> Connection: close
> X-Frame-Options: SAMEORIGIN
> X-XSS-Protection: 1
> Strict-Transport-Security: max-age=31536000
> > 0000:  13 00 00 04 00 00 00 06  00 72 61 69 6a 69 6e bb  |.........raijin.|
> > 0010:  01 00 00 00 00                                    |.....|
> Got KMP message 301 of size 316
> Unknown TLV group 3 attr 1 len 1: 00
> Unknown TLV group 3 attr 2 len 1: 01
> Received split include route 0.0.0.0/0.0.0.0
> Received MTU 1400 from server
> Received DNS server 10.232.41.251
> Received DNS server 10.102.136.251
> Received DNS search domain man.co
> Unknown TLV group 2 attr 3 len 4: 01 00 00 00
> ESP compression: 0
> ESP encryption: 0x02 (AES-128)
> ESP HMAC: 0x02 (SHA1)
> ESP key lifetime: 1200 seconds

This is where the "15 minutes" comes in. The lifetime of your ESP keys
is only 15 minutes… which means that the server should send *new* keys
after 15 minutes.

> ESP key lifetime: 0 bytes
> ESP replay protection: 1
> Unknown TLV group 8 attr 11 len 4: 00 00 00 00
> ESP port: 4500
> ESP to SSL fallback: 15 seconds
> Unknown TLV group 8 attr 8 len 4: 00 00 00 3c
> Received internal IP address 10.232.158.227
> Received netmask 255.255.255.255
> Received internal gateway address 10.200.200.200
> ESP SPI (outbound): d4520f1d
> 64 bytes of ESP secrets
> oNCP negotiation request outgoing:
> > 0000:  8e 00 00 00 00 00 00 00  01 2f 01 00 00 00 01 00  |........./......|
> > 0010:  00 00 00 00 00 10 00 06  00 00 00 0a 00 02 00 00  |................|
> > 0020:  00 04 00 00 05 78 00 00  00 00 00 00 01 2e 01 00  |.....x..........|
> > 0030:  00 00 01 00 00 00 00 00  00 56 00 07 00 00 00 50  |.........V.....P|
> > 0040:  00 01 00 00 00 04 e6 15  d3 45 00 02 00 00 00 40  |.........E.....@|
> > 0050:  9f 4c 9b ea 50 be dd b2  09 2d f6 38 de ab 25 ae  |.L..P....-.8..%.|
> > 0060:  40 ea 84 7f d7 8b 37 86  3b b7 b1 6c c2 01 47 57  |@.....7.;..l..GW|
> > 0070:  f0 d3 73 0e 00 00 00 00  00 00 00 00 00 00 00 00  |..s.............|
> > 0080:  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
> Send ESP probes
> Connected as 10.232.158.227, using SSL, with ESP in progress
> ESP session established with server

I assume there's a ~15 minute gap here before the below messages start
appearing?

> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Requeueing failed ESP send: Resource temporarily unavailable
> Incoming KMP message 302 of size 181 (got 181)

Yep, this is where the rekey happens, on schedule 👍

> Got KMP message 301 of size 181
> ESP compression: 0
> ESP encryption: 0x02 (AES-128)
> ESP HMAC: 0x02 (SHA1)
> ESP key lifetime: 1200 seconds
> ESP key lifetime: 0 bytes
> ESP replay protection: 1
> Unknown TLV group 8 attr 11 len 4: 00 00 00 00
> ESP port: 4500
> ESP to SSL fallback: 15 seconds
> Unknown TLV group 8 attr 8 len 4: 00 00 00 3c
> ESP SPI (outbound): 6aaf4c11
> 64 bytes of ESP secrets
> Received ESP packet with invalid SPI 0xe615d345
> Received ESP packet with invalid SPI 0xe615d345
> Received ESP packet with invalid SPI 0xe615d345
> Received ESP packet with invalid SPI 0xe615d345
> Received ESP packet with invalid SPI 0xe615d345

-Dan