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