liblog: use timeout for non-blocking socket ops
Use the available 2s socket timeout on open and read socket ops
for non-blocking mode.
Expand logcat exit condition with EWOULDBLOCK (see man recv) and
ETIMEOUT for connect
Logcat -t would hang if logd was busy or not available not respecting
the "dump_and_close" expected behaviour.
If the user would rather block and wait they should use -T option instead.
Bug: 196856709
Test: logd running. logcat -t exits immediately, logcat -T tails last line and waits for more until SIGTERM
Test: stop logd. logcat -t exits after 2s in connect() timeout. Start logd again
Test: logcat -T is launched in the background. During logcat runtime, logd is stopped and then resumed, logcat resumes printing logs
Test: logcat -m
Test: logcat -c -g and -G
Test: logd is stopped during a long logcat -t, enough time is given to read out all available logs (0.1s)
Test: logd is stopped during a long logcat -t there is no time to read all logs, logcat will later exit onsocket timeout and not block, fewer lines are written to log
Test: logd is already stopped or busy. logcat -T is started in background and waits in connect() until logd is available
Test results
TEST_1 logd running. logcat -t exits immediately, logcat -T tails last line and waits for more until SIGTERM
130|vsoc_x86_64:/ # ps -A | grep logd
logd 2755 1 10816296 6008 sigsuspend 0 S logd
logd 2758 1 10806064 4664 __skb_wait_for_more_packets 0 S logcat
vsoc_x86_64:/ # time logcat -t 1
--------- beginning of kernel
08-30 14:09:40.397 0 0 I logd : logdr: UID=0 GID=0 PID=2789 b tail=1 logMask=99 pid=0 start=0ns deadline=0ns
0m00.01s real 0m00.00s user 0m00.01s system
vsoc_x86_64:/ # time logcat -T 1
--------- beginning of kernel
08-30 14:10:05.113 0 0 I logd : logdr: UID=0 GID=0 PID=2793 n tail=1 logMask=99 pid=0 start=0ns deadline=0ns
08-30 14:10:14.286 0 0 I logd : logdr: UID=0 GID=0 PID=2795 b tail=1 logMask=99 pid=0 start=0ns deadline=0ns
^C 0m36.81s real 0m00.00s user 0m00.01s system
TEST_2 stop logd. logcat -t exits after 2s in connect() timeout. Start logd again
130|vsoc_x86_64:/ # kill -s SIGSTOP 2755
vsoc_x86_64:/ # time logcat -t 1
0m02.04s real 0m00.01s user 0m00.00s system
vsoc_x86_64:/ # kill -s SIGCONT 2755
TEST_3 logcat -T is launched in the background. During logcat runtime, logd is stopped and then resumed, logcat resumes printing logs
130|vsoc_x86_64:/ # logcat -T 1 &
[2] 2806
vsoc_x86_64:/ # --------- beginning of kernel
08-30 14:13:48.156 0 0 I logd : logdr: UID=0 GID=0 PID=2804 b tail=1 logMask=99 pid=0 start=0ns deadline=0ns
08-30 14:13:55.009 0 0 I logd : logdr: UID=0 GID=0 PID=2806 b tail=1 logMask=99 pid=0 start=0ns deadline=0ns
vsoc_x86_64:/ # kill -s SIGSTOP 2755
vsoc_x86_64:/ #
vsoc_x86_64:/ # kill -s SIGCONT 2755
vsoc_x86_64:/ # --------- beginning of system
08-30 14:14:29.068 572 617 V DisplayPowerController[0]: Brightness [0.39763778] reason changing to: 'manual', previous reason: 'manual [ dim ]'.
08-30 14:14:29.068 572 617 I DisplayPowerController[0]: BrightnessEvent: disp=0, physDisp=local:4619827353912518656, brt=0.39763778, initBrt=0.05, rcmdBrt=NaN, preBrt=NaN, lux=0.0, preLux=0.0, hbmMax=1.0, hbmMode=off, rbcStrength=0, powerFactor=1.0, thrmMax=1.0, wasShortTermModelActive=false, flags=, reason=manual, autoBrightness=false
vsoc_x86_64:/ # kill -s SIGTERM 2806
vsoc_x86_64:/ #
[2] - Terminated \logcat -T 1
TEST_4 test logcat -m
vsoc_x86_64:/ # logcat -m 3
--------- beginning of main
08-30 13:30:55.432 2755 2755 W auditd : type=1327 audit(0.0:31): proctitle="/system/bin/bpfloader"
--------- beginning of kernel
08-30 13:30:55.519 0 0 D LibBpfLoader: bpf_prog_load lib call for /apex/com.android.tethering/etc/bpf/net_shared/clatd.o (schedcls_ingress6_clat_rawip$4_14) returned fd: 9 (no error)
08-30 13:30:55.519 0 0 I LibBpfLoader: prog /sys/fs/bpf/net_shared/prog_clatd_schedcls_ingress6_clat_rawip id 26
TEST_5 logcat -c -g and -G
vsoc_x86_64:/ # logcat -c
vsoc_x86_64:/ # logcat -g
main: ring buffer is 256 KiB (70 KiB consumed, 0 B readable), max entry is 5120 B, max payload is 4068 B
system: ring buffer is 256 KiB (64 KiB consumed, 0 B readable), max entry is 5120 B, max payload is 4068 B
crash: ring buffer is 256 KiB (0 B consumed, 0 B readable), max entry is 5120 B, max payload is 4068 B
kernel: ring buffer is 256 KiB (78 KiB consumed, 0 B readable), max entry is 5120 B, max payload is 4068 B
vsoc_x86_64:/ # logcat -G 1M
vsoc_x86_64:/ # logcat -g
main: ring buffer is 1 MiB (0 B consumed, 0 B readable), max entry is 5120 B, max payload is 4068 B
system: ring buffer is 1 MiB (0 B consumed, 0 B readable), max entry is 5120 B, max payload is 4068 B
crash: ring buffer is 1 MiB (0 B consumed, 0 B readable), max entry is 5120 B, max payload is 4068 B
kernel: ring buffer is 1 MiB (0 B consumed, 0 B readable), max entry is 5120 B, max payload is 4068 B
vsoc_x86_64:/ #
TEST_6 logd is stopped during a long logcat -t, enough time is given to read out all available logs (0.1s)
vsoc_x86_64:/ # kill -s SIGCONT 2755
vsoc_x86_64:/ # logcat -t 9999999 > /sdcard/b.out &
[2] 3671
vsoc_x86_64:/ # sleep .1
[2] - Done \logcat -t 9999999 >/sdcard/b.out
vsoc_x86_64:/ # kill -s SIGSTOP 2755
vsoc_x86_64:/ # wc -l /sdcard/b.out
11151 /sdcard/b.out
vsoc_x86_64:/ #
TEST_7 logd is stopped during a long logcat -t there is no time to read all logs, logcat will later exit onsocket timeout and not block, fewer lines are written to log
vsoc_x86_64:/ #
vsoc_x86_64:/ # kill -s SIGCONT 2755
vsoc_x86_64:/ # logcat -t 9999999 > /sdcard/b.out &
[2] 3677
vsoc_x86_64:/ # sleep .01
vsoc_x86_64:/ # kill -s SIGSTOP 2755
vsoc_x86_64:/ # wc -l /sdcard/b.out
1903 /sdcard/b.out
vsoc_x86_64:/ #
vsoc_x86_64:/ #
[2] - Done \logcat -t 9999999 >/sdcard/b.out
vsoc_x86_64:/ #
TEST_8 logd is already stopped or busy. logcat -T is started in background and waits in connect() until logd is available
vsoc_x86_64:/ # kill -s SIGSTOP 2755
vsoc_x86_64:/ # logcat -T 1 &
[2] 3684
vsoc_x86_64:/ # sleep 10
vsoc_x86_64:/ #
vsoc_x86_64:/ # kill -s SIGCONT 2755
vsoc_x86_64:/ # --------- beginning of main
08-30 14:56:16.273 1386 1399 I m.android.phone: Background concurrent mark compact GC freed 3008KB AllocSpace bytes, 0(0B) LOS objects, 49% free, 3118KB/6237KB, paused 9.619ms,9.284ms total 58.950ms
--------- beginning of kernel
08-30 14:59:19.316 0 0 I logd : logdr: UID=0 GID=0 PID=3684 b tail=1 logMask=99 pid=0 start=0ns deadline=0ns
vsoc_x86_64:/ # kill -s SIGTERM 3684
vsoc_x86_64:/ #
[2] - Terminated \logcat -T 1
vsoc_x86_64:/ #
BYPASS_INCLUSIVE_LANGUAGE_REASON=man_used_as_manual_not_refering_to_a_person
Change-Id: Iec412a2ae4192ba2a91717966b635570d6c2f387
Signed-off-by: Andrei Diea <adiea@google.com>
Change-Id: I01aba7ee85b241e65ba35d81e00d72940a94bac2
2 files changed
