logd: sock_alloc_send_pskb starves pruning

(cherry pick from commit 5c77ad55d0cdee84cd45fd5d0d066f3c61d76ce6)

Allow socket send syscall to terminate after 32 seconds if reader
stalled because of memory pressure allocating new network buffers

Add a gTest to catch regressions, add security buffer to log_dump

Bug: 27242723
Change-Id: Idaa6699d9d284e7f5f723ae0e76b3d6aa3371489

3 files changed, 66 insertions, 0 deletions

diff --git a/logd/LogReader.cpp b/logd/LogReader.cpp
index 16362379c5..2c07984ce1 100644
--- a/logd/LogReader.cpp
+++ b/logd/LogReader.cpp
@@ -18,6 +18,7 @@
 #include <poll.h>
 #include <sys/prctl.h>
 #include <sys/socket.h>
+#include <sys/types.h>
 
 #include <cutils/sockets.h>
 
@@ -179,6 +180,11 @@ bool LogReader::onDataAvailable(SocketClient *cli) {
     }
 
     FlushCommand command(*this, nonBlock, tail, logMask, pid, sequence, timeout);
+
+    // Set acceptable upper limit to wait for slow reader processing b/27242723
+    struct timeval t = { LOGD_SNDTIMEO, 0 };
+    setsockopt(cli->getSocket(), SOL_SOCKET, SO_SNDTIMEO, (const char *)&t, sizeof(t));
+
     command.runSocketCommand(cli);
     return true;
 }
diff --git a/logd/LogReader.h b/logd/LogReader.h
index 174ee651db..98674b8af7 100644
--- a/logd/LogReader.h
+++ b/logd/LogReader.h
@@ -19,6 +19,8 @@
 
 #include <sysutils/SocketListener.h>
 
+#define LOGD_SNDTIMEO 32
+
 class LogBuffer;
 
 class LogReader : public SocketListener {
diff --git a/logd/tests/logd_test.cpp b/logd/tests/logd_test.cpp
index de19790710..2014374e75 100644
--- a/logd/tests/logd_test.cpp
+++ b/logd/tests/logd_test.cpp
@@ -30,6 +30,8 @@
 #include <log/log.h>
 #include <log/logger.h>
 
+#include "../LogReader.h" // pickup LOGD_SNDTIMEO
+
 /*
  * returns statistics
  */
@@ -253,6 +255,9 @@ static void dump_log_msg(const char *prefix,
         fprintf(stderr, "lid=crash ");
         break;
     case 5:
+        fprintf(stderr, "lid=security ");
+        break;
+    case 6:
         fprintf(stderr, "lid=kernel ");
         break;
     default:
@@ -710,3 +715,56 @@ TEST(logd, timeout) {
     EXPECT_TRUE(content_timeout);
     EXPECT_NE(0U, alarm_timeout);
 }
+
+// b/27242723 confirmed fixed
+TEST(logd, SNDTIMEO) {
+    static const unsigned sndtimeo = LOGD_SNDTIMEO; // <sigh> it has to be done!
+    static const unsigned sleep_time = sndtimeo + 3;
+    static const unsigned alarm_time = sleep_time + 5;
+
+    int fd;
+
+    ASSERT_TRUE((fd = socket_local_client("logdr",
+                                 ANDROID_SOCKET_NAMESPACE_RESERVED,
+                                 SOCK_SEQPACKET)) > 0);
+
+    struct sigaction ignore, old_sigaction;
+    memset(&ignore, 0, sizeof(ignore));
+    ignore.sa_handler = caught_signal;
+    sigemptyset(&ignore.sa_mask);
+    sigaction(SIGALRM, &ignore, &old_sigaction);
+    unsigned int old_alarm = alarm(alarm_time);
+
+    static const char ask[] = "stream lids=0,1,2,3,4,5,6"; // all sources
+    bool reader_requested = write(fd, ask, sizeof(ask)) == sizeof(ask);
+    EXPECT_TRUE(reader_requested);
+
+    log_msg msg;
+    bool read_one = recv(fd, msg.buf, sizeof(msg), 0) > 0;
+
+    EXPECT_TRUE(read_one);
+    if (read_one) {
+        dump_log_msg("user", &msg, 3, -1);
+    }
+
+    fprintf (stderr, "Sleep for >%d seconds logd SO_SNDTIMEO ...\n", sndtimeo);
+    sleep(sleep_time);
+
+    // flush will block if we did not trigger. if it did, last entry returns 0
+    int recv_ret;
+    do {
+        recv_ret = recv(fd, msg.buf, sizeof(msg), 0);
+    } while (recv_ret > 0);
+    int save_errno = (recv_ret < 0) ? errno : 0;
+
+    EXPECT_NE(0U, alarm(old_alarm));
+    sigaction(SIGALRM, &old_sigaction, NULL);
+
+    EXPECT_EQ(0, recv_ret);
+    if (recv_ret > 0) {
+        dump_log_msg("user", &msg, 3, -1);
+    }
+    EXPECT_EQ(0, save_errno);
+
+    close(fd);
+}