Merge ~dirk.zimoch/epics-base:iocLogClientFixesTry2 into ~epics-core/epics-base/+git/epics-base:7.0

[Dirk Zimoch]

fix several problems in logClient that lead to lost messages when the server (or firewall in between) disconnects

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 https://bugs.launchpad.net/epics-base/+bug/1841608 and Tech-Talk thread https://epics.anl.gov/tech-talk/2019/msg01329.php.

[mdavidsaver (mdavidsaver)]

What necessitates removing shutdown() and adding select()/recv()? To my knowledge send() should return with an error if the socket is, or becomes, disconnected.

review: Needs Information

[Dirk Zimoch (dirk.zimoch)]

Unfortunately send() does not return an error immediately. It simply puts the message into the TCP send queue, even when the peer has already shut down the socket. Only one or more messages later send() returns an error. But by then the messages are lost. The logClient has already "successfully" sent them ti the TCP stack but TCP failed to deliver them and there is no way to recover the messages now.

From the send man page: "No indication of failure to deliver is implicit in a send()."
It only tells you that queuing the message was successful.

When the peer closes the socket, select() will show the socket readable and read() will return 0, but only after everything the peer may have actually send has been read (and discarded).
That is the only reliable way to detect a closed connection.
However this method only works if the receiving side had not been shut down.

I had to google a lot until I found this out. It seems many people get this wrong assuming send() should fail immediately. It doesn't.

I can't find the page that helped me in the end any more, but this one comes close:
https://www.softlab.ntua.gr/facilities/documentation/unix/unix-socket-faq/unix-socket-faq-2.html

[mdavidsaver (mdavidsaver)]

When say "closed connection" do you mean normal closure (FIN/ACK), abnormal closure (RST), and/or (ideally) timeout?

Lack of an application level timeout is a known issue with the logging protocol. Are you trying to address this too?

[Dirk Zimoch (dirk.zimoch)]

I don't know the TCP details. I tested with a local server (ncat) which I terminated and also with our two production servers (syslog-ng adnd logstash) where the firewall closes idle connections after one hour. In both cases I can now detect when the connection breaks. Before I always lost messages.

Which timeout scenario do you have in mind? send() hanging? How could I test that?

[mdavidsaver (mdavidsaver)]

I notice that the page you link states:

> DISCLAIMER: This is my interpretation of the RFCs (I have read all the TCP-related ones I could find), but I have not attempted to examine implementation source code or trace actual connections in order to verify it. I am satisfied that the logic is correct, though.

which makes me smile.

The situation you describe, with a "firewall" in between is actually fairly complicated. And opaque in that the firewall might be acting in different ways depending on how stateful and helpful it is (eg. whether one or both sides get RST).

What I understand about BSD sockets and TCP is that:

1. If the peer maintains the connection, but doesn't call recv() (at all, or not fast enough) then send() will eventually fill the Tx socket buffer FIFO and block until it becomes not full (by peer ACK on recv() ).

2. calling send() on a socket which has been closed (peer calls close()) while the TX FIFO is empty results in an immediate EPIPE.

3. if a send() is in progress because the Tx FIFO is full (or probably when not empty), a peer close results in ECONNRESET.

4. if a the peer has shutdown(SHUT_RD), then send() will succeed until the Tx FIFO is full, then it will block as with #2. When the peer does close(), the send will return with EPIPE. (or probably ECONNRESET if some data was sent, but not ACK'd before the FIN).

5. if the peer simply stops responding, then send() will succeed until the Tx FIFO is full, then block waiting for an ACK which never comes.

So normal, or abnormal, termination of the TCP connection will break a send() immediately after RST or the FIN+ACK handshake completes. peer shutdown(SHUT_RD) or interruption of the network path will not break or error send().

I've just verified 1,2,3,4 on Linux with short python scripts. (I was surprised that #4 doesn't error) #5 I know from past experience.

So I don't think that calling recv() serves the purpose you intend. I think that SO_SNDTIMEO would be a better fit.

That said, the recv() might serve as one piece of a mechanism for a log server to detect condition #5 faster than SO_KEEPALIVE would (imo. SO_KEEPALIVE should also be set). Some extra protocol would be needed to allow a log server to detect this protocol feature.

[Dirk Zimoch (dirk.zimoch)]

