Merge "liblog: __android_log_pmsg_file_write() cleanup"

liblog/logd_reader.c

@@ -482,17 +482,17 @@ static int logdOpen(struct android_log_logger_list *logger_list,
     struct sigaction old_sigaction;
     unsigned int old_alarm = 0;
     char buffer[256], *cp, c;
-    int e, ret, remaining;
+    int e, ret, remaining, sock;
-
-    int sock = transp->context.sock;
-    if (sock > 0) {
-        return sock;
-    }
 
     if (!logger_list) {
         return -EINVAL;
     }
 
+    sock = atomic_load(&transp->context.sock);
+    if (sock > 0) {
+        return sock;
+    }
+
     sock = socket_local_client("logdr",
                                ANDROID_SOCKET_NAMESPACE_RESERVED,
                                SOCK_SEQPACKET);
@@ -587,7 +587,11 @@ static int logdOpen(struct android_log_logger_list *logger_list,
         return ret;
     }
 
-    return transp->context.sock = sock;
+    ret = atomic_exchange(&transp->context.sock, sock);
+    if ((ret > 0) && (ret != sock)) {
+        close(ret);
+    }
+    return sock;
 }
 
 /* Read from the selected logs */
@@ -662,8 +666,8 @@ static int logdPoll(struct android_log_logger_list *logger_list,
 static void logdClose(struct android_log_logger_list *logger_list __unused,
                       struct android_log_transport_context *transp)
 {
-    if (transp->context.sock > 0) {
+    int sock = atomic_exchange(&transp->context.sock, -1);
-        close (transp->context.sock);
+    if (sock > 0) {
-        transp->context.sock = -1;
+        close (sock);
     }
 }

liblog/logd_writer.c

@@ -31,7 +31,6 @@
 #include <time.h>
 #include <unistd.h>
 
-#include <android/log.h>
 #include <cutils/sockets.h>
 #include <log/logger.h>
 #include <private/android_filesystem_config.h>
@@ -65,7 +64,8 @@ static int logdOpen()
 {
     int i, ret = 0;
 
-    if (logdLoggerWrite.context.sock < 0) {
+    i = atomic_load(&logdLoggerWrite.context.sock);
+    if (i < 0) {
         i = TEMP_FAILURE_RETRY(socket(PF_UNIX, SOCK_DGRAM | SOCK_CLOEXEC | SOCK_NONBLOCK, 0));
         if (i < 0) {
             ret = -errno;
@@ -80,7 +80,11 @@ static int logdOpen()
                 ret = -errno;
                 close(i);
             } else {
-                logdLoggerWrite.context.sock = i;
+                ret = atomic_exchange(&logdLoggerWrite.context.sock, i);
+                if ((ret >= 0) && (ret != i)) {
+                    close(ret);
+                }
+                ret = 0;
             }
         }
     }
@@ -90,9 +94,9 @@ static int logdOpen()
 
 static void logdClose()
 {
-    if (logdLoggerWrite.context.sock >= 0) {
+    int sock = atomic_exchange(&logdLoggerWrite.context.sock, -1);
-        close(logdLoggerWrite.context.sock);
+    if (sock >= 0) {
-        logdLoggerWrite.context.sock = -1;
+        close(sock);
     }
 }
 
@@ -101,7 +105,7 @@ static int logdAvailable(log_id_t logId)
     if (logId > LOG_ID_SECURITY) {
         return -EINVAL;
     }
-    if (logdLoggerWrite.context.sock < 0) {
+    if (atomic_load(&logdLoggerWrite.context.sock) < 0) {
         if (access("/dev/socket/logdw", W_OK) == 0) {
             return 0;
         }
@@ -121,7 +125,7 @@ static int logdWrite(log_id_t logId, struct timespec *ts,
     static atomic_int_fast32_t dropped;
     static atomic_int_fast32_t droppedSecurity;
 
-    if (logdLoggerWrite.context.sock < 0) {
+    if (atomic_load(&logdLoggerWrite.context.sock) < 0) {
         return -EBADF;
     }
 
@@ -160,7 +164,7 @@ static int logdWrite(log_id_t logId, struct timespec *ts,
     newVec[0].iov_base = (unsigned char *)&header;
     newVec[0].iov_len  = sizeof(header);
 
-    if (logdLoggerWrite.context.sock > 0) {
+    if (atomic_load(&logdLoggerWrite.context.sock) > 0) {
         int32_t snapshot = atomic_exchange_explicit(&droppedSecurity, 0,
                                                     memory_order_relaxed);
         if (snapshot) {
@@ -174,7 +178,8 @@ static int logdWrite(log_id_t logId, struct timespec *ts,
             newVec[headerLength].iov_base = &buffer;
             newVec[headerLength].iov_len  = sizeof(buffer);
 
-            ret = TEMP_FAILURE_RETRY(writev(logdLoggerWrite.context.sock, newVec, 2));
+            ret = TEMP_FAILURE_RETRY(writev(
+                    atomic_load(&logdLoggerWrite.context.sock), newVec, 2));
             if (ret != (ssize_t)(sizeof(header) + sizeof(buffer))) {
                 atomic_fetch_add_explicit(&droppedSecurity, snapshot,
                                           memory_order_relaxed);
@@ -194,7 +199,8 @@ static int logdWrite(log_id_t logId, struct timespec *ts,
             newVec[headerLength].iov_base = &buffer;
             newVec[headerLength].iov_len  = sizeof(buffer);
 
-            ret = TEMP_FAILURE_RETRY(writev(logdLoggerWrite.context.sock, newVec, 2));
+            ret = TEMP_FAILURE_RETRY(writev(
+                      atomic_load(&logdLoggerWrite.context.sock), newVec, 2));
             if (ret != (ssize_t)(sizeof(header) + sizeof(buffer))) {
                 atomic_fetch_add_explicit(&dropped, snapshot,
                                           memory_order_relaxed);
@@ -223,7 +229,8 @@ static int logdWrite(log_id_t logId, struct timespec *ts,
      * ENOTCONN occurs if logd dies.
      * EAGAIN occurs if logd is overloaded.
      */
-    ret = TEMP_FAILURE_RETRY(writev(logdLoggerWrite.context.sock, newVec, i));
+    ret = TEMP_FAILURE_RETRY(writev(
+            atomic_load(&logdLoggerWrite.context.sock), newVec, i));
     if (ret < 0) {
         ret = -errno;
         if (ret == -ENOTCONN) {
@@ -236,7 +243,8 @@ static int logdWrite(log_id_t logId, struct timespec *ts,
                 return ret;
             }
 
-            ret = TEMP_FAILURE_RETRY(writev(logdLoggerWrite.context.sock, newVec, i));
+            ret = TEMP_FAILURE_RETRY(writev(
+                    atomic_load(&logdLoggerWrite.context.sock), newVec, i));
             if (ret < 0) {
                 ret = -errno;
             }

liblog/logger.h

@@ -17,6 +17,7 @@
 #ifndef _LIBLOG_LOGGER_H__
 #define _LIBLOG_LOGGER_H__
 
+#include <stdatomic.h>
 #include <stdbool.h>
 #include <log/uio.h>
 
@@ -31,9 +32,10 @@ __BEGIN_DECLS
 /* Union, sock or fd of zero is not allowed unless static initialized */
 union android_log_context {
   void *private;
-  int sock;
+  atomic_int sock;
-  int fd;
+  atomic_int fd;
   struct listnode *node;
+  atomic_uintptr_t atomic_pointer;
 };
 
 struct android_log_transport_write {

liblog/pmsg_reader.c

@@ -151,8 +151,8 @@ static int pmsgRead(struct android_log_logger_list *logger_list,
 
     memset(log_msg, 0, sizeof(*log_msg));
 
-    if (transp->context.fd <= 0) {
+    if (atomic_load(&transp->context.fd) <= 0) {
-        int fd = open("/sys/fs/pstore/pmsg-ramoops-0", O_RDONLY | O_CLOEXEC);
+        int i, fd = open("/sys/fs/pstore/pmsg-ramoops-0", O_RDONLY | O_CLOEXEC);
 
         if (fd < 0) {
             return -errno;
@@ -164,13 +164,22 @@ static int pmsgRead(struct android_log_logger_list *logger_list,
                 return -errno;
             }
         }
-        transp->context.fd = fd;
+        i = atomic_exchange(&transp->context.fd, fd);
+        if ((i > 0) && (i != fd)) {
+            close(i);
+        }
         preread_count = 0;
     }
 
     while(1) {
+        int fd;
+
         if (preread_count < sizeof(buf)) {
-            ret = TEMP_FAILURE_RETRY(read(transp->context.fd,
+            fd = atomic_load(&transp->context.fd);
+            if (fd <= 0) {
+                return -EBADF;
+            }
+            ret = TEMP_FAILURE_RETRY(read(fd,
                                           &buf.p.magic + preread_count,
                                           sizeof(buf) - preread_count));
             if (ret < 0) {
@@ -212,9 +221,13 @@ static int pmsgRead(struct android_log_logger_list *logger_list,
                     log_msg->entry_v4.msg :
                     log_msg->entry_v3.msg;
                 *msg = buf.prio;
-                ret = TEMP_FAILURE_RETRY(read(transp->context.fd,
+                fd = atomic_load(&transp->context.fd);
-                                          msg + sizeof(buf.prio),
+                if (fd <= 0) {
-                                          buf.p.len - sizeof(buf)));
+                    return -EBADF;
+                }
+                ret = TEMP_FAILURE_RETRY(read(fd,
+                                              msg + sizeof(buf.prio),
+                                              buf.p.len - sizeof(buf)));
                 if (ret < 0) {
                     return -errno;
                 }
@@ -239,12 +252,19 @@ static int pmsgRead(struct android_log_logger_list *logger_list,
             }
         }
 
-        current = TEMP_FAILURE_RETRY(lseek(transp->context.fd,
+        fd = atomic_load(&transp->context.fd);
-                                           (off_t)0, SEEK_CUR));
+        if (fd <= 0) {
+            return -EBADF;
+        }
+        current = TEMP_FAILURE_RETRY(lseek(fd, (off_t)0, SEEK_CUR));
         if (current < 0) {
             return -errno;
         }
-        next = TEMP_FAILURE_RETRY(lseek(transp->context.fd,
+        fd = atomic_load(&transp->context.fd);
+        if (fd <= 0) {
+            return -EBADF;
+        }
+        next = TEMP_FAILURE_RETRY(lseek(fd,
                                         (off_t)(buf.p.len - sizeof(buf)),
                                         SEEK_CUR));
         if (next < 0) {
@@ -258,10 +278,10 @@ static int pmsgRead(struct android_log_logger_list *logger_list,
 
 static void pmsgClose(struct android_log_logger_list *logger_list __unused,
                       struct android_log_transport_context *transp) {
-    if (transp->context.fd > 0) {
+    int fd = atomic_exchange(&transp->context.fd, 0);
-        close (transp->context.fd);
+    if (fd > 0) {
+        close (fd);
     }
-    transp->context.fd = 0;
 }
 
 LIBLOG_ABI_PRIVATE ssize_t __android_log_pmsg_file_read(

liblog/pmsg_writer.c

@@ -20,6 +20,7 @@
 
 #include <errno.h>
 #include <fcntl.h>
+#include <stdbool.h>
 #include <stdlib.h>
 #include <string.h>
 #include <sys/types.h>
@@ -53,18 +54,25 @@ LIBLOG_HIDDEN struct android_log_transport_write pmsgLoggerWrite = {
 
 static int pmsgOpen()
 {
-    if (pmsgLoggerWrite.context.fd < 0) {
+    int fd = atomic_load(&pmsgLoggerWrite.context.fd);
-        pmsgLoggerWrite.context.fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY | O_CLOEXEC));
+    if (fd < 0) {
+        int i;
+
+        fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY | O_CLOEXEC));
+        i = atomic_exchange(&pmsgLoggerWrite.context.fd, fd);
+        if ((i >= 0) && (i != fd)) {
+            close(i);
+        }
     }
 
-    return pmsgLoggerWrite.context.fd;
+    return fd;
 }
 
 static void pmsgClose()
 {
-    if (pmsgLoggerWrite.context.fd >= 0) {
+    int fd = atomic_exchange(&pmsgLoggerWrite.context.fd, -1);
-        close(pmsgLoggerWrite.context.fd);
+    if (fd >= 0) {
-        pmsgLoggerWrite.context.fd = -1;
+        close(fd);
     }
 }
 
@@ -78,7 +86,7 @@ static int pmsgAvailable(log_id_t logId)
             !__android_log_is_debuggable()) {
         return -EINVAL;
     }
-    if (pmsgLoggerWrite.context.fd < 0) {
+    if (atomic_load(&pmsgLoggerWrite.context.fd) < 0) {
         if (access("/dev/pmsg0", W_OK) == 0) {
             return 0;
         }
@@ -115,7 +123,7 @@ static int pmsgWrite(log_id_t logId, struct timespec *ts,
         }
     }
 
-    if (pmsgLoggerWrite.context.fd < 0) {
+    if (atomic_load(&pmsgLoggerWrite.context.fd) < 0) {
         return -EBADF;
     }
 
@@ -169,7 +177,8 @@ static int pmsgWrite(log_id_t logId, struct timespec *ts,
     }
     pmsgHeader.len += payloadSize;
 
-    ret = TEMP_FAILURE_RETRY(writev(pmsgLoggerWrite.context.fd, newVec, i));
+    ret = TEMP_FAILURE_RETRY(writev(atomic_load(&pmsgLoggerWrite.context.fd),
+                                    newVec, i));
     if (ret < 0) {
         ret = errno ? -errno : -ENOTCONN;
     }
@@ -206,7 +215,7 @@ LIBLOG_ABI_PRIVATE ssize_t __android_log_pmsg_file_write(
         char prio,
         const char *filename,
         const char *buf, size_t len) {
-    int fd;
+    bool weOpened;
     size_t length, packet_len;
     const char *tag;
     char *cp, *slash;
@@ -228,16 +237,6 @@ LIBLOG_ABI_PRIVATE ssize_t __android_log_pmsg_file_write(
         return -ENOMEM;
     }
 
-    fd = pmsgLoggerWrite.context.fd;
-    if (fd < 0) {
-        __android_log_lock();
-        fd = pmsgOpen();
-        __android_log_unlock();
-        if (fd < 0) {
-            return -EBADF;
-        }
-    }
-
     tag = cp;
     slash = strrchr(cp, '/');
     if (slash) {
@@ -256,6 +255,7 @@ LIBLOG_ABI_PRIVATE ssize_t __android_log_pmsg_file_write(
     vec[1].iov_base = (unsigned char *)tag;
     vec[1].iov_len  = length;
 
+    weOpened = false;
     for (ts.tv_nsec = 0, length = len;
             length;
             ts.tv_nsec += ANDROID_LOG_PMSG_FILE_SEQUENCE) {
@@ -279,15 +279,36 @@ LIBLOG_ABI_PRIVATE ssize_t __android_log_pmsg_file_write(
         vec[2].iov_base = (unsigned char *)buf;
         vec[2].iov_len  = transfer;
 
+        if (atomic_load(&pmsgLoggerWrite.context.fd) < 0) {
+            if (!weOpened) { /* Impossible for weOpened = true here */
+                __android_log_lock();
+            }
+            weOpened = atomic_load(&pmsgLoggerWrite.context.fd) < 0;
+            if (!weOpened) {
+                __android_log_unlock();
+            } else if (pmsgOpen() < 0) {
+                __android_log_unlock();
+                return -EBADF;
+            }
+        }
+
         ret = pmsgWrite(logId, &ts, vec, sizeof(vec) / sizeof(vec[0]));
 
         if (ret <= 0) {
+            if (weOpened) {
+                pmsgClose();
+                __android_log_unlock();
+            }
             free(cp);
-            return ret;
+            return ret ? ret : (len - length);
         }
         length -= transfer;
         buf += transfer;
     }
+    if (weOpened) {
+        pmsgClose();
+        __android_log_unlock();
+    }
     free(cp);
     return len;
 }

liblog/tests/liblog_test.cpp

@@ -20,6 +20,7 @@
 #include <inttypes.h>
 #include <semaphore.h>
 #include <signal.h>
+#include <stdio.h>
 #include <string.h>
 #include <sys/types.h>
 #include <unistd.h>
@@ -129,6 +130,70 @@ TEST(liblog, concurrent_name(__android_log_buf_print, NUM_CONCURRENT)) {
     ASSERT_LT(0, ret);
 }
 
+std::string popenToString(std::string command) {
+    std::string ret;
+
+    FILE* fp = popen(command.c_str(), "r");
+    if (fp) {
+        if (!android::base::ReadFdToString(fileno(fp), &ret)) ret = "";
+        pclose(fp);
+    }
+    return ret;
+}
+
+static bool isPmsgActive() {
+    pid_t pid = getpid();
+
+    std::string myPidFds = popenToString(android::base::StringPrintf(
+                                             "ls -l /proc/%d/fd", pid));
+    if (myPidFds.length() == 0) return true; // guess it is?
+
+    return std::string::npos != myPidFds.find(" -> /dev/pmsg0");
+}
+
+static bool isLogdwActive() {
+    std::string logdwSignature = popenToString(
+        "grep /dev/socket/logdw /proc/net/unix");
+    size_t beginning = logdwSignature.find(" ");
+    if (beginning == std::string::npos) return true;
+    beginning = logdwSignature.find(" ", beginning + 1);
+    if (beginning == std::string::npos) return true;
+    size_t end = logdwSignature.find(" ", beginning + 1);
+    if (end == std::string::npos) return true;
+    end = logdwSignature.find(" ", end + 1);
+    if (end == std::string::npos) return true;
+    end = logdwSignature.find(" ", end + 1);
+    if (end == std::string::npos) return true;
+    end = logdwSignature.find(" ", end + 1);
+    if (end == std::string::npos) return true;
+    std::string allLogdwEndpoints = popenToString(
+        "grep ' 00000002" +
+        logdwSignature.substr(beginning, end - beginning) +
+        " ' /proc/net/unix | " +
+        "sed -n 's/.* \\([0-9][0-9]*\\)$/ -> socket:[\\1]/p'");
+    if (allLogdwEndpoints.length() == 0) return true;
+
+    // NB: allLogdwEndpoints has some false positives in it, but those
+    // strangers do not overlap with the simplistic activities inside this
+    // test suite.
+
+    pid_t pid = getpid();
+
+    std::string myPidFds = popenToString(android::base::StringPrintf(
+        "ls -l /proc/%d/fd", pid));
+    if (myPidFds.length() == 0) return true;
+
+    // NB: fgrep with multiple strings is broken in Android
+    for (beginning = 0;
+         (end = allLogdwEndpoints.find("\n", beginning)) != std::string::npos;
+         beginning = end + 1) {
+        if (myPidFds.find(allLogdwEndpoints.substr(beginning,
+                                                   end - beginning)) !=
+            std::string::npos) return true;
+    }
+    return false;
+}
+
 TEST(liblog, __android_log_btwrite__android_logger_list_read) {
     struct logger_list *logger_list;
 
@@ -140,10 +205,22 @@ TEST(liblog, __android_log_btwrite__android_logger_list_read) {
     // Check that we can close and reopen the logger
     log_time ts(CLOCK_MONOTONIC);
     ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
+    bool pmsgActiveAfter__android_log_btwrite = isPmsgActive();
+    bool logdwActiveAfter__android_log_btwrite = isLogdwActive();
+    EXPECT_TRUE(pmsgActiveAfter__android_log_btwrite);
+    EXPECT_TRUE(logdwActiveAfter__android_log_btwrite);
     __android_log_close();
+    bool pmsgActiveAfter__android_log_close = isPmsgActive();
+    bool logdwActiveAfter__android_log_close = isLogdwActive();
+    EXPECT_FALSE(pmsgActiveAfter__android_log_close);
+    EXPECT_FALSE(logdwActiveAfter__android_log_close);
 
     log_time ts1(CLOCK_MONOTONIC);
     ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts1, sizeof(ts1)));
+    pmsgActiveAfter__android_log_btwrite = isPmsgActive();
+    logdwActiveAfter__android_log_btwrite = isLogdwActive();
+    EXPECT_TRUE(pmsgActiveAfter__android_log_btwrite);
+    EXPECT_TRUE(logdwActiveAfter__android_log_btwrite);
     usleep(1000000);
 
     int count = 0;
@@ -2575,12 +2652,35 @@ static const char __pmsg_file[] =
         "/data/william-shakespeare/MuchAdoAboutNothing.txt";
 
 TEST(liblog, __android_log_pmsg_file_write) {
+    __android_log_close();
+    bool pmsgActiveAfter__android_log_close = isPmsgActive();
+    bool logdwActiveAfter__android_log_close = isLogdwActive();
+    EXPECT_FALSE(pmsgActiveAfter__android_log_close);
+    EXPECT_FALSE(logdwActiveAfter__android_log_close);
     EXPECT_LT(0, __android_log_pmsg_file_write(
             LOG_ID_CRASH, ANDROID_LOG_VERBOSE,
             __pmsg_file, max_payload_buf, sizeof(max_payload_buf)));
     fprintf(stderr, "Reboot, ensure file %s matches\n"
                     "with liblog.__android_log_msg_file_read test\n",
                     __pmsg_file);
+    bool pmsgActiveAfter__android_pmsg_file_write = isPmsgActive();
+    bool logdwActiveAfter__android_pmsg_file_write = isLogdwActive();
+    EXPECT_FALSE(pmsgActiveAfter__android_pmsg_file_write);
+    EXPECT_FALSE(logdwActiveAfter__android_pmsg_file_write);
+    EXPECT_LT(0, __android_log_buf_print(LOG_ID_MAIN, ANDROID_LOG_INFO,
+                                         "TEST__android_log_pmsg_file_write",
+                                         "main"));
+    bool pmsgActiveAfter__android_log_buf_print = isPmsgActive();
+    bool logdwActiveAfter__android_log_buf_print = isLogdwActive();
+    EXPECT_TRUE(pmsgActiveAfter__android_log_buf_print);
+    EXPECT_TRUE(logdwActiveAfter__android_log_buf_print);
+    EXPECT_LT(0, __android_log_pmsg_file_write(
+            LOG_ID_CRASH, ANDROID_LOG_VERBOSE,
+            __pmsg_file, max_payload_buf, sizeof(max_payload_buf)));
+    pmsgActiveAfter__android_pmsg_file_write = isPmsgActive();
+    logdwActiveAfter__android_pmsg_file_write = isLogdwActive();
+    EXPECT_TRUE(pmsgActiveAfter__android_pmsg_file_write);
+    EXPECT_TRUE(logdwActiveAfter__android_pmsg_file_write);
 }
 
 ssize_t __pmsg_fn(log_id_t logId, char prio, const char *filename,
@@ -2597,7 +2697,7 @@ ssize_t __pmsg_fn(log_id_t logId, char prio, const char *filename,
             strcmp(max_payload_buf, buf)) {
         fprintf(stderr, "comparison fails on content \"%s\"\n", buf);
     }
-    return !arg ||
+    return arg ||
            (LOG_ID_CRASH != logId) ||
            (ANDROID_LOG_VERBOSE != prio) ||
            !strstr(__pmsg_file, filename) ||
@@ -2608,10 +2708,21 @@ ssize_t __pmsg_fn(log_id_t logId, char prio, const char *filename,
 TEST(liblog, __android_log_pmsg_file_read) {
     signaled = 0;
 
+    __android_log_close();
+    bool pmsgActiveAfter__android_log_close = isPmsgActive();
+    bool logdwActiveAfter__android_log_close = isLogdwActive();
+    EXPECT_FALSE(pmsgActiveAfter__android_log_close);
+    EXPECT_FALSE(logdwActiveAfter__android_log_close);
+
     ssize_t ret = __android_log_pmsg_file_read(
             LOG_ID_CRASH, ANDROID_LOG_VERBOSE,
             __pmsg_file, __pmsg_fn, NULL);
 
+    bool pmsgActiveAfter__android_log_pmsg_file_read = isPmsgActive();
+    bool logdwActiveAfter__android_log_pmsg_file_read = isLogdwActive();
+    EXPECT_FALSE(pmsgActiveAfter__android_log_pmsg_file_read);
+    EXPECT_FALSE(logdwActiveAfter__android_log_pmsg_file_read);
+
     if (ret == -ENOENT) {
         fprintf(stderr,
             "No pre-boot results of liblog.__android_log_mesg_file_write to "