added a so-called "On Demand Debug" mode

in which debug output can be generated only after the process has started, but not right from the beginning. This is assumed to be useful for hard-to-find bugs. Also improved the doc on the debug system.
author: Rainer Gerhards <rgerhards@adiscon.com> 2009-11-10 12:50:48 +0100
committer: Rainer Gerhards <rgerhards@adiscon.com> 2009-11-10 12:50:48 +0100
commit: 2b5e15d549940c7ace9017eaf40d523e3741c9a2 (patch)
tree: bc22cdc468329ab9996c0b8b1bc68348e0160149
parent: 224c3aef8b4d3d95ab2100c3056f2f92c130b220 (diff)
download: rsyslog-2b5e15d549940c7ace9017eaf40d523e3741c9a2.tar.gz
rsyslog-2b5e15d549940c7ace9017eaf40d523e3741c9a2.tar.xz
rsyslog-2b5e15d549940c7ace9017eaf40d523e3741c9a2.zip
4 files changed, 132 insertions, 23 deletions
diff --git a/ChangeLog b/ChangeLog
index fc75ac7a..9e0fa31d 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,5 +1,9 @@
 ---------------------------------------------------------------------------
 Version 4.5.7  [v4-beta] (rgerhards), 2009-11-??
+- added a so-called "On Demand Debug" mode, in which debug output can
+  be generated only after the process has started, but not right from
+  the beginning. This is assumed to be useful for hard-to-find bugs.
+  Also improved the doc on the debug system.
 ---------------------------------------------------------------------------
 Version 4.5.6  [v4-beta] (rgerhards), 2009-11-05
 - bugfix: named pipes did no longer work (they always got an open error)
diff --git a/doc/debug.html b/doc/debug.html
index de77f04a..3803be1a 100644
--- a/doc/debug.html
+++ b/doc/debug.html
@@ -1,41 +1,125 @@
 <!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN">
 <html><head>
-<meta http-equiv="Content-Language" content="en"><title>Debug Support</title></head>
+<meta http-equiv="Content-Language" content="en">
+<title>Rsyslog Debug Support</title></head>
 <body>
-<h1>Debug Support</h1>
+<h1>Rsyslog Debug Support</h1>
 <p>
-Rsyslog provides a number of debug aids. Some of them are activated by
+Rsyslog provides a number of debug aides. Some of them are activated by
 adding the --enable-rtinst ./configure option ("rtinst" means runtime
 instrumentation). Turning debugging on obviously costs some performance
 (in some cases considerable).
 </p>
 <p>This is document is just being created and thus terse.</p>
