On 2020-04-18 at 22:11, The Wanderer wrote: > On 2020-04-18 at 21:52, Daniel Lenski wrote: > >> On Sat, Apr 18, 2020 at 6:30 PM The Wanderer <wanderer@xxxxxxxxxxx> >> wrote: >> Well, this clarifies it. There's something screwed up with the >> server, it appears: >> >> * The server gives you initial ESP configuration, and tells you "come >> back and rekey 180 minutes later." >> * OpenConnect gets new ESP keys 179 minutes later. >> * Those new keys appear to work… for a minute. >> * One minute after getting the new keys, or 180 minutes after getting >> the original keys… the connection stops working. >> * When OpenConnect attempts to fallback to HTTPS… the server rejects >> the (supposed-to-be-unexpired) auth cookie. >> * It therefore gives up and tries to log out. >> >> Unless you can show that some other client software manages to keep >> the connection going >180 minutes, I have to assume that we're doing >> the best we can here. > > As I believe I recall that 8.05 or possibly 8.02 was working, I've now > downgraded to 8.05 and initiated another session. If it disconnects > overnight, I'll repeat with 8.02 in the morning (my next mandatory > on-shift is Monday). If that disconnects in its turn, then we can > consider it confirmed that the server has changed its behavior in the > meantime, and this has nothing to do with the upgrade and is not > OpenConnect's problem. > > If one of those remains connected, however - especially if the logs show > something else happening at this point - then it may be worth digging > deeper here. When I woke up this morning (about half an hour ago as I begin this message) and checked, the tunnel was still up, and a DNS-lookup attempt - which *may* be one I'd already performed in the same session, as a test of the tunnel right after opening it - succeeded. The only meaningful differences between this session and the overnight one which disconnected, that I can think of, are: * It used OpenConnect version 8.05, instead of 8.08. * It was carried out after two days or so without having had a tunnel up, rather than no more than a day. (I was called in to be physically at work for two days, with a day off work in between, so I had no reason to connect.) * It did not have the separate, manually-initiated repeated-ping keepalive running. Unless one of those latter two seems plausible as making the difference for why this remained up, I think we want to keep digging here. It's going to take me some time to find the time to spare to do the obfuscation / anonymization on the full log from this (again just under 1MB). However, the text that went to the terminal doesn't seem to contain anything that needs to be obfuscated, and has something that looks like it might be a hint; based on that, I've extracted a small fragment of the primary log - starting immediately after the "ESP (encryption|authentication) type" lines from the first rekey - which similarly needs no anonymization. Please see both attached. (Please ignore the non-timestamped RTNETLINK lines in the terminal-output log; those appear to be caused by my kludgy routing script, and I haven't figured out why it's producing them, since the commands which would produce them as errors seem to be succeeding.) Judging from what I can see, this OpenConnect version may not even be trying to switch to HTTPS at all; it just keeps waiting and retrying on ESP, and eventually replies to older ESP packets start coming in and things sync back up and work again. If this causes any noticeable lag or other discrepancies in my actual VPN connection, I don't recall them. Do I need to do the work to obfuscate the full log, or is this enough to point us somewhere that might be useful? Should I try connecting again (I've shut down the tunnel now) and actually using this VPN for a while, to see whether I notice any lag etc. after the rekey occurs? >>> What I'm doing here is invoking a shell script (as ordinary user) >>> from the command line, which runs >>> >>> su - -c "~/bin/vpn-bar 2>&1 >> >>> /home/ORIGINALUSER/tmp/vpn-bar-highverbosity.log" >>> >>> and that command line in turn calls a shell script which sits >>> under /root/bin/, gets run as root, and contains the actual >>> invocation of openconnect - including >>> echo password | openconnect --passwd-on-stdin [other-options] >>> and a custom routing script which adjusts the routing table so that >>> only traffic which *needs* the VPN goes over it (that latter being >>> why I need to run this as root, rather than pre-creating a tun* >>> device node and telling openconnect to use it). >> >> Something like what vpn-slice does >> (https://github.com/dlenski/vpn-slice/), but without needing a messy >> intermediary script? > > Possibly. I don't think I'd run across this before, and it doesn't seem > to be in Debian. At such point as I've upgraded again, I'll give this a > try and see if I can ditch my handbrewed solution, which is kludgy and > only mostly-effective in any case; I put it in place as a > get-things-working to begin with, and then it was working Well Enough so > I hadn't gone back to it before these disconnects started happening. It occurs to me that I left something out. The intermediate script exists so that I can have a GUI menu entry to click on, which when launched will open an xterm and run the 'su - -c' command, thereby presenting the root-password prompt. Unless I give in and keep a terminal open for the purpose, I'll probably still need this. That said, it looks like vpn-slice will probably do everything my current kludgy script does and more, and probably do it better. Thank you for pointing me to this - and for writing it. -- 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
Enter login credentials [2020-04-18 22:02:26] No MTU received. Calculated 1422 for ESP tunnel Cannot find device "tun0" Cannot find device "tun0" RTNETLINK answers: File exists RTNETLINK answers: File exists [2020-04-19 01:01:26] No MTU received. Calculated 1422 for ESP tunnel RTNETLINK answers: File exists RTNETLINK answers: File exists [2020-04-19 01:02:27] ESP detected dead peer [2020-04-19 01:03:27] ESP detected dead peer [2020-04-19 01:04:27] ESP detected dead peer [2020-04-19 01:05:27] ESP detected dead peer [2020-04-19 01:06:27] ESP detected dead peer RTNETLINK answers: File exists RTNETLINK answers: File exists [2020-04-19 04:00:26] No MTU received. Calculated 1422 for ESP tunnel RTNETLINK answers: File exists RTNETLINK answers: File exists [2020-04-19 04:01:26] ESP detected dead peer [2020-04-19 04:02:27] ESP detected dead peer [2020-04-19 04:03:27] ESP detected dead peer [2020-04-19 04:04:27] ESP detected dead peer [2020-04-19 04:05:27] ESP detected dead peer [2020-04-19 04:06:27] ESP detected dead peer [2020-04-19 04:07:27] ESP detected dead peer [2020-04-19 04:08:27] ESP detected dead peer [2020-04-19 04:09:27] ESP detected dead peer [2020-04-19 04:10:27] ESP detected dead peer [2020-04-19 04:11:27] ESP detected dead peer [2020-04-19 04:12:24] ESP detected dead peer [2020-04-19 04:13:24] ESP detected dead peer [2020-04-19 04:14:24] ESP detected dead peer [2020-04-19 04:15:24] ESP detected dead peer [2020-04-19 04:15:50] ESP detected dead peer RTNETLINK answers: File exists RTNETLINK answers: File exists [2020-04-19 06:59:26] No MTU received. Calculated 1422 for ESP tunnel RTNETLINK answers: File exists RTNETLINK answers: File exists [2020-04-19 07:00:26] ESP detected dead peer [2020-04-19 07:01:26] ESP detected dead peer [2020-04-19 07:02:26] ESP detected dead peer [2020-04-19 07:03:26] ESP detected dead peer [2020-04-19 07:04:26] ESP detected dead peer [2020-04-19 07:05:26] ESP detected dead peer [2020-04-19 07:06:26] ESP detected dead peer [2020-04-19 07:07:26] ESP detected dead peer [2020-04-19 07:08:26] ESP detected dead peer [2020-04-19 07:09:26] ESP detected dead peer [2020-04-19 07:10:26] ESP detected dead peer ^CRTNETLINK answers: No such process RTNETLINK answers: No such process Interrupt
[2020-04-19 01:01:27] Send ESP probes [2020-04-19 01:01:27] No work to do; sleeping for 5000 ms... [2020-04-19 01:01:27] Received ESP packet of 84 bytes [2020-04-19 01:01:27] Accepting later-than-expected ESP packet with seq 2 (expected 0) [2020-04-19 01:01:27] ESP session established with server [2020-04-19 01:01:27] Received ESP packet of 84 bytes [2020-04-19 01:01:27] Accepting out-of-order ESP packet with seq 1 (expected 3) [2020-04-19 01:01:27] Received ESP packet of 84 bytes [2020-04-19 01:01:27] Accepting expected ESP packet with seq 3 [2020-04-19 01:01:27] ESP tunnel connected; exiting HTTPS mainloop. [2020-04-19 01:01:27] No work to do; sleeping for 60000 ms... [2020-04-19 01:02:27] No work to do; sleeping for 5000 ms... [2020-04-19 01:02:27] Received ESP packet of 84 bytes [2020-04-19 01:02:27] Accepting later-than-expected ESP packet with seq 5 (expected 4) [2020-04-19 01:02:27] ESP session established with server [2020-04-19 01:02:27] Received ESP packet of 84 bytes [2020-04-19 01:02:27] Accepting out-of-order ESP packet with seq 4 (expected 6) [2020-04-19 01:02:27] Received ESP packet of 84 bytes [2020-04-19 01:02:27] Accepting expected ESP packet with seq 6 [2020-04-19 01:02:27] ESP tunnel connected; exiting HTTPS mainloop. [2020-04-19 01:02:27] No work to do; sleeping for 60000 ms... [2020-04-19 01:03:27] No work to do; sleeping for 5000 ms... [2020-04-19 01:03:27] Received ESP packet of 84 bytes [2020-04-19 01:03:27] Accepting expected ESP packet with seq 7 [2020-04-19 01:03:27] ESP session established with server [2020-04-19 01:03:27] Received ESP packet of 84 bytes [2020-04-19 01:03:27] Accepting expected ESP packet with seq 8 [2020-04-19 01:03:27] Received ESP packet of 84 bytes [2020-04-19 01:03:27] Accepting expected ESP packet with seq 9 [2020-04-19 01:03:27] ESP tunnel connected; exiting HTTPS mainloop. [2020-04-19 01:03:27] No work to do; sleeping for 60000 ms... [2020-04-19 01:04:27] No work to do; sleeping for 5000 ms... [2020-04-19 01:04:27] Received ESP packet of 84 bytes [2020-04-19 01:04:27] Accepting expected ESP packet with seq 10 [2020-04-19 01:04:27] ESP session established with server [2020-04-19 01:04:27] Received ESP packet of 84 bytes [2020-04-19 01:04:27] Accepting expected ESP packet with seq 11 [2020-04-19 01:04:27] Received ESP packet of 84 bytes [2020-04-19 01:04:27] Accepting expected ESP packet with seq 12 [2020-04-19 01:04:27] ESP tunnel connected; exiting HTTPS mainloop. [2020-04-19 01:04:27] No work to do; sleeping for 60000 ms... [2020-04-19 01:05:27] No work to do; sleeping for 5000 ms... [2020-04-19 01:05:27] Received ESP packet of 84 bytes [2020-04-19 01:05:27] Accepting expected ESP packet with seq 13 [2020-04-19 01:05:27] ESP session established with server [2020-04-19 01:05:27] Received ESP packet of 84 bytes [2020-04-19 01:05:27] Accepting expected ESP packet with seq 14 [2020-04-19 01:05:27] Received ESP packet of 84 bytes [2020-04-19 01:05:27] Accepting expected ESP packet with seq 15 [2020-04-19 01:05:27] ESP tunnel connected; exiting HTTPS mainloop. [2020-04-19 01:05:27] No work to do; sleeping for 60000 ms... [2020-04-19 01:06:27] No work to do; sleeping for 5000 ms... [2020-04-19 01:06:27] Received ESP packet of 84 bytes [2020-04-19 01:06:27] Accepting expected ESP packet with seq 16 [2020-04-19 01:06:27] ESP session established with server [2020-04-19 01:06:27] Received ESP packet of 84 bytes [2020-04-19 01:06:27] Accepting expected ESP packet with seq 17 [2020-04-19 01:06:27] Received ESP packet of 84 bytes [2020-04-19 01:06:27] Accepting expected ESP packet with seq 18 [2020-04-19 01:06:27] ESP tunnel connected; exiting HTTPS mainloop. [2020-04-19 01:06:27] No work to do; sleeping for 60000 ms... [2020-04-19 01:06:42] Send ESP probes for DPD [2020-04-19 01:06:42] Sent ESP packet of 100 bytes [2020-04-19 01:06:42] No work to do; sleeping for 5000 ms... [2020-04-19 01:06:42] Received ESP packet of 84 bytes [2020-04-19 01:06:42] Accepting expected ESP packet with seq 19 [2020-04-19 01:06:42] No work to do; sleeping for 10000 ms... [2020-04-19 01:06:52] Send ESP probes for DPD [2020-04-19 01:06:52] No work to do; sleeping for 5000 ms... [2020-04-19 01:06:52] Received ESP packet of 84 bytes [2020-04-19 01:06:52] Accepting expected ESP packet with seq 20 [2020-04-19 01:06:52] No work to do; sleeping for 10000 ms... [2020-04-19 01:07:02] Send ESP probes for DPD [2020-04-19 01:07:02] No work to do; sleeping for 5000 ms...
Attachment:
signature.asc
Description: OpenPGP digital signature
_______________________________________________ openconnect-devel mailing list openconnect-devel@xxxxxxxxxxxxxxxxxxx http://lists.infradead.org/mailman/listinfo/openconnect-devel
