Experimental Physics and
Industrial Control System

Dirk Zimoch has proposed merging ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0.

Commit message:
fix several problems in logClient

Requested reviews:
  EPICS Core Developers (epics-core)

For more details, see:
https://code.launchpad.net/~dirk.zimoch/epics-base/+git/epics-base/+merge/372043

Bugfix: don't send errlog to all logClients, only to iocLog
Improvements to minimize message loss when server disconnects:
* detect lost connection to server early
* do not discard buffer at disconnect
* flush buffer directly after reconnect
Other improvements:
* avoid delays on ioc startup and shutdown
* avoid repeated memmove

Relates to bug report #1841608

-- 
Your team EPICS Core Developers is requested to review the proposed merge of ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0.

diff --git a/modules/libcom/src/log/iocLog.c b/modules/libcom/src/log/iocLog.c
index e62da20..8cb1349 100644
--- a/modules/libcom/src/log/iocLog.c
+++ b/modules/libcom/src/log/iocLog.c
@@ -18,8 +18,10 @@
 
 #define epicsExportSharedSymbols
 #include "envDefs.h"
+#include "errlog.h"
 #include "logClient.h"
 #include "iocLog.h"
+#include "epicsExit.h"
 
 int iocLogDisable = 0;
 
@@ -75,6 +77,14 @@ void epicsShareAPI epicsShareAPI iocLogFlush (void)
 }
 
 /*
+ * logClientDestroy()
+ */
+static void iocLogClientDestroy (logClientId id)
+{
+    errlogRemoveListeners (logClientSendMessage, id);
+}
+
+/*
  *  iocLogClientInit()
  */
 static logClientId iocLogClientInit (void)
@@ -89,6 +99,10 @@ static logClientId iocLogClientInit (void)
         return NULL;
     }
     id = logClientCreate (addr, port);
+    if (id != NULL) {
+        errlogAddListener (logClientSendMessage, id);
+        epicsAtExit (iocLogClientDestroy, id);
+    }
     return id;
 }
 
diff --git a/modules/libcom/src/log/logClient.c b/modules/libcom/src/log/logClient.c
index 99ee671..0056a21 100644
--- a/modules/libcom/src/log/logClient.c
+++ b/modules/libcom/src/log/logClient.c
@@ -44,6 +44,7 @@ typedef struct {
     SOCKET              sock;
     epicsThreadId       restartThreadId;
     epicsEventId        stateChangeNotify;
+    epicsEventId        shutdownNotify;
     unsigned            connectCount;
     unsigned            nextMsgIndex;
     unsigned            connected;
@@ -53,7 +54,6 @@ typedef struct {
 } logClient;
 
 static const double      LOG_RESTART_DELAY = 5.0; /* sec */
-static const double      LOG_SERVER_CREATE_CONNECT_SYNC_TIMEOUT = 5.0; /* sec */
 static const double      LOG_SERVER_SHUTDOWN_TIMEOUT = 30.0; /* sec */
 
 /*
@@ -84,8 +84,6 @@ static void logClientClose ( logClient *pClient )
         pClient->sock = INVALID_SOCKET;
     }
 
-    pClient->nextMsgIndex = 0u;
-    memset ( pClient->msgBuf, '\0', sizeof ( pClient->msgBuf ) );
     pClient->connected = 0u;
 
     /*
@@ -113,6 +111,7 @@ static void logClientDestroy (logClientId id)
     epicsMutexMustLock ( pClient->mutex );
     pClient->shutdown = 1u;
     epicsMutexUnlock ( pClient->mutex );
+    epicsEventSignal ( pClient->shutdownNotify );
 
     /* unblock log client thread blocking in send() or connect() */
     interruptInfo =
@@ -154,13 +153,11 @@ static void logClientDestroy (logClientId id)
         return;
     }
 
-    errlogRemoveListeners ( logClientSendMessage, (void *) pClient );
-
     logClientClose ( pClient );
 
     epicsMutexDestroy ( pClient->mutex );
