This has been around for ~5 years but there has been roughly no
adoption, so remove this as we clean up the logging code.
Future efforts may track the monotonic timestamp in all cases.
Test: logging unit tests
Change-Id: I55ed565669f923988e741f6b384141bba893630d
1) We can use real member functions with std::thread and
std::function, so use those instead of the 'me' pointer.
2) Don't expose member variables directly.
3) Rename and document member variables, since all of their references
are being touched anyway.
Test: logging unit tests
Change-Id: I9a357a3ea8691433d58687c95356b984b83e9c36
LogTimes has evolved from being simply a store of the last timestamp
that each reader has read to being a class representing an individual
reader thread, including the thread function, so name it
appropriately.
Test: logging unit tests
Change-Id: I6914824376a6ff1f7509e657fa4dc044ead62954
I added mOldest recently before mentally committing to have new code
follow the Google C++ style guide.
Test: build
Change-Id: I6d5bab5833e14ac3808862598a2a60989d805e18
logd needs a pointer to PruneList, but it should not own it and it
should not have initPrune() or formatPrune() functions.
Test: logging unit tests
Change-Id: Id1668c26d07eb5d1e4cf267f5748c20a79f711ae
It doesn't look like there are any users, since there is a much better
mechanism, `logd --reinit` that exists for this behavior. The
settings app and init.rc use that mechanism and they are the two major
clients that force logd to reinitialize.
This saves us from creating a thread and marginally cleans up
main.cpp.
Test: log reinitialization works
Change-Id: Icdb56b6f59adbba82812231a4f3a6ffd1a7955fc
LogBuffer needs a pointer to LogTags, but it should not own the
instance. It should not provide accessors into LogTags either.
Also, clean up CommandListener a bit.
Test: logging unit tests
Change-Id: Ic0c86a2bac0c4dd80262278588b9fdc2326dbe5b
This code was duplicated throughout LogBuffer.cpp, so refactor it into
a single location and clean up some comments along the way.
This may fix a subtle bug: if `logcat -c` is used from a
non-privileged UID, the current code may set mLast to the oldest seen
log message *from that UID* and not not the oldest log message for
that log id. That may prevent pruning from the start of that log,
resulting in old log entries that are impossible to delete.
Bug: 144382260
Test: logging works, and above scenario is not seen
Change-Id: I1749293ce6ea1697dd8a9258cfd7eab29dbeac6e
This reverts commit 3614a0c5d4.
The original commit was added to check if what should be impossible
cases were happening. In the years after it was added, it doesn't
appear that these cases have happened. Recent reverts removed the
commits that caused the paranoia in the first place, making these
cases even more impossible.
Test: logging unit tests
Change-Id: I687c4d7876a38485e940f004dbd5ae6a1e15fb4c
This reverts commit 5a34d6ea43.
There is a long standing bug that logd will leak memory during its
prune process if the time on the device changes significantly forwards
then backwards. This is due to using the timestamp of each log
message to determine what log messages are yet to be processed by a
reader thread.
Various attempts have been made to rectify this, but the only solution
that safely fixes this issue is to go back to using sequence numbers
on the log messages.
Bug: 64675203
Bug: 77971811
Bug: 149340579
Bug: 150923384
Test: logcat output looks sane
Change-Id: Ibce79cf184eb29a4914f3e42a8cb2868d04dc165
This reverts commit 0878a7c167.
This is a partial revert of the above commit. It simply removes
pruneMargin from these calculations since it is going away.
Bug: 149340579
Test: --clear works well
Change-Id: I1763be56fae7052058a800fad3b295c73cdcadf6
Sorting does not work in all cases:
* It only sorts messages up to 5 seconds backwards in time
* CLOCK_REALTIME, which is used as the time that is sorted, can jump
drastically
* Buffers are not sorted if there is a reader holding a region lock
Removing sorting entirely will give more consistent behavior from
logd.
Test: logcat still seems sane
Change-Id: I0923ab2fb377cda941c1e4972689df46f395ac99
This buffer isn't human readable and the parsers aren't set up to
handle the 'chatty' message for identical log messages. Further, it
is a low volume buffer so there's not much in terms of memory saving
if this were enabled.
Bug: 137093665
Test: security unit tests
Change-Id: I03fce518d3308a6d9240bd29e83ff3237203fe3b
We're kicking logcat clients more frequently than expected, so print
this information for debugging purposes.
Bug: 144311420
Test: see these logs
Change-Id: I1570cd4b377a62c863bc26c7b3148e04c2433a9c
logd currently only reports the UID of a log message for 'privileged'
readers (those with a uid or gid of root, system, or log). However,
UIDs are not particularly sensitive. Much more importantly,
non-privileged readers can only see less messages from their own UID,
so this restriction is essentially a no-op, as those readers will
already know their own uid.
Test: liblog and logd unit tests
Change-Id: I9da7d15eb840ba3200128391e70d618eec79f988
- Zero initialize log_time instances by default
- Disable implicit conversions by making constructors explicit
- Explicitly initialize to EPOCH in most places
- Change sniffTime() to avoid in-place modification of a log_time
I stopped here, but we could consider following up with a more invasive
change to make log_time instances immutable and perhaps also remove the
default constructor to force explicit initialization to EPOCH.
Test: atest libbase_test netd_unit_test
Change-Id: I67e716ef74adaaf40ab2c6e2e0dddb8d309bc7ca
LogTimeEntry's lifecycle is spread out in various locations. It
further seems incomplete as there is logic that assumes that its
associated thread can exit while the underlying LogTimeEntry remains
valid, however it doesn't appear that that is actually a supported
situation.
This change simplifies this logic to have only one valid state for a
LogTimeEntry: it must have its thread running and be present in
LastLogTimes. A LogTimeEntry will never be placed into LastLogTimes
unless its thread is running and its thread will remove its associated
LogTimeEntry from LastLogTimes before it has exited.
This admittedly breaks situations where a blocking socket gets issued
multiple commands with different pid filters, tail lines, etc,
however, I'm reasonably sure that these situations were already
broken. A check is added to close the socket in this case.
Test: multiple logcat instances work, logd.reader.per's are cleaned up
Change-Id: Ibe8651e7d530c5e9a8d6ce3150cd247982887cbe
Events in the LogBuffer are supposed to be sorted by timestamp, but for a variety
of reasons that doesn't always happen. When a LogReader is reading from LogBuffer,
LogBuffer starts at the newest event, and scans backward through the list, looking
for the last event. Previously it would accept a couple that were a little bit out
of order, but if it found one that was ancient, it would just bail. This change
removes that check for the ancient messages. They are probably indicative of
something else upstream, but since there is no invariant of the list being sorted,
this change simplifies the search algorithm, and makes it look only at the previous
300 events.
Bug: 77222120
Test: while true ; do frameworks/base/cmds/statsd/run_tests.sh 2h ; done
Change-Id: I0824ee7590d34056ce27233a87cd7802c28f50e4
(cherry pick from commit 22712428b8)
Discovered while running AddressSanitizer, binary events were fed
into logd that were smaller than the binary event string header.
Fix is to check the buffer sizes before performing the memcmp
operation.
Test: compile
Bug: 74574189
Change-Id: Ic01ef6fb0725258d9f39bbdca582ed648a1adc5d
Fix for buffer overrun when a tag that is too big is sent to logd.
Buffer supplied is precisely the right size for max message length
however strlen will be run on the buffer, so need to ensure null
terminator, otherwise any strlen will go off the end of the buffer.
Also converted LogBuffer::Log() over to use the safer strnlen in the
case where it is measuring the buffer (and converted over to using
__android_log_is_loggable_len())
Signed-off-by: Paul Elliott <paul.elliott@arm.com>
Test: liblog.android_log_buf_print__maxtag
Change-Id: I3cb8b25af55943fb0f4658657560eb2300f52961
We have already searched for the start point, the start filter check
is paranoia that removes out-of-order entries that we are undoubtably
interested in. Out-of-order entries occur under reader pressure, as
the writer gets pushed back from in-place sorted order and lands it
at the end for the reader to pick it up. If this occurred during a
batch run or a logger thread wakeup, the entry could be filtered out
and never output to the reader.
We have to treat exact finds for start in the list as terminal when
we search as they represent restarts, depending on the fact that it
is impossible to have the exact same time reported in two log entries
or requested from a batched reader. This does break down if a log
entry has xxxxxx000 nanoseconds reported, we fix that by making sure
we never log such a case and slip it by a ns.
Found one case where logcat.tail_time* tests failed which was fixed
with this adjustment.
Test: gTest logd-unit-tests, liblog-unit-tests and logcat-unit-tests
Bug: 38046067
Bug: 37791296
Bug: 38341453
Change-Id: I4dd2e2596dd67b8d602160dd79661e01805227a9
Regressed by introducing too much overlap in the results.
This reverts commit 982ad208b5.
Bug: 38341453
Change-Id: I9d630a6b9f3e464f523424b640090f7e268da9bd
We have already searched for the start point, the start filter check
is paranoia that removes out-of-order entries that we are undoubtably
interested in. Out-of-order entries occur under reader pressure, as
the writer gets pushed back from in-place sorted order and lands it
at the end for the reader to pick it up. If this occurred during a
batch run or a logger thread wakeup, the entry could be filtered out
and never output to the reader.
Found one case where logcat.tail_time* tests failed which was fixed
with this adjustment.
Test: gTest logd-unit-tests, liblog-unit-tests and logcat-unit-tests
Bug: 38046067
Bug: 37791296
Change-Id: Icbde6b33dca7ab98348c3a872793aeef3997d460
While a reader is present, consider it a success, and not busy, if a
buffer is pruned down to pruneMargin plus one second of additional
margin of logspan. If not busy, no need to trigger any mitigations
regarding the readers, or to report any errors.
Side Effects are we no longer mitigate the reader when performing
chatty filtration. This is a positive side effect because we were
getting --wrap wakeups that seemed premature.
Add kickMe() and isBusy() methods to ease maintenance and uniformity
of actions.
Test: gTest liblog-unit-tests, logd-unit-tests & logcat-unit-tests
Test: manual: 'logcat -b all -c' repeat in a loop, at various logging
load levels, simultaneously 'logcat -b' all in another session.
Bug: 38046067
Change-Id: I3d0c8a2d416a25c45504eda3bfe70b6f6e09ab27
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
Replace stats.add(elem) + stats.subtract(elem) with a new more
efficient method stats.addTotal(elem).
Test: gTest liblog-unit-test, logd-unit-tests and logcat-unit-tests
Bug: 37254265
Change-Id: I2b3c2ac44209772b38f383ae46fe6c4422b542cf
Add checking for impossible(tm) scenarios within LogBuffer::flushTo:
1) When iterating through the log entries, check if the iterator
returns two identical element references and break out of the loop.
2) Cap the maximum number of log entries we will skip while holding
the iterator lock at 4194304, break out of the loop.
We print a message to the kernel logs if we hit these cases.
ToDo: Remove this paranoia at some future date.
Test: gTest liblog-unit-tests logcat-unit-tests and logd-unit-tests
Bug: 37378309
Change-Id: I789594649db14093238828b9f6d1daeca8b780c2
Deal with a regression introduced in commit
5a34d6ea43 (logd: drop mSequence from
LogBufferElement) where log_time was compared against nsec() time
miscalculating the watermark boundary. When dealing with logcat
-t/-T, or any tail reading, add a margin to prune to back off by a
period of 3 seconds (pruneMargin).
Test: gTest liblog-unit-tests logcat-unit-tests and logd-unit-tests
Bug: 37378309
Change-Id: I72ea858e4e7b5fa91741ea84c40d2e7c3c4aa031
Reduce the period we are willing to look back at for out-of-order
entries. Cap the number of iterations we are willing to look back
for out-of-order entries to 300.
Test: gTest liblog-unit-tests, logd-unit-tests and logcat-unit-tests
Bug: 36875387
Bug: 36874561
Bug: 36861142
Change-Id: Icee289dfc0a37ccab9912dc8ab40a10ef3967b7a
Move lastTid array from local in LogBuffer::flushTo to per-reader
context in LogTimes::mLastTid and pass into LogBuffer::flushTo.
Replace NULL with nullptr in touched files.
Simplify LogTimeEntry::cleanSkip_Locked initialization of skipAhead
to memset, to match mLastTid memset initialization.
Test: gTest liblog-unit-tests, logd-unit-tests & logcat-unit-tests
Test: adb logcat -b all | grep chatty | grep -v identical
Bug: 36488201
Change-Id: I0c3887f220a57f80c0490be4b182657b9563aa3f
last should start with mLogElements.end() and be updated as
we iterate to find a matching time entry in the list. Since
it is impossible(sic) for a newer start time to be supplied
than the list, the incorrect iterator initialization should
be inconsequential, but if it ever happens this change will
behave correctly and dump nothing.
Test: gTest liblog-unit-tests, logd-unit-tests and logcat-unit-tests
Bug: 36536248
Bug: 36608728
Change-Id: I96998c4b713258f29d5db2e24a83ae562ddf3420
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
Add some deterministic behavior should the user change the hour
backwards when altering the device time, prevent sort-in-place
and cause the logger to land the new entries at the end.
Do not limit how far kernel logs can be sorted.
Test: gTest liblog-unit-tests logd-unit-tests logcat-unit-tests
Bug: 35373582
Change-Id: Ie897c40b97adf1e3996687a0e28c1199c41e0d0c