4. Was the problem. send does not fail until some time later. But than messages are already lost.
So my fix is not to rely on send failing but on recv returning EOF.
SO_KEEPALIVE has a default timeout of 2 hours and you cannot change it per socket but only system wide. It is totally useless for solving the problems with lost messages. It is there to allow to clean up stale connections and not to run out of file descriptors in server programs that are constantly running. But that's about all. So it may help the log server but not the client.

The problem I solve here is that send succeeds until the FIFO is full, just as you pointed out in 4. and 5.

I cannot confirm 2 though. My tests with ncat as a server have shown that send does not detect immediately when the server has exited (and thus the kernel has closed the socket).

But leaving discussions about how TCP is supposed to work aside, my main argument for this change is: Now it works, before it didn't.

[Andrew Johnson (anj)]

@Dirk: Does your new version still work with the original iocLogServer?

IIRC at connection time that server explicitly closes the socket in the log-server -> client IOC direction because the server never sends data back to the client. I'm not sure whether that might cause the client to get an EOF from a recv() call sooner than with the other log-servers that don't do that close.

[Dirk Zimoch (dirk.zimoch)]

Indeed this looks like a close to the client and it closes the connection, but re-opens it on the next message. No messages are lost. The disconnect is not nice though. I'll have a look how to fix that.

[mdavidsaver (mdavidsaver)]

wrt. iocLogServer, I think it would be reasonable to accept removal of the shutdown(SHUT_WR) in iocLogServer.c. So long as older IOCs can still log against newer iocLogServer (which I think would be true).

[Dirk Zimoch (dirk.zimoch)]

It seems that the broken connection is quite reliably detected at the second send() after the connection had been closed. A dummy send(socket, NULL, 0, 0) seems sufficient to detect the broken connection to iocLogServer as well as to ncat and do Michael's server.py example.

[Andrew Johnson (anj)]

@Dirk: Which architectures have you tested that on?

[Dirk Zimoch (dirk.zimoch)]

Linux so far. I am about to test on vxWorks and Windows right now.

[Dirk Zimoch (dirk.zimoch)]

Hmm... Not all Linux versions behave the same. On some send(socket, NULL, 0, 0) is a NOOP and does not detect a broken connection.

[Dirk Zimoch (dirk.zimoch)]

The send() trick with 0 bytes does not work on all systems. It seems to depend on the Linux kernel version as well.

I am testing now a different solution. On Linux the call ioctl(sock, TIOCOUTQ, &unsent) gives the number of unsent bytes in the TCP output queue. This allows to keep the unsent bytes in the buffer in case it turns out later that the connection is broken.

On macOS there seems to be a similar functionality with getsockopt(sock, SOL_SOCKET, SO_NWRITE, &unsent), but I cannot test because I have no mac.

Other Unix flavors may or may not have such a feature.

For vxWorks I could not find a way to get the number of unsent bytes, neither for version 5.5 nor for 6.7.

I don't know about RTEMS.

On Windows 10 the number of unsent bytes should be available with WSAIoctl(sock, SIO_TCP_INFO, ..._). I spent most of last week to find out why it is not working before finding out that the Win 10 version I got was too old. I am upgrading now. Older Windows versions seem to have no way to find out the number of unsent bytes.

So I can mitigate the problem of message loss for some clients but not for all. Depending on the OS.

[mdavidsaver (mdavidsaver)]

> The send() trick with 0 bytes does not work on all systems.

Unless poll() is used, there is a race condition involved. A second send() will only fail if a RST has been received. This may or may not be platform dependent.

Have you discarded the idea of removing the 'shutdown(SHUT_WR)' from iocLogServer?

[Dirk Zimoch (dirk.zimoch)]

I first want to stay as compatible as possible to existing iocLogServer implementations.

[Dirk Zimoch (dirk.zimoch)]

I made a new branch some commits below the head of this one. How can I change the merge request to the new branch?

[mdavidsaver (mdavidsaver)]

I usually do a force push to replace the existing branch content. I don't think branches can be changed, so the alternative is a new MR.

[Martin Konrad (info-martin-konrad)]

Beware that force pushing messes up the diff on Launchpad's MR. Dirk, have you considered doing this in smaller steps (separate MRs for each issue you are addressing)? This way some of your modifications might get merged faster.

[Ralph Lange (ralph-lange)]

iirc, when you properly supersede the MP through the web interface, you have an option to pull/link the existing conversation to the new proposal.

[Dirk Zimoch (dirk.zimoch)]

The "resubmit proposal" link seems to do the job. It allows to switch branches. No force push needed. Diffs look fine and the conversation gets transferred.
Martin, the smaller steps are the individual commits. Each should be one (and in most cases small and understandable) change. Each commit I did results in working code. So if there is a problem with one particular step, it can be reverted.