-   
     epicsEventDestroy ( pClient->stateChangeNotify );
+    epicsEventDestroy ( pClient->shutdownNotify );
 
     free ( pClient );
 }
@@ -176,57 +173,23 @@ static void sendMessageChunk(logClient * pClient, const char * message) {
         unsigned msgBufBytesLeft = 
             sizeof ( pClient->msgBuf ) - pClient->nextMsgIndex;
 
-        if ( strSize > msgBufBytesLeft ) {
-            int status;
-
-            if ( ! pClient->connected ) {
-                break;
-            }
-
-            if ( msgBufBytesLeft > 0u ) {
-                memcpy ( & pClient->msgBuf[pClient->nextMsgIndex],
-                    message, msgBufBytesLeft );
-                pClient->nextMsgIndex += msgBufBytesLeft;
-                strSize -= msgBufBytesLeft;
-                message += msgBufBytesLeft;
-            }
-
-            status = send ( pClient->sock, pClient->msgBuf, 
-                pClient->nextMsgIndex, 0 );
-            if ( status > 0 ) {
-                unsigned nSent = (unsigned) status;
-                if ( nSent < pClient->nextMsgIndex ) {
-                    unsigned newNextMsgIndex = pClient->nextMsgIndex - nSent;
-                    memmove ( pClient->msgBuf, & pClient->msgBuf[nSent], 
-                        newNextMsgIndex );
-                    pClient->nextMsgIndex = newNextMsgIndex;
-                }
-                else {
-                    pClient->nextMsgIndex = 0u;
-                }
-            }
-            else {
-                if ( ! pClient->shutdown ) {
-                    char sockErrBuf[64];
-                    if ( status ) {
-                        epicsSocketConvertErrnoToString ( sockErrBuf, sizeof ( sockErrBuf ) );
-                    }
-                    else {
-                        strcpy ( sockErrBuf, "server initiated disconnect" );
-                    }
-                    fprintf ( stderr, "log client: lost contact with log server at \"%s\" because \"%s\"\n", 
-                        pClient->name, sockErrBuf );
-                }
-                logClientClose ( pClient );
-                break;
-            }
+        if ( msgBufBytesLeft < strSize && pClient->nextMsgIndex != 0u && pClient->connected)
+        {
+            /* buffer is full, thus flush it */
+            logClientFlush ( pClient );
+            msgBufBytesLeft = sizeof ( pClient->msgBuf ) - pClient->nextMsgIndex;
         }
-        else {
-            memcpy ( & pClient->msgBuf[pClient->nextMsgIndex],
-                message, strSize );
-            pClient->nextMsgIndex += strSize;
+        if ( msgBufBytesLeft == 0u ) {
+            fprintf ( stderr, "log client: messages to \"%s\" are lost\n",
+                pClient->name );
             break;
         }
+        if ( msgBufBytesLeft > strSize) msgBufBytesLeft = strSize;
+        memcpy ( & pClient->msgBuf[pClient->nextMsgIndex],
+            message, msgBufBytesLeft );
+        pClient->nextMsgIndex += msgBufBytesLeft;
+        strSize -= msgBufBytesLeft;
+        message += msgBufBytesLeft;
     }
 }
 
@@ -255,28 +218,38 @@ void epicsShareAPI logClientSend ( logClientId id, const char * message )
 
 void epicsShareAPI logClientFlush ( logClientId id )
 {
+    unsigned nSent = 0u;
+
     logClient * pClient = ( logClient * ) id;
 
-    if ( ! pClient ) {
+    if ( ! pClient || ! pClient->connected ) {
         return;
     }
 
     epicsMutexMustLock ( pClient->mutex );
 
-    while ( pClient->nextMsgIndex && pClient->connected ) {
-        int status = send ( pClient->sock, pClient->msgBuf, 
-            pClient->nextMsgIndex, 0 );
+    while (1) {
+        struct timeval timeout = { 0, 0 };
+        fd_set set;
+        char buffer[256];
+
+        FD_ZERO ( &set );
+        FD_SET ( pClient->sock, &set );
+        if ( select ( pClient->sock + 1, &set, NULL, NULL, &timeout ) == 0)
+            break;
+        if ( recv ( pClient->sock, buffer, sizeof ( buffer ), 0 ) == 0 ) {
+            fprintf ( stderr, "log client: connection closed by server \"%s\"\n",
+                pClient->name );
+            logClientClose ( pClient );
+            break;
+        }
+    }
+
+    while ( nSent < pClient->nextMsgIndex && pClient->connected ) {
+        int status = send ( pClient->sock, pClient->msgBuf + nSent,
+            pClient->nextMsgIndex - nSent, 0 );
         if ( status > 0 ) {
-            unsigned nSent = (unsigned) status;
-            if ( nSent < pClient->nextMsgIndex ) {
-                unsigned newNextMsgIndex = pClient->nextMsgIndex - nSent;
-                memmove ( pClient->msgBuf, & pClient->msgBuf[nSent], 
-                    newNextMsgIndex );
-                pClient->nextMsgIndex = newNextMsgIndex;
-            }
-            else {
-                pClient->nextMsgIndex = 0u;
-            }
+            nSent += (unsigned) status;
         }
         else {
             if ( ! pClient->shutdown ) {
@@ -294,6 +267,11 @@ void epicsShareAPI logClientFlush ( logClientId id )
             break;
         }
     }
+    pClient->nextMsgIndex -= nSent;
+    if ( nSent > 0 && pClient->nextMsgIndex > 0 ) {
+        memmove ( pClient->msgBuf, & pClient->msgBuf[nSent],
+            pClient->nextMsgIndex );
+    }
     epicsMutexUnlock ( pClient->mutex );
 }
 
@@ -399,20 +377,6 @@ static void logClientConnect (logClient *pClient)
     }
 
     /*
-     * we don't need full-duplex (clients only write), so we shutdown
-     * the read end of our socket
-     */
-    status = shutdown (pClient->sock, SHUT_RD);
-    if (status < 0) {
-        char sockErrBuf[64];
-        epicsSocketConvertErrnoToString ( 
-            sockErrBuf, sizeof ( sockErrBuf ) );
-        fprintf (stderr, "%s:%d shutdown(%d,SHUT_RD) error was \"%s\"\n", 
-            __FILE__, __LINE__, pClient->sock, sockErrBuf);
-        /* not fatal (although it shouldn't happen) */
-    }
-
-    /*
      * set how long we will wait for the TCP state machine
      * to clean up when we issue a close(). This
      * guarantees that messages are serialized when we
@@ -457,14 +421,10 @@ static void logClientRestart ( logClientId id )
 
         epicsMutexUnlock ( pClient->mutex );
 
-        if ( isConn ) {
-            logClientFlush ( pClient );
-        }
-        else {
-            logClientConnect ( pClient );
-        }
-        
-        epicsThreadSleep ( LOG_RESTART_DELAY );
+        if ( ! isConn ) logClientConnect ( pClient );
+        logClientFlush ( pClient );
+
+        epicsEventWaitWithTimeout ( pClient->shutdownNotify, LOG_RESTART_DELAY);
 
         epicsMutexMustLock ( pClient->mutex );
     }
@@ -480,9 +440,7 @@ static void logClientRestart ( logClientId id )
 logClientId epicsShareAPI logClientCreate (
     struct in_addr server_addr, unsigned short server_port)
 {
-    epicsTimeStamp begin, current;
     logClient *pClient;
-    double diff;
 
     pClient = calloc (1, sizeof (*pClient));
     if (pClient==NULL) {
@@ -507,14 +465,22 @@ logClientId epicsShareAPI logClientCreate (
     pClient->shutdownConfirm = 0;
 
     epicsAtExit (logClientDestroy, (void*) pClient);
-    
+
     pClient->stateChangeNotify = epicsEventCreate (epicsEventEmpty);
     if ( ! pClient->stateChangeNotify ) {
         epicsMutexDestroy ( pClient->mutex );
         free ( pClient );
         return NULL;
     }
-   
+
+    pClient->shutdownNotify = epicsEventCreate (epicsEventEmpty);
+    if ( ! pClient->shutdownNotify ) {
+        epicsMutexDestroy ( pClient->mutex );
+        epicsEventDestroy ( pClient->stateChangeNotify );
+        free ( pClient );
+        return NULL;
+    }
+
     pClient->restartThreadId = epicsThreadCreate (
         "logRestart", epicsThreadPriorityLow, 
         epicsThreadGetStackSize(epicsThreadStackSmall),
@@ -522,35 +488,12 @@ logClientId epicsShareAPI logClientCreate (
     if ( pClient->restartThreadId == NULL ) {
         epicsMutexDestroy ( pClient->mutex );
         epicsEventDestroy ( pClient->stateChangeNotify );
+        epicsEventDestroy ( pClient->shutdownNotify );
         free (pClient);
         fprintf(stderr, "log client: unable to start log client connection watch dog thread\n");
         return NULL;
     }
 
-    /*
-     * attempt to synchronize with circuit connect
-     */
-    epicsTimeGetCurrent ( & begin );
-    epicsMutexMustLock ( pClient->mutex );
-    do {
-        epicsMutexUnlock ( pClient->mutex );
-        epicsEventWaitWithTimeout ( 
-            pClient->stateChangeNotify, 
-            LOG_SERVER_CREATE_CONNECT_SYNC_TIMEOUT / 10.0 ); 
-        epicsTimeGetCurrent ( & current );
-        diff = epicsTimeDiffInSeconds ( & current, & begin );
-        epicsMutexMustLock ( pClient->mutex );
-    }
-    while ( ! pClient->connected && diff < LOG_SERVER_CREATE_CONNECT_SYNC_TIMEOUT );
-    epicsMutexUnlock ( pClient->mutex );
-
-    if ( ! pClient->connected ) {
-        fprintf (stderr, "log client create: timed out synchronizing with circuit connect to \"%s\" after %.1f seconds\n",
-            pClient->name, LOG_SERVER_CREATE_CONNECT_SYNC_TIMEOUT );
-    }
-        
-    errlogAddListener ( logClientSendMessage, (void *) pClient );
-
     return (void *) pClient;
 }
 

Replies:

[Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 Dirk Zimoch via Core-talk

[Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 Dirk Zimoch via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 mdavidsaver via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 Dirk Zimoch via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 mdavidsaver via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 Dirk Zimoch via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 mdavidsaver via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 Dirk Zimoch via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 Andrew Johnson via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 Dirk Zimoch via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 mdavidsaver via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 Dirk Zimoch via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 Andrew Johnson via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 Dirk Zimoch via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 Dirk Zimoch via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 Dirk Zimoch via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 mdavidsaver via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 Dirk Zimoch via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 Dirk Zimoch via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 mdavidsaver via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 Martin Konrad via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 Ralph Lange via Core-talk

[Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 Dirk Zimoch via Core-talk

[Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 Dirk Zimoch via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 Dirk Zimoch via Core-talk

Re: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 mdavidsaver via Core-talk

[Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 mdavidsaver via Core-talk

Navigate by Date:

Prev: [Bug 1841608] Re: logClient falsely sends error logs on all connections Dirk Zimoch via Core-talk

Next: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 Dirk Zimoch via Core-talk

Index: 2002  2003  2004  2005  2006  2007  2008  2009  2010  2011  2012  2013  2014  2015  2016  2017  2018  <2019>  2020  2021  2022  2023  2024 

Navigate by Thread:

Prev: Build failed: EPICS Base base-7.0-422 AppVeyor via Core-talk

Next: [Merge] ~dirk.zimoch/epics-base:iocLogClientFixes into epics-base:7.0 Dirk Zimoch via Core-talk

Index: 2002  2003  2004  2005  2006  2007  2008  2009  2010  2011  2012  2013  2014  2015  2016  2017  2018  <2019>  2020  2021  2022  2023  2024