-<p style="font-weight: bold;">Signals supported</p>
-<p>SIGUSR1 - turns debug messages on and off (expect this signal
-to go away over time)</p>
-<p>SIGUSR2 - outputs debug information (including active threads
+<h2>Signals supported</h2>
+<p><b>SIGUSR1</b> - turns debug messages on and off. Note that for this
+signal to work, rsyslogd must be running with debugging enabled, either
+via the -d command line switch or the environment options specified below.
+It is <b>not</b> required that rsyslog was compiled with debugging enabled
+(but depending on the settings this may lead to better debug info).
+<p><b>SIGUSR2</b> - outputs debug information (including active threads
 and a call stack) for the state when SIGUSR2 was received. This is a
-one-time output. Can be sent as often as the user likes.</p>
-<p style="font-weight: bold;">Environment Variables</p>
-<p>There are two environment variables that set several debug settings. The "RSYSLOG_DEBUGLOG" (sample: &nbsp;RSYSLOG_DEBUGLOG="/path/to/debuglog/")
+one-time output. Can be sent as often as the user likes.
+<p><b>Note:</b> this signal <b>may go away</b> in later releases and may
+be replaced by something else.</p>
+<h2>Environment Variables</h2>
+<p>There are two environment variables that set several debug settings:
+<ul>
+<li>The "RSYSLOG_DEBUGLOG" (sample: &nbsp;RSYSLOG_DEBUGLOG="/path/to/debuglog/")
 writes (allmost)
 all debug message to the specified log file in addition to stdout. Some
 system messages (e.g. segfault or abort message) are not written to the
-file as we can not capture them. Runtime debug support is controlled by
-"RSYSLOG_DEBUG". It contains an option string with the following
-options possible (all are case insensitive):</p><ul><li><span style="font-weight: bold;">LogFuncFlow</span> - print out the logical flow of functions (entering and exiting them)</li><li><span style="font-weight: bold;">FileTrace</span> - specifies which files to trace LogFuncFlow. If <span style="font-weight: bold;">not</span>
+file as we can not capture them.
+<li>Runtime debug support is controlled by "RSYSLOG_DEBUG".
+<p>The "RSYSLOG_DEBUG" environment variable contains an option string with the following
+options possible (all are case insensitive):</p>
+<ul>
+<li><b>LogFuncFlow</b> - print out the logical flow of functions (entering and exiting them)</li>
+<li><b>FileTrace</b> - specifies which files to trace LogFuncFlow. If <b>not</b>
 set (the default), a LogFuncFlow trace is provided for all files. Set
 to limit it to the files specified. FileTrace may be specified multiple
 times, one file each (e.g. export RSYSLOG_DEBUG="LogFuncFlow
-FileTrace=vm.c FileTrace=expr.c"</li><li><span style="font-weight: bold;">PrintFuncDB</span> - print the content of the debug function database whenever debug information is printed (e.g. abort case)!</li><li><span style="font-weight: bold;">PrintAllDebugInfoOnExit</span> - print all debug information immediately before rsyslogd exits (<span style="font-weight: bold; font-style: italic;">currently not implemented!</span>)</li><li><span style="font-weight: bold;">PrintMutexAction</span> - print mutex action as it happens. Useful for finding deadlocks and such.</li><li><span style="font-weight: bold;">NoLogTimeStamp</span> - do not prefix log lines with a timestamp (default is to do that).</li><li><span style="font-weight: bold;">NoStdOut</span> - do not emit debug messages to stdout. If RSYSLOG_DEBUGLOG is not set, this means no messages will be displayed at all.</li><li><span style="font-weight: bold;">help</span> - display a very short list of commands - hopefully a life saver if you can't access the documentation...</li></ul>
+FileTrace=vm.c FileTrace=expr.c"</li>
+<li><b>PrintFuncDB</b> - print the content of the debug function database whenever debug information is printed (e.g. abort case)!</li>
+<li><b>PrintAllDebugInfoOnExit</b> - print all debug information immediately before rsyslogd exits (<span style="font-weight: bold; font-style: italic;">currently not implemented!</span>)</li>
+<li><b>PrintMutexAction</b> - print mutex action as it happens. Useful for finding deadlocks and such.</li>
+<li><b>NoLogTimeStamp</b> - do not prefix log lines with a timestamp (default is to do that).</li>
+<li><b>NoStdOut</b> - do not emit debug messages to stdout. If RSYSLOG_DEBUGLOG is not set, this means no messages will be displayed at all.</li>
+<li><b>Debug</b> - if present, turns on the debug system and enables debug output
+<li><b>DebugOnDemand</b> - if present, turns on the debug system but does not enable
+debug output itself. You need to send SIGUSR1 to turn it on when desired.
+<li><b>help</b> - display a very short list of commands - hopefully a life saver if you can't access the documentation...</li>
+</ul>
+</ul>
+<h2>Getting debug information from a running Instance</h2>
+<p>It is possible to obtain debugging information from a running instance, but this requires
+some setup. We assume that the instance runs in the background, so debug output to
+stdout is not desired. As such, all debug information needs to go into a log file.
+<p>To create this setup, you need to
 <ul>
+<li>point the RSYSLOG_DEBUGLOG environment variable to a file that is accessible
+during the while runtime (we strongly suggest a file in the local file system!)
+<li>set RSYSLOG_DEBUG at least to "DebugOnDeman NoStdOut"
+<li>make sure these environment variables are set in the correct (distro-specifc)
+startup script if you do not run rsyslogd interactively
 </ul>
+<p>These settings enable the capability to react to SIGUSR1. The signal will toggle
+debug status when received. So send it one to turn debug loggin on, and send it again
+to turn debug logging off again. The third time it will be turned on again ... and so on.
+<p>On a typical system, you can signal rsyslogd as follows:
+<pre>
+kill -USR1 `cat /var/run/rsyslogd.pid`
+</pre>
+Important: there are backticks around the "cat"-command. If you use the regular
+quote it won't work. The debug log will show whether debug logging has been turned
+on or off. There is no other indication of the status.
+<p>Note: running with DebugOnDemand by itself does in practice not have any performance
+toll. However, switching debug logging on has a severe performance toll. Also, debug
+logging synchronizes much of the code, removing a lot of concurrency and thus
+potential race conditions. As such, the very same running instance may behave
+very differently with debug logging turned on vs. off. The on-demand debug log
+functionality is considered to be very valuable to analyze hard-to-find bugs that
+only manifest after a long runtime. Turning debug logging on a failing instance
+may reveal the cause of the failure. However, depending on the failure, debug logging
+may not even be successfully be turned on. Also note that with this rsyslog version we cannot 
+obtain any debug information on events that happened <i>before</i> debug logging was
+turned on.
+<p>If an instance hangs, it is possible to obtain some useful information about the current
+threads and their calling stack by sending SIGUSR2. However, the usefulness of that
+information is very much depending on rsyslog compile-time settings, must importantly
+the --enable-rtinst configure flag. Note that activating this option causes additional overhead
+and slows down rsyslgod considerable. So if you do that, you need to check if it is
+capable to handle the workload. Also, threading behavior is modified by the
+runtime instrumentation.
+<p>Sending SIGUSR2 writes new process state information to the log file each time 
+it is sent. So it may be useful to do that from time to time. It probably is most 
+useful if the process seems to hang, in which case it may (may!) be able to output
+some diagnostic information on the current processing state. In that case, turning
+on the mutex debugging options (see above) is probably useful.
+<h2>Interpreting the Logs</h2>
+<p>Debug logs are primarily meant for rsyslog developers. But they may still provide valuable
+information to users. Just be warned that logs sometimes contains informaton the looks like
+an error, but actually is none. We put a lot of extra information into the logs, and there
+are some cases where it is OK for an error to happen, we just wanted to record it inside
+the log. The code handles many cases automatically. So, in short, the log may not make sense to
+you, but it (hopefully) makes sense to a developer. Note that we developers often need
+many lines of the log file, it is relatively rare that a problem can be diagnosed by
+looking at just a couple of (hundered) log records.
+<h2>Security Risks</h2>
+<p>The debug log will reveal potentially sensible information, including user accounts and
+passwords, to anyone able to read the log file. As such, it is recommended to properly
+guard access to the log file. Also, an instance running with debug log enabled runs much
+slower than one without. An attacker may use this to place carry out a denial-of-service
+attack or try to hide some information from the log file. As such, it is suggested to
+enable DebugOnDemand mode only for a reason. Note that when no debug mode is enabled,
+SIGUSR1 and SIGUSR2 are completely ignored.
+<p>When running in any of the debug modes (including on demand mode), an interactive 
+instance of rsyslogd can be aborted by pressing ctl-c.
+<p>
 <p>[<a href="manual.html">manual index</a>] [<a href="http://www.rsyslog.com/">rsyslog site</a>]</p>
 <p><font size="2">This documentation is part of the
-<a href="http://www.rsyslog.com/">rsyslog</a>
-project.<br>
-Copyright&nbsp;� 2008 by <a href="http://www.gerhards.net/rainer">Rainer
-Gerhards</a> and
+<a href="http://www.rsyslog.com/">rsyslog</a> project.<br>
+Copyright &copy; 2008, 2009 by <a href="http://www.gerhards.net/rainer">Rainer Gerhards</a> and
 <a href="http://www.adiscon.com/">Adiscon</a>.
 Released under the GNU GPL version 3 or higher.</font></p>
-</body></html>
-\ No newline at end of file
+</body></html>
diff --git a/runtime/debug.c b/runtime/debug.c
index 1b592ef3..9547eee6 100644
--- a/runtime/debug.c
+++ b/runtime/debug.c
@@ -51,6 +51,7 @@
 #include "rsyslog.h"
 #include "debug.h"
 #include "atomic.h"
+#include "cfsysline.h"
 #include "obj.h"
 
 
@@ -1263,6 +1264,7 @@ dbgGetRuntimeOptions(void)
 					"NoLogTimestamp\n"
 					"Nostdoout\n"
 					"filetrace=file (may be provided multiple times)\n"
+					"DebugOnDemand - enables debugging on USR1, but does not turn on output\n"
 					"\nSee debug.html in your doc set or http://www.rsyslog.com for details\n");
 				exit(1);
 			} else if(!strcasecmp((char*)optname, "debug")) {
@@ -1271,6 +1273,13 @@ dbgGetRuntimeOptions(void)
 				 */
 				Debug = 1;
 				debugging_on = 1;
+			} else if(!strcasecmp((char*)optname, "debugondemand")) {
+				/* Enables debugging, but turns off debug output */
+				Debug = 1;
+				debugging_on = 1;
+				dbgprintf("Note: debug on demand turned on via configuraton file, "
+					  "use USR1 signal to activate.\n");
+				debugging_on = 0;
 			} else if(!strcasecmp((char*)optname, "logfuncflow")) {
 				bLogFuncFlow = 1;
 			} else if(!strcasecmp((char*)optname, "logallocfree")) {
diff --git a/tools/syslogd.c b/tools/syslogd.c
index fb3294d5..7649d054 100644
--- a/tools/syslogd.c
+++ b/tools/syslogd.c
@@ -1469,13 +1469,27 @@ doFlushRptdMsgs(void)
 
 static void debug_switch()
 {
+	time_t tTime;
+	struct tm tp;
 	struct sigaction sigAct;
 
+	time(&tTime);
+	localtime_r(&tTime, &tp);
 	if(debugging_on == 0) {
 		debugging_on = 1;
-		DBGPRINTF("Switching debugging_on to true\n");
+		dbgprintf("\n");
+		dbgprintf("\n");
+		dbgprintf("********************************************************************************\n");
+		dbgprintf("Switching debugging_on to true at %2.2d:%2.2d:%2.2d\n",
+			  tp.tm_hour, tp.tm_min, tp.tm_sec);
+		dbgprintf("********************************************************************************\n");
 	} else {
-		DBGPRINTF("Switching debugging_on to false\n");
+		dbgprintf("********************************************************************************\n");
+		dbgprintf("Switching debugging_on to false at %2.2d:%2.2d:%2.2d\n",
+			  tp.tm_hour, tp.tm_min, tp.tm_sec);
+		dbgprintf("********************************************************************************\n");
+		dbgprintf("\n");
+		dbgprintf("\n");
 		debugging_on = 0;
 	}
 	
@@ -3082,8 +3096,6 @@ doGlblProcessInit(void)
 			fputs(" Already running.\n", stderr);
 			exit(1); /* "good" exit, done if syslogd is already running */
 		}
-	} else {
-		debugging_on = 1;
 	}
 
 	/* tuck my process id away */
author	Rainer Gerhards <rgerhards@adiscon.com>	2009-11-10 12:50:48 +0100
committer	Rainer Gerhards <rgerhards@adiscon.com>	2009-11-10 12:50:48 +0100
commit	2b5e15d549940c7ace9017eaf40d523e3741c9a2 (patch)
tree	bc22cdc468329ab9996c0b8b1bc68348e0160149
parent	224c3aef8b4d3d95ab2100c3056f2f92c130b220 (diff)
download	rsyslog-2b5e15d549940c7ace9017eaf40d523e3741c9a2.tar.gz rsyslog-2b5e15d549940c7ace9017eaf40d523e3741c9a2.tar.xz rsyslog-2b5e15d549940c7ace9017eaf40d523e3741c9a2.zip