• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1 /*
2 **
3 ** Copyright 2006-2014, The Android Open Source Project
4 **
5 ** Licensed under the Apache License, Version 2.0 (the "License");
6 ** you may not use this file except in compliance with the License.
7 ** You may obtain a copy of the License at
8 **
9 **     http://www.apache.org/licenses/LICENSE-2.0
10 **
11 ** Unless required by applicable law or agreed to in writing, software
12 ** distributed under the License is distributed on an "AS IS" BASIS,
13 ** WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14 ** See the License for the specific language governing permissions and
15 ** limitations under the License.
16 */
17 
18 #define _GNU_SOURCE /* for asprintf */
19 #ifndef __MINGW32__
20 #define HAVE_STRSEP
21 #endif
22 
23 #include <assert.h>
24 #include <ctype.h>
25 #include <errno.h>
26 #include <inttypes.h>
27 #ifndef __MINGW32__
28 #include <pwd.h>
29 #endif
30 #include <stdbool.h>
31 #include <stdint.h>
32 #include <stdio.h>
33 #include <stdlib.h>
34 #include <string.h>
35 #include <sys/param.h>
36 #include <sys/types.h>
37 
38 #include <cutils/list.h>
39 #include <log/log.h>
40 #include <log/logprint.h>
41 
42 #include "log_portability.h"
43 
44 #define MS_PER_NSEC 1000000
45 #define US_PER_NSEC 1000
46 
47 #ifndef MIN
48 #define MIN(a, b) (((a) < (b)) ? (a) : (b))
49 #endif
50 
51 typedef struct FilterInfo_t {
52   char* mTag;
53   android_LogPriority mPri;
54   struct FilterInfo_t* p_next;
55 } FilterInfo;
56 
57 struct AndroidLogFormat_t {
58   android_LogPriority global_pri;
59   FilterInfo* filters;
60   AndroidLogPrintFormat format;
61   bool colored_output;
62   bool usec_time_output;
63   bool nsec_time_output;
64   bool printable_output;
65   bool year_output;
66   bool zone_output;
67   bool epoch_output;
68   bool monotonic_output;
69   bool uid_output;
70   bool descriptive_output;
71 };
72 
73 /*
74  * API issues prevent us from exposing "descriptive" in AndroidLogFormat_t
75  * during android_log_processBinaryLogBuffer(), so we break layering.
76  */
77 static bool descriptive_output = false;
78 
79 /*
80  *  gnome-terminal color tags
81  *    See http://misc.flogisoft.com/bash/tip_colors_and_formatting
82  *    for ideas on how to set the forground color of the text for xterm.
83  *    The color manipulation character stream is defined as:
84  *      ESC [ 3 8 ; 5 ; <color#> m
85  */
86 #define ANDROID_COLOR_BLUE 75
87 #define ANDROID_COLOR_DEFAULT 231
88 #define ANDROID_COLOR_GREEN 40
89 #define ANDROID_COLOR_ORANGE 166
90 #define ANDROID_COLOR_RED 196
91 #define ANDROID_COLOR_YELLOW 226
92 
filterinfo_new(const char * tag,android_LogPriority pri)93 static FilterInfo* filterinfo_new(const char* tag, android_LogPriority pri) {
94   FilterInfo* p_ret;
95 
96   p_ret = (FilterInfo*)calloc(1, sizeof(FilterInfo));
97   p_ret->mTag = strdup(tag);
98   p_ret->mPri = pri;
99 
100   return p_ret;
101 }
102 
103 /* balance to above, filterinfo_free left unimplemented */
104 
105 /*
106  * Note: also accepts 0-9 priorities
107  * returns ANDROID_LOG_UNKNOWN if the character is unrecognized
108  */
filterCharToPri(char c)109 static android_LogPriority filterCharToPri(char c) {
110   android_LogPriority pri;
111 
112   c = tolower(c);
113 
114   if (c >= '0' && c <= '9') {
115     if (c >= ('0' + ANDROID_LOG_SILENT)) {
116       pri = ANDROID_LOG_VERBOSE;
117     } else {
118       pri = (android_LogPriority)(c - '0');
119     }
120   } else if (c == 'v') {
121     pri = ANDROID_LOG_VERBOSE;
122   } else if (c == 'd') {
123     pri = ANDROID_LOG_DEBUG;
124   } else if (c == 'i') {
125     pri = ANDROID_LOG_INFO;
126   } else if (c == 'w') {
127     pri = ANDROID_LOG_WARN;
128   } else if (c == 'e') {
129     pri = ANDROID_LOG_ERROR;
130   } else if (c == 'f') {
131     pri = ANDROID_LOG_FATAL;
132   } else if (c == 's') {
133     pri = ANDROID_LOG_SILENT;
134   } else if (c == '*') {
135     pri = ANDROID_LOG_DEFAULT;
136   } else {
137     pri = ANDROID_LOG_UNKNOWN;
138   }
139 
140   return pri;
141 }
142 
filterPriToChar(android_LogPriority pri)143 static char filterPriToChar(android_LogPriority pri) {
144   switch (pri) {
145     /* clang-format off */
146     case ANDROID_LOG_VERBOSE: return 'V';
147     case ANDROID_LOG_DEBUG:   return 'D';
148     case ANDROID_LOG_INFO:    return 'I';
149     case ANDROID_LOG_WARN:    return 'W';
150     case ANDROID_LOG_ERROR:   return 'E';
151     case ANDROID_LOG_FATAL:   return 'F';
152     case ANDROID_LOG_SILENT:  return 'S';
153 
154     case ANDROID_LOG_DEFAULT:
155     case ANDROID_LOG_UNKNOWN:
156     default:                  return '?';
157     /* clang-format on */
158   }
159 }
160 
colorFromPri(android_LogPriority pri)161 static int colorFromPri(android_LogPriority pri) {
162   switch (pri) {
163     /* clang-format off */
164     case ANDROID_LOG_VERBOSE: return ANDROID_COLOR_DEFAULT;
165     case ANDROID_LOG_DEBUG:   return ANDROID_COLOR_BLUE;
166     case ANDROID_LOG_INFO:    return ANDROID_COLOR_GREEN;
167     case ANDROID_LOG_WARN:    return ANDROID_COLOR_ORANGE;
168     case ANDROID_LOG_ERROR:   return ANDROID_COLOR_RED;
169     case ANDROID_LOG_FATAL:   return ANDROID_COLOR_RED;
170     case ANDROID_LOG_SILENT:  return ANDROID_COLOR_DEFAULT;
171 
172     case ANDROID_LOG_DEFAULT:
173     case ANDROID_LOG_UNKNOWN:
174     default:                  return ANDROID_COLOR_DEFAULT;
175     /* clang-format on */
176   }
177 }
178 
filterPriForTag(AndroidLogFormat * p_format,const char * tag)179 static android_LogPriority filterPriForTag(AndroidLogFormat* p_format,
180                                            const char* tag) {
181   FilterInfo* p_curFilter;
182 
183   for (p_curFilter = p_format->filters; p_curFilter != NULL;
184        p_curFilter = p_curFilter->p_next) {
185     if (0 == strcmp(tag, p_curFilter->mTag)) {
186       if (p_curFilter->mPri == ANDROID_LOG_DEFAULT) {
187         return p_format->global_pri;
188       } else {
189         return p_curFilter->mPri;
190       }
191     }
192   }
193 
194   return p_format->global_pri;
195 }
196 
197 /**
198  * returns 1 if this log line should be printed based on its priority
199  * and tag, and 0 if it should not
200  */
android_log_shouldPrintLine(AndroidLogFormat * p_format,const char * tag,android_LogPriority pri)201 LIBLOG_ABI_PUBLIC int android_log_shouldPrintLine(AndroidLogFormat* p_format,
202                                                   const char* tag,
203                                                   android_LogPriority pri) {
204   return pri >= filterPriForTag(p_format, tag);
205 }
206 
android_log_format_new()207 LIBLOG_ABI_PUBLIC AndroidLogFormat* android_log_format_new() {
208   AndroidLogFormat* p_ret;
209 
210   p_ret = calloc(1, sizeof(AndroidLogFormat));
211 
212   p_ret->global_pri = ANDROID_LOG_VERBOSE;
213   p_ret->format = FORMAT_BRIEF;
214   p_ret->colored_output = false;
215   p_ret->usec_time_output = false;
216   p_ret->nsec_time_output = false;
217   p_ret->printable_output = false;
218   p_ret->year_output = false;
219   p_ret->zone_output = false;
220   p_ret->epoch_output = false;
221 #ifdef __ANDROID__
222   p_ret->monotonic_output = android_log_clockid() == CLOCK_MONOTONIC;
223 #else
224   p_ret->monotonic_output = false;
225 #endif
226   p_ret->uid_output = false;
227   p_ret->descriptive_output = false;
228   descriptive_output = false;
229 
230   return p_ret;
231 }
232 
233 static list_declare(convertHead);
234 
android_log_format_free(AndroidLogFormat * p_format)235 LIBLOG_ABI_PUBLIC void android_log_format_free(AndroidLogFormat* p_format) {
236   FilterInfo *p_info, *p_info_old;
237 
238   p_info = p_format->filters;
239 
240   while (p_info != NULL) {
241     p_info_old = p_info;
242     p_info = p_info->p_next;
243 
244     free(p_info_old);
245   }
246 
247   free(p_format);
248 
249   /* Free conversion resource, can always be reconstructed */
250   while (!list_empty(&convertHead)) {
251     struct listnode* node = list_head(&convertHead);
252     list_remove(node);
253     free(node);
254   }
255 }
256 
android_log_setPrintFormat(AndroidLogFormat * p_format,AndroidLogPrintFormat format)257 LIBLOG_ABI_PUBLIC int android_log_setPrintFormat(AndroidLogFormat* p_format,
258                                                  AndroidLogPrintFormat format) {
259   switch (format) {
260     case FORMAT_MODIFIER_COLOR:
261       p_format->colored_output = true;
262       return 0;
263     case FORMAT_MODIFIER_TIME_USEC:
264       p_format->usec_time_output = true;
265       return 0;
266     case FORMAT_MODIFIER_TIME_NSEC:
267       p_format->nsec_time_output = true;
268       return 0;
269     case FORMAT_MODIFIER_PRINTABLE:
270       p_format->printable_output = true;
271       return 0;
272     case FORMAT_MODIFIER_YEAR:
273       p_format->year_output = true;
274       return 0;
275     case FORMAT_MODIFIER_ZONE:
276       p_format->zone_output = !p_format->zone_output;
277       return 0;
278     case FORMAT_MODIFIER_EPOCH:
279       p_format->epoch_output = true;
280       return 0;
281     case FORMAT_MODIFIER_MONOTONIC:
282       p_format->monotonic_output = true;
283       return 0;
284     case FORMAT_MODIFIER_UID:
285       p_format->uid_output = true;
286       return 0;
287     case FORMAT_MODIFIER_DESCRIPT:
288       p_format->descriptive_output = true;
289       descriptive_output = true;
290       return 0;
291     default:
292       break;
293   }
294   p_format->format = format;
295   return 1;
296 }
297 
298 static const char tz[] = "TZ";
299 static const char utc[] = "UTC";
300 
301 /**
302  * Returns FORMAT_OFF on invalid string
303  */
304 LIBLOG_ABI_PUBLIC AndroidLogPrintFormat
android_log_formatFromString(const char * formatString)305 android_log_formatFromString(const char* formatString) {
306   static AndroidLogPrintFormat format;
307 
308   /* clang-format off */
309   if (!strcmp(formatString, "brief")) format = FORMAT_BRIEF;
310   else if (!strcmp(formatString, "process")) format = FORMAT_PROCESS;
311   else if (!strcmp(formatString, "tag")) format = FORMAT_TAG;
312   else if (!strcmp(formatString, "thread")) format = FORMAT_THREAD;
313   else if (!strcmp(formatString, "raw")) format = FORMAT_RAW;
314   else if (!strcmp(formatString, "time")) format = FORMAT_TIME;
315   else if (!strcmp(formatString, "threadtime")) format = FORMAT_THREADTIME;
316   else if (!strcmp(formatString, "long")) format = FORMAT_LONG;
317   else if (!strcmp(formatString, "color")) format = FORMAT_MODIFIER_COLOR;
318   else if (!strcmp(formatString, "colour")) format = FORMAT_MODIFIER_COLOR;
319   else if (!strcmp(formatString, "usec")) format = FORMAT_MODIFIER_TIME_USEC;
320   else if (!strcmp(formatString, "nsec")) format = FORMAT_MODIFIER_TIME_NSEC;
321   else if (!strcmp(formatString, "printable")) format = FORMAT_MODIFIER_PRINTABLE;
322   else if (!strcmp(formatString, "year")) format = FORMAT_MODIFIER_YEAR;
323   else if (!strcmp(formatString, "zone")) format = FORMAT_MODIFIER_ZONE;
324   else if (!strcmp(formatString, "epoch")) format = FORMAT_MODIFIER_EPOCH;
325   else if (!strcmp(formatString, "monotonic")) format = FORMAT_MODIFIER_MONOTONIC;
326   else if (!strcmp(formatString, "uid")) format = FORMAT_MODIFIER_UID;
327   else if (!strcmp(formatString, "descriptive")) format = FORMAT_MODIFIER_DESCRIPT;
328   /* clang-format on */
329 
330 #ifndef __MINGW32__
331   else {
332     extern char* tzname[2];
333     static const char gmt[] = "GMT";
334     char* cp = getenv(tz);
335     if (cp) {
336       cp = strdup(cp);
337     }
338     setenv(tz, formatString, 1);
339     /*
340      * Run tzset here to determine if the timezone is legitimate. If the
341      * zone is GMT, check if that is what was asked for, if not then
342      * did not match any on the system; report an error to caller.
343      */
344     tzset();
345     if (!tzname[0] ||
346         ((!strcmp(tzname[0], utc) || !strcmp(tzname[0], gmt)) /* error? */
347          && strcasecmp(formatString, utc) &&
348          strcasecmp(formatString, gmt))) { /* ok */
349       if (cp) {
350         setenv(tz, cp, 1);
351       } else {
352         unsetenv(tz);
353       }
354       tzset();
355       format = FORMAT_OFF;
356     } else {
357       format = FORMAT_MODIFIER_ZONE;
358     }
359     free(cp);
360   }
361 #endif
362 
363   return format;
364 }
365 
366 /**
367  * filterExpression: a single filter expression
368  * eg "AT:d"
369  *
370  * returns 0 on success and -1 on invalid expression
371  *
372  * Assumes single threaded execution
373  */
374 
android_log_addFilterRule(AndroidLogFormat * p_format,const char * filterExpression)375 LIBLOG_ABI_PUBLIC int android_log_addFilterRule(AndroidLogFormat* p_format,
376                                                 const char* filterExpression) {
377   size_t tagNameLength;
378   android_LogPriority pri = ANDROID_LOG_DEFAULT;
379 
380   tagNameLength = strcspn(filterExpression, ":");
381 
382   if (tagNameLength == 0) {
383     goto error;
384   }
385 
386   if (filterExpression[tagNameLength] == ':') {
387     pri = filterCharToPri(filterExpression[tagNameLength + 1]);
388 
389     if (pri == ANDROID_LOG_UNKNOWN) {
390       goto error;
391     }
392   }
393 
394   if (0 == strncmp("*", filterExpression, tagNameLength)) {
395     /*
396      * This filter expression refers to the global filter
397      * The default level for this is DEBUG if the priority
398      * is unspecified
399      */
400     if (pri == ANDROID_LOG_DEFAULT) {
401       pri = ANDROID_LOG_DEBUG;
402     }
403 
404     p_format->global_pri = pri;
405   } else {
406     /*
407      * for filter expressions that don't refer to the global
408      * filter, the default is verbose if the priority is unspecified
409      */
410     if (pri == ANDROID_LOG_DEFAULT) {
411       pri = ANDROID_LOG_VERBOSE;
412     }
413 
414     char* tagName;
415 
416 /*
417  * Presently HAVE_STRNDUP is never defined, so the second case is always taken
418  * Darwin doesn't have strndup, everything else does
419  */
420 #ifdef HAVE_STRNDUP
421     tagName = strndup(filterExpression, tagNameLength);
422 #else
423     /* a few extra bytes copied... */
424     tagName = strdup(filterExpression);
425     tagName[tagNameLength] = '\0';
426 #endif /*HAVE_STRNDUP*/
427 
428     FilterInfo* p_fi = filterinfo_new(tagName, pri);
429     free(tagName);
430 
431     p_fi->p_next = p_format->filters;
432     p_format->filters = p_fi;
433   }
434 
435   return 0;
436 error:
437   return -1;
438 }
439 
440 #ifndef HAVE_STRSEP
441 /* KISS replacement helper for below */
strsep(char ** stringp,const char * delim)442 static char* strsep(char** stringp, const char* delim) {
443   char* token;
444   char* ret = *stringp;
445 
446   if (!ret || !*ret) {
447     return NULL;
448   }
449   token = strpbrk(ret, delim);
450   if (token) {
451     *token = '\0';
452     ++token;
453   } else {
454     token = ret + strlen(ret);
455   }
456   *stringp = token;
457   return ret;
458 }
459 #endif
460 
461 /**
462  * filterString: a comma/whitespace-separated set of filter expressions
463  *
464  * eg "AT:d *:i"
465  *
466  * returns 0 on success and -1 on invalid expression
467  *
468  * Assumes single threaded execution
469  *
470  */
android_log_addFilterString(AndroidLogFormat * p_format,const char * filterString)471 LIBLOG_ABI_PUBLIC int android_log_addFilterString(AndroidLogFormat* p_format,
472                                                   const char* filterString) {
473   char* filterStringCopy = strdup(filterString);
474   char* p_cur = filterStringCopy;
475   char* p_ret;
476   int err;
477 
478   /* Yes, I'm using strsep */
479   while (NULL != (p_ret = strsep(&p_cur, " \t,"))) {
480     /* ignore whitespace-only entries */
481     if (p_ret[0] != '\0') {
482       err = android_log_addFilterRule(p_format, p_ret);
483 
484       if (err < 0) {
485         goto error;
486       }
487     }
488   }
489 
490   free(filterStringCopy);
491   return 0;
492 error:
493   free(filterStringCopy);
494   return -1;
495 }
496 
497 /**
498  * Splits a wire-format buffer into an AndroidLogEntry
499  * entry allocated by caller. Pointers will point directly into buf
500  *
501  * Returns 0 on success and -1 on invalid wire format (entry will be
502  * in unspecified state)
503  */
android_log_processLogBuffer(struct logger_entry * buf,AndroidLogEntry * entry)504 LIBLOG_ABI_PUBLIC int android_log_processLogBuffer(struct logger_entry* buf,
505                                                    AndroidLogEntry* entry) {
506   entry->message = NULL;
507   entry->messageLen = 0;
508 
509   entry->tv_sec = buf->sec;
510   entry->tv_nsec = buf->nsec;
511   entry->uid = -1;
512   entry->pid = buf->pid;
513   entry->tid = buf->tid;
514 
515   /*
516    * format: <priority:1><tag:N>\0<message:N>\0
517    *
518    * tag str
519    *   starts at buf->msg+1
520    * msg
521    *   starts at buf->msg+1+len(tag)+1
522    *
523    * The message may have been truncated by the kernel log driver.
524    * When that happens, we must null-terminate the message ourselves.
525    */
526   if (buf->len < 3) {
527     /*
528      * An well-formed entry must consist of at least a priority
529      * and two null characters
530      */
531     fprintf(stderr, "+++ LOG: entry too small\n");
532     return -1;
533   }
534 
535   int msgStart = -1;
536   int msgEnd = -1;
537 
538   int i;
539   char* msg = buf->msg;
540   struct logger_entry_v2* buf2 = (struct logger_entry_v2*)buf;
541   if (buf2->hdr_size) {
542     if ((buf2->hdr_size < sizeof(((struct log_msg*)NULL)->entry_v1)) ||
543         (buf2->hdr_size > sizeof(((struct log_msg*)NULL)->entry))) {
544       fprintf(stderr, "+++ LOG: entry illegal hdr_size\n");
545       return -1;
546     }
547     msg = ((char*)buf2) + buf2->hdr_size;
548     if (buf2->hdr_size >= sizeof(struct logger_entry_v4)) {
549       entry->uid = ((struct logger_entry_v4*)buf)->uid;
550     }
551   }
552   for (i = 1; i < buf->len; i++) {
553     if (msg[i] == '\0') {
554       if (msgStart == -1) {
555         msgStart = i + 1;
556       } else {
557         msgEnd = i;
558         break;
559       }
560     }
561   }
562 
563   if (msgStart == -1) {
564     /* +++ LOG: malformed log message, DYB */
565     for (i = 1; i < buf->len; i++) {
566       /* odd characters in tag? */
567       if ((msg[i] <= ' ') || (msg[i] == ':') || (msg[i] >= 0x7f)) {
568         msg[i] = '\0';
569         msgStart = i + 1;
570         break;
571       }
572     }
573     if (msgStart == -1) {
574       msgStart = buf->len - 1; /* All tag, no message, print truncates */
575     }
576   }
577   if (msgEnd == -1) {
578     /* incoming message not null-terminated; force it */
579     msgEnd = buf->len - 1; /* may result in msgEnd < msgStart */
580     msg[msgEnd] = '\0';
581   }
582 
583   entry->priority = msg[0];
584   entry->tag = msg + 1;
585   entry->tagLen = msgStart - 1;
586   entry->message = msg + msgStart;
587   entry->messageLen = (msgEnd < msgStart) ? 0 : (msgEnd - msgStart);
588 
589   return 0;
590 }
591 
592 /*
593  * Extract a 4-byte value from a byte stream.
594  */
get4LE(const uint8_t * src)595 static inline uint32_t get4LE(const uint8_t* src) {
596   return src[0] | (src[1] << 8) | (src[2] << 16) | (src[3] << 24);
597 }
598 
599 /*
600  * Extract an 8-byte value from a byte stream.
601  */
get8LE(const uint8_t * src)602 static inline uint64_t get8LE(const uint8_t* src) {
603   uint32_t low, high;
604 
605   low = src[0] | (src[1] << 8) | (src[2] << 16) | (src[3] << 24);
606   high = src[4] | (src[5] << 8) | (src[6] << 16) | (src[7] << 24);
607   return ((uint64_t)high << 32) | (uint64_t)low;
608 }
609 
findChar(const char ** cp,size_t * len,int c)610 static bool findChar(const char** cp, size_t* len, int c) {
611   while ((*len) && isspace(*(*cp))) {
612     ++(*cp);
613     --(*len);
614   }
615   if (c == INT_MAX) return *len;
616   if ((*len) && (*(*cp) == c)) {
617     ++(*cp);
618     --(*len);
619     return true;
620   }
621   return false;
622 }
623 
624 /*
625  * Recursively convert binary log data to printable form.
626  *
627  * This needs to be recursive because you can have lists of lists.
628  *
629  * If we run out of room, we stop processing immediately.  It's important
630  * for us to check for space on every output element to avoid producing
631  * garbled output.
632  *
633  * Returns 0 on success, 1 on buffer full, -1 on failure.
634  */
635 enum objectType {
636   TYPE_OBJECTS = '1',
637   TYPE_BYTES = '2',
638   TYPE_MILLISECONDS = '3',
639   TYPE_ALLOCATIONS = '4',
640   TYPE_ID = '5',
641   TYPE_PERCENT = '6',
642   TYPE_MONOTONIC = 's'
643 };
644 
android_log_printBinaryEvent(const unsigned char ** pEventData,size_t * pEventDataLen,char ** pOutBuf,size_t * pOutBufLen,const char ** fmtStr,size_t * fmtLen)645 static int android_log_printBinaryEvent(const unsigned char** pEventData,
646                                         size_t* pEventDataLen, char** pOutBuf,
647                                         size_t* pOutBufLen, const char** fmtStr,
648                                         size_t* fmtLen) {
649   const unsigned char* eventData = *pEventData;
650   size_t eventDataLen = *pEventDataLen;
651   char* outBuf = *pOutBuf;
652   char* outBufSave = outBuf;
653   size_t outBufLen = *pOutBufLen;
654   size_t outBufLenSave = outBufLen;
655   unsigned char type;
656   size_t outCount = 0;
657   int result = 0;
658   const char* cp;
659   size_t len;
660   int64_t lval;
661 
662   if (eventDataLen < 1) return -1;
663 
664   type = *eventData++;
665   eventDataLen--;
666 
667   cp = NULL;
668   len = 0;
669   if (fmtStr && *fmtStr && fmtLen && *fmtLen && **fmtStr) {
670     cp = *fmtStr;
671     len = *fmtLen;
672   }
673   /*
674    * event.logtag format specification:
675    *
676    * Optionally, after the tag names can be put a description for the value(s)
677    * of the tag. Description are in the format
678    *    (<name>|data type[|data unit])
679    * Multiple values are separated by commas.
680    *
681    * The data type is a number from the following values:
682    * 1: int
683    * 2: long
684    * 3: string
685    * 4: list
686    * 5: float
687    *
688    * The data unit is a number taken from the following list:
689    * 1: Number of objects
690    * 2: Number of bytes
691    * 3: Number of milliseconds
692    * 4: Number of allocations
693    * 5: Id
694    * 6: Percent
695    * s: Number of seconds (monotonic time)
696    * Default value for data of type int/long is 2 (bytes).
697    */
698   if (!cp || !findChar(&cp, &len, '(')) {
699     len = 0;
700   } else {
701     char* outBufLastSpace = NULL;
702 
703     findChar(&cp, &len, INT_MAX);
704     while (len && *cp && (*cp != '|') && (*cp != ')')) {
705       if (outBufLen <= 0) {
706         /* halt output */
707         goto no_room;
708       }
709       outBufLastSpace = isspace(*cp) ? outBuf : NULL;
710       *outBuf = *cp;
711       ++outBuf;
712       ++cp;
713       --outBufLen;
714       --len;
715     }
716     if (outBufLastSpace) {
717       outBufLen += outBuf - outBufLastSpace;
718       outBuf = outBufLastSpace;
719     }
720     if (outBufLen <= 0) {
721       /* halt output */
722       goto no_room;
723     }
724     if (outBufSave != outBuf) {
725       *outBuf = '=';
726       ++outBuf;
727       --outBufLen;
728     }
729 
730     if (findChar(&cp, &len, '|') && findChar(&cp, &len, INT_MAX)) {
731       static const unsigned char typeTable[] = {
732         EVENT_TYPE_INT, EVENT_TYPE_LONG, EVENT_TYPE_STRING, EVENT_TYPE_LIST,
733         EVENT_TYPE_FLOAT
734       };
735 
736       if ((*cp >= '1') &&
737           (*cp < (char)('1' + (sizeof(typeTable) / sizeof(typeTable[0])))) &&
738           (type != typeTable[(size_t)(*cp - '1')]))
739         len = 0;
740 
741       if (len) {
742         ++cp;
743         --len;
744       } else {
745         /* reset the format */
746         outBuf = outBufSave;
747         outBufLen = outBufLenSave;
748       }
749     }
750   }
751   outCount = 0;
752   lval = 0;
753   switch (type) {
754     case EVENT_TYPE_INT:
755       /* 32-bit signed int */
756       {
757         int32_t ival;
758 
759         if (eventDataLen < 4) return -1;
760         ival = get4LE(eventData);
761         eventData += 4;
762         eventDataLen -= 4;
763 
764         lval = ival;
765       }
766       goto pr_lval;
767     case EVENT_TYPE_LONG:
768       /* 64-bit signed long */
769       if (eventDataLen < 8) return -1;
770       lval = get8LE(eventData);
771       eventData += 8;
772       eventDataLen -= 8;
773     pr_lval:
774       outCount = snprintf(outBuf, outBufLen, "%" PRId64, lval);
775       if (outCount < outBufLen) {
776         outBuf += outCount;
777         outBufLen -= outCount;
778       } else {
779         /* halt output */
780         goto no_room;
781       }
782       break;
783     case EVENT_TYPE_FLOAT:
784       /* float */
785       {
786         uint32_t ival;
787         float fval;
788 
789         if (eventDataLen < 4) return -1;
790         ival = get4LE(eventData);
791         fval = *(float*)&ival;
792         eventData += 4;
793         eventDataLen -= 4;
794 
795         outCount = snprintf(outBuf, outBufLen, "%f", fval);
796         if (outCount < outBufLen) {
797           outBuf += outCount;
798           outBufLen -= outCount;
799         } else {
800           /* halt output */
801           goto no_room;
802         }
803       }
804       break;
805     case EVENT_TYPE_STRING:
806       /* UTF-8 chars, not NULL-terminated */
807       {
808         unsigned int strLen;
809 
810         if (eventDataLen < 4) return -1;
811         strLen = get4LE(eventData);
812         eventData += 4;
813         eventDataLen -= 4;
814 
815         if (eventDataLen < strLen) {
816           result = -1; /* mark truncated */
817           strLen = eventDataLen;
818         }
819 
820         if (cp && (strLen == 0)) {
821           /* reset the format if no content */
822           outBuf = outBufSave;
823           outBufLen = outBufLenSave;
824         }
825         if (strLen < outBufLen) {
826           memcpy(outBuf, eventData, strLen);
827           outBuf += strLen;
828           outBufLen -= strLen;
829         } else {
830           if (outBufLen > 0) {
831             /* copy what we can */
832             memcpy(outBuf, eventData, outBufLen);
833             outBuf += outBufLen;
834             outBufLen -= outBufLen;
835           }
836           if (!result) result = 1; /* if not truncated, return no room */
837         }
838         eventData += strLen;
839         eventDataLen -= strLen;
840         if (result != 0) goto bail;
841         break;
842       }
843     case EVENT_TYPE_LIST:
844       /* N items, all different types */
845       {
846         unsigned char count;
847         int i;
848 
849         if (eventDataLen < 1) return -1;
850 
851         count = *eventData++;
852         eventDataLen--;
853 
854         if (outBufLen <= 0) goto no_room;
855 
856         *outBuf++ = '[';
857         outBufLen--;
858 
859         for (i = 0; i < count; i++) {
860           result = android_log_printBinaryEvent(
861               &eventData, &eventDataLen, &outBuf, &outBufLen, fmtStr, fmtLen);
862           if (result != 0) goto bail;
863 
864           if (i < (count - 1)) {
865             if (outBufLen <= 0) goto no_room;
866             *outBuf++ = ',';
867             outBufLen--;
868           }
869         }
870 
871         if (outBufLen <= 0) goto no_room;
872 
873         *outBuf++ = ']';
874         outBufLen--;
875       }
876       break;
877     default:
878       fprintf(stderr, "Unknown binary event type %d\n", type);
879       return -1;
880   }
881   if (cp && len) {
882     if (findChar(&cp, &len, '|') && findChar(&cp, &len, INT_MAX)) {
883       switch (*cp) {
884         case TYPE_OBJECTS:
885           outCount = 0;
886           /* outCount = snprintf(outBuf, outBufLen, " objects"); */
887           break;
888         case TYPE_BYTES:
889           if ((lval != 0) && ((lval % 1024) == 0)) {
890             /* repaint with multiplier */
891             static const char suffixTable[] = { 'K', 'M', 'G', 'T' };
892             size_t idx = 0;
893             outBuf -= outCount;
894             outBufLen += outCount;
895             do {
896               lval /= 1024;
897               if ((lval % 1024) != 0) break;
898             } while (++idx <
899                      ((sizeof(suffixTable) / sizeof(suffixTable[0])) - 1));
900             outCount = snprintf(outBuf, outBufLen, "%" PRId64 "%cB", lval,
901                                 suffixTable[idx]);
902           } else {
903             outCount = snprintf(outBuf, outBufLen, "B");
904           }
905           break;
906         case TYPE_MILLISECONDS:
907           if (((lval <= -1000) || (1000 <= lval)) &&
908               (outBufLen || (outBuf[-1] == '0'))) {
909             /* repaint as (fractional) seconds, possibly saving space */
910             if (outBufLen) outBuf[0] = outBuf[-1];
911             outBuf[-1] = outBuf[-2];
912             outBuf[-2] = outBuf[-3];
913             outBuf[-3] = '.';
914             while ((outBufLen == 0) || (*outBuf == '0')) {
915               --outBuf;
916               ++outBufLen;
917             }
918             if (*outBuf != '.') {
919               ++outBuf;
920               --outBufLen;
921             }
922             outCount = snprintf(outBuf, outBufLen, "s");
923           } else {
924             outCount = snprintf(outBuf, outBufLen, "ms");
925           }
926           break;
927         case TYPE_MONOTONIC: {
928           static const uint64_t minute = 60;
929           static const uint64_t hour = 60 * minute;
930           static const uint64_t day = 24 * hour;
931 
932           /* Repaint as unsigned seconds, minutes, hours ... */
933           outBuf -= outCount;
934           outBufLen += outCount;
935           uint64_t val = lval;
936           if (val >= day) {
937             outCount = snprintf(outBuf, outBufLen, "%" PRIu64 "d ", val / day);
938             if (outCount >= outBufLen) break;
939             outBuf += outCount;
940             outBufLen -= outCount;
941             val = (val % day) + day;
942           }
943           if (val >= minute) {
944             if (val >= hour) {
945               outCount = snprintf(outBuf, outBufLen, "%" PRIu64 ":",
946                                   (val / hour) % (day / hour));
947               if (outCount >= outBufLen) break;
948               outBuf += outCount;
949               outBufLen -= outCount;
950             }
951             outCount =
952                 snprintf(outBuf, outBufLen,
953                          (val >= hour) ? "%02" PRIu64 ":" : "%" PRIu64 ":",
954                          (val / minute) % (hour / minute));
955             if (outCount >= outBufLen) break;
956             outBuf += outCount;
957             outBufLen -= outCount;
958           }
959           outCount = snprintf(outBuf, outBufLen,
960                               (val >= minute) ? "%02" PRIu64 : "%" PRIu64 "s",
961                               val % minute);
962         } break;
963         case TYPE_ALLOCATIONS:
964           outCount = 0;
965           /* outCount = snprintf(outBuf, outBufLen, " allocations"); */
966           break;
967         case TYPE_ID:
968           outCount = 0;
969           break;
970         case TYPE_PERCENT:
971           outCount = snprintf(outBuf, outBufLen, "%%");
972           break;
973         default: /* ? */
974           outCount = 0;
975           break;
976       }
977       ++cp;
978       --len;
979       if (outCount < outBufLen) {
980         outBuf += outCount;
981         outBufLen -= outCount;
982       } else if (outCount) {
983         /* halt output */
984         goto no_room;
985       }
986     }
987     if (!findChar(&cp, &len, ')')) len = 0;
988     if (!findChar(&cp, &len, ',')) len = 0;
989   }
990 
991 bail:
992   *pEventData = eventData;
993   *pEventDataLen = eventDataLen;
994   *pOutBuf = outBuf;
995   *pOutBufLen = outBufLen;
996   if (cp) {
997     *fmtStr = cp;
998     *fmtLen = len;
999   }
1000   return result;
1001 
1002 no_room:
1003   result = 1;
1004   goto bail;
1005 }
1006 
1007 /**
1008  * Convert a binary log entry to ASCII form.
1009  *
1010  * For convenience we mimic the processLogBuffer API.  There is no
1011  * pre-defined output length for the binary data, since we're free to format
1012  * it however we choose, which means we can't really use a fixed-size buffer
1013  * here.
1014  */
android_log_processBinaryLogBuffer(struct logger_entry * buf,AndroidLogEntry * entry,const EventTagMap * map __unused,char * messageBuf,int messageBufLen)1015 LIBLOG_ABI_PUBLIC int android_log_processBinaryLogBuffer(
1016     struct logger_entry* buf, AndroidLogEntry* entry,
1017     const EventTagMap* map __unused, /* only on !__ANDROID__ */
1018     char* messageBuf, int messageBufLen) {
1019   size_t inCount;
1020   uint32_t tagIndex;
1021   const unsigned char* eventData;
1022 
1023   entry->message = NULL;
1024   entry->messageLen = 0;
1025 
1026   entry->tv_sec = buf->sec;
1027   entry->tv_nsec = buf->nsec;
1028   entry->priority = ANDROID_LOG_INFO;
1029   entry->uid = -1;
1030   entry->pid = buf->pid;
1031   entry->tid = buf->tid;
1032 
1033   /*
1034    * Pull the tag out, fill in some additional details based on incoming
1035    * buffer version (v3 adds lid, v4 adds uid).
1036    */
1037   eventData = (const unsigned char*)buf->msg;
1038   struct logger_entry_v2* buf2 = (struct logger_entry_v2*)buf;
1039   if (buf2->hdr_size) {
1040     if ((buf2->hdr_size < sizeof(((struct log_msg*)NULL)->entry_v1)) ||
1041         (buf2->hdr_size > sizeof(((struct log_msg*)NULL)->entry))) {
1042       fprintf(stderr, "+++ LOG: entry illegal hdr_size\n");
1043       return -1;
1044     }
1045     eventData = ((unsigned char*)buf2) + buf2->hdr_size;
1046     if ((buf2->hdr_size >= sizeof(struct logger_entry_v3)) &&
1047         (((struct logger_entry_v3*)buf)->lid == LOG_ID_SECURITY)) {
1048       entry->priority = ANDROID_LOG_WARN;
1049     }
1050     if (buf2->hdr_size >= sizeof(struct logger_entry_v4)) {
1051       entry->uid = ((struct logger_entry_v4*)buf)->uid;
1052     }
1053   }
1054   inCount = buf->len;
1055   if (inCount < 4) return -1;
1056   tagIndex = get4LE(eventData);
1057   eventData += 4;
1058   inCount -= 4;
1059 
1060   entry->tagLen = 0;
1061   entry->tag = NULL;
1062 #ifdef __ANDROID__
1063   if (map != NULL) {
1064     entry->tag = android_lookupEventTag_len(map, &entry->tagLen, tagIndex);
1065   }
1066 #endif
1067 
1068   /*
1069    * If we don't have a map, or didn't find the tag number in the map,
1070    * stuff a generated tag value into the start of the output buffer and
1071    * shift the buffer pointers down.
1072    */
1073   if (entry->tag == NULL) {
1074     size_t tagLen;
1075 
1076     tagLen = snprintf(messageBuf, messageBufLen, "[%" PRIu32 "]", tagIndex);
1077     if (tagLen >= (size_t)messageBufLen) {
1078       tagLen = messageBufLen - 1;
1079     }
1080     entry->tag = messageBuf;
1081     entry->tagLen = tagLen;
1082     messageBuf += tagLen + 1;
1083     messageBufLen -= tagLen + 1;
1084   }
1085 
1086   /*
1087    * Format the event log data into the buffer.
1088    */
1089   const char* fmtStr = NULL;
1090   size_t fmtLen = 0;
1091 #ifdef __ANDROID__
1092   if (descriptive_output && map) {
1093     fmtStr = android_lookupEventFormat_len(map, &fmtLen, tagIndex);
1094   }
1095 #endif
1096 
1097   char* outBuf = messageBuf;
1098   size_t outRemaining = messageBufLen - 1; /* leave one for nul byte */
1099   int result = 0;
1100 
1101   if ((inCount > 0) || fmtLen) {
1102     result = android_log_printBinaryEvent(&eventData, &inCount, &outBuf,
1103                                           &outRemaining, &fmtStr, &fmtLen);
1104   }
1105   if ((result == 1) && fmtStr) {
1106     /* We overflowed :-(, let's repaint the line w/o format dressings */
1107     eventData = (const unsigned char*)buf->msg;
1108     if (buf2->hdr_size) {
1109       eventData = ((unsigned char*)buf2) + buf2->hdr_size;
1110     }
1111     eventData += 4;
1112     outBuf = messageBuf;
1113     outRemaining = messageBufLen - 1;
1114     result = android_log_printBinaryEvent(&eventData, &inCount, &outBuf,
1115                                           &outRemaining, NULL, NULL);
1116   }
1117   if (result < 0) {
1118     fprintf(stderr, "Binary log entry conversion failed\n");
1119   }
1120   if (result) {
1121     if (!outRemaining) {
1122       /* make space to leave an indicator */
1123       --outBuf;
1124       ++outRemaining;
1125     }
1126     *outBuf++ = (result < 0) ? '!' : '^'; /* Error or Truncation? */
1127     outRemaining--;
1128     /* pretend we ate all the data to prevent log stutter */
1129     inCount = 0;
1130     if (result > 0) result = 0;
1131   }
1132 
1133   /* eat the silly terminating '\n' */
1134   if (inCount == 1 && *eventData == '\n') {
1135     eventData++;
1136     inCount--;
1137   }
1138 
1139   if (inCount != 0) {
1140     fprintf(stderr, "Warning: leftover binary log data (%zu bytes)\n", inCount);
1141   }
1142 
1143   /*
1144    * Terminate the buffer.  The NUL byte does not count as part of
1145    * entry->messageLen.
1146    */
1147   *outBuf = '\0';
1148   entry->messageLen = outBuf - messageBuf;
1149   assert(entry->messageLen == (messageBufLen - 1) - outRemaining);
1150 
1151   entry->message = messageBuf;
1152 
1153   return result;
1154 }
1155 
1156 /*
1157  * One utf8 character at a time
1158  *
1159  * Returns the length of the utf8 character in the buffer,
1160  * or -1 if illegal or truncated
1161  *
1162  * Open coded from libutils/Unicode.cpp, borrowed from utf8_length(),
1163  * can not remove from here because of library circular dependencies.
1164  * Expect one-day utf8_character_length with the same signature could
1165  * _also_ be part of libutils/Unicode.cpp if its usefullness needs to
1166  * propagate globally.
1167  */
utf8_character_length(const char * src,size_t len)1168 LIBLOG_WEAK ssize_t utf8_character_length(const char* src, size_t len) {
1169   const char* cur = src;
1170   const char first_char = *cur++;
1171   static const uint32_t kUnicodeMaxCodepoint = 0x0010FFFF;
1172   int32_t mask, to_ignore_mask;
1173   size_t num_to_read;
1174   uint32_t utf32;
1175 
1176   if ((first_char & 0x80) == 0) { /* ASCII */
1177     return first_char ? 1 : -1;
1178   }
1179 
1180   /*
1181    * (UTF-8's character must not be like 10xxxxxx,
1182    *  but 110xxxxx, 1110xxxx, ... or 1111110x)
1183    */
1184   if ((first_char & 0x40) == 0) {
1185     return -1;
1186   }
1187 
1188   for (utf32 = 1, num_to_read = 1, mask = 0x40, to_ignore_mask = 0x80;
1189        num_to_read < 5 && (first_char & mask);
1190        num_to_read++, to_ignore_mask |= mask, mask >>= 1) {
1191     if (num_to_read > len) {
1192       return -1;
1193     }
1194     if ((*cur & 0xC0) != 0x80) { /* can not be 10xxxxxx? */
1195       return -1;
1196     }
1197     utf32 = (utf32 << 6) + (*cur++ & 0b00111111);
1198   }
1199   /* "first_char" must be (110xxxxx - 11110xxx) */
1200   if (num_to_read >= 5) {
1201     return -1;
1202   }
1203   to_ignore_mask |= mask;
1204   utf32 |= ((~to_ignore_mask) & first_char) << (6 * (num_to_read - 1));
1205   if (utf32 > kUnicodeMaxCodepoint) {
1206     return -1;
1207   }
1208   return num_to_read;
1209 }
1210 
1211 /*
1212  * Convert to printable from message to p buffer, return string length. If p is
1213  * NULL, do not copy, but still return the expected string length.
1214  */
convertPrintable(char * p,const char * message,size_t messageLen)1215 static size_t convertPrintable(char* p, const char* message, size_t messageLen) {
1216   char* begin = p;
1217   bool print = p != NULL;
1218 
1219   while (messageLen) {
1220     char buf[6];
1221     ssize_t len = sizeof(buf) - 1;
1222     if ((size_t)len > messageLen) {
1223       len = messageLen;
1224     }
1225     len = utf8_character_length(message, len);
1226 
1227     if (len < 0) {
1228       snprintf(buf, sizeof(buf),
1229                ((messageLen > 1) && isdigit(message[1])) ? "\\%03o" : "\\%o",
1230                *message & 0377);
1231       len = 1;
1232     } else {
1233       buf[0] = '\0';
1234       if (len == 1) {
1235         if (*message == '\a') {
1236           strcpy(buf, "\\a");
1237         } else if (*message == '\b') {
1238           strcpy(buf, "\\b");
1239         } else if (*message == '\t') {
1240           strcpy(buf, "\t"); /* Do not escape tabs */
1241         } else if (*message == '\v') {
1242           strcpy(buf, "\\v");
1243         } else if (*message == '\f') {
1244           strcpy(buf, "\\f");
1245         } else if (*message == '\r') {
1246           strcpy(buf, "\\r");
1247         } else if (*message == '\\') {
1248           strcpy(buf, "\\\\");
1249         } else if ((*message < ' ') || (*message & 0x80)) {
1250           snprintf(buf, sizeof(buf), "\\%o", *message & 0377);
1251         }
1252       }
1253       if (!buf[0]) {
1254         strncpy(buf, message, len);
1255         buf[len] = '\0';
1256       }
1257     }
1258     if (print) {
1259       strcpy(p, buf);
1260     }
1261     p += strlen(buf);
1262     message += len;
1263     messageLen -= len;
1264   }
1265   return p - begin;
1266 }
1267 
readSeconds(char * e,struct timespec * t)1268 static char* readSeconds(char* e, struct timespec* t) {
1269   unsigned long multiplier;
1270   char* p;
1271   t->tv_sec = strtoul(e, &p, 10);
1272   if (*p != '.') {
1273     return NULL;
1274   }
1275   t->tv_nsec = 0;
1276   multiplier = NS_PER_SEC;
1277   while (isdigit(*++p) && (multiplier /= 10)) {
1278     t->tv_nsec += (*p - '0') * multiplier;
1279   }
1280   return p;
1281 }
1282 
sumTimespec(struct timespec * left,struct timespec * right)1283 static struct timespec* sumTimespec(struct timespec* left,
1284                                     struct timespec* right) {
1285   left->tv_nsec += right->tv_nsec;
1286   left->tv_sec += right->tv_sec;
1287   if (left->tv_nsec >= (long)NS_PER_SEC) {
1288     left->tv_nsec -= NS_PER_SEC;
1289     left->tv_sec += 1;
1290   }
1291   return left;
1292 }
1293 
subTimespec(struct timespec * result,struct timespec * left,struct timespec * right)1294 static struct timespec* subTimespec(struct timespec* result,
1295                                     struct timespec* left,
1296                                     struct timespec* right) {
1297   result->tv_nsec = left->tv_nsec - right->tv_nsec;
1298   result->tv_sec = left->tv_sec - right->tv_sec;
1299   if (result->tv_nsec < 0) {
1300     result->tv_nsec += NS_PER_SEC;
1301     result->tv_sec -= 1;
1302   }
1303   return result;
1304 }
1305 
nsecTimespec(struct timespec * now)1306 static long long nsecTimespec(struct timespec* now) {
1307   return (long long)now->tv_sec * NS_PER_SEC + now->tv_nsec;
1308 }
1309 
1310 #ifdef __ANDROID__
convertMonotonic(struct timespec * result,const AndroidLogEntry * entry)1311 static void convertMonotonic(struct timespec* result,
1312                              const AndroidLogEntry* entry) {
1313   struct listnode* node;
1314   struct conversionList {
1315     struct listnode node; /* first */
1316     struct timespec time;
1317     struct timespec convert;
1318   } * list, *next;
1319   struct timespec time, convert;
1320 
1321   /* If we do not have a conversion list, build one up */
1322   if (list_empty(&convertHead)) {
1323     bool suspended_pending = false;
1324     struct timespec suspended_monotonic = { 0, 0 };
1325     struct timespec suspended_diff = { 0, 0 };
1326 
1327     /*
1328      * Read dmesg for _some_ synchronization markers and insert
1329      * Anything in the Android Logger before the dmesg logging span will
1330      * be highly suspect regarding the monotonic time calculations.
1331      */
1332     FILE* p = popen("/system/bin/dmesg", "re");
1333     if (p) {
1334       char* line = NULL;
1335       size_t len = 0;
1336       while (getline(&line, &len, p) > 0) {
1337         static const char suspend[] = "PM: suspend entry ";
1338         static const char resume[] = "PM: suspend exit ";
1339         static const char healthd[] = "healthd";
1340         static const char battery[] = ": battery ";
1341         static const char suspended[] = "Suspended for ";
1342         struct timespec monotonic;
1343         struct tm tm;
1344         char *cp, *e = line;
1345         bool add_entry = true;
1346 
1347         if (*e == '<') {
1348           while (*e && (*e != '>')) {
1349             ++e;
1350           }
1351           if (*e != '>') {
1352             continue;
1353           }
1354         }
1355         if (*e != '[') {
1356           continue;
1357         }
1358         while (*++e == ' ') {
1359           ;
1360         }
1361         e = readSeconds(e, &monotonic);
1362         if (!e || (*e != ']')) {
1363           continue;
1364         }
1365 
1366         if ((e = strstr(e, suspend))) {
1367           e += sizeof(suspend) - 1;
1368         } else if ((e = strstr(line, resume))) {
1369           e += sizeof(resume) - 1;
1370         } else if (((e = strstr(line, healthd))) &&
1371                    ((e = strstr(e + sizeof(healthd) - 1, battery)))) {
1372           /* NB: healthd is roughly 150us late, worth the price to
1373            * deal with ntp-induced or hardware clock drift. */
1374           e += sizeof(battery) - 1;
1375         } else if ((e = strstr(line, suspended))) {
1376           e += sizeof(suspended) - 1;
1377           e = readSeconds(e, &time);
1378           if (!e) {
1379             continue;
1380           }
1381           add_entry = false;
1382           suspended_pending = true;
1383           suspended_monotonic = monotonic;
1384           suspended_diff = time;
1385         } else {
1386           continue;
1387         }
1388         if (add_entry) {
1389           /* look for "????-??-?? ??:??:??.????????? UTC" */
1390           cp = strstr(e, " UTC");
1391           if (!cp || ((cp - e) < 29) || (cp[-10] != '.')) {
1392             continue;
1393           }
1394           e = cp - 29;
1395           cp = readSeconds(cp - 10, &time);
1396           if (!cp) {
1397             continue;
1398           }
1399           cp = strptime(e, "%Y-%m-%d %H:%M:%S.", &tm);
1400           if (!cp) {
1401             continue;
1402           }
1403           cp = getenv(tz);
1404           if (cp) {
1405             cp = strdup(cp);
1406           }
1407           setenv(tz, utc, 1);
1408           time.tv_sec = mktime(&tm);
1409           if (cp) {
1410             setenv(tz, cp, 1);
1411             free(cp);
1412           } else {
1413             unsetenv(tz);
1414           }
1415           list = calloc(1, sizeof(struct conversionList));
1416           list_init(&list->node);
1417           list->time = time;
1418           subTimespec(&list->convert, &time, &monotonic);
1419           list_add_tail(&convertHead, &list->node);
1420         }
1421         if (suspended_pending && !list_empty(&convertHead)) {
1422           list = node_to_item(list_tail(&convertHead), struct conversionList,
1423                               node);
1424           if (subTimespec(&time, subTimespec(&time, &list->time, &list->convert),
1425                           &suspended_monotonic)
1426                   ->tv_sec > 0) {
1427             /* resume, what is convert factor before? */
1428             subTimespec(&convert, &list->convert, &suspended_diff);
1429           } else {
1430             /* suspend */
1431             convert = list->convert;
1432           }
1433           time = suspended_monotonic;
1434           sumTimespec(&time, &convert);
1435           /* breakpoint just before sleep */
1436           list = calloc(1, sizeof(struct conversionList));
1437           list_init(&list->node);
1438           list->time = time;
1439           list->convert = convert;
1440           list_add_tail(&convertHead, &list->node);
1441           /* breakpoint just after sleep */
1442           list = calloc(1, sizeof(struct conversionList));
1443           list_init(&list->node);
1444           list->time = time;
1445           sumTimespec(&list->time, &suspended_diff);
1446           list->convert = convert;
1447           sumTimespec(&list->convert, &suspended_diff);
1448           list_add_tail(&convertHead, &list->node);
1449           suspended_pending = false;
1450         }
1451       }
1452       pclose(p);
1453     }
1454     /* last entry is our current time conversion */
1455     list = calloc(1, sizeof(struct conversionList));
1456     list_init(&list->node);
1457     clock_gettime(CLOCK_REALTIME, &list->time);
1458     clock_gettime(CLOCK_MONOTONIC, &convert);
1459     clock_gettime(CLOCK_MONOTONIC, &time);
1460     /* Correct for instant clock_gettime latency (syscall or ~30ns) */
1461     subTimespec(&time, &convert, subTimespec(&time, &time, &convert));
1462     /* Calculate conversion factor */
1463     subTimespec(&list->convert, &list->time, &time);
1464     list_add_tail(&convertHead, &list->node);
1465     if (suspended_pending) {
1466       /* manufacture a suspend @ point before */
1467       subTimespec(&convert, &list->convert, &suspended_diff);
1468       time = suspended_monotonic;
1469       sumTimespec(&time, &convert);
1470       /* breakpoint just after sleep */
1471       list = calloc(1, sizeof(struct conversionList));
1472       list_init(&list->node);
1473       list->time = time;
1474       sumTimespec(&list->time, &suspended_diff);
1475       list->convert = convert;
1476       sumTimespec(&list->convert, &suspended_diff);
1477       list_add_head(&convertHead, &list->node);
1478       /* breakpoint just before sleep */
1479       list = calloc(1, sizeof(struct conversionList));
1480       list_init(&list->node);
1481       list->time = time;
1482       list->convert = convert;
1483       list_add_head(&convertHead, &list->node);
1484     }
1485   }
1486 
1487   /* Find the breakpoint in the conversion list */
1488   list = node_to_item(list_head(&convertHead), struct conversionList, node);
1489   next = NULL;
1490   list_for_each(node, &convertHead) {
1491     next = node_to_item(node, struct conversionList, node);
1492     if (entry->tv_sec < next->time.tv_sec) {
1493       break;
1494     } else if (entry->tv_sec == next->time.tv_sec) {
1495       if (entry->tv_nsec < next->time.tv_nsec) {
1496         break;
1497       }
1498     }
1499     list = next;
1500   }
1501 
1502   /* blend time from one breakpoint to the next */
1503   convert = list->convert;
1504   if (next) {
1505     unsigned long long total, run;
1506 
1507     total = nsecTimespec(subTimespec(&time, &next->time, &list->time));
1508     time.tv_sec = entry->tv_sec;
1509     time.tv_nsec = entry->tv_nsec;
1510     run = nsecTimespec(subTimespec(&time, &time, &list->time));
1511     if (run < total) {
1512       long long crun;
1513 
1514       float f = nsecTimespec(subTimespec(&time, &next->convert, &convert));
1515       f *= run;
1516       f /= total;
1517       crun = f;
1518       convert.tv_sec += crun / (long long)NS_PER_SEC;
1519       if (crun < 0) {
1520         convert.tv_nsec -= (-crun) % NS_PER_SEC;
1521         if (convert.tv_nsec < 0) {
1522           convert.tv_nsec += NS_PER_SEC;
1523           convert.tv_sec -= 1;
1524         }
1525       } else {
1526         convert.tv_nsec += crun % NS_PER_SEC;
1527         if (convert.tv_nsec >= (long)NS_PER_SEC) {
1528           convert.tv_nsec -= NS_PER_SEC;
1529           convert.tv_sec += 1;
1530         }
1531       }
1532     }
1533   }
1534 
1535   /* Apply the correction factor */
1536   result->tv_sec = entry->tv_sec;
1537   result->tv_nsec = entry->tv_nsec;
1538   subTimespec(result, result, &convert);
1539 }
1540 #endif
1541 
1542 /**
1543  * Formats a log message into a buffer
1544  *
1545  * Uses defaultBuffer if it can, otherwise malloc()'s a new buffer
1546  * If return value != defaultBuffer, caller must call free()
1547  * Returns NULL on malloc error
1548  */
1549 
android_log_formatLogLine(AndroidLogFormat * p_format,char * defaultBuffer,size_t defaultBufferSize,const AndroidLogEntry * entry,size_t * p_outLength)1550 LIBLOG_ABI_PUBLIC char* android_log_formatLogLine(AndroidLogFormat* p_format,
1551                                                   char* defaultBuffer,
1552                                                   size_t defaultBufferSize,
1553                                                   const AndroidLogEntry* entry,
1554                                                   size_t* p_outLength) {
1555 #if !defined(_WIN32)
1556   struct tm tmBuf;
1557 #endif
1558   struct tm* ptm;
1559   /* good margin, 23+nul for msec, 26+nul for usec, 29+nul to nsec */
1560   char timeBuf[64];
1561   char prefixBuf[128], suffixBuf[128];
1562   char priChar;
1563   int prefixSuffixIsHeaderFooter = 0;
1564   char* ret;
1565   time_t now;
1566   unsigned long nsec;
1567 
1568   priChar = filterPriToChar(entry->priority);
1569   size_t prefixLen = 0, suffixLen = 0;
1570   size_t len;
1571 
1572   /*
1573    * Get the current date/time in pretty form
1574    *
1575    * It's often useful when examining a log with "less" to jump to
1576    * a specific point in the file by searching for the date/time stamp.
1577    * For this reason it's very annoying to have regexp meta characters
1578    * in the time stamp.  Don't use forward slashes, parenthesis,
1579    * brackets, asterisks, or other special chars here.
1580    *
1581    * The caller may have affected the timezone environment, this is
1582    * expected to be sensitive to that.
1583    */
1584   now = entry->tv_sec;
1585   nsec = entry->tv_nsec;
1586 #if __ANDROID__
1587   if (p_format->monotonic_output) {
1588     /* prevent convertMonotonic from being called if logd is monotonic */
1589     if (android_log_clockid() != CLOCK_MONOTONIC) {
1590       struct timespec time;
1591       convertMonotonic(&time, entry);
1592       now = time.tv_sec;
1593       nsec = time.tv_nsec;
1594     }
1595   }
1596 #endif
1597   if (now < 0) {
1598     nsec = NS_PER_SEC - nsec;
1599   }
1600   if (p_format->epoch_output || p_format->monotonic_output) {
1601     ptm = NULL;
1602     snprintf(timeBuf, sizeof(timeBuf),
1603              p_format->monotonic_output ? "%6lld" : "%19lld", (long long)now);
1604   } else {
1605 #if !defined(_WIN32)
1606     ptm = localtime_r(&now, &tmBuf);
1607 #else
1608     ptm = localtime(&now);
1609 #endif
1610     strftime(timeBuf, sizeof(timeBuf),
1611              &"%Y-%m-%d %H:%M:%S"[p_format->year_output ? 0 : 3], ptm);
1612   }
1613   len = strlen(timeBuf);
1614   if (p_format->nsec_time_output) {
1615     len += snprintf(timeBuf + len, sizeof(timeBuf) - len, ".%09ld", nsec);
1616   } else if (p_format->usec_time_output) {
1617     len += snprintf(timeBuf + len, sizeof(timeBuf) - len, ".%06ld",
1618                     nsec / US_PER_NSEC);
1619   } else {
1620     len += snprintf(timeBuf + len, sizeof(timeBuf) - len, ".%03ld",
1621                     nsec / MS_PER_NSEC);
1622   }
1623   if (p_format->zone_output && ptm) {
1624     strftime(timeBuf + len, sizeof(timeBuf) - len, " %z", ptm);
1625   }
1626 
1627   /*
1628    * Construct a buffer containing the log header and log message.
1629    */
1630   if (p_format->colored_output) {
1631     prefixLen = snprintf(prefixBuf, sizeof(prefixBuf), "\x1B[38;5;%dm",
1632                          colorFromPri(entry->priority));
1633     prefixLen = MIN(prefixLen, sizeof(prefixBuf));
1634     suffixLen = snprintf(suffixBuf, sizeof(suffixBuf), "\x1B[0m");
1635     suffixLen = MIN(suffixLen, sizeof(suffixBuf));
1636   }
1637 
1638   char uid[16];
1639   uid[0] = '\0';
1640   if (p_format->uid_output) {
1641     if (entry->uid >= 0) {
1642 /*
1643  * This code is Android specific, bionic guarantees that
1644  * calls to non-reentrant getpwuid() are thread safe.
1645  */
1646 #if !defined(__MINGW32__)
1647 #if (FAKE_LOG_DEVICE == 0)
1648 #ifndef __BIONIC__
1649 #warning \
1650     "This code assumes that getpwuid is thread safe, only true with Bionic!"
1651 #endif
1652 #endif
1653       struct passwd* pwd = getpwuid(entry->uid);
1654       if (pwd && (strlen(pwd->pw_name) <= 5)) {
1655         snprintf(uid, sizeof(uid), "%5s:", pwd->pw_name);
1656       } else
1657 #endif
1658       {
1659         /* Not worth parsing package list, names all longer than 5 */
1660         snprintf(uid, sizeof(uid), "%5d:", entry->uid);
1661       }
1662     } else {
1663       snprintf(uid, sizeof(uid), "      ");
1664     }
1665   }
1666 
1667   switch (p_format->format) {
1668     case FORMAT_TAG:
1669       len = snprintf(prefixBuf + prefixLen, sizeof(prefixBuf) - prefixLen,
1670                      "%c/%-8.*s: ", priChar, (int)entry->tagLen, entry->tag);
1671       strcpy(suffixBuf + suffixLen, "\n");
1672       ++suffixLen;
1673       break;
1674     case FORMAT_PROCESS:
1675       len = snprintf(suffixBuf + suffixLen, sizeof(suffixBuf) - suffixLen,
1676                      "  (%.*s)\n", (int)entry->tagLen, entry->tag);
1677       suffixLen += MIN(len, sizeof(suffixBuf) - suffixLen);
1678       len = snprintf(prefixBuf + prefixLen, sizeof(prefixBuf) - prefixLen,
1679                      "%c(%s%5d) ", priChar, uid, entry->pid);
1680       break;
1681     case FORMAT_THREAD:
1682       len = snprintf(prefixBuf + prefixLen, sizeof(prefixBuf) - prefixLen,
1683                      "%c(%s%5d:%5d) ", priChar, uid, entry->pid, entry->tid);
1684       strcpy(suffixBuf + suffixLen, "\n");
1685       ++suffixLen;
1686       break;
1687     case FORMAT_RAW:
1688       prefixBuf[prefixLen] = 0;
1689       len = 0;
1690       strcpy(suffixBuf + suffixLen, "\n");
1691       ++suffixLen;
1692       break;
1693     case FORMAT_TIME:
1694       len = snprintf(prefixBuf + prefixLen, sizeof(prefixBuf) - prefixLen,
1695                      "%s %c/%-8.*s(%s%5d): ", timeBuf, priChar,
1696                      (int)entry->tagLen, entry->tag, uid, entry->pid);
1697       strcpy(suffixBuf + suffixLen, "\n");
1698       ++suffixLen;
1699       break;
1700     case FORMAT_THREADTIME:
1701       ret = strchr(uid, ':');
1702       if (ret) {
1703         *ret = ' ';
1704       }
1705       len = snprintf(prefixBuf + prefixLen, sizeof(prefixBuf) - prefixLen,
1706                      "%s %s%5d %5d %c %-8.*s: ", timeBuf, uid, entry->pid,
1707                      entry->tid, priChar, (int)entry->tagLen, entry->tag);
1708       strcpy(suffixBuf + suffixLen, "\n");
1709       ++suffixLen;
1710       break;
1711     case FORMAT_LONG:
1712       len = snprintf(prefixBuf + prefixLen, sizeof(prefixBuf) - prefixLen,
1713                      "[ %s %s%5d:%5d %c/%-8.*s ]\n", timeBuf, uid, entry->pid,
1714                      entry->tid, priChar, (int)entry->tagLen, entry->tag);
1715       strcpy(suffixBuf + suffixLen, "\n\n");
1716       suffixLen += 2;
1717       prefixSuffixIsHeaderFooter = 1;
1718       break;
1719     case FORMAT_BRIEF:
1720     default:
1721       len = snprintf(prefixBuf + prefixLen, sizeof(prefixBuf) - prefixLen,
1722                      "%c/%-8.*s(%s%5d): ", priChar, (int)entry->tagLen,
1723                      entry->tag, uid, entry->pid);
1724       strcpy(suffixBuf + suffixLen, "\n");
1725       ++suffixLen;
1726       break;
1727   }
1728 
1729   /* snprintf has a weird return value.   It returns what would have been
1730    * written given a large enough buffer.  In the case that the prefix is
1731    * longer then our buffer(128), it messes up the calculations below
1732    * possibly causing heap corruption.  To avoid this we double check and
1733    * set the length at the maximum (size minus null byte)
1734    */
1735   prefixLen += len;
1736   if (prefixLen >= sizeof(prefixBuf)) {
1737     prefixLen = sizeof(prefixBuf) - 1;
1738     prefixBuf[sizeof(prefixBuf) - 1] = '\0';
1739   }
1740   if (suffixLen >= sizeof(suffixBuf)) {
1741     suffixLen = sizeof(suffixBuf) - 1;
1742     suffixBuf[sizeof(suffixBuf) - 2] = '\n';
1743     suffixBuf[sizeof(suffixBuf) - 1] = '\0';
1744   }
1745 
1746   /* the following code is tragically unreadable */
1747 
1748   size_t numLines;
1749   char* p;
1750   size_t bufferSize;
1751   const char* pm;
1752 
1753   if (prefixSuffixIsHeaderFooter) {
1754     /* we're just wrapping message with a header/footer */
1755     numLines = 1;
1756   } else {
1757     pm = entry->message;
1758     numLines = 0;
1759 
1760     /*
1761      * The line-end finding here must match the line-end finding
1762      * in for ( ... numLines...) loop below
1763      */
1764     while (pm < (entry->message + entry->messageLen)) {
1765       if (*pm++ == '\n') numLines++;
1766     }
1767     /* plus one line for anything not newline-terminated at the end */
1768     if (pm > entry->message && *(pm - 1) != '\n') numLines++;
1769   }
1770 
1771   /*
1772    * this is an upper bound--newlines in message may be counted
1773    * extraneously
1774    */
1775   bufferSize = (numLines * (prefixLen + suffixLen)) + 1;
1776   if (p_format->printable_output) {
1777     /* Calculate extra length to convert non-printable to printable */
1778     bufferSize += convertPrintable(NULL, entry->message, entry->messageLen);
1779   } else {
1780     bufferSize += entry->messageLen;
1781   }
1782 
1783   if (defaultBufferSize >= bufferSize) {
1784     ret = defaultBuffer;
1785   } else {
1786     ret = (char*)malloc(bufferSize);
1787 
1788     if (ret == NULL) {
1789       return ret;
1790     }
1791   }
1792 
1793   ret[0] = '\0'; /* to start strcat off */
1794 
1795   p = ret;
1796   pm = entry->message;
1797 
1798   if (prefixSuffixIsHeaderFooter) {
1799     strcat(p, prefixBuf);
1800     p += prefixLen;
1801     if (p_format->printable_output) {
1802       p += convertPrintable(p, entry->message, entry->messageLen);
1803     } else {
1804       strncat(p, entry->message, entry->messageLen);
1805       p += entry->messageLen;
1806     }
1807     strcat(p, suffixBuf);
1808     p += suffixLen;
1809   } else {
1810     do {
1811       const char* lineStart;
1812       size_t lineLen;
1813       lineStart = pm;
1814 
1815       /* Find the next end-of-line in message */
1816       while (pm < (entry->message + entry->messageLen) && *pm != '\n') pm++;
1817       lineLen = pm - lineStart;
1818 
1819       strcat(p, prefixBuf);
1820       p += prefixLen;
1821       if (p_format->printable_output) {
1822         p += convertPrintable(p, lineStart, lineLen);
1823       } else {
1824         strncat(p, lineStart, lineLen);
1825         p += lineLen;
1826       }
1827       strcat(p, suffixBuf);
1828       p += suffixLen;
1829 
1830       if (*pm == '\n') pm++;
1831     } while (pm < (entry->message + entry->messageLen));
1832   }
1833 
1834   if (p_outLength != NULL) {
1835     *p_outLength = p - ret;
1836   }
1837 
1838   return ret;
1839 }
1840 
1841 /**
1842  * Either print or do not print log line, based on filter
1843  *
1844  * Returns count bytes written
1845  */
1846 
android_log_printLogLine(AndroidLogFormat * p_format,int fd,const AndroidLogEntry * entry)1847 LIBLOG_ABI_PUBLIC int android_log_printLogLine(AndroidLogFormat* p_format,
1848                                                int fd,
1849                                                const AndroidLogEntry* entry) {
1850   int ret;
1851   char defaultBuffer[512];
1852   char* outBuffer = NULL;
1853   size_t totalLen;
1854 
1855   outBuffer = android_log_formatLogLine(
1856       p_format, defaultBuffer, sizeof(defaultBuffer), entry, &totalLen);
1857 
1858   if (!outBuffer) return -1;
1859 
1860   do {
1861     ret = write(fd, outBuffer, totalLen);
1862   } while (ret < 0 && errno == EINTR);
1863 
1864   if (ret < 0) {
1865     fprintf(stderr, "+++ LOG: write failed (errno=%d)\n", errno);
1866     ret = 0;
1867     goto done;
1868   }
1869 
1870   if (((size_t)ret) < totalLen) {
1871     fprintf(stderr, "+++ LOG: write partial (%d of %d)\n", ret, (int)totalLen);
1872     goto done;
1873   }
1874 
1875 done:
1876   if (outBuffer != defaultBuffer) {
1877     free(outBuffer);
1878   }
1879 
1880   return ret;
1881 }
1882