I am not yet quite satisfied with the behavior, so some more changes may come. But please have a look already.

My test:
Start iocLogServer
Start softIoc and do ioclogInit
errlog msg1
Stop iocLogServer and restart it
errlog msg2
wait at least 10 seconds
errlog msg3

All 3 error messages should be logged.
On Linux (all version?) connection loss is detected latest 5 seconds after msg2.
On recent Win 10 connection loss is detected at only at msg3 because send(sock,NULL,0) has no effect,
 but no message is lost.
On vxWorks 5.5 and older Windows versions (< Win 10 version 1703) msg2 is lost because they have no o way to detect when a message is actually sent on the network.
Can someone test with Mac and RTEMS?

[Dirk Zimoch (dirk.zimoch)]

So, now I have both variants for discussion.
This one, which requires a change in iocLogServer as well (not to shutdown its write channel).
Or mp+372925 which does not quite work for vxWorks and older Windows and uses an unspecified feature of send() in Linux.

[mdavidsaver (mdavidsaver)]

> Stop iocLogServer and restart it

A related test would be to suspend (SIGSTOP) iocLogServer. This way the socket remains allocated, which is a better simulation of a non-responsive peer.

You might also want to try sending (large) log messages until the various queues fill up. Messages will be lost at some point.

[Dirk Zimoch (dirk.zimoch)]

I did that briefly. The client (ioc) happily sends to the server and on the server the TCP input queue fills up. If the server then dies the messages are lost.

I have not tried it until the queues filled up. The the logClient may block while holding the mutex which may make errlog (or whatever client) block. I will test that.

I suggest to remove the code that attempts to send from sendMessageChunk() and accept (and report) that messages are lost.

Can you please also review the usage of the mutex in the original code. I have the impression it does not really make sense.

[Andrew Johnson (anj)]

Can the necessary testing be done in modules/libcom/test/epicsErrlogTest.c or something similar? That file already has tests that implement a local log-server, needed to check iocLogPrefix().

Dirk, did you check this against a VxWorks 6.x version using the newer IP stack? We aren't supporting VxWorks 5.5 in EPICS 7 any more, but we do want it to work with the newer OS versions.

Some comments against the diff as well, but note that I haven't reviewed the functionality, just the build and APIs.

[Dirk Zimoch (dirk.zimoch)]

epicsErrlogTest.c: I have not yet looked into this but I guess it should be possible.

VxWorks 6: I don't have vxWorks 6 running on my IOCs. Was always low on my work list.

[Dirk Zimoch (dirk.zimoch)]

'#if defined (TIOCOUTQ)' fails when compiling for vxWorks 6. The macro does not exist in any vxWorks 6 header file. Same for SO_NWRITE. What exists is FIONWRITE, but that does not work on sockes, only on serial lines (at least for vxWorks 5).

[Dirk Zimoch (dirk.zimoch)]

Hm, the in-diff comments become kind of hidden with a new push.
About epicsSocketCountUnsentBytes() [or whatever we call it] returning size_t instead of int: In vxWorks and Windows all socket operations use int for size and Windows does not have ssize_t.

[Andrew Johnson (anj)]

I see what you mean about viewing in-diff comments. Clicking one of the "Show diff comments" links in an existing comment helped me earlier, but older comments seem to have disappeared (at least while I have some new unsaved diff comments pending).

I withdraw my size_t suggestion, but see my new in-diff comments regarding the name.

[Dirk Zimoch (dirk.zimoch)]

> older comments seem to have disappeared (at least while I have some new unsaved diff
> comments pending).

That may be the result a result of force-push when an in-diff comment refers to a line in a commit that has disappeared.

[mdavidsaver (mdavidsaver)]

Dirk, I hope you won't take this as a disincentive, but I think a better approach would be either to switch to an actually reliable logging protocol, log over TLS with the heartbeat extension, switch to simply UDP logging, and/or teach caPutLog to use the system logging (aka call 'syslog()' or open '/dev/log').

I happened upon https://rainer.gerhards.net/2008/04/on-unreliability-of-plain-tcp-syslog.html which does a good job of summarizing some of the thoughts I've been having about iocLog "protocol" and the seeming impossibility of making it truly reliable while maintaining compatibility.

I also wonder if it would be better to move iocLogClient out of Base and into the caPutLog module as an internal API? caPutLog seems to be the only (public) user of this API, and I think that removing the separation would enable a more effective restructuring of the code.

