Fix syslog mutual exclusion and interrupt level logic

git-svn-id: svn://svn.code.sf.net/p/nuttx/code/trunk@4999 42af7a65-404d-4744-a932-0658087f49c3

6 files changed, 132 insertions, 38 deletions

diff --git a/nuttx/Documentation/NuttxPortingGuide.html b/nuttx/Documentation/NuttxPortingGuide.html
index 21212a386..893522358 100644
--- a/nuttx/Documentation/NuttxPortingGuide.html
+++ b/nuttx/Documentation/NuttxPortingGuide.html
@@ -4101,6 +4101,7 @@ build
   <li>
     <code>CONFIG_SYSLOG_CHAR</code>:
       Enable the generic character device for the SYSLOG.
+      A disadvantage of using the generic character device for the SYSLOG is that it cannot handle debug output generated from interrupt level handlers.
       NOTE:  No more than one SYSLOG device should be configured.
   <p>
     Alternatively, a circular buffer in RAM can be used as the SYSLOGing device.
@@ -4118,11 +4119,11 @@ build
     circular buffer and can be viewed using the NSH 'dmesg' command.
   </li>
   <li>
-    <code>CONFIG_RAMLOG_SYSLOG</code>: Use the RAM logging device for the syslogging
-    interface.  If this feature is enabled (along with <code>CONFIG_SYSLOG</code>),
-    then all debug output (only) will be re-directed to the circular
-    buffer in RAM.  This RAM log can be view from NSH using the 'dmesg'
-    command.
+    <code>CONFIG_RAMLOG_SYSLOG</code>:
+    Use the RAM logging device for the syslogging interface.
+    If this feature is enabled (along with <code>CONFIG_SYSLOG</code>), then all debug output (only) will be re-directed to the circular buffer in RAM.
+    This RAM log can be view from NSH using the <code>dmesg</code> command.
+    NOTE: Unlike the limited, generic character driver SYSLOG device, the RAMLOG <i>can</i> be used to generate debug output from interrupt level handlers.
   </li>
   <li>
     <code>CONFIG_RAMLOG_NPOLLWAITERS</code>: The number of threads than can be waiting
diff --git a/nuttx/configs/README.txt b/nuttx/configs/README.txt
index 9b44a4e43..a8deb3ce6 100644
--- a/nuttx/configs/README.txt
+++ b/nuttx/configs/README.txt
@@ -381,6 +381,8 @@ defconfig -- This is a configuration file similar to the Linux
     is selected, then these options are also available.
 
     CONFIG_SYSLOG_CHAR - Enable the generic character device for the SYSLOG.
+      A disadvantage of using the generic character device for the SYSLOG is that
+      it cannot handle debug output generated from interrupt level handlers.
       NOTE:  No more than one SYSLOG device should be configured.
 
     CONFIG_RAMLOG - Enables the RAM logging feature. The RAM log is a circular
@@ -395,7 +397,9 @@ defconfig -- This is a configuration file similar to the Linux
       interface.  If this feature is enabled (along with CONFIG_SYSLOG),
       then all debug output (only) will be re-directed to the circular
       buffer in RAM.  This RAM log can be view from NSH using the 'dmesg'
-      command.
+      command.  NOTE:  Unlike the limited, generic character driver SYSLOG
+      device, the RAMLOG *can* be used to generate debug output from interrupt
+      level handlers.
     CONFIG_RAMLOG_NPOLLWAITERS - The number of threads than can be waiting
      for this driver on poll().  Default: 4
 
diff --git a/nuttx/drivers/syslog/README.txt b/nuttx/drivers/syslog/README.txt
index 611f43567..bfef73ae8 100644
--- a/nuttx/drivers/syslog/README.txt
+++ b/nuttx/drivers/syslog/README.txt
@@ -14,10 +14,16 @@ syslog_putc().
 One version of syslog_putc() is defined in fs/fs_syslog.c; that version is
 used when CONFIG_SYSLOG_CHAR is defined.  That version of syslog_putc()
 just integrates with the file system to re-direct debug output to a
-character device or to a file.
+character device or to a file. A disadvantage of using the generic character
+device for the SYSLOG is that it cannot handle debug output generated from
+interrupt level handles.
 
 If CONFIG_SYSLOG_CHAR is not defined, then other custom SYSLOG drivers
-can be used.  Those custom SYSLOG drivers reside in this directory.
+can be used.  These custom SYSLOG drivers can do things like handle
+unusual logging media and since they can avoid the general file system
+interfaces, can be designed to support debug output from interrupt handlers.
+
+Those custom SYSLOG drivers reside in this directory.
 
 ramlog.c
 --------
@@ -46,7 +52,9 @@ ramlog.c
       interface.  If this feature is enabled (along with CONFIG_SYSLOG),
       then all debug output (only) will be re-directed to the circular
       buffer in RAM.  This RAM log can be view from NSH using the 'dmesg'
-      command.
+      command.  NOTE:  Unlike the limited, generic character driver SYSLOG
+      device, the RAMLOG *can* be used to generate debug output from interrupt
+      level handlers.
     CONFIG_RAMLOG_NPOLLWAITERS - The number of threads than can be waiting
       for this driver on poll().  Default: 4
 
