liblog_test.cpp revision 5d9fe779c8ec2705865a23061834ad8cdbee5b82
1/* 2 * Copyright (C) 2013-2014 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License. 15 */ 16 17#include <fcntl.h> 18#include <inttypes.h> 19#include <signal.h> 20#include <gtest/gtest.h> 21#include <log/log.h> 22#include <log/logger.h> 23#include <log/log_read.h> 24 25// enhanced version of LOG_FAILURE_RETRY to add support for EAGAIN and 26// non-syscall libs. Since we are only using this in the emergency of 27// a signal to stuff a terminating code into the logs, we will spin rather 28// than try a usleep. 29#define LOG_FAILURE_RETRY(exp) ({ \ 30 typeof (exp) _rc; \ 31 do { \ 32 _rc = (exp); \ 33 } while (((_rc == -1) \ 34 && ((errno == EINTR) \ 35 || (errno == EAGAIN))) \ 36 || (_rc == -EINTR) \ 37 || (_rc == -EAGAIN)); \ 38 _rc; }) 39 40TEST(liblog, __android_log_buf_print) { 41 ASSERT_LT(0, __android_log_buf_print(LOG_ID_RADIO, ANDROID_LOG_INFO, 42 "TEST__android_log_buf_print", 43 "radio")); 44 usleep(1000); 45 ASSERT_LT(0, __android_log_buf_print(LOG_ID_SYSTEM, ANDROID_LOG_INFO, 46 "TEST__android_log_buf_print", 47 "system")); 48 usleep(1000); 49 ASSERT_LT(0, __android_log_buf_print(LOG_ID_MAIN, ANDROID_LOG_INFO, 50 "TEST__android_log_buf_print", 51 "main")); 52 usleep(1000); 53} 54 55TEST(liblog, __android_log_buf_write) { 56 ASSERT_LT(0, __android_log_buf_write(LOG_ID_RADIO, ANDROID_LOG_INFO, 57 "TEST__android_log_buf_write", 58 "radio")); 59 usleep(1000); 60 ASSERT_LT(0, __android_log_buf_write(LOG_ID_SYSTEM, ANDROID_LOG_INFO, 61 "TEST__android_log_buf_write", 62 "system")); 63 usleep(1000); 64 ASSERT_LT(0, __android_log_buf_write(LOG_ID_MAIN, ANDROID_LOG_INFO, 65 "TEST__android_log_buf_write", 66 "main")); 67 usleep(1000); 68} 69 70TEST(liblog, __android_log_btwrite) { 71 int intBuf = 0xDEADBEEF; 72 ASSERT_LT(0, __android_log_btwrite(0, 73 EVENT_TYPE_INT, 74 &intBuf, sizeof(intBuf))); 75 long long longBuf = 0xDEADBEEFA55A5AA5; 76 ASSERT_LT(0, __android_log_btwrite(0, 77 EVENT_TYPE_LONG, 78 &longBuf, sizeof(longBuf))); 79 usleep(1000); 80 char Buf[] = "\20\0\0\0DeAdBeEfA55a5aA5"; 81 ASSERT_LT(0, __android_log_btwrite(0, 82 EVENT_TYPE_STRING, 83 Buf, sizeof(Buf) - 1)); 84 usleep(1000); 85} 86 87static void* ConcurrentPrintFn(void *arg) { 88 int ret = __android_log_buf_print(LOG_ID_MAIN, ANDROID_LOG_INFO, 89 "TEST__android_log_print", "Concurrent %" PRIuPTR, 90 reinterpret_cast<uintptr_t>(arg)); 91 return reinterpret_cast<void*>(ret); 92} 93 94#define NUM_CONCURRENT 64 95#define _concurrent_name(a,n) a##__concurrent##n 96#define concurrent_name(a,n) _concurrent_name(a,n) 97 98TEST(liblog, concurrent_name(__android_log_buf_print, NUM_CONCURRENT)) { 99 pthread_t t[NUM_CONCURRENT]; 100 int i; 101 for (i=0; i < NUM_CONCURRENT; i++) { 102 ASSERT_EQ(0, pthread_create(&t[i], NULL, 103 ConcurrentPrintFn, 104 reinterpret_cast<void *>(i))); 105 } 106 int ret = 0; 107 for (i=0; i < NUM_CONCURRENT; i++) { 108 void* result; 109 ASSERT_EQ(0, pthread_join(t[i], &result)); 110 int this_result = reinterpret_cast<uintptr_t>(result); 111 if ((0 == ret) && (0 != this_result)) { 112 ret = this_result; 113 } 114 } 115 ASSERT_LT(0, ret); 116} 117 118TEST(liblog, __android_log_btwrite__android_logger_list_read) { 119 struct logger_list *logger_list; 120 121 pid_t pid = getpid(); 122 123 ASSERT_EQ(0, NULL == (logger_list = android_logger_list_open( 124 LOG_ID_EVENTS, O_RDONLY | O_NDELAY, 1000, pid))); 125 126 log_time ts(CLOCK_MONOTONIC); 127 128 ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); 129 usleep(1000000); 130 131 int count = 0; 132 133 for (;;) { 134 log_msg log_msg; 135 if (android_logger_list_read(logger_list, &log_msg) <= 0) { 136 break; 137 } 138 139 ASSERT_EQ(log_msg.entry.pid, pid); 140 141 if ((log_msg.entry.len != (4 + 1 + 8)) 142 || (log_msg.id() != LOG_ID_EVENTS)) { 143 continue; 144 } 145 146 char *eventData = log_msg.msg(); 147 148 if (eventData[4] != EVENT_TYPE_LONG) { 149 continue; 150 } 151 152 log_time tx(eventData + 4 + 1); 153 if (ts == tx) { 154 ++count; 155 } 156 } 157 158 ASSERT_EQ(1, count); 159 160 android_logger_list_close(logger_list); 161} 162 163static unsigned signaled; 164log_time signal_time; 165 166static void caught_blocking(int signum) 167{ 168 unsigned long long v = 0xDEADBEEFA55A0000ULL; 169 170 v += getpid() & 0xFFFF; 171 172 ++signaled; 173 if ((signal_time.tv_sec == 0) && (signal_time.tv_nsec == 0)) { 174 clock_gettime(CLOCK_MONOTONIC, &signal_time); 175 signal_time.tv_sec += 2; 176 } 177 178 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); 179} 180 181// Fill in current process user and system time in 10ms increments 182static void get_ticks(unsigned long long *uticks, unsigned long long *sticks) 183{ 184 *uticks = *sticks = 0; 185 186 pid_t pid = getpid(); 187 188 char buffer[512]; 189 snprintf(buffer, sizeof(buffer), "/proc/%u/stat", pid); 190 191 FILE *fp = fopen(buffer, "r"); 192 if (!fp) { 193 return; 194 } 195 196 char *cp = fgets(buffer, sizeof(buffer), fp); 197 fclose(fp); 198 if (!cp) { 199 return; 200 } 201 202 pid_t d; 203 char s[sizeof(buffer)]; 204 char c; 205 long long ll; 206 unsigned long long ull; 207 208 if (15 != sscanf(buffer, 209 "%d %s %c %lld %lld %lld %lld %lld %llu %llu %llu %llu %llu %llu %llu ", 210 &d, s, &c, &ll, &ll, &ll, &ll, &ll, &ull, &ull, &ull, &ull, &ull, 211 uticks, sticks)) { 212 *uticks = *sticks = 0; 213 } 214} 215 216TEST(liblog, android_logger_list_read__cpu) { 217 struct logger_list *logger_list; 218 unsigned long long v = 0xDEADBEEFA55A0000ULL; 219 220 pid_t pid = getpid(); 221 222 v += pid & 0xFFFF; 223 224 ASSERT_EQ(0, NULL == (logger_list = android_logger_list_open( 225 LOG_ID_EVENTS, O_RDONLY, 1000, pid))); 226 227 int count = 0; 228 229 int signals = 0; 230 231 unsigned long long uticks_start; 232 unsigned long long sticks_start; 233 get_ticks(&uticks_start, &sticks_start); 234 235 const unsigned alarm_time = 10; 236 237 memset(&signal_time, 0, sizeof(signal_time)); 238 239 signal(SIGALRM, caught_blocking); 240 alarm(alarm_time); 241 242 signaled = 0; 243 244 do { 245 log_msg log_msg; 246 if (android_logger_list_read(logger_list, &log_msg) <= 0) { 247 break; 248 } 249 250 alarm(alarm_time); 251 252 ++count; 253 254 ASSERT_EQ(log_msg.entry.pid, pid); 255 256 if ((log_msg.entry.len != (4 + 1 + 8)) 257 || (log_msg.id() != LOG_ID_EVENTS)) { 258 continue; 259 } 260 261 char *eventData = log_msg.msg(); 262 263 if (eventData[4] != EVENT_TYPE_LONG) { 264 continue; 265 } 266 267 unsigned long long l = eventData[4 + 1 + 0] & 0xFF; 268 l |= (unsigned long long) (eventData[4 + 1 + 1] & 0xFF) << 8; 269 l |= (unsigned long long) (eventData[4 + 1 + 2] & 0xFF) << 16; 270 l |= (unsigned long long) (eventData[4 + 1 + 3] & 0xFF) << 24; 271 l |= (unsigned long long) (eventData[4 + 1 + 4] & 0xFF) << 32; 272 l |= (unsigned long long) (eventData[4 + 1 + 5] & 0xFF) << 40; 273 l |= (unsigned long long) (eventData[4 + 1 + 6] & 0xFF) << 48; 274 l |= (unsigned long long) (eventData[4 + 1 + 7] & 0xFF) << 56; 275 276 if (l == v) { 277 ++signals; 278 break; 279 } 280 } while (!signaled || ({log_time t(CLOCK_MONOTONIC); t < signal_time;})); 281 alarm(0); 282 signal(SIGALRM, SIG_DFL); 283 284 ASSERT_LT(1, count); 285 286 ASSERT_EQ(1, signals); 287 288 android_logger_list_close(logger_list); 289 290 unsigned long long uticks_end; 291 unsigned long long sticks_end; 292 get_ticks(&uticks_end, &sticks_end); 293 294 // Less than 1% in either user or system time, or both 295 const unsigned long long one_percent_ticks = alarm_time; 296 unsigned long long user_ticks = uticks_end - uticks_start; 297 unsigned long long system_ticks = sticks_end - sticks_start; 298 ASSERT_GT(one_percent_ticks, user_ticks); 299 ASSERT_GT(one_percent_ticks, system_ticks); 300 ASSERT_GT(one_percent_ticks, user_ticks + system_ticks); 301} 302 303TEST(liblog, android_logger_get_) { 304 struct logger_list * logger_list = android_logger_list_alloc(O_WRONLY, 0, 0); 305 306 for(int i = LOG_ID_MIN; i < LOG_ID_MAX; ++i) { 307 log_id_t id = static_cast<log_id_t>(i); 308 const char *name = android_log_id_to_name(id); 309 if (id != android_name_to_log_id(name)) { 310 continue; 311 } 312 struct logger * logger; 313 ASSERT_EQ(0, NULL == (logger = android_logger_open(logger_list, id))); 314 ASSERT_EQ(id, android_logger_get_id(logger)); 315 ASSERT_LT(0, android_logger_get_log_size(logger)); 316 ASSERT_LT(0, android_logger_get_log_readable_size(logger)); 317 ASSERT_LT(0, android_logger_get_log_version(logger)); 318 } 319 320 android_logger_list_close(logger_list); 321} 322