liblog: remove Rwlocks for logd_socket and pmsg_fd
These historically used atomics to manage their lifetime. They were unfortunately unsafe and later replace with a RwLock. A lock is also problematic as it is too heavy weight for the typical use case and implies that logging is neither async nor fork safe. This change returns us to using atomics with two key changes: 1) compare_exchange_strong() is used instead of atomic_exchange(). The latter has a race condition where a separate thread could have read the atomic value into a register, while the thread performing the atomic_exchange closes that FD. The new code only changes the FD in the atomic if it is uninitialized. 2) Using the fact that DGRAM sockets can have connect() called on them multiple times, it uses a single logd_socket for the duration of the program. These sockets are thread/async/fork safely created and accessed. The one caveat is __android_log_close(), which is intended only to be used by zygote when it is single threaded and is therefore not thread safe. It will close this socket and reset the underlying variable, such that the next log message will go through the above initialization. Bug: 65062446 Test: logging works, logging unit tests Test: new unit test Change-Id: Ia4dbf7479dbe50683d124558ab2f83bff53b8f5f
This commit is contained in:
parent
91fd50c78f
commit
7acfba274c
7 changed files with 148 additions and 194 deletions
|
@ -144,8 +144,11 @@ clockid_t android_log_clockid(void);
|
|||
/*
|
||||
* Release any logger resources (a new log write will immediately re-acquire)
|
||||
*
|
||||
* May be used to clean up File descriptors after a Fork, the resources are
|
||||
* all O_CLOEXEC so wil self clean on exec().
|
||||
* This is specifically meant to be used by Zygote to close open file descriptors after fork()
|
||||
* and before specialization. O_CLOEXEC is used on file descriptors, so they will be closed upon
|
||||
* exec() in normal use cases.
|
||||
*
|
||||
* Note that this is not safe to call from a multi-threaded program.
|
||||
*/
|
||||
void __android_log_close(void);
|
||||
|
||||
|
|
|
@ -32,58 +32,53 @@
|
|||
#include <time.h>
|
||||
#include <unistd.h>
|
||||
|
||||
#include <shared_mutex>
|
||||
|
||||
#include <private/android_filesystem_config.h>
|
||||
#include <private/android_logger.h>
|
||||
|
||||
#include "logger.h"
|
||||
#include "rwlock.h"
|
||||
#include "uio.h"
|
||||
|
||||
static int logd_socket;
|
||||
static RwLock logd_socket_lock;
|
||||
|
||||
static void OpenSocketLocked() {
|
||||
logd_socket = TEMP_FAILURE_RETRY(socket(PF_UNIX, SOCK_DGRAM | SOCK_CLOEXEC | SOCK_NONBLOCK, 0));
|
||||
if (logd_socket <= 0) {
|
||||
return;
|
||||
}
|
||||
static atomic_int logd_socket;
|
||||
|
||||
// Note that it is safe to call connect() multiple times on DGRAM Unix domain sockets, so this
|
||||
// function is used to reconnect to logd without requiring a new socket.
|
||||
static void LogdConnect() {
|
||||
sockaddr_un un = {};
|
||||
un.sun_family = AF_UNIX;
|
||||
strcpy(un.sun_path, "/dev/socket/logdw");
|
||||
|
||||
if (TEMP_FAILURE_RETRY(
|
||||
connect(logd_socket, reinterpret_cast<sockaddr*>(&un), sizeof(sockaddr_un))) < 0) {
|
||||
close(logd_socket);
|
||||
logd_socket = 0;
|
||||
}
|
||||
TEMP_FAILURE_RETRY(connect(logd_socket, reinterpret_cast<sockaddr*>(&un), sizeof(sockaddr_un)));
|
||||
}
|
||||
|
||||
static void OpenSocket() {
|
||||
auto lock = std::unique_lock{logd_socket_lock};
|
||||
if (logd_socket > 0) {
|
||||
// Someone raced us and opened the socket already.
|
||||
// logd_socket should only be opened once. If we see that logd_socket is uninitialized, we create a
|
||||
// new socket and attempt to exchange it into the atomic logd_socket. If the compare/exchange was
|
||||
// successful, then that will be the socket used for the duration of the program, otherwise a
|
||||
// different thread has already opened and written the socket to the atomic, so close the new socket
|
||||
// and return.
|
||||
static void GetSocket() {
|
||||
if (logd_socket != 0) {
|
||||
return;
|
||||
}
|
||||
|
||||
OpenSocketLocked();
|
||||
}
|
||||
|
||||
static void ResetSocket(int old_socket) {
|
||||
auto lock = std::unique_lock{logd_socket_lock};
|
||||
if (old_socket != logd_socket) {
|
||||
// Someone raced us and reset the socket already.
|
||||
int new_socket =
|
||||
TEMP_FAILURE_RETRY(socket(PF_UNIX, SOCK_DGRAM | SOCK_CLOEXEC | SOCK_NONBLOCK, 0));
|
||||
if (new_socket <= 0) {
|
||||
return;
|
||||
}
|
||||
close(logd_socket);
|
||||
logd_socket = 0;
|
||||
OpenSocketLocked();
|
||||
|
||||
int uninitialized_value = 0;
|
||||
if (!logd_socket.compare_exchange_strong(uninitialized_value, new_socket)) {
|
||||
close(new_socket);
|
||||
return;
|
||||
}
|
||||
|
||||
LogdConnect();
|
||||
}
|
||||
|
||||
// This is the one exception to the above. Zygote uses this to clean up open FD's after fork() and
|
||||
// before specialization. It is single threaded at this point and therefore this function is
|
||||
// explicitly not thread safe. It sets logd_socket to 0, so future logs will be safely initialized
|
||||
// whenever they happen.
|
||||
void LogdClose() {
|
||||
auto lock = std::unique_lock{logd_socket_lock};
|
||||
if (logd_socket > 0) {
|
||||
close(logd_socket);
|
||||
}
|
||||
|
@ -99,12 +94,7 @@ int LogdWrite(log_id_t logId, struct timespec* ts, struct iovec* vec, size_t nr)
|
|||
static atomic_int dropped;
|
||||
static atomic_int droppedSecurity;
|
||||
|
||||
auto lock = std::shared_lock{logd_socket_lock};
|
||||
if (logd_socket <= 0) {
|
||||
lock.unlock();
|
||||
OpenSocket();
|
||||
lock.lock();
|
||||
}
|
||||
GetSocket();
|
||||
|
||||
if (logd_socket <= 0) {
|
||||
return -EBADF;
|
||||
|
@ -183,10 +173,7 @@ int LogdWrite(log_id_t logId, struct timespec* ts, struct iovec* vec, size_t nr)
|
|||
// the connection, so we reset it and try again.
|
||||
ret = TEMP_FAILURE_RETRY(writev(logd_socket, newVec, i));
|
||||
if (ret < 0 && errno != EAGAIN) {
|
||||
int old_socket = logd_socket;
|
||||
lock.unlock();
|
||||
ResetSocket(old_socket);
|
||||
lock.lock();
|
||||
LogdConnect();
|
||||
|
||||
ret = TEMP_FAILURE_RETRY(writev(logd_socket, newVec, i));
|
||||
}
|
||||
|
|
|
@ -23,30 +23,36 @@
|
|||
#include <sys/types.h>
|
||||
#include <time.h>
|
||||
|
||||
#include <shared_mutex>
|
||||
|
||||
#include <log/log_properties.h>
|
||||
#include <private/android_logger.h>
|
||||
|
||||
#include "logger.h"
|
||||
#include "rwlock.h"
|
||||
#include "uio.h"
|
||||
|
||||
static int pmsg_fd;
|
||||
static RwLock pmsg_fd_lock;
|
||||
static atomic_int pmsg_fd;
|
||||
|
||||
static void PmsgOpen() {
|
||||
auto lock = std::unique_lock{pmsg_fd_lock};
|
||||
if (pmsg_fd > 0) {
|
||||
// Someone raced us and opened the socket already.
|
||||
// pmsg_fd should only beopened once. If we see that pmsg_fd is uninitialized, we open "/dev/pmsg0"
|
||||
// then attempt to compare/exchange it into pmsg_fd. If the compare/exchange was successful, then
|
||||
// that will be the fd used for the duration of the program, otherwise a different thread has
|
||||
// already opened and written the fd to the atomic, so close the new fd and return.
|
||||
static void GetPmsgFd() {
|
||||
if (pmsg_fd != 0) {
|
||||
return;
|
||||
}
|
||||
|
||||
pmsg_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY | O_CLOEXEC));
|
||||
int new_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY | O_CLOEXEC));
|
||||
if (new_fd <= 0) {
|
||||
return;
|
||||
}
|
||||
|
||||
int uninitialized_value = 0;
|
||||
if (!pmsg_fd.compare_exchange_strong(uninitialized_value, new_fd)) {
|
||||
close(new_fd);
|
||||
return;
|
||||
}
|
||||
}
|
||||
|
||||
void PmsgClose() {
|
||||
auto lock = std::unique_lock{pmsg_fd_lock};
|
||||
if (pmsg_fd > 0) {
|
||||
close(pmsg_fd);
|
||||
}
|
||||
|
@ -77,13 +83,7 @@ int PmsgWrite(log_id_t logId, struct timespec* ts, struct iovec* vec, size_t nr)
|
|||
}
|
||||
}
|
||||
|
||||
auto lock = std::shared_lock{pmsg_fd_lock};
|
||||
|
||||
if (pmsg_fd <= 0) {
|
||||
lock.unlock();
|
||||
PmsgOpen();
|
||||
lock.lock();
|
||||
}
|
||||
GetPmsgFd();
|
||||
|
||||
if (pmsg_fd <= 0) {
|
||||
return -EBADF;
|
||||
|
|
|
@ -1,39 +0,0 @@
|
|||
/*
|
||||
* Copyright (C) 2019 The Android Open Source Project
|
||||
*
|
||||
* Licensed under the Apache License, Version 2.0 (the "License");
|
||||
* you may not use this file except in compliance with the License.
|
||||
* You may obtain a copy of the License at
|
||||
*
|
||||
* http://www.apache.org/licenses/LICENSE-2.0
|
||||
*
|
||||
* Unless required by applicable law or agreed to in writing, software
|
||||
* distributed under the License is distributed on an "AS IS" BASIS,
|
||||
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
||||
* See the License for the specific language governing permissions and
|
||||
* limitations under the License.
|
||||
*/
|
||||
|
||||
#pragma once
|
||||
|
||||
#include <pthread.h>
|
||||
|
||||
// As of the end of Dec 2019, std::shared_mutex is *not* simply a pthread_rwlock, but rather a
|
||||
// combination of std::mutex and std::condition variable, which is obviously less efficient. This
|
||||
// immitates what std::shared_mutex should be doing and is compatible with std::shared_lock and
|
||||
// std::unique_lock.
|
||||
|
||||
class RwLock {
|
||||
public:
|
||||
RwLock() {}
|
||||
~RwLock() {}
|
||||
|
||||
void lock() { pthread_rwlock_wrlock(&rwlock_); }
|
||||
void unlock() { pthread_rwlock_unlock(&rwlock_); }
|
||||
|
||||
void lock_shared() { pthread_rwlock_rdlock(&rwlock_); }
|
||||
void unlock_shared() { pthread_rwlock_unlock(&rwlock_); }
|
||||
|
||||
private:
|
||||
pthread_rwlock_t rwlock_ = PTHREAD_RWLOCK_INITIALIZER;
|
||||
};
|
|
@ -63,8 +63,8 @@ cc_defaults {
|
|||
"log_system_test.cpp",
|
||||
"log_time_test.cpp",
|
||||
"log_wrap_test.cpp",
|
||||
"logd_writer_test.cpp",
|
||||
"logprint_test.cpp",
|
||||
"rwlock_test.cpp",
|
||||
],
|
||||
shared_libs: [
|
||||
"libcutils",
|
||||
|
@ -108,7 +108,6 @@ cc_test_host {
|
|||
"liblog_host_test.cpp",
|
||||
"liblog_default_tag.cpp",
|
||||
"liblog_global_state.cpp",
|
||||
"rwlock_test.cpp",
|
||||
],
|
||||
isolated: true,
|
||||
}
|
||||
|
|
95
liblog/tests/logd_writer_test.cpp
Normal file
95
liblog/tests/logd_writer_test.cpp
Normal file
|
@ -0,0 +1,95 @@
|
|||
/*
|
||||
* Copyright (C) 2020 The Android Open Source Project
|
||||
*
|
||||
* Licensed under the Apache License, Version 2.0 (the "License");
|
||||
* you may not use this file except in compliance with the License.
|
||||
* You may obtain a copy of the License at
|
||||
*
|
||||
* http://www.apache.org/licenses/LICENSE-2.0
|
||||
*
|
||||
* Unless required by applicable law or agreed to in writing, software
|
||||
* distributed under the License is distributed on an "AS IS" BASIS,
|
||||
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
||||
* See the License for the specific language governing permissions and
|
||||
* limitations under the License.
|
||||
*/
|
||||
|
||||
#include <sys/un.h>
|
||||
#include <unistd.h>
|
||||
|
||||
#include <android-base/file.h>
|
||||
#include <android-base/stringprintf.h>
|
||||
#include <android-base/unique_fd.h>
|
||||
#include <gtest/gtest.h>
|
||||
|
||||
using android::base::StringPrintf;
|
||||
using android::base::unique_fd;
|
||||
|
||||
// logd_writer takes advantage of the fact that connect() can be called multiple times for a DGRAM
|
||||
// socket. This tests for that behavior.
|
||||
TEST(liblog, multi_connect_dgram_socket) {
|
||||
#ifdef __ANDROID__
|
||||
auto temp_dir = TemporaryDir();
|
||||
auto socket_path = StringPrintf("%s/test_socket", temp_dir.path);
|
||||
|
||||
unique_fd server_socket;
|
||||
|
||||
auto open_server_socket = [&] {
|
||||
server_socket.reset(TEMP_FAILURE_RETRY(socket(AF_UNIX, SOCK_DGRAM | SOCK_CLOEXEC, 0)));
|
||||
ASSERT_TRUE(server_socket.ok());
|
||||
|
||||
sockaddr_un server_sockaddr = {};
|
||||
server_sockaddr.sun_family = AF_UNIX;
|
||||
strlcpy(server_sockaddr.sun_path, socket_path.c_str(), sizeof(server_sockaddr.sun_path));
|
||||
ASSERT_EQ(0,
|
||||
TEMP_FAILURE_RETRY(bind(server_socket, reinterpret_cast<sockaddr*>(&server_sockaddr),
|
||||
sizeof(server_sockaddr))));
|
||||
};
|
||||
|
||||
// Open the server socket.
|
||||
open_server_socket();
|
||||
|
||||
// Open the client socket.
|
||||
auto client_socket =
|
||||
unique_fd{TEMP_FAILURE_RETRY(socket(AF_UNIX, SOCK_DGRAM | SOCK_NONBLOCK | SOCK_CLOEXEC, 0))};
|
||||
ASSERT_TRUE(client_socket.ok());
|
||||
sockaddr_un client_sockaddr = {};
|
||||
client_sockaddr.sun_family = AF_UNIX;
|
||||
strlcpy(client_sockaddr.sun_path, socket_path.c_str(), sizeof(client_sockaddr.sun_path));
|
||||
ASSERT_EQ(0,
|
||||
TEMP_FAILURE_RETRY(connect(client_socket, reinterpret_cast<sockaddr*>(&client_sockaddr),
|
||||
sizeof(client_sockaddr))));
|
||||
|
||||
// Ensure that communication works.
|
||||
constexpr static char kSmoke[] = "smoke test";
|
||||
ssize_t smoke_len = sizeof(kSmoke);
|
||||
ASSERT_EQ(smoke_len, TEMP_FAILURE_RETRY(write(client_socket, kSmoke, sizeof(kSmoke))));
|
||||
char read_buf[512];
|
||||
ASSERT_EQ(smoke_len, TEMP_FAILURE_RETRY(read(server_socket, read_buf, sizeof(read_buf))));
|
||||
ASSERT_STREQ(kSmoke, read_buf);
|
||||
|
||||
// Close the server socket.
|
||||
server_socket.reset();
|
||||
ASSERT_EQ(0, unlink(socket_path.c_str())) << strerror(errno);
|
||||
|
||||
// Ensure that write() from the client returns an error since the server is closed.
|
||||
ASSERT_EQ(-1, TEMP_FAILURE_RETRY(write(client_socket, kSmoke, sizeof(kSmoke))));
|
||||
ASSERT_EQ(errno, ECONNREFUSED) << strerror(errno);
|
||||
|
||||
// Open the server socket again.
|
||||
open_server_socket();
|
||||
|
||||
// Reconnect the same client socket.
|
||||
ASSERT_EQ(0,
|
||||
TEMP_FAILURE_RETRY(connect(client_socket, reinterpret_cast<sockaddr*>(&client_sockaddr),
|
||||
sizeof(client_sockaddr))))
|
||||
<< strerror(errno);
|
||||
|
||||
// Ensure that communication works.
|
||||
ASSERT_EQ(smoke_len, TEMP_FAILURE_RETRY(write(client_socket, kSmoke, sizeof(kSmoke))));
|
||||
ASSERT_EQ(smoke_len, TEMP_FAILURE_RETRY(read(server_socket, read_buf, sizeof(read_buf))));
|
||||
ASSERT_STREQ(kSmoke, read_buf);
|
||||
#else
|
||||
GTEST_LOG_(INFO) << "This test does nothing.\n";
|
||||
#endif
|
||||
}
|
|
@ -1,91 +0,0 @@
|
|||
/*
|
||||
* Copyright (C) 2019 The Android Open Source Project
|
||||
*
|
||||
* Licensed under the Apache License, Version 2.0 (the "License");
|
||||
* you may not use this file except in compliance with the License.
|
||||
* You may obtain a copy of the License at
|
||||
*
|
||||
* http://www.apache.org/licenses/LICENSE-2.0
|
||||
*
|
||||
* Unless required by applicable law or agreed to in writing, software
|
||||
* distributed under the License is distributed on an "AS IS" BASIS,
|
||||
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
||||
* See the License for the specific language governing permissions and
|
||||
* limitations under the License.
|
||||
*/
|
||||
|
||||
#include "../rwlock.h"
|
||||
|
||||
#include <chrono>
|
||||
#include <shared_mutex>
|
||||
#include <thread>
|
||||
|
||||
#include <gtest/gtest.h>
|
||||
|
||||
using namespace std::literals;
|
||||
|
||||
TEST(rwlock, reader_then_reader_lock) {
|
||||
RwLock lock;
|
||||
|
||||
bool thread_ran = false;
|
||||
auto read_guard = std::shared_lock{lock};
|
||||
|
||||
auto reader_thread = std::thread([&] {
|
||||
auto read_guard = std::shared_lock{lock};
|
||||
thread_ran = true;
|
||||
});
|
||||
|
||||
auto end_time = std::chrono::steady_clock::now() + 1s;
|
||||
|
||||
while (std::chrono::steady_clock::now() < end_time) {
|
||||
if (thread_ran) {
|
||||
break;
|
||||
}
|
||||
}
|
||||
|
||||
EXPECT_EQ(true, thread_ran);
|
||||
|
||||
// Unlock the lock in case something went wrong, to ensure that we can still join() the thread.
|
||||
read_guard.unlock();
|
||||
reader_thread.join();
|
||||
}
|
||||
|
||||
template <template <typename> typename L1, template <typename> typename L2>
|
||||
void TestBlockingLocks() {
|
||||
RwLock lock;
|
||||
|
||||
bool thread_ran = false;
|
||||
auto read_guard = L1{lock};
|
||||
|
||||
auto reader_thread = std::thread([&] {
|
||||
auto read_guard = L2{lock};
|
||||
thread_ran = true;
|
||||
});
|
||||
|
||||
auto end_time = std::chrono::steady_clock::now() + 1s;
|
||||
|
||||
while (std::chrono::steady_clock::now() < end_time) {
|
||||
if (thread_ran) {
|
||||
break;
|
||||
}
|
||||
}
|
||||
|
||||
EXPECT_EQ(false, thread_ran);
|
||||
|
||||
read_guard.unlock();
|
||||
reader_thread.join();
|
||||
|
||||
EXPECT_EQ(true, thread_ran);
|
||||
}
|
||||
|
||||
TEST(rwlock, reader_then_writer_lock) {
|
||||
TestBlockingLocks<std::shared_lock, std::unique_lock>();
|
||||
}
|
||||
|
||||
TEST(rwlock, writer_then_reader_lock) {
|
||||
TestBlockingLocks<std::unique_lock, std::shared_lock>();
|
||||
}
|
||||
|
||||
TEST(rwlock, writer_then_writer_lock) {
|
||||
TestBlockingLocks<std::unique_lock, std::unique_lock>();
|
||||
}
|
Loading…
Reference in a new issue