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