Re: [PATCH] ulogd: Restructures signal handling by self-pipe trick.

Re: [PATCH] ulogd: Restructures signal handling by self-pipe trick.

[Eric Leblond]

Hello,

On Tue, 2016-02-02 at 23:01 +0900, Hironobu Ishii wrote:
> ulogd had a critical bug that is calling Async-Signal-Unsafe
> functions
> in signal hander context.

Thanks a lot for this detailed bug report and fix. I'm gonna apply it
with minor white space fixes.

BR,
--
Eric.


>   - Most of libc functions like fopen(), malloc() are Async-Signal-
> Unsafe.
>     So you should not call these functions in signal handler context.
>   - Calling pluginstances in signal handler context is danger.
>     For implementer of pluginstances, it is very hard to recognize
> their
>     functions are called in signal handler context.
> 
> To solve the issue, I restructured signal handling by self-pipe
> trick.
> For more detail on self-pipe trick, please see the following.
> https://lwn.net/Articles/177897/
> 
> This patch will solve various symptoms like following.
>   - Deadlock
>   - Segmentation fault caused by libc management data corruption,
>   - Other unpredictable behavior.
> 
> Deadlock example
> ================
> This bug was already filed at:
> https://bugzilla.netfilter.org/show_bug.cgi?id=1030
> 
> I also hit this bug. The backtrace of this issue is following.
> In this case, main thread was calling ctime(),
> and signal handler called localtime_r().
> That caused the dead lock while getting tzset_lock in __tz_convert().
> Because vsyslog() is Async-Signal-Unsafe function, we cannot call
> this function in signal handler context.
> 
>  (gdb) bt
>  #0  __lll_lock_wait_private () at
> ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:95
>  #1  0x00007f3c3fc7e4ac in _L_lock_2462 () at tzset.c:621
>  #2  0x00007f3c3fc7e2e7 in __tz_convert (timer=0x7f3c3ff8bf00
> <tzset_lock>,
>      timer@entry=0x7fffcfa923b8, use_localtime=use_localtime@entry=1,
>      tp=tp@entry=0x7fffcfa92400) at tzset.c:624
>  #3  0x00007f3c3fc7c28d in __localtime_r (t=t@entry=0x7fffcfa923b8,
>      tp=tp@entry=0x7fffcfa92400) at localtime.c:32
>  #4  0x00007f3c3fcbf1ba in __GI___vsyslog_chk (pri=<optimized out>,
> flag=1,
>      fmt=0x406fa8 "signal received, calling pluginstances\n",
> ap=0x7fffcfa924a0)
>      at ../misc/syslog.c:199
>  #5  0x00000000004037b5 in __ulogd_log ()
>  #6  0x00000000004047be in signal_handler ()
>  #7  <signal handler called>
>  #8  0x00007f3c3fcb62f5 in __GI___xstat (vers=<optimized out>,
>      name=0x7f3c3fd4b2c3 "/etc/localtime", buf=0x7fffcfa92c10)
>      at ../sysdeps/unix/sysv/linux/wordsize-64/xstat.c:37
>  #9  0x00007f3c3fc7e5f6 in __tzfile_read (file=file@entry=0x7f3c3fd4b
> 2c3 "/etc/localtime",
>      extra=extra@entry=0, extrap=extrap@entry=0x0) at tzfile.c:170
>  #10 0x00007f3c3fc7d954 in tzset_internal (always=<optimized out>,
>      explicit=explicit@entry=1) at tzset.c:444
>  #11 0x00007f3c3fc7e303 in __tz_convert (timer=0x7fffcfa92d50,
>      use_localtime=use_localtime@entry=1, tp=tp@entry=0x7f3c3ff8ed80
> <_tmbuf>)
>      at tzset.c:629
>  #12 0x00007f3c3fc7c2a1 in __GI_localtime (t=<optimized out>) at
> localtime.c:42
>  #13 0x00007f3c3fc7c1f9 in ctime (t=<optimized out>) at ctime.c:27
>  #14 0x00007f3c3e180ec2 in ?? ()
>  #15 0x0000000056a100c2 in ?? ()
>  #16 0xf8570f79d4fc4200 in ?? ()
>  #17 0x000000000209bec0 in ?? ()
>  #18 0x00007f3c4059f1f8 in ?? ()
>  #19 0x000000000000003c in ?? ()
>  #20 0x0000000000404952 in ulogd_propagate_results ()
>  #21 0x00007f3c3f9cc203 in ?? ()
>  #22 0x0000000000000000 in ?? ()
> 
> Segmentation fault in free()
> ============================
> From my experience, I think this was caused by some routine called
> malloc()/free() in signal handler context.
> By that, malloc() management data became inconsistent.
> As a result, free() made a wrong dereference.
> 
> Program terminated with signal SIGSEGV, Segmentation fault.
>  #0  __GI___libc_free (mem=0x7f430f011000) at malloc.c:2903
>  2903      if (chunk_is_mmapped(p))                       /* release
> mmapped memory. */
>  (gdb) bt
>  #0  __GI___libc_free (mem=0x7f430f011000) at malloc.c:2903
>  #1  0x00007f430e68affa in __GI__IO_free_backup_area (fp=fp@entry=0x7
> 42500)
>      at genops.c:210
>  #2  0x00007f430e68a795 in _IO_new_file_overflow (f=0x742500, ch=-1)
> at fileops.c:849
>  #3  0x00007f430e689511 in _IO_new_file_xsputn (f=0x742500,
> data=<optimized out>, n=15)
>      at fileops.c:1372
>  #4  0x00007f430e65aa4d in _IO_vfprintf_internal (s=s@entry=0x742500,
>      format=<optimized out>, format@entry=0x7f430cbc4008 "%.15s %s
> %s",
>      ap=ap@entry=0x7fff456ece38) at vfprintf.c:1635
>  #5  0x00007f430e71d615 in ___fprintf_chk (fp=0x742500, flag=flag@ent
> ry=1,
>      format=format@entry=0x7f430cbc4008 "%.15s %s %s") at
> fprintf_chk.c:36
>  #6  0x00007f430cbc3f04 in fprintf (__fmt=0x7f430cbc4008 "%.15s %s
> %s",
>      __stream=<optimized out>) at /usr/include/bits/stdio2.h:97
>  #7  _output_logemu (upi=0x74e5a0) at ulogd_output_LOGEMU.c:102
>  #8  0x0000000000404952 in ulogd_propagate_results ()
>  #9  0x00007f430e40f203 in interp_packet (ldata=0x7fff456ed060,
> pf_family=2 '\002',
>      upi=0x74a6b0) at ulogd_inppkt_NFLOG.c:400
>  #10 msg_cb (gh=<optimized out>, nfmsg=0x7f430efe2020,
> nfa=0x7fff456ed060, data=0x74a6b0)
>      at ulogd_inppkt_NFLOG.c:483
>  #11 0x00007f430e20a307 in __nflog_rcv_pkt (nlh=<optimized out>,
> nfa=<optimized out>,
>      data=<optimized out>) at libnetfilter_log.c:160
>  #12 0x00007f430e0056b7 in __nfnl_handle_msg (len=268,
> nlh=0x7f430efe2010, h=0x74e8e0)
>      at libnfnetlink.c:1236
>  #13 nfnl_handle_packet (h=0x74e8e0, buf=0x7f430efe2010 "\f\001",
> len=<optimized out>)
>      at libnfnetlink.c:1256
>  #14 0x00007f430e20a508 in nflog_handle_packet (h=<optimized out>,
> buf=<optimized out>,
>      len=<optimized out>) at libnetfilter_log.c:323
>  #15 0x00007f430e40eaed in nful_read_cb (fd=<optimized out>,
> what=<optimized out>,
>      param=0x74a6b0) at ulogd_inppkt_NFLOG.c:463
>  #16 0x0000000000404ee0 in ulogd_select_main ()
>  #17 0x0000000000402b17 in main ()
> 
> Signed-off-by: Hironobu Ishii <ishii.hironobu@jp.fujitsu.com>
> ---
>  src/ulogd.c | 132
> ++++++++++++++++++++++++++++++++++++++++++++++++++++++++----
>  1 file changed, 125 insertions(+), 7 deletions(-)
> 
> diff --git a/src/ulogd.c b/src/ulogd.c
> index 958c30a..4c76e43 100644
> --- a/src/ulogd.c
> +++ b/src/ulogd.c
> @@ -90,6 +90,29 @@ static int info_mode = 0;
>  static int verbose = 0;
>  static int created_pidfile = 0;
>  
> +/*
> + * Using self-pipe trick to handle signals safely.
> + * (To avoid calling Async-Signal-Unsafe functions in signal
> handler.)
> + *
> + * cf. https://lwn.net/Articles/177897/
> + * 
> + * Capacity of pipe(2) buffer is >= 4096.
> + */
> +static int signal_channel[2] = { -1, -1 };	/* initialize with
> invalid fd */
> +#define	SIGNAL_RX_FD	(signal_channel[0])	/*
> main thread select() this fd */
> +#define	SIGNAL_TX_FD	(signal_channel[1])	/*
> signal handler writes to this fd */
> +
> +static void signal_handler(int signal);
> +static void sigterm_handler_task(int signal);
> +static void signal_handler_task(int signal);
> +
> +static int  signal_channel_callback(int fd, unsigned int what, void
> *data);
> +static struct ulogd_fd	signal_channel_ulogfd = {
> +	.when = ULOGD_FD_READ,
> +	.cb = &signal_channel_callback,
> +	.data = &signal_channel_ulogfd,
> +};
> +
>  /* linked list for all registered plugins */
>  static LLIST_HEAD(ulogd_plugins);
>  /* linked list for all plugins handle */
> @@ -387,6 +410,80 @@ void ulogd_register_plugin(struct ulogd_plugin
> *me)
>  }
>  
>  /*******************************************************************
> ****
> + * UTILITY FUNCTIONS FOR SIGNAL HANDLING
> +
> *********************************************************************
> **/
> +static void call_signal_handler_tasks(int sig)
> +{
> +	/* Deliver signals */
> +	switch (sig) {
> +	case SIGTERM:
> +	case SIGINT:
> +		sigterm_handler_task(sig);
> +		break;
> +	case SIGHUP:
> +	case SIGALRM:
> +	case SIGUSR1:
> +	case SIGUSR2:
> +		signal_handler_task(sig);
> +		break;
> +	default:
> +		break;
> +	}
> +}
> +
> +static int signal_channel_callback(int fd, unsigned int what, void
> *data)
> +{
> +	int	ret;
> +	unsigned char c;
> +
> +	while ((ret = read(fd, &c, 1)) > 0) {
> +		call_signal_handler_tasks((int)c);
> +	}
> +	return 0;
> +}
> +
> +static int create_signal_channel(void)
> +{
> +	int	ret;
> +	long	flags;
> +
> +	if ((ret = pipe(signal_channel)) < 0)
> +		return ret;
> +
> +	/* SIGNAL_RX_FD, channel[0] */
> +	if ((flags = fcntl(SIGNAL_RX_FD, F_GETFL)) < 0)
> +		goto err_exit;
> +	flags |= O_NONBLOCK;
> +	if ( fcntl(SIGNAL_RX_FD, F_SETFL, flags) < 0 )
> +		goto err_exit;
> +
> +	/* SIGNAL_TX_FD, channel[1] */
> +	if ((flags = fcntl(SIGNAL_TX_FD, F_GETFL)) < 0)
> +		goto err_exit;
> +	flags |= O_NONBLOCK;
> +	if ( fcntl(SIGNAL_TX_FD, F_SETFL, flags) < 0 )
> +		goto err_exit;
> +
> +	/* register SIGNAL_RX_FD to ulogd */
> +	signal_channel_ulogfd.fd = SIGNAL_RX_FD;
> +	ulogd_register_fd(&signal_channel_ulogfd);
> +
> +	return 0;
> +
> +err_exit:
> +	if (SIGNAL_RX_FD >= 0) {
> +		(void)close(SIGNAL_RX_FD);
> +		SIGNAL_RX_FD = -1;
> +	}
> +	if (SIGNAL_TX_FD >= 0) {
> +		(void)close(SIGNAL_TX_FD);
> +		SIGNAL_TX_FD = -1;
> +	}
> +	return -1;
> +}
> +
> +
> +/*******************************************************************
> ****
>   * MAIN PROGRAM
>  
> *********************************************************************
> **/
>  
> @@ -925,7 +1022,6 @@ static void ulogd_main_loop(void)
>  	struct timeval *next = NULL;
>  
>  	while (1) {
> -		/* XXX: signal blocking? */
>  		if (next != NULL && !timerisset(next))
>  			next = ulogd_do_timer_run(&next_alarm);
>  		else
> @@ -1225,7 +1321,19 @@ static void stop_stack()
>  }
>  
>  
> -static void sigterm_handler(int signal)
> +/* This is a real SIGTERM, SIGINT, SIGHUP, SIGALRM, SIGUSR1, SIGUSR2
> handler */
> +static void signal_handler(int signal)
> +{
> +	unsigned char	c = (unsigned char)signal;
> +
> +	(void)write(SIGNAL_TX_FD, &c, 1);
> +}
> +
> +/* This is NOT a real signal handler.
> + * It is called in ulogd_main_loop() to avoid
> + * calling Async-Signal-UnSafe functions in signal handler.
> + */
> +static void sigterm_handler_task(int signal)
>  {
>  
>  	ulogd_log(ULOGD_NOTICE, "Terminal signal received,
> exiting\n");
> @@ -1255,7 +1363,12 @@ static void sigterm_handler(int signal)
>  	exit(0);
>  }
>  
> -static void signal_handler(int signal)
> +
> +/* This is NOT a real signal handler.
> + * It is called in ulogd_main_loop() to avoid
> + * calling Async-Signal-UnSafe functions in signal handler.
> + */
> +static void signal_handler_task(int signal)
>  {
>  	ulogd_log(ULOGD_NOTICE, "signal received, calling
> pluginstances\n");
>  	
> @@ -1269,7 +1382,7 @@ static void signal_handler(int signal)
>  				fprintf(stderr, 
>  					"ERROR: can't open logfile
> %s: %s\n", 
>  					ulogd_logfile,
> strerror(errno));
> -				sigterm_handler(signal);
> +				sigterm_handler_task(signal);
>  			}
>  	
>  		}
> @@ -1464,8 +1577,13 @@ int main(int argc, char* argv[])
>  		}
>  	}
>  
> -	signal(SIGTERM, &sigterm_handler);
> -	signal(SIGINT, &sigterm_handler);
> +	if (create_signal_channel() < 0) {
> +		ulogd_log(ULOGD_FATAL, "can't create signal
> channel\n");
> +		warn_and_exit(daemonize);
> +	}
> +
> +	signal(SIGTERM, &signal_handler);
> +	signal(SIGINT, &signal_handler);
>  	signal(SIGHUP, &signal_handler);
>  	signal(SIGALRM, &signal_handler);
>  	signal(SIGUSR1, &signal_handler);
> @@ -1477,6 +1595,6 @@ int main(int argc, char* argv[])
>  	ulogd_main_loop();
>  
>  	/* hackish, but result is the same */
> -	sigterm_handler(SIGTERM);	
> +	sigterm_handler_task(SIGTERM);	
>  	return(0);
>  }
-- 
Eric Leblond <eric@regit.org>


--
To unsubscribe from this list: send the line "unsubscribe netfilter-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html