Commit graph

32 commits

Author SHA1 Message Date
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
407537f798 logd: add getEventTag id= command
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
2017-02-22 14:16:31 -08:00
Mark Salyzyn
c9e5f37166 liblog: add android_lookupEventTagNum
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
2017-02-02 15:21:15 -08:00
Mark Salyzyn
61e9ce6709 logd: add getEventTag command and service
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
2017-02-02 14:24:18 -08:00
Mark Salyzyn
b5b8796785 logd: multiple identical do not report expired
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
2017-01-24 11:02:18 -08:00
Mark Salyzyn
c3c06294e5 logd: test: switch to /data/backup/ for sepolicy avc injection
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
2017-01-20 09:42:02 -08:00
Mark Salyzyn
247d682fe1 logd: sepolicy dynamic rate limiting
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
2017-01-04 14:46:58 -08:00
Mark Salyzyn
1736c4866c logd: gtest: logd.timeout socket does not clean up properly
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
2016-12-29 12:59:22 -08: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
c8d3194098 logd: switch to using arraysize() from libbase macros
Test: logd-unit-tests, liblog-unit-tests & logcat-unit-tests
Bug: 32450474
Change-Id: Iacdc4677f2c83898a7812c2af2c36e7ff7d92764
2016-11-03 12:27:29 -07: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
0dd4431072 logd: logcat: Replace log/log.h with android/log.h
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
2016-09-30 12:47:05 -07:00
Mark Salyzyn
305374cf0f logger: validate hdr_size field in logger entry
- 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
2016-08-23 14:51:50 -07:00
Mark Salyzyn
5c77ad55d0 logd: sock_alloc_send_pskb starves pruning
Allow socket send syscall to terminate after 32 seconds if reader
stalled because of memory pressure allocating new network buffers

Add a gTest to catch regressions, add security buffer to log_dump

Bug: 27242723
Change-Id: Idaa6699d9d284e7f5f723ae0e76b3d6aa3371489
2016-02-24 10:15:32 -08:00
Mark Salyzyn
ef4e4f3f07 logd: test wrap functionality
Behavior is modified now, so react by fortifying the tests

Bug: 26447386
Change-Id: I6295783a0bc75282499aeba503a86bdb846908b5
2016-01-21 11:56:23 -08:00
Mark Salyzyn
7b4a2049b0 logd: test drop __unused
Change-Id: I1ccf49809b8a0a125601bdb52834c463e2d94165
2015-12-18 10:35:00 -08:00
Mark Salyzyn
fc9f5b8af4 logd: test wakeup on wrap timeout
Change-Id: I8dd605452f1fef7706a627eedc251e39bb2e34cc
2015-12-07 14:24:02 -08:00
Mark Salyzyn
074f542476 logd: test: leniency towards background cgroup
Accepting a new lower standard of performance due to
the realities of the background cgroup.

Change-Id: Icd85050ffbf7f0129dd4c053323faedd0ff74048
2015-12-07 11:26:12 -08:00
Mark Salyzyn
f33657da4d logd: test: statistics report chatty effective percentage
Add parsing to recognize optional chatty effective
percentage field as reported in the logger statistics.

Bug: 22855208
Change-Id: Id9c5e4a907ed0f9319beb9ddbfa27f4844bffc7d
2015-12-07 11:10:04 -08:00
Mark Salyzyn
cb41e3673b logd: deprecate TARGET_USES_LOGD
This is not the kernel logger you are looking for

Bug: 22787659
Change-Id: Idbf8fae908287ae9a96007b6353ec56d3c49f5bf
2015-07-28 09:37:07 -07:00
Mark Salyzyn
62d6a2a921 logd: test modernization
Bug: 19603976
Change-Id: Ie920c128e7e6a436fea7a96c7d68bc39e13a2ad4
2015-05-26 12:24:51 -07:00
Elliott Hughes
bcc2b5f44a Remove LOCAL_ADDITIONAL_DEPENDENCIES in cases where it's not needed.
Change-Id: I720b8ef1050da45a7833adef8219b6acb2cf3a38
2015-04-02 14:31:07 -07:00
Mark Salyzyn
4ed16b4381 Revert "logd: Add minimum time bucket statistics"
This forward port reverts
    commit e457b74ce6

No longer as necessary once we add
    liblog: Instrument logging of logd write drops
Although this provided an indication of how close statistically we
were to overloading logd it is simpler to understand fails thus to
hunt and peck a corrected value for /proc/sys/net/unix/max_dgram_qlen

Change-Id: I2b30e0fc30625a48fd11a12c2d2cc6a41f26226f
2015-03-04 13:21:41 -08:00
Chih-Hung Hsieh
634118e261 logd: fix format-extra-args warning.
Bug: 17409250
Change-Id: Id50ebb57754b12d69ed605d0e2901b8e05c607c6
2014-09-12 23:37:42 +00:00
Mark Salyzyn
89472df4cd logd: test: disable kernel LOGGER
Bug: 15384806
Change-Id: I3072d6dd0618fa9ebe151c78a85eb121327f9df3
2014-07-10 13:31:57 -07:00
Mark Salyzyn
6e9aaae9ed logd: test: deal with spam filter turned off
Change-Id: I759c65e869d0c7cd81063fa7993ba3d67ef9cd06
2014-06-18 11:12:27 -07:00
Mark Salyzyn
0c57bd864d logd: test: modernize
- Correct default tense for kernel or user logger
- harden code that parses the benchmark data
- give more meaning to the spam filter test

Change-Id: I97699037ca9d56718f53f08d22be79092fb431de
2014-06-18 11:12:27 -07:00
Mark Salyzyn
c61895ac3a logd: turn on -Werror
- Deal with some -Wunused / -Wunused-variable issues

Change-Id: Ic86cd7b0680868ad0536198b71a34cb19134fc21
2014-05-02 14:16:00 -07:00
Mark Salyzyn
e821dace41 logd: enable UID spam filter and test
Change-Id: Ie9c7a744e341e6e64afa14973d4d095717c97933
2014-04-25 11:03:58 -07:00
Mark Salyzyn
696817d352 liblog: Statistics truncated to 16384 bytes
- if network read/write broken up, reassemble the pieces.
- Use a 20ms poll to check if a new fragment has been
  sent by the other side.
- fixup logd-unit-tests to take a (simplified) fragment
  from the liblog changes.

Bug: 14164765
Change-Id: I98ff87888c119e1e8349717646d0f733e8971bc8
2014-04-21 17:07:25 -07:00
Mark Salyzyn
99f47a9e7c logd: liblog: logcat: debuggerd: Add LOG_ID_CRASH
Change-Id: Iea453764a1a4fc1661f461f10c641c30150e4d20
2014-04-16 15:38:50 -07:00
Mark Salyzyn
d3ba665020 logd: Add logd_test
* Test statistics output, all four main log id types
  are checked to be present, and output is properly
  formatted with header (ascii new-line terminated
  byte count) and trailer (newline formfeed) frames.
* On dev build test dgram_qlen, circumvent if
  liblog benchmarks executed first though.
* Test if kernel and user space loggers are
  present, and if any content has leaked to both.
* test benchmark and use it to verify worst UID pruning

Change-Id: I890c89f64825956f40108de806ed750b0170ac6c
2014-04-15 10:21:57 -07:00