blob: bc8fc99e7d4390d8bdc0f7cc021b9f65708d7e84 (
plain) (
blame)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
|
graphic: 0.937
performance: 0.699
semantic: 0.625
device: 0.574
architecture: 0.531
ppc: 0.481
peripherals: 0.464
network: 0.459
x86: 0.458
files: 0.455
i386: 0.417
kernel: 0.410
PID: 0.407
user-level: 0.388
permissions: 0.358
vnc: 0.352
risc-v: 0.328
TCG: 0.314
VMM: 0.302
KVM: 0.291
register: 0.290
mistranslation: 0.284
arm: 0.266
debug: 0.266
hypervisor: 0.264
socket: 0.238
virtual: 0.190
boot: 0.146
assembly: 0.077
Strace Log Output Mangled
Description of problem:
The syscall log entries from the strace logging capability can be interrupted by other log messages before the full syscall line is
complete.
This makes parsing the strace syscall lines from the log output difficult.
Steps to reproduce:
1. Run the supplied command with a simple dynamically linked binary, or a binary that performs mmaps
2. Notice that the strace 'mmap' syscall log entries in the trace file are interrupted by the page log output
Additional information:
I have attached an example log from a dynamically linked 'hello world' binary, which demonstrates the bug in the mmap syscall strace entries. [output.trace](/uploads/88c83273582d00241fbf95af735dcc61/output.trace)
I believe this bug caused by a couple of things:
Firstly, in the linux-user/syscall.c file: the strace syscall entry is not output atomically, but instead split across two calls:
The first half is at `print_syscall`: https://gitlab.com/qemu-project/qemu/-/blob/master/linux-user/syscall.c#L13153
And the return value (and new line) is printed in `print_syscall_ret`: https://gitlab.com/qemu-project/qemu/-/blob/master/linux-user/syscall.c#L13160
In the case of the mmap syscall, the function `log_page_dump` is called between these two functions resulting in the mangled log output:
https://gitlab.com/qemu-project/qemu/-/blob/master/linux-user/mmap.c#L633
There may be other syscalls that behave similarly, but this was noticed due to the mmap behavior.
Internally to the `print_syscall` and `print_syscall_ret` functions, `qemu_log` is called multiple times to compose the full log entry, and it seems that it is inside `qemu_log` that the logfile lock is obtained and dropped - so theoretically another thread can output to the log during the printing of a single syscall entry between these `qemu_log` calls. I do not know if this actually happens in practice besides the mmap scenario described above.
|