Mark Salyzyn | 819c58a | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 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> |
Elliott Hughes | 5d9fe77 | 2014-02-05 17:50:35 -0800 | [diff] [blame] | 18 | #include <inttypes.h> |
Mark Salyzyn | cef098e | 2014-01-09 09:02:55 -0800 | [diff] [blame] | 19 | #include <signal.h> |
Mark Salyzyn | 819c58a | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 20 | #include <gtest/gtest.h> |
| 21 | #include <log/log.h> |
| 22 | #include <log/logger.h> |
| 23 | #include <log/log_read.h> |
| 24 | |
Mark Salyzyn | cef098e | 2014-01-09 09:02:55 -0800 | [diff] [blame] | 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 | |
Mark Salyzyn | 819c58a | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 40 | TEST(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 | |
| 55 | TEST(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 | |
| 70 | TEST(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 | |
| 87 | static void* ConcurrentPrintFn(void *arg) { |
| 88 | int ret = __android_log_buf_print(LOG_ID_MAIN, ANDROID_LOG_INFO, |
Elliott Hughes | 5d9fe77 | 2014-02-05 17:50:35 -0800 | [diff] [blame] | 89 | "TEST__android_log_print", "Concurrent %" PRIuPTR, |
| 90 | reinterpret_cast<uintptr_t>(arg)); |
Mark Salyzyn | 819c58a | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 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 | |
| 98 | TEST(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)); |
Elliott Hughes | 5d9fe77 | 2014-02-05 17:50:35 -0800 | [diff] [blame] | 110 | int this_result = reinterpret_cast<uintptr_t>(result); |
| 111 | if ((0 == ret) && (0 != this_result)) { |
| 112 | ret = this_result; |
Mark Salyzyn | 819c58a | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 113 | } |
| 114 | } |
| 115 | ASSERT_LT(0, ret); |
| 116 | } |
| 117 | |
| 118 | TEST(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 | |
Mark Salyzyn | cef098e | 2014-01-09 09:02:55 -0800 | [diff] [blame] | 163 | static unsigned signaled; |
| 164 | log_time signal_time; |
| 165 | |
| 166 | static 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)) { |
Mark Salyzyn | 7e2f83c | 2014-03-05 07:41:49 -0800 | [diff] [blame^] | 174 | signal_time = log_time(CLOCK_MONOTONIC); |
Mark Salyzyn | cef098e | 2014-01-09 09:02:55 -0800 | [diff] [blame] | 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 |
| 182 | static 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 | |
| 216 | TEST(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 | |
Mark Salyzyn | 819c58a | 2013-11-22 12:39:43 -0800 | [diff] [blame] | 303 | TEST(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 | } |