diff --git a/nuttx/fs/fs_syslog.c b/nuttx/fs/fs_syslog.c
index 71207292c..6586b90bc 100644
--- a/nuttx/fs/fs_syslog.c
+++ b/nuttx/fs/fs_syslog.c
@@ -49,6 +49,7 @@
 #include <assert.h>
 
 #include <nuttx/fs/fs.h>
+#include <nuttx/arch.h>
 #include <nuttx/syslog.h>
 
 #include "fs_internal.h"
@@ -66,6 +67,10 @@
 
 #define SYSLOG_OFLAGS (O_WRONLY | O_CREAT | O_APPEND)
 
+/* An invalid thread ID */
+
+#define NO_HOLDER     ((pid_t)-1)
+
 /****************************************************************************
  * Private Types
  ****************************************************************************/
@@ -75,7 +80,7 @@
 enum syslog_state_e
 {
   SYSLOG_UNINITIALIZED = 0, /* SYSLOG has not been initialized */
-  SYSLOG_BUSY,              /* SYSLOG is not available for this thread */
+  SYSLOG_INITIALIZING,      /* SYSLOG is being initialized */
   SYSLOG_REOPEN,            /* SYSLOG open failed... try again later */
   SYSLOG_FAILURE,           /* SYSLOG open failed... don't try again */
   SYSLOG_OPENED,            /* SYSLOG device is open and ready to use */
@@ -87,6 +92,7 @@ struct syslog_dev_s
 {
   uint8_t     sl_state;     /* See enum syslog_state_e */
   sem_t       sl_sem;       /* Enforces mutually exclusive access */
+  pid_t       sl_holder;    /* PID of the thread that holds the semaphore */
   struct file sl_file;      /* The syslog file structure */
 };
 
@@ -108,6 +114,69 @@ static const uint8_t       g_syscrlf[2]  = { '\r', '\n' };
  ****************************************************************************/
 
 /****************************************************************************
+ * Name: syslog_takesem
+ *
+ * Description:
+ *   Write to the syslog device
+ *
+ ****************************************************************************/
+
+static inline int syslog_takesem(void)
+{
+  pid_t me = getpid();
+  int ret;
+
+  /* Does this thread already hold the semaphore?  That could happen if
+   * we wer called recursively, i.e., if the logic kicked off by
+   * syslog_write() where to generate more debug output.  Return an error
+   * in that case.
+   */
+
+  if (g_sysdev.sl_holder == me)
+    {
+      /* Return an error (instead of deadlocking) */
+
+      return -EWOULDBLOCK;
+    }
+
+  /* Either the semaphore is available or is currently held by another
+   * thread.  Wait for it to become available.
+   */
+
+  ret = sem_wait(&g_sysdev.sl_sem);
+  if (ret < 0)
+    {
+      return -get_errno();
+    }
+
+  /* We hold the semaphore.  We can safely mark ourself as the holder
+   * of the semaphore.
+   */
+
+  g_sysdev.sl_holder = me;
+  return OK;
+}
+
+/****************************************************************************
+ * Name: syslog_givesem
+ *
+ * Description:
+ *   Write to the syslog device
+ *
+ ****************************************************************************/
+
+static inline void syslog_givesem(void)
+{
+  pid_t me = getpid();
+  DEBUGASSERT(g_sysdev.sl_holder == me);
+
+  /* Relinquish the semaphore */
+
+  g_sysdev.sl_holder = NO_HOLDER;
+  sem_post(&g_sysdev.sl_sem);
+}
+  
+/****************************************************************************
  * Name: syslog_write
  *
  * Description:
@@ -172,13 +241,13 @@ int syslog_initialize(void)
   int                  ret;
 
   /* At this point, the only expected states are SYSLOG_UNINITIALIZED or
-   * SYSLOG_REOPEN..  Not SYSLOG_BUSY, SYSLOG_FAILURE, SYSLOG_OPENED.
+   * SYSLOG_REOPEN..  Not SYSLOG_INITIALIZING, SYSLOG_FAILURE, SYSLOG_OPENED.
    */
 
   DEBUGASSERT(g_sysdev.sl_state == SYSLOG_UNINITIALIZED ||
               g_sysdev.sl_state == SYSLOG_REOPEN);
 
-  g_sysdev.sl_state = SYSLOG_BUSY;
+  g_sysdev.sl_state = SYSLOG_INITIALIZING;
 
   /* Try to open the device.
    *
@@ -272,7 +341,8 @@ int syslog_initialize(void)
   /* The SYSLOG device is open and ready for writing. */
 
   sem_init(&g_sysdev.sl_sem, 0, 1);
-  g_sysdev.sl_state = SYSLOG_OPENED;
+  g_sysdev.sl_holder = NO_HOLDER;
+  g_sysdev.sl_state  = SYSLOG_OPENED;
   return OK;
 
  errout_with_inode:
@@ -300,27 +370,33 @@ int syslog_putc(int ch)
 
   /* Ignore any output:
    *
-   *   (1) Before the SYSLOG device has been initialized.  This could happen
-   *       from debug output that occurs early in the boot sequence before
-   *       syslog_initialize() is called (SYSLOG_UNINITIALIZED_.
-   *   (2) While the device is being initialized.  The case could happen if
-   *       debug output is generated while syslog_initialize() executes
-   *       (SYSLOG_BUSY).
-   *   (2) While we are generating SYSLOG output.  The case could happen if
-   *       debug output is generated while syslog_putc() executes (also
-   *       SYSLOG_BUSY).
+   * (1) Before the SYSLOG device has been initialized.  This could happen
+   *     from debug output that occurs early in the boot sequence before
+   *     syslog_initialize() is called (SYSLOG_UNINITIALIZED).
+   * (2) While the device is being initialized.  The case could happen if
+   *     debug output is generated while syslog_initialize() executes
+   *     (SYSLOG_INITIALIZING).
+   * (3) While we are generating SYSLOG output.  The case could happen if
+   *     debug output is generated while syslog_putc() executes
+   *     (This case is actually handled inside of syslog_semtake()).
+   * (4) Any debug output generated from interrupt handlers.  A disadvantage
+   *     of using the generic character device for the SYSLOG is that it
+   *     cannot handle debug output generated from interrupt level handlers.
+   * (5) If an irrecoverable failure occurred during initialization.  In
+   *     this case, we won't ever bother to try again (ever).
+   *
+   * NOTE: That the third case is different.  It applies only to the thread
+   * that currently holds the sl_sem sempaphore.  Other threads should wait.
+   * that is why that case is handled in syslog_semtake().
    */
 
   if (g_sysdev.sl_state == SYSLOG_UNINITIALIZED ||
-      g_sysdev.sl_state == SYSLOG_BUSY)
+      g_sysdev.sl_state == SYSLOG_INITIALIZING ||
+      up_interrupt_context())
     {
       return -EAGAIN;
     }
 
