Opened 4 years ago

Closed 4 years ago

#777 closed Bug / Defect (fixed)

excessive logging with explicit-exit-notify

Reported by: rf Owned by:
Priority: major Milestone:
Component: Generic / unclassified Version: OpenVPN 2.4_alpha2 (Community Ed)
Severity: Not set (select this one, unless your'e a OpenVPN developer) Keywords:
Cc: Selva Nair

Description

With the current Windows beta version:

Mon Nov 28 21:13:19 2016 OpenVPN 2.4_beta2 x86_64-w64-mingw32 [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] built on Nov 25 2016

running on:

Mon Nov 28 21:13:19 2016 Windows version 6.2 (Windows 8 or greater) 64bit

stopping a OpenVPN connection with "explicit-exit-notify 2" and "verb 3" set in the configuration file results in excessive logging of Ignoring SIGUSR1 received during exit notification messages.

Example:

Mon Nov 28 21:14:19 2016 SIGTERM received, sending exit notification to peer
Mon Nov 28 21:14:19 2016 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mon Nov 28 21:14:19 2016 TLS Error: TLS handshake failed
Mon Nov 28 21:14:19 2016 Ignoring SIGUSR1 received during exit notification
Mon Nov 28 21:14:19 2016 Ignoring SIGUSR1 received during exit notification
Mon Nov 28 21:14:19 2016 Ignoring SIGUSR1 received during exit notification

[.. thousands of repeated lines, the logfile is 14MBytes big full
of duplicated lines ..]

Mon Nov 28 21:14:21 2016 Ignoring SIGUSR1 received during exit notification
Mon Nov 28 21:14:21 2016 SIGTERM[soft,exit-with-notification] received, process exiting
Mon Nov 28 21:14:21 2016 MANAGEMENT: >STATE:1480364061,EXITING,exit-with-notification,,,,,

It seems that the message is logged as long as the explicit notify process is going on.

Change History (7)

comment:1 Changed 4 years ago by Gert Döring

Cc: Selva Nair added

does this happen on any "stop", or just if you stop the connection attempt before it completes?

@selva: your understanding of the signal logic is better than mine - and the line in question came in by one of your commits anyway :-) - any quick idea how to tackle this?

"git blame" says this came in due to commit 63b3e000c9141f4ca03a374354da26334257bc18, which basically is the fix for #687 - which still make sense, but why is the SIGUSR1-being-ignored getting stuck?

comment:2 Changed 4 years ago by Selva Nair

The reported log shows TLS key negotiation failed. In that case exit-notification cannot happen and probably something is triggering SIGUSR1 restart instead. Before the said commit, the restart would have proceeded with the usual timewait and the SIGTERM lost in the process.

Looks like the fix ignored situations where exit notification wont happen. May be we should remap the restart signal to a SIGTERM and promptly exit?

EDIT: or openvpn_sleep(1)?

Last edited 4 years ago by Selva Nair (previous) (diff)

comment:3 Changed 4 years ago by Selva Nair

Looked into this further and I can reproduce it even on Linux with some carefully timed ctrl-c. To see this, TLS key negotiation timeout has to happen during the exit-notification wait interval -- so use an unreachabe udp port, set --exit-notify 5 and press ctrl-c a second or so before the 60 second handshake_window expires. --ping-restart should be > 60 sec.

More technical comments and a patch sent to the devel-list.

comment:4 in reply to:  3 Changed 4 years ago by Gert Döring

Replying to selvanair:

More technical comments and a patch sent to the devel-list.

Cool, thanks. Waking up to find patches :-)

comment:5 Changed 4 years ago by Gert Döring

Since I can reproduce this with ctrl-C on linux, I can now also attest that this patch fixes it :-)

commit f25a0217e35f53c3110ebb226e1d1f3528152cb5
Author: Selva Nair <selva.nair@…>
Date: Mon Nov 28 21:27:04 2016 -0500

Map restart signals from event loop to SIGTERM during exit-notification wait

thanks a lot.

@rf: the snapshot builder will build a new windows installer with this patch in about half an hour - if you want to re-test? (to be found on https://build.openvpn.net/download/snapshots/)

comment:6 Changed 4 years ago by rf

Thanks a lot for the quick fix! After installing the snapshot build from today the excessive logging does not occur anymore.

comment:7 Changed 4 years ago by Gert Döring

Resolution: fixed
Status: newclosed

@rf: thanks for re-testing.

2.3 got the fix as well to day (thanks, Selva), so this ticket can be closed for good :-)

commit 4d397fcbc023271c7117cb83b13114389bf3265b
Author: Selva Nair <selva.nair@…>
Date: Tue Nov 29 20:48:55 2016 -0500

Map restart signals from event loop to SIGTERM during exit-notification wait

Note: See TracTickets for help on using tickets.