Commit graph

36 commits

Author SHA1 Message Date
Mark Salyzyn
3c501b50b4 logd: reader/writer element locks
Switch to a reader writer lock for the Element List lock.  Also setup
for a reader writer lock for the Times list, but continue to use a
mutex where rdlock() and wrlock() are the same implementation for now.

This should improve general reader performance and prevent blocking of
other reader operations or exit by a single hung logd.reader.per
thread.  For example, a full length logcat of an empty buffer (eg:
crash log buffer) will hold a lock while the iterator scans the entire
list.

Test: gTest liblog-unit-tests, logd-unit-tests, logcat-unit-tests
Bug: 37378309
Bug: 37483775
Change-Id: If5723ff4a978e17d828a75321e8f0ba91d4a09e0
2017-04-20 08:24:38 -07:00
Mark Salyzyn
0484b3b575 logd: ASAN cleansing
A mixture of fixes and cleanup for LogKlog.cpp and friends.

- sscanf calls strlen.  Check if the string is missing a nul
  terminator, if it is, do not call sscanf.
- replace NULL with nullptr for stronger typechecking.
- pass by reference for simpler code.
- Use ssize_t where possible to check for negative values.
- fix FastCmp to add some validity checking since ASAN reports that
  callers are not making sure pre-conditions are met.
- add fasticmp templates for completeness.
- if the buffer is too small to contain a meaningful time, do not
  call down to log_time::strptime() because it does not limit its
  accesses to the buffer boundaries, instead stopping at a
  terminating nul or invalid match.
- move strnstr to LogUtils.h, drop size checking of needle and
  clearly report the list of needles used with android::strnstr
- replace 'sizeof(static const char[]) - 1' with strlen.

Test: gTest liblog-unit-test, logd-unit-tests & logcat-unit-tests
Bug: 30792935
Bug: 36536248
Bug: 35468874
Bug: 34949125
Bug: 34606909
Bug: 36075298
Bug: 36608728
Change-Id: I161bf03ba029050e809b31cceef03f729d318866
2017-03-27 13:32:57 -07:00
Andreas Gampe
34450d70c5 Logd: Fix wrong parameters
Better keep the right order, or ASAN will complain when you read
out of bounds.

Bug: 36234128
Test: m
Test: m && m SANITIZE_TARGET=address
Test: Sanitized device boots without ASAN crashes
Change-Id: Ifc09cb0ece6835d2b636a3ad2128e09ca9aa45c9
2017-03-14 20:43:43 -07:00
Mark Salyzyn
501c373916 logd: specify clang format
Switch _all_ file's coding style to match to ease all future changes.

SideEffects: None
Test: compile
Bug: 35373582
Change-Id: I470cb17f64fa48f14aafc02f574e296bffe3a3f3
2017-03-13 10:31:09 -07:00
Mark Salyzyn
a2c022257c logd: record multiple duplicate messages as chatty
If a series of messages arrive from a single source with identical
message content payload, then suppress them and generate a chatty
report.  The checking is done on a per log id basis.

This alters the assumption that chatty messages are always at the
oldest entries, they now show up in the middle too.  To address this
change in behavior we print the first line, a chatty reference
which internally takes little space, then the last line in the series.

This does not conserve processing time in logd, and certainly has no
impact on the long path of formatting and submitting log messages from
from the source, but it may contribute to memory space and signal to
noise savings under heavy spammy loads.

Test: gTest liblog-unit-tests, logd-unit-tests & logcat-unit-tests
Bug: 33535908
Change-Id: I3160c36d4f4e2f8216f528605a1b3993173f4dec
2016-12-15 16:31:51 -08:00
Mark Salyzyn
0eeb06b932 utils: Add FastStrcmp.h
Move existing fast<str*cmp> templates for general use, pulled from
the implementation used in logd that dealt with speed through cache
locality and subroutine call mitigation.  Rename to fastcmp.

Test: logd-benchmarks and based on manual profiling from the past
Bug: 31456426
Change-Id: Ic62f4a437fc3e06ffdeaae73a6f34e197957a6b0
2016-12-09 12:40:17 -08:00
Mark Salyzyn
28fcac705b liblog: logd: logcat: Split out log/logger.h into public and private.
am: aeaaf81c2c

Change-Id: I124c69673c30bb5f2259849792ed4ca99f4d6b60
2016-10-24 22:53:11 +00:00
Mark Salyzyn
aeaaf81c2c liblog: logd: logcat: Split out log/logger.h into public and private.
log/logger.h pieces moved into log/log.h.  Correct for some
minor Android Coding standards.