[mdavidsaver (mdavidsaver)]

Specifically, I don't like the idea of epicsSocketCountUnsentBytes() becoming public API. This is a highly specific use case, which can't be fully supported on our range of target OSs. I would like to see it removed from the public/installed headers unless at least one external user can be identified.

review: Needs Fixing

[mdavidsaver (mdavidsaver)]

I think the 'send(NULL)' pattern is a race condition as it depends on a TCP reset message having arrived prior to the second send(NULL) call. With real network latency I don't think it will work as intended to quickly and reliably detect when the preceding send() elicits a RST.

I'm not going to insist on a change here because I don't think it will break anything. The RST just won't be handled (via. EPIPE) unless the next time the log queue is flushed, and send() is called again.

[mdavidsaver (mdavidsaver)]

cf. https://code.launchpad.net/~epics-core/epics-base/+git/Com/+merge/373098

which is not mutually exclusive to this work. I wanted to try the idea.

[Dirk Zimoch (dirk.zimoch)]

It is totally fine for me to keep os-specific unsent cound inside logClient as a bunch of #if branches.

'send(NULL)' is not race condition, because I do not rely on getting the RST right after sending. It is fine to get it at some point. It simply polls for RST every 5 seconds.

Maybe it is better to use the other approach: https://code.launchpad.net/~dirk.zimoch/epics-base/+git/epics-base/+merge/372043. This one is very os-dependent and uses unspecified behavior.

[mdavidsaver (mdavidsaver)]

Results of discussion at core dev. meeting

Add '#ifdef EPICS_PRIVATE_API' around declaration of epicsSocketCountUnsentBytes() in osiSock.h.

Also, can you confirm that you've tested this (final) version on a target where epicsSocketCountUnsentBytes()==-1 ?

[Dirk Zimoch (dirk.zimoch)]

I have tested it against vxWorks 5 where epicsSocketCountUnsentBytes()==-1. The effect is that the log Client cannot keep track of the unsent bytes and messages may be lost as before.

[mdavidsaver (mdavidsaver)]

I did a test merge. Some CI failures resulted with cross-mingw and some older MSVC. Looks like some of the defines and structs related to TCP_INFO aren't available.

https://ci.appveyor.com/project/mdavidsaver/epics-base/builds/28358563

https://travis-ci.org/mdavidsaver/epics-base/builds/602443942

review: Needs Fixing

[mdavidsaver (mdavidsaver)]

I've tried the simple fix of checking _MSC_VER.

https://github.com/mdavidsaver/epics-base/commit/d5bc04a76bc88885a663ae30fc91c41183b51baf

https://ci.appveyor.com/project/mdavidsaver/epics-base/builds/28368174
https://travis-ci.org/mdavidsaver/epics-base/builds/602608951

[Andrew Johnson (anj)]

This could use an entry describing the changes in the Release Notes (which are now formatted in Markdown on both branches; I merged 3.15 up over the weekend and just pushed).

[mdavidsaver (mdavidsaver)]

The other variant was merged, so this one is no longer relevant.

review: Disapprove

diff --git a/modules/database/src/ioc/misc/dbCore.dbd b/modules/database/src/ioc/misc/dbCore.dbd
index 51f9c96..adde24e 100644
--- a/modules/database/src/ioc/misc/dbCore.dbd
+++ b/modules/database/src/ioc/misc/dbCore.dbd
@@ -33,3 +33,6 @@ variable(callbackParallelThreadsDefault,int)
 
 # Real-time operation
 variable(dbThreadRealtimeLock,int)
+
+# show logClient network activity
+variable(logClientDebug,int)
diff --git a/modules/libcom/src/log/iocLog.c b/modules/libcom/src/log/iocLog.c
index e62da20..ba78041 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,24 @@ void epicsShareAPI epicsShareAPI iocLogFlush (void)
 }
 
 /*
+ * logClientSendMessage ()
+ */
+static void logClientSendMessage ( logClientId id, const char * message )
+{
+    if ( !iocLogDisable ) {
+        logClientSend (id, message);
+    }
+}
+
+/*
+ * iocLogClientDestroy()
+ */
+static void iocLogClientDestroy (logClientId id)
+{
+    errlogRemoveListeners (logClientSendMessage, id);
+}
+
+/*
  *  iocLogClientInit()
  */
 static logClientId iocLogClientInit (void)