-  /* If an irrecoverable failure occurred, then don't bother to try again
-   * (ever)
-   */
-
   if (g_sysdev.sl_state == SYSLOG_FAILURE)
     {
       return -ENXIO;
@@ -369,18 +445,20 @@ int syslog_putc(int ch)
    * value to write.
    */
 
-  ret = sem_wait(&g_sysdev.sl_sem);
+  ret = syslog_takesem();
   if (ret < 0)
     {
-      return -get_errno();
+      /* We probably already hold the semaphore and were probably
+       * re-entered by the logic kicked off by syslog_write().
+       * We might also have been interrupted by a signal.  Either
+       * way, we are outta here.
+       */
+
+      return ret;
     }
 
-  /* Pre-pend a newline with a carriage return.  Setting sl_state to
-   * SYSLOG_BUSY will suppress any recursive debug logic generated by
-   * the syslog_write call.
-   */
+  /* Pre-pend a newline with a carriage return. */
 
-  g_sysdev.sl_state == SYSLOG_BUSY;
   if (ch == '\n')
     {
       /* Write the CR-LF sequence */
@@ -405,8 +483,7 @@ int syslog_putc(int ch)
       nbytes = syslog_write(&ch, 1);
     }
 
-  g_sysdev.sl_state == SYSLOG_OPENED;
-  sem_post(&g_sysdev.sl_sem);
+  syslog_givesem();
 
   /* Check if the write was successful */
 
diff --git a/nuttx/include/nuttx/ramlog.h b/nuttx/include/nuttx/ramlog.h
index d5a37ba30..7831ea509 100644
--- a/nuttx/include/nuttx/ramlog.h
+++ b/nuttx/include/nuttx/ramlog.h
@@ -73,7 +73,9 @@
  *   interface.  If this feature is enabled (along with CONFIG_SYSLOG),
  *   then all debug output (only) will be re-directed to the circular
  *   buffer in RAM.  This RAM log can be view from NSH using the 'dmesg'
- *   command.
+ *   command.  NOTE:  Unlike the limited, generic character driver SYSLOG
+ *   device, the RAMLOG *can* be used to generate debug output from interrupt
+ *   level handlers.
  * CONFIG_RAMLOG_NPOLLWAITERS - The number of threads than can be waiting
  *   for this driver on poll().  Default: 4
  *
diff --git a/nuttx/include/nuttx/syslog.h b/nuttx/include/nuttx/syslog.h
index 89d0c7267..3c340d23a 100644
--- a/nuttx/include/nuttx/syslog.h
+++ b/nuttx/include/nuttx/syslog.h
@@ -59,7 +59,9 @@
  *      described in the include/nuttx/ramlog.h header file.
  *
  *   2. And a generic character device that may be used as the SYSLOG.  The
- *      generic device interfaces are described in this file.
+ *      generic device interfaces are described in this file.  A disadvantage
+ *      of using the generic character device for the SYSLOG is that it
+ *      cannot handle debug output generated from interrupt level handlers.
  *
  * CONFIG_SYSLOG_CHAR - Enable the generic character device for the SYSLOG.
  *   The full path to the SYSLOG device is provided by CONFIG_SYSLOG_DEVPATH.