On 2020-04-19 at 14:30, Daniel Lenski wrote: > On Sun, Apr 19, 2020 at 4:54 AM The Wanderer <wanderer@xxxxxxxxxxx> > wrote: >> 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.) > > These logs are quite confusing to me. I don't understand why, or > HOW, you are getting *repeated* messages of "ESP tunnel connected; > exiting HTTPS mainloop." Immediately after printing that message, > OpenConnect sets a flag which prevents it from entering that code > section again. ¯\_(ツ)_/¯ > > https://gitlab.com/openconnect/openconnect/blob/v8.08/gpst.c#L1083-1084 I take it that this particular code has not changed meaningfully since 8.05? Because 8.05 is what this latest log was from. Comparing against https://gitlab.com/openconnect/openconnect/blob/v8.05/gpst.c#L1053-1054 I do see a code change in this vicinity, involving timeouts, but I don't know the codebase well enough to tell whether it's of any significance here; at a glance I'm inclined to guess no. I gather that the flag you're referring to is vpininfo->dtls_state being set to DTLS_CONNECTED, only in the case that its previous value was DTLS_CONNECTING. In 8.05, vpninfo->dtls_state is only ever set to DTLS_CONNECTING in three places: dtls.c lines 149 and 360, and esp.c line 237, immediately after the printing of the "ESP session established with server" message, only if the previous state was DTLS_SLEEPING. Since that message is appearing in between consecutive appearances of the "exiting HTTPS mainloop" following the rekey, I'm guessing something is taking us back there in between. I notice that the "exiting HTTPS mainloop" / "ESP session established" rotation stops happening after the first time we get a "Send ESP probes for DPD" after the rekey. I haven't looked into what makes that happen, or why it didn't happen earlier. To trace it any further without a lot of hassle, I'd need to pull the source locally (both 8.05 and 8.08, most likely, and probably current HEAD for good measure) and set up a more comprehensive examination environment, and I'm not sure I want to go to that bother without being sure this isn't an obvious dead end. >> 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. > > There aren't any code changes I can see that would explain this, we > didn't do anything to fix such behavior, and I don't see any > evidence of that in the logs you attached. ...then I'm not sure what the "later-than-expected" and "out-of-order" ESP packet references in the log excerpt from 8.05 are about, if they don't qualify as evidence that the client stayed with 8.05 and kept retrying and eventually got responses to older packets. > Also, replying to wrong/older ESP packets on a regular basis would > jam up your VPN connection thoroughly, and OpenConnect has an ESP > replay-protection mechanism that would be complaining ("replayed > packet" in the logs) if it were receiving packets significantly out > of order. I don't know about "significantly", but I certainly interpret "Accepting out-of-order ESP packet" as indicating that it has received a packet that was not in the expected order. The order received from the previous log excerpt was 2, 1, 3, 5, 4, 6, after which it went back to monotonic increments; packet 0 doesn't seem to have shown up at all. >> 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? > > I suggest that you try running openconnect without any kind of > wrapper script, just "openconnect -u user --prot=gp > server.compay.com/whatever --dump -vvvvv 2>&1 | tee openconnect.log". > Do that in a terminal and see how it runs. It appears that the > wrapper scripts you're using are adding a significant amount of > confusion about what's going on here. I don't really see how they're doing that, but sure, I can do this for one session's worth. I've got it running now (using the command from my innermost non-routing-script script, verbatim except for omitting --passwd-on-stdin and recombining it back onto one line, with that redirection modification added). I'll go grocery shopping pretty soon, and close the session and report results before the end of the night. The every-30-seconds ping keepalive to a machine across the VPN is running alongside it. This is with 8.05, by the way - the version from the most recent set of logs, which so far has not seen the connection drop like this. I can run a similar check (most likely overnight tonight) with 8.08, if desired. -- 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
Attachment:
signature.asc
Description: OpenPGP digital signature
_______________________________________________ openconnect-devel mailing list openconnect-devel@xxxxxxxxxxxxxxxxxxx http://lists.infradead.org/mailman/listinfo/openconnect-devel
