Commit graph

455 commits

Author SHA1 Message Date
Mark Salyzyn
9f27c6985d Merge "logd: add getEventTag id= command" am: 3e3aaca4c3 am: b7987ce8c4
am: 9bd6e36a9f

Change-Id: I5995e912626100462dd5a706d5e3af7d92488155
2017-02-22 23:33:55 +00: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
Greg Hartman
a6754dd558 Fix read past end of malloc block in logd
Bug: 35412453
Test: Local build
Change-Id: I0f9dee84ef689b042926b6b48abf0caeaa784add
2017-02-16 18:30:45 +00: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
Treehugger Robot
5badada997 Merge "LogAudit.cpp: replace newlines with spaces in audit messages" 2017-01-03 22:21:37 +00:00
Nick Kralevich
2e58867771 LogAudit.cpp: replace newlines with spaces in audit messages
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
2017-01-03 12:39:28 -08:00
Mark Salyzyn
ce80da3018 logd: Add support for ro.logd.auditd.[main|events]
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
2017-01-03 09:44:42 -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
684bdb576d logd: LogBufferElementKey use uint32_t for uid
Test: gTest liblog-unit-tests, logd-unit-tests & logcat-unit-test
Change-Id: Icae34b1fa0b3df0a45ad175ec81aaf232f322f38
2016-12-21 12:16:46 -08:00
Treehugger Robot
2ead17196c Merge "logd: trailing spaces in log statistics (part deux)" 2016-12-20 18:16:15 +00:00
Treehugger Robot
1fa079b255 Merge "Revert "logd: trailing spaces in log statistics"" 2016-12-20 18:16:00 +00:00
Treehugger Robot
27425fd80d Merge "logd: sum liblog tag messages" 2016-12-19 23:43:48 +00:00
Treehugger Robot
9fa0215e15 Merge "logd: correct duplicate message state machine" 2016-12-19 23:43:23 +00:00
Mark Salyzyn
b545e1c9e3 logd: trailing spaces in log statistics (part deux)
Test: manual
Bug: 30118730
Change-Id: Iafda6f95e1b1377649e01868c81c0056c116e01b
2016-12-19 15:06:42 -08:00
Mark Salyzyn
d966e22680 Revert "logd: trailing spaces in log statistics"
Caused +/- field data to land under the Pruned column

This reverts commit 0adcc3e3e8.

Test: manual
Bug: 30118730
Change-Id: Ic75ce3a90baded19f3efc0cc77474fe5d9a8accd
2016-12-19 15:06:37 -08:00
Mark Salyzyn
1dfb4de436 logd: sum liblog tag messages
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
2016-12-19 14:03:38 -08:00
Mark Salyzyn
8f83a35511 logd: correct duplicate message state machine
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
2016-12-19 14:01:45 -08:00
Mark Salyzyn
3296291cff logd: add android::sizesTotal() function
Test: gTest liblog-unit-tests, logd-unit-tests and logcat-unit-tests
Bug: 31456426
Change-Id: I6fb6cd589227fc43d22f9336e01f1bf7e3feb24c
2016-12-19 08:00:16 -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
Jeff Sharkey
dff44709cf Define range of GIDs for cached app data.
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
2016-12-13 13:28:08 -07: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
10f4044341 Merge "system/core: replace EVENT_TAG_MAP_FILE with NULL"
am: 9bfd9f558b

Change-Id: Ief7fcc4f7dd8086186b38c091fed626560ca7215
2016-11-29 19:46:50 +00:00
Mark Salyzyn
1179eb8048 system/core: replace EVENT_TAG_MAP_FILE with NULL
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
2016-11-21 11:13:02 -08:00
Mark Salyzyn
2cfd0e08e9 Merge "logd: add EXIT command"
am: 16300f192b

Change-Id: Idd68cfba26f8fcc928db4fe2483d30e5d4f49a59
2016-11-18 16:10:23 +00:00
Mark Salyzyn
c8749d5108 logd: add EXIT command
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
2016-11-17 14:42:33 -08:00
Mark Salyzyn
809dee506e Merge "libcutils: move cutils/files.h to cutils/android_get_control_file.h"
am: 8c41e791ed

Change-Id: Ifbc00285da734859d590153a7c6cfc8e51c014f9
2016-11-17 15:33:02 +00:00
Mark Salyzyn
52bd37e633 libcutils: move cutils/files.h to cutils/android_get_control_file.h
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
2016-11-16 15:56:56 -08:00
Mark Salyzyn
49893142ec logd: report last prune memory overhead
am: b0672290e3