@@ -89,6 +109,10 @@ static logClientId iocLogClientInit (void)
         return NULL;
     }
     id = logClientCreate (addr, port);
+    if (id != NULL) {
+        errlogAddListener (logClientSendMessage, id);
+        epicsAtExit (iocLogClientDestroy, id);
+    }
     return id;
 }
 
@@ -135,3 +159,4 @@ logClientId epicsShareAPI logClientInit (void)
 {
     return iocLogClientInit ();
 }
+
diff --git a/modules/libcom/src/log/logClient.c b/modules/libcom/src/log/logClient.c
index 99ee671..9a09ef7 100644
--- a/modules/libcom/src/log/logClient.c
+++ b/modules/libcom/src/log/logClient.c
@@ -21,11 +21,11 @@
 #include <string.h>
 #include <stdio.h>
 
+#define EPICS_PRIVATE_API
 #define epicsExportSharedSymbols
 #include "dbDefs.h"
 #include "epicsEvent.h"
 #include "iocLog.h"
-#include "errlog.h"
 #include "epicsMutex.h"
 #include "epicsThread.h"
 #include "epicsTime.h"
@@ -33,9 +33,13 @@
 #include "epicsAssert.h"
 #include "epicsExit.h"
 #include "epicsSignal.h"
+#include "epicsExport.h"
 
 #include "logClient.h"
 
