Regression from commit 8e8e8db549
For liblogcat reader -t or -T <timestamp> tail requests, continue
search for pertinent out-of-order entries for an additional 30 seconds
back into logging history to find a more inclusive starting point.
For example, if you have an out of order landing like
[..., 3, 6, 1, 8, 2, 5] and ask for 3 you used to get only 5, and now
you get 3, 6, 8, 5 as 'expected'
Test: gTest liblog-unit-tests logd-unit-tests logcat-unit-tests
Bug: 35373582
Change-Id: I2a0732933fa371aed383d49c8d48d01f33db2a79
Use getRealTime() instead and leverage private liblog log_time
comparison and math functions. This saves 8 bytes off each
element in the logging database.
Test: gTest liblog-unit-tests logd-unit-tests logcat-unit-tests
Bug: 35373582
Change-Id: Ia55ef8b95cbb2a841ccb1dae9a24f314735b076a
- Improves accuracy of -t/-T '<timestamp>' behavior when out of order
arrival of entries messes with mSequence as the list will now have
monotonic sequence numbers enforced.
- Out of order time entries still remain because of reader requiring
the ability to receive newly arrived old entries.
- -t/-T '<timestamp>' can still quit backward search prematurely
because an old entry lands later in the list.
- Adjust insert in place algorithm from two loops of scan placement
and then limit against watermark, into one that does all of that
plus iteratively swap update the sequence numbers to set
monotonicity. Side effect will be that the read lock (which is
actually the LogTimes lock) will be held longer while we search
for a placement above the youngest LogTimes watermark. We need
to hold the read (LogTimes) lock because we may be altering the
sequence numbers affecting -t/-T '<timestamp>' search.
Test: gTest logd-unit-tests liblog-unit-tests logcat-unit-tests
Bug: 35373582
Change-Id: I79a385fc149bac2179128b53d4c8f71e429181ae
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
Bug: 34949125
Bug: 34606909
Test: Make sure Android boots when built with SANITIZE_TARGET='address'
Change-Id: I9c004e806f2025098aa72228284b05affd2c2802
Switch _all_ file's coding style to match to ease all future changes.
SideEffects: None
Test: compile
Bug: 35373582
Change-Id: I470cb17f64fa48f14aafc02f574e296bffe3a3f3
Bug: 34949125
Bug: 34606909
Test: Make sure Android boots when built with SANITIZE_TARGET='address'
Change-Id: I9c004e806f2025098aa72228284b05affd2c2802
This is the precursor for "Plan B" recovery when access to
/dev/event-log-tags is blocked to untrusted zones. Also
deals with mitigating issues with long-lived mappings that
do not update /dev/event-log-tags when dynamically changed.
Test: gTest logd-unit-test --gtest_filter=logd.getEventTag_42
Bug: 31456426
Bug: 35326290
Change-Id: I3db2e73763603727a369da3952c5ab4cf709f901
android_lookupEventTagNum added. Adds support for creating a new
log tag at runtime, registered to the logd service.
Tested on Hikey, all services stopped, shell only access, CPUs not
locked (there is enough repeatability on this platform).
$ /data/nativetest64/liblog-benchmarks/liblog-benchmarks BM_lookupEventTagNum
iterations ns/op
Precharge: start
Precharge: stop 231
NB: only Tag matching, linear lookup (as reference, before unordered_map)
BM_lookupEventTagNum 1000000 1017
NB: unordered_map with full Tag & Format lookup, but with Tag hashing
BM_lookupEventTagNum 2000000 683
NB: with full Tag & Format hash and lookup for matching
BM_lookupEventTagNum 2000000 814
NB: only Tag matching (Hail Mary path)
BM_lookupEventTagNum 5000000 471
Because the database can now be dynamic, we added reader/writer locks
which adds a 65ns (uncontended) premium on lookups, and switch to
check for an allocation adds 25ns (either open code, or using
string_view, no difference) which means our overall speed takes 90%
as long as the requests did before we switched to unordered_map.
Faster than before where we originally utilized binary lookup on
static content, but not by much. Dynamic updates that are not cached
locally take the following times to acquire long path to logd to
generate.
BM_lookupEventTag 20000000 139
BM_lookupEventTag_NOT 20000000 87
BM_lookupEventFormat 20000000 139
BM_lookupEventTagNum_logd_new 5000 335936
BM_lookupEventTagNum_logd_existing 10000 249226
The long path pickups are mitigated by the built-in caching, and
the public mapping in /dev/event-log-tags.
SideEffects: Event tags and signal handlers do not mix
Test: liblog benchmarks
Bug: 31456426
Change-Id: I69e6489d899cf35cdccffcee0d8d7cad469ada0a
Will register a new event tag by name and format, and return an
event-log-tags format response with the newly allocated tag.
If format is not specified, then nothing will be recorded, but
a pre-existing named entry will be listed. If name and format are
not specified, list all dynamic entries. If name=* list all
event log tag entries.
Stickiness through logd crash will be managed with the tmpfs file
/dev/event-log-tags and through a reboot with add_tag entries in
the pmsg last logcat event log. On debug builds we retain a
/data/misc/logd/event-log-tags file that aids stickiness and that
can be picked up by the bugreport.
If we detect truncation damage to /dev/event-log-tags, or to
/data/misc/logd/event-log-tags, rebuild file with a new first line
signature incorporating the time so mmap'd readers of the file can
detect the possible change in shape and order.
Manual testing:
Make sure nc (netcat) is built for the target platform on the host:
$ m nc
Then the following can be used to issue a request on the platform:
$ echo -n 'getEventTag name=<name> format="<format>"\0EXIT\0' |
> nc -U /dev/socket/logd
Test: gTest logd-unit-test --gtest_filter=getEventTag*
Bug: 31456426
Change-Id: I5dacc5f84a24d52dae09cca5ee1a3a9f9207f06d
Report multiple identical chatty messages differently than for
regular expire chatty messages. Multiple identical will
report identical count, while spam filter will report
expire count.
This should reduce the expected flood of people confused
but chatty messages in continuous logcat output.
Test: gTest logd_unit_tests --gtest_filter=logd.multiple*
Change-Id: Iad93d3efc6a3938a4b87ccadddbd86626a015d44
Resolve issues seen on continuous testing frame:
- statistics test, info instead of fail on missing radio log data.
- sepolicy switch from /data/misc/logd/ to /data/backup/ as the
directory we access(2) to inject sepolicy violations. The key here
is we are still root, but we are in u:r:shell:s0, and the directory
does not provide us DAC access (0700 system system) so we trigger
the pair dac_override and dac_read_search on every try to get past
the message de-duper. /data/misc/logd is not always there, until
logpersist is enabled, but /data/backup is always there.
- a stricter signature of '): avc: denied'
- put in a looser threshold for sepolicy_rate_limiter_spam test.
Test: gTest logd-unit-tests --gtest_filter=logd.sepolicy*
Bug: 34454758
Change-Id: I28ce4fdb51dc4869944e3253b593ce222d16ec98
Processing overhead for selinux violation messages is costly. We want
to deal with bursts of violations, but we have no intent of allowing
that sustained burst to go unabated as there is a cost of processing
and battery usage.
Tunables in libaudit.h are:
AUDIT_RATE_LIMIT_DEFAULT 20 /* acceptable burst rate */
AUDIT_RATE_LIMIT_BURST_DURATION 10 /* number of seconds of burst */
AUDIT_RATE_LIMIT_MAX 5 /* acceptable sustained rate */
Since we can only asymptotically handle DEFAULT rate, we set an upper
threshold of half way between the MAX and DEFAULT rate.
Default kernel audit subsystem message rate is set to 20 a second.
If sepolicy exceeds 125 violation messages over up to ten seconds
(>=~12/s), tell kernel audit subsystem to drop the rate to 5 messages
a second. If rate drops below 50 messages over the past ten seconds
(<5/s), tell kernel it is ok to increase the burst rate back to 20
messages a second.
Test: gTest logd-unit-tests --gtest_filter=logd.sepolicy_rate_limiter_*
Bug: 27878170
Change-Id: I843f8dcfbb3ecfbbe94a4865ea332c858e3be7f2
Some kernels have a bug which causes a newline to show up in audit
messages. The embedded newlines cause one message to look like two due
to prefix controls.
Replace any newlines with spaces. Duplicate spaces are further
consolidated in code immediately after this newly added code.
Test: create an audit message with a newline, and watch it be cleaned up.
Bug: 27878170
Change-Id: Id90c29ab9e10d3be96f51403b0293622d782422a
log selinux audit messages boolean (true or false, default true)
selection for logging destinations:
ro.logd.auditd - turn on logd.auditd to pick up violations.
ro.logd.auditd.dmesg - to the kernel log.
ro.logd.auditd.main - to the "main" log buffer.
ro.logd.auditd.events - to the "events" log buffer.
We used to also read logd.auditd.dmesg and persist.logd.auditd.dmesg
which do not get refreshed when /data mounts internally. This is a
confusing state as these properties will be read after a logd crash
and restart, adjusting the behavior of the logger. Same can be said
for logd.auditd as well. Drop reading these other parameters.
Test: manual set r/o parameters, stop/start logd to confirm behavior
Bug: 33969000
Bug: 27878170
Change-Id: I1a6bb4a903074c9aa7b227cf583a0094d49cbefd
Until the socket ages out, it sticks around and gets reused in
subsequent tests affecting the outcome of those tests. We opt
to run logd.timeout in a forked and isolated process to keep
these conditions from interfering.
Adjusted benchmark execute to only run the tests we are
interested in to improve the time it takes to run.
Commented some areas of code to make them easier to maintain.
Test: gTest logd-unit-tests success
Bug: 33962045
Change-Id: Ic1b98bc4a2d7e8927f1a87628e3bcc368c9cf8ce
Caused +/- field data to land under the Pruned column
This reverts commit 0adcc3e3e8.
Test: manual
Bug: 30118730
Change-Id: Ic75ce3a90baded19f3efc0cc77474fe5d9a8accd
As an extension to the duplicate multiple message filtering, special
case liblog tagged event messages to be summed. This solves the
inefficient and confusing duplicate message report from the DOS attack
detection such as:
liblog: 2
liblog: 2
liblog: 2
liblog: 2
liblog: 3
which would result in:
liblog: 2
chatty: ... expire 2 lines
liblog: 2
liblog: 3
And instead sums them and turns them all into:
liblog: 11
liblog messages should never be subject to chatty conversion.
Test: liblog-benchmarks manually check for coalesced liblog messages
and make sure they do not turn into chatty messages.
Instrumented code to capture sum intermediates to be sure.
Bug: 33535908
Change-Id: I3bf03c4bfa36071b578bcd6f62234b409a91184b
Inspection turned up that for the case of three identical messages,
the result would be a stutter of the first message only. Added
comments to describe the state machine, incoming variables, outcoming
and false condition outputs, for proper maintenance in the future.
Test: gTest liblog-benchmarks BM_log_maximum* and manually check
for correct midstream chatty messages,
Bug: 33535908
Change-Id: I852260d18a484e6207b80063159f1a74eaa83b55
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
To support upcoming disk usage calculation optimizations, this change
creates a new GID for each app that will be used to mark its cached
data. We're allocating these unique GIDs so that we can use
quotactl() to track cached data on a per-app basis.
This change also tightens up the implementation of both the cache
and shared GID calculation to ensure that they stay inside the valid
ranges, and includes tests to verify.
Test: builds, boots, tests pass
Bug: 27948817
Change-Id: Ie4377e5aae267f2da39a165888139228995987cb
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
NULL represents system default. In the future, NULL could represent
static and dynamic tags, which can come from multiple files based on
implementation details in the liblog library.
Test: gTest logd-unit-tests & liblog-unit-tests
Bug: 31456426
Change-Id: I0e3d296de81ca299ae63d7b83781639ee67ec298
Debugging aid. Allows us to run:
$ cat -n '<STUFF>\0EXIT\0' | nc -U /dev/socket/logd
and the pipeline will exit once done. Without the EXIT command
we will have to <CTRL+C> out to terminate the pipeline. This is
necessary since Android's netcat command does not support the -q
feature, and having the EXIT command is faster and cleaner anyways.
Test: manual as noted above.
Bug: 31456426
Change-Id: I65333358188db85e2eb1bb6a14deed1565826ac4
files.[h|cpp] is bound to be abused with junk, replace with
android_get_control_file.[h|cpp]. Plus some sundry cleanup.
Test: gTest libcutils-tests, logd-unit-tests, liblog-unit-tests,
logcat-unit-tests and init_tests
Bug: 32450474
Change-Id: Ibd4a7aa4624ea19a43d1f98a3c71ac37805d36b5
An estimate based on chatty impact for all known pids, uids and tags
and per log id if applicable, calculate the maximum last pruned
watermark iterator map usage and add to the Total Overhead.
Test: Confirm that the Total Overhead change is negligable.
Bug: 31942525
Change-Id: Icd2e9bc0747c3376ca0e9c90aa110c103529d98f
Add in to the Total Overhead the amount of storage we are
using to hold on to the statistics.
Test: see that the Total Overhead accounts for about 100K
Bug: 31942525
Change-Id: Ibe241c0bccc5a9df52395802338c8a7fc3b64104
* changes:
logd: if eng build, be a bit more permissive about failures
libcutils: klog inherit android_get_control_file("/dev/kmsg")
logd: start logd service in logd uid
logd: auditd + klogd control CAPS
logd: drop capabilities in logd --reinit and logd.daemon
logd: drop libminijail dependency
logd: start logd services in logd gid
logd: set executable's capabilities in file system
logd: inherit android_get_control_file()
init: service file keyword
libcutils: add android_get_control_file()
libcutils: add android_get_control_socket() test
Allows us some leaway to investigate logd issues on eng builds
Test: gTests logd-unit-tests, liblog-unit-tests and logcat-unit-tests
Manual on eng builds, bad logd.rc to fake permission issues
Bug: 32450474
Change-Id: I432016e29e5601d67c502076ead941cecdcbebe7
Use libcap instead of libminijail. Set CAP_SETGID before setgroups,
then clear it afterwards.
Test: gTest logd-unit-tests, liblog-unit-tests and logcat-unit-tests
Bug: 32450474
Change-Id: I2ed027fd5efd95f76b1dd4c5791bae5f2ea94c28
Setup and then collect from the environment /proc/kmsg and /dev/kmsg
file descriptors. Do not do so for logcat --reinit.
Test: gTest logd-unit-tests, liblog-unit-tests and logcat-unit-tests
Bug: 32450474
Change-Id: Ied537ca561fcd4e71a9ad9c57398a23ba23f6ced
Do not allow anyone to see logd memory.
Test: gTest logd-unit-tests, liblog-unit-tests and logcat-unit-tests
Bug: 32450474
Change-Id: Ic7377efcb7e1d3cd91b50741061037a0fb589045
getTag() becomes invalid when entry is dropped because mMsg
disappears to save space; but the per-tag spam filter depends on it
still being valid. Conserve space in LogBufferElement by optimizing
the size of the fields, then add a new mTag field that is set in the
object constructor. Add an isBinary() method.
SideEffects: save 12 bytes/log message overhead on 64-bit.
Test: define DEBUG_CHECK_FOR_STALE_ENTRIES and look for stale entries
Bug: 32247044
Change-Id: Iaa5f416718a92c9e0e6ffd56bd5260d8b908d5c0
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
Do not make the assumption that if worstPid is set, that the log
buffer id is not LOG_ID_EVENTS or LOG_ID_SECURITY. Add comments
to prevent future over-optimization based on this assumption.
Make sure we reset mLast[id] = begin() when we mark it unset, but
tell optimizer this is an _impossible_ path.
SideEffects: drop two branches in all erase calls, gain an unordered
find() on an empty list for events and security buffers.
Test: gTest logd-unit-tests, liblog-unit-test & logcat-unit-tests
Bug: 32247044
Change-Id: Ic156ca2253c050c28021cedf48bedaf7bd692c09
mLastWorstPidOfSystem is filled with iterator references
that are not from AID_SYSTEM to aid the performance. But
we only clear entries from the list during erase if they
are from AID_SYSTEM. Remove the filter check in erase so
the stale references will be removed.
The conditions that caused this failure are difficult to
reproduce and are rare.
Test: gTests logd-unit-tests, liblog-unit-tests and logcat-unit-tests
Bug: 32247044
Bug: 31237377
Change-Id: Ie405dd643203b816cac15eef5c97600551cee450
Point to log/log.h where necessary, define LOG_TAG where necessary.
Accept that private/android_logger.h is suitable replacement for
log/logger.h and android/log.h.
Correct liblog/README
Effectively a cleanup and controlled select revert of
'system/core: drop or replace log/logger.h' and
'system/core: Replace log/log.h with android/log.h'.
Test: compile
Bug: 30465923
Change-Id: Ic2ad157bad6f5efe2c6af293a73bb753300b17a2
On 64 bit system, calculates to roughly 80 bytes of metadata and
list overhead for each entry.
In unit test example, we report 3388987 bytes of logging data and
overhead total, showmap reports 4652K of dirty data. We still want
to account for the remainder (fragmentation, other sources of
internal allocations etc).
Test: see values and check math
Bug: 31942525
Change-Id: I75f3162ce691faf1ae5a5dec18939fea535ede7e
Allows us to mitigate the impact of MAP_PRIVATE and copy on write by
calling android_lookupEventTag_len instead of android_lookupEventTag,
and delaying the copy on write impact to the later. We return a
string length in a supplied location along with the string pointer
with android_lookupEventTag_len(const EventTagMap* map, size_t* len,
int tag). The string is not guaranteed to be nul terminated. Since
android_lookupEventTag() called even once can cause the memory
impact, we will mark it as deprecated, but we currently have no
timeframe for removal since this is a very old interface.
Add an API for __android_log_is_loggable_len() that accepts the non
null terminated content and fixup callers that would gain because the
length is known prior to the call either in the compiler or at
runtime. Tackle transition to android_lookupEventTag_len() and
fixup callers.
On any application that performs logging (eg: com.android.phone)
/proc/<pid>/smaps before:
xxxxxxxxxx-xxxxxxxxxx rw-p 00000000 fd:00 463 /system/etc/event-log-tags
Size: 20 kB
Rss: 20 kB
Pss: 1 kB
Shared_Clean: 0 kB
Shared_Dirty: 20 kB
Private_Clean: 0 kB
Private_Dirty: 0 kB
Referenced: 0 kB
Anonymous: 20 kB
AnonHugePages: 0 kB
Swap: 0 kB
SwapPss: 0 kB
KernelPageSize: 4 kB
MMUPageSize: 4 kB
Locked: 0 kB
VmFlags: rd wr mr mw me ac
/proc/<pid>/smaps after:
xxxxxxxxxx-xxxxxxxxxx rw-p 00000000 fd:00 1773 /system/etc/event-log-tags
Size: 20 kB
Rss: 20 kB
Pss: 1 kB
Shared_Clean: 20 kB (was 0kB)
Shared_Dirty: 0 kB (was 20kB)
Private_Clean: 0 kB
Private_Dirty: 0 kB
Referenced: 20 kB (was 0kB)
Anonymous: 0 kB (was 20kB)
AnonHugePages: 0 kB
Swap: 0 kB
SwapPss: 0 kB
KernelPageSize: 4 kB
MMUPageSize: 4 kB
Locked: 0 kB
VmFlags: rd wr mr mw me ac
Added liblog-unit-tests --gtest_filter=liblog.event_log_tags to
check for Shared_Clean: to not be 0 and Anonymous: to be 0 for
all processes referencing event-log-tags. Which can include multiple
references to /system/etc/event-log-tags and future possible refs to
/data/misc/logd/event-log-tags and /dev/event-log-tags. We want
failure messages to help point to errant code using the deprecated
interface.
This change saves 1/4MB of memory or more on a typical system.
Test: gTest liblog-unit-tests
Bug: 31456426
Change-Id: I9e08e44d9092bd96fe704b5709242e7195281d33
Should use android/log.h instead of log/log.h as a good example
to all others.
Test: Compile
Bug: 26552300
Bug: 31289077
Change-Id: If4c9711eb57267d4707b03d54a932af9de241b13
Always used in combination with log/logger.h except in log_time.cpp,
and not used externally. As a result liblog has to support stl, a
small price to pay since goal is to convert liblog to C++ internally.
Test: compile
Bug: 31456426
Bug: 26552300
Bug: 31289077
Change-Id: I72828ec807d0a2c8e40bbdebd7a69f147a7ca5a9
pruneRows not necessarily ULONG_MAX when uid not system source,
allow for speed up for status response if pruneRows exhausted.
Change-Id: I38c76bb20215e3d96513a575e2e3bc85a5e5b41c
mLastWorstPidOfSystem is supposed to be indexed by element->getPid()
Bug: 31237377
Bug: 30797725
Bug: 30688716
Change-Id: I81a55e92f175ded1c571a0aa8836736d86b36b1d
- check hdr_size to make sure it is in the expected range
from sizeof entry_v1 to entry (entry_v4).
- alter msg() method to report NULL on invalid hdr_size
- alter all users of msg() method.
Bug: 30947841
Change-Id: I9bc1740d7aa9f37df5be966c18de1fb9de63d5dd
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
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
Mark Salyzyn