Change-Id: I4b060ad4427e24170cc7a3aeae7aa9f6643ba8d6
2016-11-04 20:57:16 +00:00
Mark Salyzyn
1970d994b6 logd: report statistics memory overhead
am: 6d981af120

Change-Id: I69376a8783867a21f0cd85eea4b299f3d2c81a95
2016-11-04 20:57:12 +00:00
Mark Salyzyn
f8ba9eb1a3 logd: if eng build, be a bit more permissive about failures
am: 107e29ac1b

Change-Id: I85ebcae9f756bf2feb79e6d77ea63ad0b2ff4829
2016-11-04 14:43:47 +00:00
Mark Salyzyn
21dbb8aece logd: start logd service in logd uid
am: 77fdb22cf6

Change-Id: I38d93fb74ea4f37ee137f78063d082637b8fd68a
2016-11-04 14:43:36 +00:00
Mark Salyzyn
3d2c4829a0 logd: auditd + klogd control CAPS
am: d2b3291ffa

Change-Id: I7d8fd4a7df7ceffd90e8eaab03861ae426cbf35b
2016-11-04 14:43:31 +00:00
Mark Salyzyn
83a40b0eb2 logd: drop capabilities in logd --reinit and logd.daemon
am: d8f01807b8

Change-Id: I17f06463258e95a6cc83242cc8a8d4bb0ccb4907
2016-11-04 14:43:26 +00:00
Mark Salyzyn
c65f2ca81f logd: drop libminijail dependency
am: f0b8e1bce6

Change-Id: I968916b41f82fa1cbe4f7ac37dc75c938a9c1627
2016-11-04 14:43:21 +00:00
Mark Salyzyn
b0e425abc4 logd: start logd services in logd gid
am: 5b44340acb

Change-Id: Id9f27660a09e640815071dac85ed4bac78172886
2016-11-04 14:43:17 +00:00
Mark Salyzyn
b0672290e3 logd: report last prune memory overhead
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
2016-11-04 07:43:16 -07:00
Mark Salyzyn
6d981af120 logd: report statistics memory overhead
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
2016-11-04 07:43:16 -07:00
Mark Salyzyn
1259d9ea4b logd: inherit android_get_control_file()
am: e0b8ccd1a3

Change-Id: I7b6fc3898d2e69542309fe120122849579f91f22
2016-11-04 14:43:07 +00:00
Treehugger Robot
fc3e90689e Merge changes I432016e2,Id208b11b,Ia6a38729,Icdaf9e35,I842a7a64, ...
* 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
2016-11-04 14:38:23 +00:00
Mark Salyzyn
cb2314e5bd Merge "logd: switch to using arraysize() from libbase macros"
am: fc08963f85

Change-Id: If17fd9389ec65f379fa42096e835be2ed667f703
2016-11-03 22:14:34 +00:00
Treehugger Robot
fc08963f85 Merge "logd: switch to using arraysize() from libbase macros" 2016-11-03 22:07:42 +00:00
Mark Salyzyn
d1687af980 logd: clear DUMPABLE
am: 6a70ded7bf

Change-Id: I4bcfb53d9c4a13761c80a8f2070320c85b486b0b
2016-11-03 21:01:45 +00:00
Mark Salyzyn
107e29ac1b logd: if eng build, be a bit more permissive about failures
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
2016-11-03 13:34:27 -07:00
Mark Salyzyn
77fdb22cf6 logd: start logd service in logd uid
Test: gTest logd-unit-tests, liblog-unit-tests and logcat-unit-tests
      Manual inspect grep '^Cap' /proc/<tid>/status for correct capabilities
Bug: 32450474
Change-Id: Ia6a3872901969a789d4309d410dbfd5f5d17b3ce
2016-11-03 13:34:27 -07:00
Mark Salyzyn
d2b3291ffa logd: auditd + klogd control CAPS
Test: gTest logd-unit-tests, liblog-unit-tests and logcat-unit-testsa
Bug: 32450474
Change-Id: Icdaf9e352e86c9e140928509201da743004aeedb
2016-11-03 13:34:27 -07:00
Mark Salyzyn
d8f01807b8 logd: drop capabilities in logd --reinit and logd.daemon
Test: gTest logd-unit-tests, liblog-unit-tests and logcat-unit-tests
Bug: 32450474
Change-Id: I842a7a64f0ba695acef66caf54270f9475c9f9ac
2016-11-03 13:34:27 -07:00