Test: gTests liblog-unit-tests, logd-unit-tests and logcat-unit-tests
Bug: 19235719
Bug: 26552300
Bug: 31289077
Bug: 31456426
Change-Id: I0a19fd8788eec20a582e72e4c62c04534bdb1b9a
2016-10-24 11:12:49 -07:00
Mark Salyzyn
f9fb584b66 Merge "logd: klogd crash (part deux)" am: 96c36d35ce am: e36dbdda43
am: 6d2e1c73a3

Change-Id: Ib31392aa400b744e144788792199931760568281
2016-08-12 14:38:18 +00:00
Mark Salyzyn
83b247891c logd: klogd crash (part deux)
LogBuffer::pidToUid(pid_t pid) { return stats.pidToUid(pid); }
needs to have LogBuffer::lock()/unlock() to prevent unordered_map
data corruption. This can lead to multiple symptoms, crashes and
continuous spins on corrupted iterators.

Bug: 30688716
Bug: 30050636
Bug: 30614675
Bug: 25620123
Bug: 30792935
Change-Id: I1d8fec8e5fda98c6a08645e7456b081507696b3c
2016-08-11 16:13:01 -07:00
Mark Salyzyn
fe51e78209 Merge "logd: klogd crash" am: e23e0914ff am: 5118d8f633
am: 73ded18d31

Change-Id: I6797f0120af2e933611374f63b29b480dd8b7ed7
2016-08-09 14:50:26 +00:00
Mark Salyzyn
a146a779e2 logd: klogd crash
dmesg parser could wrap taglen limit resulting in out of bound
accesses. Can lead to crash or data corruption.

Fixed an issue with two-word tag parsing. Switched to case
insensitive tag content matching. Added a few extra limit
checks that could also wrap, simplified the parsing, then added
means to stop using hard coded constants.

Bug: 30688716
Bug: 30050636
Bug: 30614675
Bug: 25620123
Change-Id: Iae4f664f63ef7b842d82eaa1638b6d7a0d28fd18
2016-08-08 09:58:28 -07:00
Mark Salyzyn
0b4a63d212 logd: klogd: deal with htc modified printk
Skip leading 'c0  32767 ' and place pid (32767 in example) into pid
field of log record.

Bug: 29831823
Change-Id: I9fcd3cb0235dfcad78627736712a20d2dc1250cc
2016-07-19 11:13:14 -07:00
Mark Salyzyn
317bfb923c logd: Allow (some) headers to be individually importable
(cherry pick from commit 2ad0bd0a9b)

LogReader.h needs to be individually importable.

Fix a few others, drop includes of local includes, let them be
included in source instead and allow headers to be included
alphabetically. Was not a complete audit since goal was to
separate LogReader.h out from the pack.

Bug: 27242723
Change-Id: Ic7759ef90995e5bd285810706af33550c73cf5b5
2016-02-25 12:42:31 -08:00
Mark Salyzyn
2ad0bd0a9b logd: Allow (some) headers to be individually importable
LogReader.h needs to be individually importable.

Fix a few others, drop includes of local includes, let them be
included in source instead and allow headers to be included
alphabetically. Was not a complete audit since goal was to
separate LogReader.h out from the pack.

Bug: 27242723
Change-Id: Ic7759ef90995e5bd285810706af33550c73cf5b5
2016-02-24 10:15:22 -08:00
Mark Salyzyn
ff8b8e838b logd: build breakage aosp-brillo-master @ 2508494
Change-Id: I38e506bc997c6e9759a064b517f9372a27d0e510
2015-12-30 13:46:07 -08:00
Mark Salyzyn
10b82b6834 logd: isMonotonic improvements
Use 1972 as a right delineation. Otherwise use half way point
between the monotonic and realtime. Treat correction factor as
unsigned, ensure that any wrapping to a negative value is
dropped or set to EPOCH. Acknowledge that we can get a more
accurate time track by acquiring the time rather than relying on
healthd timestamp.

Bug: 26331432
Change-Id: I09075fca58676a30cf7d87baf2d4b0f53795abaa
2015-12-29 11:34:29 -08:00
Mark Salyzyn
b06247d9a0 logd: best 2/3 filter for timezone glitches
klogd is sensitive to changes in timezone resulting in glitches
surrounding conversion to local realtime logging. logger manages
a map from monotonic to realtime, but the process is racey since
the system can change the timezone at any time, this catches those
cases where it glitches.

Bug: 21868540
Change-Id: I03de6675fcd04f18ba7306a24dc3d9e750d86976
2015-12-10 13:20:48 -08:00
Mark Salyzyn
eb29808615 logd: klogd: parse error
Resolve three areas missing taglen checking. Add some additional
limit-checking paranoia. Problem started when p was allowed to
go beyond the size of the incoming buffer in some blind
p = cp + 1 fragments, placed the check for that after them all
before harm could be done, rather than in each location.

