From d45d36e011bf2a42bffac07424d3990022287f3c Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Thu, 12 Feb 2015 15:14:26 -0800 Subject: liblog: Instrument logging of logd write drops - If logger system is prostrated, send an event message with the liblog tag from the associated UID and PID with a count of dropped messages once logging is resumed. - Added to the README a description of the error return values. - Describe in the README the appropriate mitigations for dropped messages. - If the caller sees this message, then /proc/sys/net/unix/max_dgram_qlen is likely too small Change-Id: Iaf387b9e5e1b6aa93bebc7481f9e8353732e3229 --- liblog/Android.mk | 10 ++++++---- liblog/README | 27 +++++++++++++++++++++++++++ liblog/event.logtags | 36 ++++++++++++++++++++++++++++++++++++ liblog/logd_write.c | 28 +++++++++++++++++++++++++++- 4 files changed, 96 insertions(+), 5 deletions(-) create mode 100644 liblog/event.logtags (limited to 'liblog') diff --git a/liblog/Android.mk b/liblog/Android.mk index 5756c54..9353546 100644 --- a/liblog/Android.mk +++ b/liblog/Android.mk @@ -16,6 +16,8 @@ LOCAL_PATH := $(my-dir) include $(CLEAR_VARS) +liblog_cflags := $(shell sed -n 's/^\([0-9]*\)[ \t]*liblog[ \t].*/-DLIBLOG_LOG_TAG=\1/p' $(LOCAL_PATH)/event.logtags) + ifneq ($(TARGET_USES_LOGD),false) liblog_sources := logd_write.c else @@ -45,7 +47,7 @@ else uio.c endif -liblog_host_sources := $(liblog_sources) fake_log_device.c +liblog_host_sources := $(liblog_sources) fake_log_device.c event.logtags liblog_target_sources := $(liblog_sources) log_time.cpp log_is_loggable.c ifneq ($(TARGET_USES_LOGD),false) liblog_target_sources += log_read.c @@ -57,7 +59,7 @@ endif # ======================================================== LOCAL_MODULE := liblog LOCAL_SRC_FILES := $(liblog_host_sources) -LOCAL_CFLAGS := -DFAKE_LOG_DEVICE=1 -Werror +LOCAL_CFLAGS := -DFAKE_LOG_DEVICE=1 -Werror $(liblog_cflags) LOCAL_MULTILIB := both include $(BUILD_HOST_STATIC_LIBRARY) @@ -76,13 +78,13 @@ include $(BUILD_HOST_SHARED_LIBRARY) include $(CLEAR_VARS) LOCAL_MODULE := liblog LOCAL_SRC_FILES := $(liblog_target_sources) -LOCAL_CFLAGS := -Werror +LOCAL_CFLAGS := -Werror $(liblog_cflags) include $(BUILD_STATIC_LIBRARY) include $(CLEAR_VARS) LOCAL_MODULE := liblog LOCAL_WHOLE_STATIC_LIBRARIES := liblog -LOCAL_CFLAGS := -Werror +LOCAL_CFLAGS := -Werror $(liblog_cflags) include $(BUILD_SHARED_LIBRARY) include $(call first-makefiles-under,$(LOCAL_PATH)) diff --git a/liblog/README b/liblog/README index 461dfbe..f29ac04 100644 --- a/liblog/README +++ b/liblog/README @@ -131,6 +131,33 @@ DESCRIPTION when opening the sub-log. It is recommended to open the log ANDROID_LOG_RDONLY in these cases. +ERRORS + If messages fail, a negative error code will be returned to the caller. + + The -ENOTCONN return code indicates that the logger daemon is stopped. + + The -EBADF return code indicates that the log access point can not be + opened, or the log buffer id is out of range. + + For the -EAGAIN return code, this means that the logging message was + temporarily backed-up either because of Denial Of Service (DOS) logging + pressure from some chatty application or service in the Android system, + or if too small of a value is set in /proc/sys/net/unix/max_dgram_qlen. + To aid in diagnosing the occurence of this, a binary event from liblog + will be sent to the log daemon once a new message can get through + indicating how many messages were dropped as a result. Please take + action to resolve the structural problems at the source. + + It is generally not advised for the caller to retry the -EAGAIN return + code as this will only make the problem(s) worse and cause your + application to temporarily drop to the logger daemon priority, BATCH + scheduling policy and background task cgroup. If you require a group of + messages to be passed atomically, merge them into one message with + embedded newlines to the maximum length LOGGER_ENTRY_MAX_PAYLOAD. + + Other return codes from writing operation can be returned. Since the + library retries on EINTR, -EINTR should never be returned. + SEE ALSO syslogd(8) diff --git a/liblog/event.logtags b/liblog/event.logtags new file mode 100644 index 0000000..72ecab1 --- /dev/null +++ b/liblog/event.logtags @@ -0,0 +1,36 @@ +# The entries in this file map a sparse set of log tag numbers to tag names. +# This is installed on the device, in /system/etc, and parsed by logcat. +# +# Tag numbers are decimal integers, from 0 to 2^31. (Let's leave the +# negative values alone for now.) +# +# Tag names are one or more ASCII letters and numbers or underscores, i.e. +# "[A-Z][a-z][0-9]_". Do not include spaces or punctuation (the former +# impacts log readability, the latter makes regex searches more annoying). +# +# Tag numbers and names are separated by whitespace. Blank lines and lines +# starting with '#' are ignored. +# +# Optionally, after the tag names can be put a description for the value(s) +# of the tag. Description are in the format +# (|data type[|data unit]) +# Multiple values are separated by commas. +# +# The data type is a number from the following values: +# 1: int +# 2: long +# 3: string +# 4: list +# +# The data unit is a number taken from the following list: +# 1: Number of objects +# 2: Number of bytes +# 3: Number of milliseconds +# 4: Number of allocations +# 5: Id +# 6: Percent +# Default value for data of type int/long is 2 (bytes). +# +# TODO: generate ".java" and ".h" files with integer constants from this file. + +1005 liblog (dropped|1) diff --git a/liblog/logd_write.c b/liblog/logd_write.c index 0208c73..c8a6162 100644 --- a/liblog/logd_write.c +++ b/liblog/logd_write.c @@ -13,12 +13,14 @@ * See the License for the specific language governing permissions and * limitations under the License. */ +#include #include #include #if !defined(_WIN32) #include #endif #include +#include #include #include #include @@ -172,6 +174,7 @@ static int __write_to_log_daemon(log_id_t log_id, struct iovec *vec, size_t nr) size_t i, payload_size; static uid_t last_uid = AID_ROOT; /* logd *always* starts up as AID_ROOT */ static pid_t last_pid = (pid_t) -1; + static atomic_int_fast32_t dropped; if (last_uid == AID_ROOT) { /* have we called to get the UID yet? */ last_uid = getuid(); @@ -206,7 +209,6 @@ static int __write_to_log_daemon(log_id_t log_id, struct iovec *vec, size_t nr) pmsg_header.uid = last_uid; pmsg_header.pid = last_pid; - header.id = log_id; header.tid = gettid(); header.realtime.tv_sec = ts.tv_sec; header.realtime.tv_nsec = ts.tv_nsec; @@ -216,6 +218,28 @@ static int __write_to_log_daemon(log_id_t log_id, struct iovec *vec, size_t nr) newVec[1].iov_base = (unsigned char *) &header; newVec[1].iov_len = sizeof(header); + if (logd_fd > 0) { + int32_t snapshot = atomic_exchange_explicit(&dropped, 0, memory_order_relaxed); + if (snapshot) { + android_log_event_int_t buffer; + + header.id = LOG_ID_EVENTS; + buffer.header.tag = htole32(LIBLOG_LOG_TAG); + buffer.payload.type = EVENT_TYPE_INT; + buffer.payload.data = htole32(snapshot); + + newVec[2].iov_base = &buffer; + newVec[2].iov_len = sizeof(buffer); + + ret = TEMP_FAILURE_RETRY(writev(logd_fd, newVec + 1, 2)); + if (ret != (ssize_t)(sizeof(header) + sizeof(buffer))) { + atomic_fetch_add_explicit(&dropped, snapshot, memory_order_relaxed); + } + } + } + + header.id = log_id; + for (payload_size = 0, i = header_length; i < nr + header_length; i++) { newVec[i].iov_base = vec[i - header_length].iov_base; payload_size += newVec[i].iov_len = vec[i - header_length].iov_len; @@ -281,6 +305,8 @@ static int __write_to_log_daemon(log_id_t log_id, struct iovec *vec, size_t nr) if (ret > (ssize_t)sizeof(header)) { ret -= sizeof(header); + } else if (ret == -EAGAIN) { + atomic_fetch_add_explicit(&dropped, 1, memory_order_relaxed); } #endif -- cgit v1.1