2014-08-08 14:54:54 +04:00
/*
2008-01-16 14:03:01 +03:00
ctdb logging code
Copyright ( C ) Andrew Tridgell 2008
This program is free software ; you can redistribute it and / or modify
it under the terms of the GNU General Public License as published by
the Free Software Foundation ; either version 3 of the License , or
( at your option ) any later version .
2014-08-08 14:54:54 +04:00
2008-01-16 14:03:01 +03:00
This program is distributed in the hope that it will be useful ,
but WITHOUT ANY WARRANTY ; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE . See the
GNU General Public License for more details .
2014-08-08 14:54:54 +04:00
2008-01-16 14:03:01 +03:00
You should have received a copy of the GNU General Public License
along with this program ; if not , see < http : //www.gnu.org/licenses/>.
*/
2015-10-26 08:50:46 +03:00
# include "replace.h"
# include "system/filesys.h"
# include "system/network.h"
2008-01-16 14:03:01 +03:00
# include "system/syslog.h"
# include "system/time.h"
2015-10-26 08:50:46 +03:00
# include <talloc.h>
# include <tevent.h>
2014-08-11 11:07:41 +04:00
# include "lib/util/dlinklist.h"
2015-10-26 08:50:46 +03:00
# include "lib/util/debug.h"
# include "ctdb_private.h"
# include "ctdb_client.h"
# include "ctdb_logging.h"
2015-10-23 06:11:53 +03:00
# include "common/system.h"
2015-10-23 06:17:34 +03:00
# include "common/common.h"
2014-08-11 11:07:41 +04:00
2015-11-11 06:31:41 +03:00
const char * debug_extra = " " ;
2014-08-11 11:07:41 +04:00
struct ctdb_log_backend {
struct ctdb_log_backend * prev , * next ;
const char * prefix ;
ctdb_log_setup_fn_t setup ;
} ;
2008-01-16 14:03:01 +03:00
struct ctdb_log_state {
2011-08-26 03:39:25 +04:00
const char * prefix ;
2008-01-16 14:03:01 +03:00
int fd , pfd ;
char buf [ 1024 ] ;
uint16_t buf_used ;
2009-12-08 05:14:30 +03:00
void ( * logfn ) ( const char * , uint16_t , void * ) ;
void * logfn_private ;
2014-08-11 11:07:41 +04:00
struct ctdb_log_backend * backends ;
2008-01-16 14:03:01 +03:00
} ;
2014-08-11 11:07:41 +04:00
/* Used by ctdb_set_child_logging() */
2008-01-16 14:03:01 +03:00
static struct ctdb_log_state * log_state ;
2014-08-11 11:07:41 +04:00
void ctdb_log_register_backend ( const char * prefix , ctdb_log_setup_fn_t setup )
{
struct ctdb_log_backend * b ;
b = talloc_zero ( log_state , struct ctdb_log_backend ) ;
if ( b = = NULL ) {
printf ( " Failed to register backend \" %s \" - no memory \n " ,
prefix ) ;
return ;
}
b - > prefix = prefix ;
b - > setup = setup ;
DLIST_ADD_END ( log_state - > backends , b , NULL ) ;
}
/* Initialise logging */
bool ctdb_logging_init ( TALLOC_CTX * mem_ctx , const char * logging )
2008-01-16 14:03:01 +03:00
{
2014-08-11 11:07:41 +04:00
struct ctdb_log_backend * b ;
2009-05-20 14:08:13 +04:00
int ret ;
2009-10-30 10:53:17 +03:00
2014-10-16 13:03:51 +04:00
log_state = talloc_zero ( mem_ctx , struct ctdb_log_state ) ;
2014-08-08 05:50:37 +04:00
if ( log_state = = NULL ) {
2009-05-20 13:47:34 +04:00
printf ( " talloc_zero failed \n " ) ;
abort ( ) ;
}
2008-01-16 14:03:01 +03:00
2014-08-11 11:07:41 +04:00
ctdb_log_init_file ( ) ;
ctdb_log_init_syslog ( ) ;
for ( b = log_state - > backends ; b ! = NULL ; b = b - > next ) {
size_t l = strlen ( b - > prefix ) ;
/* Exact match with prefix or prefix followed by ':' */
if ( strncmp ( b - > prefix , logging , l ) = = 0 & &
( logging [ l ] = = ' \0 ' | | logging [ l ] = = ' : ' ) ) {
ret = b - > setup ( mem_ctx , logging , " ctdbd " ) ;
if ( ret = = 0 ) {
return true ;
}
printf ( " Log init for \" %s \" failed with \" %s \" \n " ,
logging , strerror ( ret ) ) ;
return false ;
2008-01-16 14:03:01 +03:00
}
}
2014-08-11 11:07:41 +04:00
printf ( " Unable to find log backend for \" %s \" \n " , logging ) ;
return false ;
2008-01-16 14:03:01 +03:00
}
2009-12-08 05:14:30 +03:00
/* Note that do_debug always uses the global log state. */
static void write_to_log ( struct ctdb_log_state * log ,
const char * buf , unsigned int len )
{
2014-09-24 11:12:56 +04:00
if ( script_log_level < = DEBUGLEVEL ) {
2011-08-26 03:39:25 +04:00
if ( log ! = NULL & & log - > prefix ! = NULL ) {
2014-08-19 06:15:31 +04:00
dbgtext ( " %s: %*.*s \n " , log - > prefix , len , len , buf ) ;
2011-08-26 03:39:25 +04:00
} else {
2014-08-19 06:15:31 +04:00
dbgtext ( " %*.*s \n " , len , len , buf ) ;
2011-08-26 03:39:25 +04:00
}
2009-12-08 05:14:30 +03:00
/* log it in the eventsystem as well */
2013-11-11 05:39:27 +04:00
if ( log & & log - > logfn ) {
2009-12-08 05:14:30 +03:00
log - > logfn ( log - > buf , len , log - > logfn_private ) ;
2013-11-11 05:39:27 +04:00
}
2009-12-08 05:14:30 +03:00
}
}
2008-01-16 14:03:01 +03:00
/*
called when log data comes in from a child process
*/
2015-10-26 08:50:09 +03:00
static void ctdb_child_log_handler ( struct tevent_context * ev ,
struct tevent_fd * fde ,
2014-08-08 05:42:51 +04:00
uint16_t flags , void * private )
2008-01-16 14:03:01 +03:00
{
2009-12-07 17:01:29 +03:00
struct ctdb_log_state * log = talloc_get_type ( private , struct ctdb_log_state ) ;
2008-01-16 14:03:01 +03:00
char * p ;
2008-07-23 09:25:52 +04:00
int n ;
2008-01-16 14:03:01 +03:00
2015-10-26 08:50:09 +03:00
if ( ! ( flags & TEVENT_FD_READ ) ) {
2008-01-16 14:03:01 +03:00
return ;
}
2011-08-26 03:39:25 +04:00
2014-07-30 15:03:53 +04:00
n = sys_read ( log - > pfd , & log - > buf [ log - > buf_used ] ,
2009-12-07 17:01:29 +03:00
sizeof ( log - > buf ) - log - > buf_used ) ;
2008-07-23 09:25:52 +04:00
if ( n > 0 ) {
2009-12-07 17:01:29 +03:00
log - > buf_used + = n ;
2009-12-15 02:23:58 +03:00
} else if ( n = = 0 ) {
2009-12-15 11:04:52 +03:00
if ( log ! = log_state ) {
talloc_free ( log ) ;
}
2009-12-15 02:23:58 +03:00
return ;
2008-01-16 14:03:01 +03:00
}
2009-12-07 17:01:29 +03:00
while ( log - > buf_used > 0 & &
( p = memchr ( log - > buf , ' \n ' , log - > buf_used ) ) ! = NULL ) {
int n1 = ( p - log - > buf ) + 1 ;
2008-07-23 09:25:52 +04:00
int n2 = n1 - 1 ;
/* swallow \r from child processes */
2009-12-07 17:01:29 +03:00
if ( n2 > 0 & & log - > buf [ n2 - 1 ] = = ' \r ' ) {
2008-07-23 09:25:52 +04:00
n2 - - ;
2008-01-16 15:06:37 +03:00
}
2009-12-08 05:14:30 +03:00
write_to_log ( log , log - > buf , n2 ) ;
2009-12-07 17:01:29 +03:00
memmove ( log - > buf , p + 1 , sizeof ( log - > buf ) - n1 ) ;
log - > buf_used - = n1 ;
2008-01-16 14:03:01 +03:00
}
2008-07-23 09:25:52 +04:00
/* the buffer could have completely filled - unfortunately we have
no choice but to dump it out straight away */
2009-12-07 17:01:29 +03:00
if ( log - > buf_used = = sizeof ( log - > buf ) ) {
2009-12-08 05:14:30 +03:00
write_to_log ( log , log - > buf , log - > buf_used ) ;
2009-12-07 17:01:29 +03:00
log - > buf_used = 0 ;
2008-01-16 14:40:01 +03:00
}
2008-01-16 14:03:01 +03:00
}
2009-12-08 05:14:30 +03:00
static int log_context_destructor ( struct ctdb_log_state * log )
{
/* Flush buffer in case it wasn't \n-terminated. */
if ( log - > buf_used > 0 ) {
write_to_log ( log , log - > buf , log - > buf_used ) ;
}
return 0 ;
}
2013-12-16 08:39:29 +04:00
/*
* vfork + exec , redirecting child output to logging and specified callback .
*/
struct ctdb_log_state * ctdb_vfork_with_logging ( TALLOC_CTX * mem_ctx ,
struct ctdb_context * ctdb ,
const char * log_prefix ,
const char * helper ,
int helper_argc ,
const char * * helper_argv ,
void ( * logfn ) ( const char * , uint16_t , void * ) ,
void * logfn_private , pid_t * pid )
{
int p [ 2 ] ;
struct ctdb_log_state * log ;
struct tevent_fd * fde ;
char * * argv ;
int i ;
log = talloc_zero ( mem_ctx , struct ctdb_log_state ) ;
CTDB_NO_MEMORY_NULL ( ctdb , log ) ;
log - > prefix = log_prefix ;
log - > logfn = logfn ;
log - > logfn_private = logfn_private ;
if ( pipe ( p ) ! = 0 ) {
DEBUG ( DEBUG_ERR , ( __location__ " Failed to setup pipe for child logging \n " ) ) ;
goto free_log ;
}
argv = talloc_array ( mem_ctx , char * , helper_argc + 2 ) ;
if ( argv = = NULL ) {
DEBUG ( DEBUG_ERR , ( __location__ " Failed to allocate memory for helper \n " ) ) ;
goto free_log ;
}
argv [ 0 ] = discard_const ( helper ) ;
argv [ 1 ] = talloc_asprintf ( argv , " %d " , p [ 1 ] ) ;
if ( argv [ 1 ] = = NULL ) {
DEBUG ( DEBUG_ERR , ( __location__ " Failed to allocate memory for helper \n " ) ) ;
talloc_free ( argv ) ;
goto free_log ;
}
for ( i = 0 ; i < helper_argc ; i + + ) {
argv [ i + 2 ] = discard_const ( helper_argv [ i ] ) ;
}
* pid = vfork ( ) ;
if ( * pid = = 0 ) {
execv ( helper , argv ) ;
_exit ( 1 ) ;
}
close ( p [ 1 ] ) ;
if ( * pid < 0 ) {
DEBUG ( DEBUG_ERR , ( __location__ " vfork failed for helper process \n " ) ) ;
close ( p [ 0 ] ) ;
goto free_log ;
}
ctdb_track_child ( ctdb , * pid ) ;
log - > pfd = p [ 0 ] ;
set_close_on_exec ( log - > pfd ) ;
talloc_set_destructor ( log , log_context_destructor ) ;
2015-10-26 08:50:09 +03:00
fde = tevent_add_fd ( ctdb - > ev , log , log - > pfd , TEVENT_FD_READ ,
2014-08-08 05:42:51 +04:00
ctdb_child_log_handler , log ) ;
2013-12-16 08:39:29 +04:00
tevent_fd_set_auto_close ( fde ) ;
return log ;
free_log :
talloc_free ( log ) ;
return NULL ;
}
2008-01-16 14:03:01 +03:00
/*
setup for logging of child process stdout
*/
int ctdb_set_child_logging ( struct ctdb_context * ctdb )
{
int p [ 2 ] ;
2010-01-07 15:29:09 +03:00
int old_stdout , old_stderr ;
2010-08-18 03:46:31 +04:00
struct tevent_fd * fde ;
2008-01-16 14:03:01 +03:00
2014-08-08 05:50:37 +04:00
if ( log_state - > fd = = STDOUT_FILENO ) {
2008-01-16 14:03:01 +03:00
/* not needed for stdout logging */
return 0 ;
}
/* setup a pipe to catch IO from subprocesses */
if ( pipe ( p ) ! = 0 ) {
2008-02-04 12:07:15 +03:00
DEBUG ( DEBUG_ERR , ( __location__ " Failed to setup for child logging pipe \n " ) ) ;
2008-01-16 14:03:01 +03:00
return - 1 ;
}
2010-01-07 15:29:09 +03:00
/* We'll fail if stderr/stdout not already open; it's simpler. */
old_stdout = dup ( STDOUT_FILENO ) ;
old_stderr = dup ( STDERR_FILENO ) ;
2011-08-10 19:53:56 +04:00
if ( old_stdout < 0 | | old_stderr < 0 ) {
DEBUG ( DEBUG_ERR , ( " Failed to dup stdout/stderr for child logging \n " ) ) ;
return - 1 ;
}
2010-01-07 15:29:09 +03:00
if ( dup2 ( p [ 1 ] , STDOUT_FILENO ) < 0 | | dup2 ( p [ 1 ] , STDERR_FILENO ) < 0 ) {
int saved_errno = errno ;
dup2 ( old_stdout , STDOUT_FILENO ) ;
dup2 ( old_stderr , STDERR_FILENO ) ;
close ( old_stdout ) ;
close ( old_stderr ) ;
close ( p [ 0 ] ) ;
close ( p [ 1 ] ) ;
errno = saved_errno ;
printf ( __location__ " dup2 failed: %s \n " ,
strerror ( errno ) ) ;
return - 1 ;
}
close ( p [ 1 ] ) ;
close ( old_stdout ) ;
close ( old_stderr ) ;
2015-10-26 08:50:09 +03:00
fde = tevent_add_fd ( ctdb - > ev , log_state , p [ 0 ] , TEVENT_FD_READ ,
ctdb_child_log_handler , log_state ) ;
2010-08-18 03:46:31 +04:00
tevent_fd_set_auto_close ( fde ) ;
2014-08-08 05:50:37 +04:00
log_state - > pfd = p [ 0 ] ;
2008-01-16 14:03:01 +03:00
2010-02-03 22:37:41 +03:00
DEBUG ( DEBUG_DEBUG , ( __location__ " Created PIPE FD:%d for logging \n " , p [ 0 ] ) ) ;
2009-10-15 04:24:54 +04:00
2008-01-16 14:03:01 +03:00
return 0 ;
}
2009-11-18 04:44:18 +03:00
2010-09-22 04:59:01 +04:00
/*
* set up a log handler to catch logging from TEVENT
*/
2014-12-15 16:54:18 +03:00
static void ctdb_tevent_logging ( void * private_data ,
enum tevent_debug_level level ,
const char * fmt ,
va_list ap ) PRINTF_ATTRIBUTE ( 3 , 0 ) ;
2010-09-22 04:59:01 +04:00
static void ctdb_tevent_logging ( void * private_data ,
enum tevent_debug_level level ,
const char * fmt ,
va_list ap )
{
2012-09-28 03:39:12 +04:00
enum debug_level lvl = DEBUG_CRIT ;
2010-09-22 04:59:01 +04:00
switch ( level ) {
case TEVENT_DEBUG_FATAL :
2012-09-28 03:39:12 +04:00
lvl = DEBUG_CRIT ;
2010-09-22 04:59:01 +04:00
break ;
case TEVENT_DEBUG_ERROR :
lvl = DEBUG_ERR ;
break ;
case TEVENT_DEBUG_WARNING :
lvl = DEBUG_WARNING ;
break ;
case TEVENT_DEBUG_TRACE :
lvl = DEBUG_DEBUG ;
break ;
}
2014-09-24 11:12:56 +04:00
if ( lvl < = DEBUGLEVEL ) {
2014-12-15 16:54:18 +03:00
dbgtext_va ( fmt , ap ) ;
2010-09-22 04:59:01 +04:00
}
}
int ctdb_init_tevent_logging ( struct ctdb_context * ctdb )
{
int ret ;
ret = tevent_set_debug ( ctdb - > ev ,
ctdb_tevent_logging ,
2014-08-08 14:54:54 +04:00
ctdb ) ;
2010-09-22 04:59:01 +04:00
return ret ;
}