Bug: 25620123
Change-Id: Ib5687fd30ef0cd3ba3bc0df310b436ad675ccabc
2015-11-13 07:58:05 -08:00
Mark Salyzyn
b6bee33182 liblog: logd: support logd.timestamp = monotonic
if ro.logd.timestamp or persist.logd.timestamp are set to the value
monotonic then liblog writer, liblog printing and logd all switch to
recording/printing monotonic time rather than realtime. If reinit
detects a change for presist.logd.timestamp, correct the older entry
timestamps in place.

ToDo: A corner case condition where new log entries in monotonic time
      occur before logd reinit detects persist.logd.timestamp, there
      will be a few out-of-order entries, but with accurate
      timestamps. This problem does not happen for ro.logd.timestamp
      as it is set before logd starts.

NB: This offers a nano second time accuracy on all log entries
    that may be more suitable for merging with other system
    activities, such as systrace, that also use monotonic time. This
    feature is for debugging.

Bug: 23668800
Change-Id: Iee6dab7140061b1a6627254921411f61b01aa5c2
2015-11-03 15:15:51 -08:00
Mark Salyzyn
ddda212faa logd: optimize code hotspots
Discovered that we had a few libc hotspots. Adjust code to generally
reduce or nullify the number of calls to malloc, free, strlen,
strcmp, strncmp, memcmp & strncasecmp. Total gain looks to be about
3% of logd's processing time. malloc still contributes to 3%, but all
others are now total 0.5%.

Bug: 23685592
Change-Id: Ife721121667969260cdb8b055524ae90f5911278
2015-10-02 16:45:22 -07:00
Mark Salyzyn
151beac76d logd: klogd deal with nuls in dmesg
Switch to using string and length in all transactions, treating
trailing nuls the same as spaces.

ToDo: change dumpstate (bugreport) to use logcat -b printable _regardless_

Bug: 23517551
Change-Id: I42162365e6bf8ed79d356e7b689a673902116fdb
2015-09-29 15:51:38 -07:00
Mark Salyzyn
ea1a241107 logd: log_strtok_r deal with nuls
Rename to log_strntok_r and change from dealing with strings
to dealing with a string and an associated length.

Bug: 23517551
Change-Id: Ia72f1305a53f55eeef9861ac378fb8205fd2378e
2015-09-29 15:43:34 -07:00
Mark Salyzyn
2d159bf3b5 logd: klogd: sniff for time correction on Mediatek
Need some more flexibility when parsing kernel messages
cluttered with extra fluff. This is the minimal relaxation
we can do to the rules to ensure that we work on all
possible devices and kernels when sniffing for time
correction information.

We want to minimize any future maintenance, keep in mind
klogd is a "userdebug" or "eng" feature and is disabled
in "user" builds. Manage expectations.

Bug: 23517551
Change-Id: I026d074e14fb2550e728683e85a973bd87e78a9c
2015-09-29 15:43:07 -07:00
Mark Salyzyn
47dba71f24 logd: klogd and Mediatek part deux
- switch to an open coded strnrchr
- validity checking on n, taglen and b values.