+int logClientDebug = 0;
+epicsExportAddress (int, logClientDebug);
+
 typedef struct {
     char                msgBuf[0x4000];
     struct sockaddr_in  addr;
@@ -44,8 +48,10 @@ typedef struct {
     SOCKET              sock;
     epicsThreadId       restartThreadId;
     epicsEventId        stateChangeNotify;
+    epicsEventId        shutdownNotify;
     unsigned            connectCount;
     unsigned            nextMsgIndex;
+    unsigned            backlog;
     unsigned            connected;
     unsigned            shutdown;
     unsigned            shutdownConfirm;
@@ -53,7 +59,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 */
 
 /*
@@ -66,10 +71,10 @@ static char* logClientPrefix = NULL;
  */
 static void logClientClose ( logClient *pClient )
 {
-#   ifdef DEBUG
+    if (logClientDebug) {
         fprintf (stderr, "log client: lingering for connection close...");
         fflush (stderr);
-#   endif
+    }
 
     /*
      * mutex on
@@ -84,8 +89,6 @@ static void logClientClose ( logClient *pClient )
         pClient->sock = INVALID_SOCKET;
     }
 
-    pClient->nextMsgIndex = 0u;
-    memset ( pClient->msgBuf, '\0', sizeof ( pClient->msgBuf ) );
     pClient->connected = 0u;
 
     /*
@@ -93,9 +96,8 @@ static void logClientClose ( logClient *pClient )
      */
     epicsMutexUnlock (pClient->mutex);
 
-#   ifdef DEBUG
+    if (logClientDebug)
         fprintf (stderr, "done\n");
-#   endif
 }
 
 /*
@@ -113,6 +115,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 +157,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,61 +177,26 @@ 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;
     }
 }
 
-
 /* 
  * logClientSend ()
  */
@@ -255,43 +221,54 @@ void epicsShareAPI logClientSend ( logClientId id, const char * message )
 
 void epicsShareAPI logClientFlush ( logClientId id )
 {
+    unsigned nSent;
+    int status = 0;
+
     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 );
-        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 = pClient->backlog;
+    while ( nSent < pClient->nextMsgIndex && pClient->connected ) {
+        status = send ( pClient->sock, pClient->msgBuf + nSent,
+            pClient->nextMsgIndex - nSent, 0 );
+        if ( status < 0 ) break;
+        nSent += status;
+    }
+
+    if ( pClient->backlog > 0 && status >= 0 )
+    {
+        /* On Linux send 0 bytes can detect EPIPE */
+        /* NOOP on Windows, fails on vxWorks */
+        errno = 0;
+        status = send ( pClient->sock, NULL, 0, 0 );
+        if (!(errno == ECONNRESET || errno == EPIPE)) status = 0;
+    }
+
+    if ( status < 0 ) {
+        if ( ! pClient->shutdown ) {
+            char sockErrBuf[128];
+            epicsSocketConvertErrnoToString ( sockErrBuf, sizeof ( sockErrBuf ) );
+            fprintf ( stderr, "log client: lost contact with log server at \"%s\" because \"%s\"\n", 
+                pClient->name, sockErrBuf );
         }
-        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;
+        pClient->backlog = 0;
+        logClientClose ( pClient );
+    }
+    else if ( nSent > 0 && pClient->nextMsgIndex > 0 ) {
+        int backlog = epicsSocketUnsentCount ( pClient->sock );
+        if (backlog >= 0) {
+            pClient->backlog = backlog;
+            nSent -= backlog;
+        }
+        pClient->nextMsgIndex -= nSent;
+        if ( nSent > 0 && pClient->nextMsgIndex > 0 ) {
+            memmove ( pClient->msgBuf, & pClient->msgBuf[nSent],
+                pClient->nextMsgIndex );
         }
     }
     epicsMutexUnlock ( pClient->mutex );
@@ -302,10 +279,10 @@ void epicsShareAPI logClientFlush ( logClientId id )
  */
 static void logClientMakeSock (logClient *pClient)
 {
-    
-#   ifdef DEBUG
+    if (logClientDebug) {
         fprintf (stderr, "log client: creating socket...");
-#   endif
+        fflush (stderr);
+    }
 
     epicsMutexMustLock (pClient->mutex);
    
@@ -314,7 +291,7 @@ static void logClientMakeSock (logClient *pClient)
      */
     pClient->sock = epicsSocketCreate ( AF_INET, SOCK_STREAM, 0 );
     if ( pClient->sock == INVALID_SOCKET ) {
-        char sockErrBuf[64];
+        char sockErrBuf[128];
         epicsSocketConvertErrnoToString ( 
             sockErrBuf, sizeof ( sockErrBuf ) );
         fprintf ( stderr, "log client: no socket error %s\n", 
@@ -323,10 +300,8 @@ static void logClientMakeSock (logClient *pClient)
     
     epicsMutexUnlock (pClient->mutex);
 
-#   ifdef DEBUG
+    if (logClientDebug)
         fprintf (stderr, "done\n");
-#   endif
-
 }
 
 /*
@@ -366,7 +341,7 @@ static void logClientConnect (logClient *pClient)
             }
             else {
                 if ( pClient->connFailStatus != errnoCpy && ! pClient->shutdown ) {
-                    char sockErrBuf[64];
+                    char sockErrBuf[128];
                     epicsSocketConvertErrnoToString (
                         sockErrBuf, sizeof ( sockErrBuf ) );
                     fprintf (stderr,
@@ -392,7 +367,7 @@ static void logClientConnect (logClient *pClient)
     optval = TRUE;
     status = setsockopt (pClient->sock, SOL_SOCKET, SO_KEEPALIVE, (char *)&optval, sizeof(optval));
     if (status<0) {
-        char sockErrBuf[64];
+        char sockErrBuf[128];
         epicsSocketConvertErrnoToString ( 
             sockErrBuf, sizeof ( sockErrBuf ) );
         fprintf (stderr, "log client: unable to enable keepalive option because \"%s\"\n", sockErrBuf);
@@ -404,11 +379,11 @@ static void logClientConnect (logClient *pClient)
      */
     status = shutdown (pClient->sock, SHUT_RD);
     if (status < 0) {
-        char sockErrBuf[64];
+        char sockErrBuf[128];
         epicsSocketConvertErrnoToString ( 
             sockErrBuf, sizeof ( sockErrBuf ) );
-        fprintf (stderr, "%s:%d shutdown(%d,SHUT_RD) error was \"%s\"\n", 
-            __FILE__, __LINE__, pClient->sock, sockErrBuf);
+        fprintf (stderr, "%s:%d shutdown(sock,SHUT_RD) error was \"%s\"\n", 
+            __FILE__, __LINE__, sockErrBuf);
         /* not fatal (although it shouldn't happen) */
     }
 
@@ -425,7 +400,7 @@ static void logClientConnect (logClient *pClient)
         lingerval.l_linger = 60*5; 
         status = setsockopt (pClient->sock, SOL_SOCKET, SO_LINGER, (char *) &lingerval, sizeof(lingerval));
         if (status<0) {
-            char sockErrBuf[64];
+            char sockErrBuf[128];
             epicsSocketConvertErrnoToString ( 
                 sockErrBuf, sizeof ( sockErrBuf ) );
             fprintf (stderr, "log client: unable to set linger options because \"%s\"\n", sockErrBuf);
@@ -457,14 +432,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 +451,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 +476,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 +499,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;
 }
 
@@ -568,24 +522,21 @@ void epicsShareAPI logClientShow (logClientId id, unsigned level)
         printf ("log client: disconnected from log server at \"%s\"\n", pClient->name);
     }
 
-    if (level>1) {
-        printf ("log client: sock=%s, connect cycles = %u\n",
-            pClient->sock==INVALID_SOCKET?"INVALID":"OK",
-            pClient->connectCount);
-    }
-
     if (logClientPrefix) {
         printf ("log client: prefix is \"%s\"\n", logClientPrefix);
     }
-}
 
-/*
- * logClientSendMessage (); deprecated
- */
-void logClientSendMessage ( logClientId id, const char * message )
-{
-    if ( !iocLogDisable ) {
-        logClientSend (id, message);
+    if (level>0) {
+        printf ("log client: sock %s, connect cycles = %u\n",
+            pClient->sock==INVALID_SOCKET?"INVALID":"OK",
+            pClient->connectCount);
+    }
+    if (level>1) {
+        printf ("log client: %u bytes in buffer\n", pClient->nextMsgIndex);
+        if (pClient->nextMsgIndex)
+            printf("-------------------------\n"
+                "%.*s-------------------------\n",
+                (int)(pClient->nextMsgIndex), pClient->msgBuf);
     }
 }
 
diff --git a/modules/libcom/src/log/logClient.h b/modules/libcom/src/log/logClient.h
index 1797bbb..3b3f63a 100644
--- a/modules/libcom/src/log/logClient.h
+++ b/modules/libcom/src/log/logClient.h
@@ -38,7 +38,6 @@ epicsShareFunc void epicsShareAPI iocLogPrefix(const char* prefix);
 /* deprecated interface; retained for backward compatibility */
 /* note: implementations are in iocLog.c, not logClient.c */
 epicsShareFunc logClientId epicsShareAPI logClientInit (void);
-epicsShareFunc void logClientSendMessage (logClientId id, const char *message);
 
 #ifdef __cplusplus
 }
diff --git a/modules/libcom/src/osi/Makefile b/modules/libcom/src/osi/Makefile
index ecbf4c2..71d8c3d 100644
--- a/modules/libcom/src/osi/Makefile
+++ b/modules/libcom/src/osi/Makefile
@@ -86,6 +86,7 @@ endif
 
 Com_SRCS += osdSock.c
 Com_SRCS += osdSockAddrReuse.cpp
+Com_SRCS += osdSockUnsentCount.c
 Com_SRCS += osiSock.c
 Com_SRCS += systemCallIntMech.cpp
 Com_SRCS += epicsSocketConvertErrnoToString.cpp
diff --git a/modules/libcom/src/osi/os/Darwin/osdSockUnsentCount.c b/modules/libcom/src/osi/os/Darwin/osdSockUnsentCount.c
 new file mode 100644
index 0000000..20bd82b
--- /dev/null
+++ b/modules/libcom/src/osi/os/Darwin/osdSockUnsentCount.c
@@ -0,0 +1,19 @@
+/*************************************************************************\
+* EPICS BASE is distributed subject to a Software License Agreement found
+* in file LICENSE that is included with this distribution.
+\*************************************************************************/
+
+#define EPICS_PRIVATE_API
+#include "osiSock.h"
+
+/*
+ * epicsSocketUnsentCount ()
+ * See https://www.unix.com/man-page/osx/2/setsockopt
+ */
+int epicsSocketUnsentCount(SOCKET sock) {
+    int unsent;
+    socklen_t len = sizeof(unsent);
+    if (getsockopt(sock, SOL_SOCKET, SO_NWRITE, &unsent, &len) == 0)
+        return unsent;
+    return -1;
+}
diff --git a/modules/libcom/src/osi/os/Linux/osdSockUnsentCount.c b/modules/libcom/src/osi/os/Linux/osdSockUnsentCount.c
 new file mode 100644
index 0000000..3c0a8f9
--- /dev/null
+++ b/modules/libcom/src/osi/os/Linux/osdSockUnsentCount.c
@@ -0,0 +1,19 @@
+/*************************************************************************\
+* EPICS BASE is distributed subject to a Software License Agreement found
+* in file LICENSE that is included with this distribution.
+\*************************************************************************/
+
+#include <linux/sockios.h>
+#define EPICS_PRIVATE_API
+#include "osiSock.h"
+
+/*
+ * epicsSocketUnsentCount ()
+ * See https://linux.die.net/man/7/tcp
+ */
+int epicsSocketUnsentCount(SOCKET sock) {
+    int unsent;
+    if (ioctl(sock, SIOCOUTQ, &unsent) == 0)
+        return unsent;
+    return -1;
+}
diff --git a/modules/libcom/src/osi/os/WIN32/osdSockUnsentCount.c b/modules/libcom/src/osi/os/WIN32/osdSockUnsentCount.c
 new file mode 100644
index 0000000..fe68ead
--- /dev/null
+++ b/modules/libcom/src/osi/os/WIN32/osdSockUnsentCount.c
@@ -0,0 +1,26 @@
+/*************************************************************************\
+* EPICS BASE is distributed subject to a Software License Agreement found
+* in file LICENSE that is included with this distribution.
+\*************************************************************************/
+
+#define epicsExportSharedSymbols
+#define EPICS_PRIVATE_API
+#include "osiSock.h"
+#include <mstcpip.h>
+
+/*
+ * epicsSocketUnsentCount ()
+ * See https://docs.microsoft.com/en-us/windows/win32/api/mstcpip/ns-mstcpip-tcp_info_v0
+ */
+int epicsSocketUnsentCount(SOCKET sock) {
+#if defined (_WIN32) && WINVER >= _WIN32_WINNT_WIN10
+/* Windows 10 Version 1703 / Server 2016 */
+    DWORD infoVersion = 0, bytesReturned;
+    TCP_INFO_v0 tcpInfo;
+    int status;
+    if ((status = WSAIoctl(sock, SIO_TCP_INFO, &infoVersion, sizeof(infoVersion),
+        &tcpInfo, sizeof(tcpInfo), &bytesReturned, NULL, NULL)) == 0)
+        return tcpInfo.BytesInFlight;
+#endif
+    return -1;
+}
diff --git a/modules/libcom/src/osi/os/default/osdSockUnsentCount.c b/modules/libcom/src/osi/os/default/osdSockUnsentCount.c
 new file mode 100644
index 0000000..ef01e9b
--- /dev/null
+++ b/modules/libcom/src/osi/os/default/osdSockUnsentCount.c
@@ -0,0 +1,15 @@
+/*************************************************************************\
+* EPICS BASE is distributed subject to a Software License Agreement found
+* in file LICENSE that is included with this distribution.
+\*************************************************************************/
+
+#define EPICS_PRIVATE_API
+#include "osiSock.h"
+
+/*
+ * epicsSocketUnsentCount ()
+ */
+int epicsSocketUnsentCount(SOCKET sock) {
+    /* not implemented */
+    return -1;
+}
diff --git a/modules/libcom/src/osi/os/iOS/osdSockUnsentCount.c b/modules/libcom/src/osi/os/iOS/osdSockUnsentCount.c
 new file mode 100644
index 0000000..20bd82b
--- /dev/null
+++ b/modules/libcom/src/osi/os/iOS/osdSockUnsentCount.c
@@ -0,0 +1,19 @@
+/*************************************************************************\
+* EPICS BASE is distributed subject to a Software License Agreement found
+* in file LICENSE that is included with this distribution.
+\*************************************************************************/
+
+#define EPICS_PRIVATE_API
+#include "osiSock.h"
+
+/*
+ * epicsSocketUnsentCount ()
+ * See https://www.unix.com/man-page/osx/2/setsockopt
+ */
+int epicsSocketUnsentCount(SOCKET sock) {
+    int unsent;
+    socklen_t len = sizeof(unsent);
+    if (getsockopt(sock, SOL_SOCKET, SO_NWRITE, &unsent, &len) == 0)
+        return unsent;
+    return -1;
+}
diff --git a/modules/libcom/src/osi/osiSock.h b/modules/libcom/src/osi/osiSock.h
index 061619e..6e3b053 100644
--- a/modules/libcom/src/osi/osiSock.h
+++ b/modules/libcom/src/osi/osiSock.h
@@ -52,6 +52,14 @@ enum epicsSocketSystemCallInterruptMechanismQueryInfo {
 epicsShareFunc enum epicsSocketSystemCallInterruptMechanismQueryInfo 
         epicsSocketSystemCallInterruptMechanismQuery ();
 
+#ifdef EPICS_PRIVATE_API
+/*
+ * Some systems (e.g Linux and Windows 10) allow to check the amount
+ * of unsent data in the output queue.
+ * Returns -1 if the information is not available.
+ */
+epicsShareFunc int epicsSocketUnsentCount(SOCKET sock);
+#endif
 
 /*
  * convert socket address to ASCII in this order