Bug: 23517551
Change-Id: I568e25c5aa6d8474835454a0e83b19c2921b7986
2015-09-29 15:40:08 -07:00
Mark Salyzyn
46d159d462 logd: klogd and Mediatek
- sniff for PID in kernel log messages if available
- properly deal with klogd watermark in face of modified output
- deal more stringently with priority tag, must have [ following
- suppress process-name stutter in tag that can happen
- do not use : to demark tag if within [ ]

Mediatek-special change that adds <printk_state>(<cpu>)[<pid>:<comm>]
as a prefix to the printk messages. Along the lines of (simplified
for entertainment purposes, YMMV):

    char tbuf[50]; /* printk prefix */
    int this_cpu = smp_processor_id();
    char state = __raw_get_cpu_var(printk_state);
    unsigned tlen = snprintf(tbuf, sizeof(tbuf), "%c(%x)[%d:%s]",
               state, this_cpu, current->pid, current->comm);

Bug: 23517551
Change-Id: I568e25c5aa6d8474835454a0e83b19c2921b7985
2015-08-26 14:57:16 -07:00
Mark Salyzyn
acb1ddf56c healthd: logd: add timestamp to kernel logged battery messages
Aid monotonic to realtime logging synchronization correction in
the Android ecosystem by providing a periodic notification.  We
now have the following messages in the kernel logs:

- PM: suspend entry %Y-%m-%d %H:%M:%S.%09q UTC
- PM: suspend exit %Y-%m-%d %H:%M:%S.%09q UTC
- Suspended for %s.%03q seconds
- healthd: battery l=100 ... %Y-%m-%d %H:%M:%S.%09q UTC

Alter klogd to resynchronize on healthd messages as well.

NB: Time using strftime format, %q is a reference to fractional
second as introduced into log_time strptime method.

Bug: 21868540
Change-Id: I854afc0a07dff9c7f26d2b2f68990e52bf90e300
2015-07-28 16:52:58 -07:00
Andreas Gampe
d75564f9b8 Logd: Handle unused variable and fields
For build-system CFLAGS clean-up.

Bug: 18632512
Change-Id: If81d6705b44e9a29f64c44c56ea633c031e831b7
2015-07-27 14:17:33 -07:00
Mark Salyzyn
618d0dec50 logd: refine is_prio
- Heuristics associated with translation of kernel messages to
  Android user space logs.
- Limit is_prio to 4 characters, we got false positives on hex
  values like <register contents> with no alpha chars.
- x11 and other register definitions are not valid tags, en0 is
- fix some Android coding standard issues

Change-Id: Idc3dcc53a2cb75ac38628c8ef7a5d5b53f12587a
2015-07-22 07:36:03 -07:00
Mark Salyzyn
ee49c6a670 logd: missing klogd content
- regression in log_strtok_r (part deux) In commit
      'logd: fix kernel logline stutter'
  2c3b300fd8 we introduced log_strtok_r.
  as a replacement for strtok_r that dealt with a problem with
  some kernel log messages. Fix is to refine definition of
  is_timestamp to not match on patterns like [0], requiring
  a single period. Another fix is to refine definition of
  is_prio to properly escape non-digit content.
- Missing content because SYSLOG_ACTION_SIZE_BUFFER with added logging
  is too short for full read of SYSLOG_ACTION_READ_ALL dropping
  initial content. Add a margin for additional 1024 bytes.
- Absolute _first_ log entry has sequence number of 1, which is
  specifically dropped, start sequence count at 1 rather than 0.
- Remove trailing space for efficiency.
- If tag exists but no content, trick into kernel logging.

Bug: 21851884
Change-Id: I0867a555a3bca09bbf18d18e75e41dffffe57a23
2015-06-15 21:19:10 +00:00
Mark Salyzyn
4fb24dda34 Revert "logd: regression in log_strtok_r"
This reverts commit d3c5093a3c.

Change-Id: I52558fd0e9f75ba1cc6a151785fc91857c27ab9a
2015-06-12 22:36:57 +00:00
Mark Salyzyn
d3c5093a3c logd: regression in log_strtok_r
In commit 'logd: fix kernel logline stutter'
2c3b300fd8 we introduced log_strtok_r.
as a replacement for strtok_r that dealt with a problem with
some kernel log messages. Fix is to refine definition of
is_timestamp to not match on patterns like [0].

Change-Id: I0867a555a3bca09bbf18d18e75e41dffffe57a22
2015-06-12 22:21:44 +00:00
Mark Salyzyn
3e21de2915 logd: build breakage
OPEN_BRACKET_SPACE comparison always false

Change-Id: I1ff4288b4b79a49702727d3a8b8c8f179f500951
2015-06-08 14:52:14 -07:00
Mark Salyzyn
2c3b300fd8 logd: fix kernel logline stutter
- look for cases where one log line contains two without a newline.
- rare condition, occurs when a printk does not have
  a terminating newline under certain race conditions.
- the newline may be performed broken up as a second call
- the timestamps can be reversed (showing the race effects).
- driver(s) should really have the newline in there log messages.

Change-Id: Ibfb56b32047da3d6513db059ca6edad0f0105168
2015-06-08 13:10:31 -07:00
Mark Salyzyn
7718778793 logd: Cleanup
- Android Coding Standard for Constructors
- Side effects NONE

Change-Id: I2cda9dd73f3ac3ab58f394015cb810820093d47b
2015-05-12 15:51:46 -07:00
Mark Salyzyn
ae4d928d81 logd: Add klogd
- Add a klogd to collect the kernel logs and place them into a
  new kernel log buffer
- Parse priority, tag and message from the kernel log messages.
- Turn off pruning for worst UID for the kernel log buffer
- Sniff for 'PM: suspend exit', 'PM: suspend enter' and
  'Suspended for' messages and correct the internal definition
  time correction against monotonic dynamically.
- Discern if we have monotonic or real time (delineation 1980) in
  audit messages.
- perform appropriate math to correct the timestamp to be real time
- filter out any external sources of kernel logging

Change-Id: I8d4c7c5ac19f1f3218079ee3a05a50e2ca55f60d
2015-05-12 15:51:46 -07:00