Product SiteDocumentation Site

⁠Глава 8. Трассировка вызовов

8.1. Управление вызовами
При разработке программы необходимо учитывать возможное поведение системы при ошибках. Отслеживание исполнения инструкций программы, выявление проблем и непосредственный контроль исполнения кода — всё это называется трассировка выполнения. Более подробно об этом можно прочитать в источниках, здесь же будет подробнее рассмотрена трассировка системных вызовов, направленная на отслеживание выполнения обращений программы к ОС.
Ключевым системным вызовом, позволяющим проводить трассировку, является ptrace. На его основе работает большинство (если не все) отладчиков (включая GDB). Также на его основе работают команды по предзагрузке библиотек.
Один из классических инструментов трассировки системных вызовов на основе ptrace —  проект Strace. Рассмотрим некоторые возможности утилиты:
  • непосредственно трассировка — показ всех произведённых системных вызовов (как видим, даже простейшая утилита date делает их немало):
    @user 
    [user@VM ~]$ date
Пт 18 июл 2025 11:52:32 MSK
[user@VM ~]$ strace date
execve("/usr/bin/date", ["date"], 0x7ffdb8d7cbe0 /* 79 vars */) = 0
brk(NULL)				= 0x55b7781f6000
access("/etc/ld.so.preload", R_OK)	= -1 ENOENT (Нет такого файла или каталога)
<...>
close(1)				= 0
close(2)				= 0
exit_group(0)				= ?
+++ exited with 0 +++
[user@VM ~]$ strace date |& wc
   116	   715	  8509
[user@VM ~]$
  • фильтрация трассировки по конкретным системным вызовам:
    @user 
    [user@VM ~]$ strace -e brk date
brk(NULL)				= 0x55fdaf32f000
brk(NULL)				= 0x55fdaf32f000
brk(0x55fdaf350000)			= 0x55fdaf350000
Пт 18 июл 2025 11:54:10 MSK
+++ exited with 0 +++
[user@VM ~]$
  • трассировка системных вызовов, связанных с конкретными объектами файловой системы:
    @user 
    [user@VM ~]$ strace -P /usr/lib/locale/ru_RU.utf8/LC_MESSAGES/SYS_LC_MESSAGES date
openat(AT_FDCWD, "/usr/lib/locale/ru_RU.utf8/LC_MESSAGES/SYS_LC_MESSAGES", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=70, ...}) = 0
mmap(NULL, 70, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fc1adbc6000
close(3)				= 0
Пт 18 июл 2025 11:56:14 MSK
+++ exited with 0 +++
[user@VM ~]$
  • получение более полной диагностики:
    @user 
    [user@VM ~]$ strace -e fstat date
fstat(3, {st_mode=S_IFREG|0644, st_size=43543, ...}) = 0
fstat(3, {st_mode=S_IFREG|0755, st_size=2012192, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=341, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=27012, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=23, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=52, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=165, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=62, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=34, ...}) = 0
fstat(3, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=70, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=294, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=2586930, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=3416, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=54, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=360460, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=908, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=908, ...}) = 0
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0), ...}) = 0
Пт 18 июл 2025 11:57:54 MSK
+++ exited with 0 +++
[user@VM ~]$ strace -e fstat date |& wc
    21	   125	  1109
[user@VM ~]$ strace -e fstat -v date |& wc
    21	   543	  7702
[user@VM ~]$
  • вывод таблицы выполнения системных вызовов:
    @user 
    [user@VM ~]$ strace -w -c date
Пт 18 июл 2025 11:59:58 MSK
% time	   seconds  usecs/call	   calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
24,36	 0,001554	   50	     31        14 openat
17,81	 0,001136	   54	     21		  mmap
13,39	 0,000854	  854	      1		  execve
13,25	 0,000845	   44	     19		  close
12,34	 0,000787	   41	     19		  fstat
 3,59	 0,000229	   76	      3		  mprotect
 2,36	 0,000150	  150	      1		1 access
 2,00	 0,000128	   42	      3		  brk
 1,94	 0,000124	   41	      3		  read
 1,58	 0,000101	   50	      2		  pread64
 1,33	 0,000085	   85	      1		  munmap
 0,85	 0,000054	   54	      1		  write
 0,85	 0,000054	   54	      1		  futex
 0,68	 0,000043	   43	      1		  arch_prctl
 0,65	 0,000041	   41	      1		  getrandom
 0,62	 0,000040	   39	      1		  prlimit64
 0,61	 0,000039	   38	      1		  rseq
 0,60	 0,000038	   38	      1		  set_robust_list
 0,59	 0,000038	   37	      1		  set_tid_address
 0,59	 0,000038	   37	      1		  lseek
------ ----------- ----------- --------- --------- ----------------
100,00	  0,006379	    56	     113	15 total
[user@VM ~]$

⁠8.1. Управление вызовами

Поскольку ptrace отлавливает системные вызовы в момент их вызова и в момент выхода из них, возможно подменять результат работы вызовов вручную. Для подмены предпочтительнее всего использовать ключ --inject, параметры ключа доступны в man.
Соберём пакет с использованием в директиве %check проверки на основе strace. Для начала напишем программу с достаточным количеством системных вызовов:
  1. Программа последовательно создаёт 10 файлов, пишет в них с помощью системного вызова write(), читает из них с помощью системного вызова read(), после чего выводит сообщение об успешной итерации в файл вывода:
    • все файлы являются временными и создаются в директории /tmp;
    • некорректная работа системных вызовов сопровождается записью информационных сообщений в файл вывода (что, вообще говоря, также сопровождается системными вызовами☺);
  2. Добавлена обработка двух пользовательских сигналов: SIGUSR1 выполняет исключительно информационную функцию, SIGUSR2 по достижении некоторого количества получений сигнала включает механизм завершения программы:
    @user: strace-pkg/strace-pkg-1.0.c 
    #include <stdio.h>
#include <unistd.h>
#include <string.h>
#include <fcntl.h>
#include <signal.h>

volatile int count = 0;

volatile int output_fd;
volatile int fd;


void hdlr(int sig) {
       switch(sig) {
	       case SIGUSR1:
		       dprintf(output_fd, "SIGUSR1 arrived: 42\n");
		       break;
	       case SIGUSR2:
		       dprintf(output_fd, "SIGUSR2 arrived %d time(s)\n", ++count);
		       if (count == 3) {close(fd); _exit(0);}
		       break;
       }
}

int main(void) {
       output_fd = open("/tmp/strace-pkg/output", O_TRUNC | O_CREAT | O_WRONLY);
       sigaction(SIGUSR1, &(struct sigaction) { .sa_handler = hdlr, .sa_flags = SA_RESTART}, NULL);
       sigaction(SIGUSR2, &(struct sigaction) { .sa_handler = hdlr, .sa_flags = SA_RESTART}, NULL);

       for (int i = 0; i < 10; i++) {
	       char filename[100] = {}, string[100] = {};
	       snprintf(filename, 100, "/tmp/strace-pkg/strace-file-%d", i);
	       fd = open(filename, O_TRUNC | O_CREAT | O_RDWR, 0666);
	       if (write(fd, "Hello\n\0", strlen("Hello\n\0")) != strlen("Hello\n\0")) {
		       dprintf(output_fd, "Bad writing\n");
		       close(fd);
		       _exit(0);
	       }
	       if (read(fd, string, strlen(string)) < 0) {
		       dprintf(output_fd, "Bad reading\n");
		       close(fd);
		       _exit(0);
	       }
	       dprintf(output_fd, "strace-file-%d success\n", i);
	       close(fd);
       }

       return 0;
}
При работе strace будет отлавливать исполнение системных вызовов, с помощью --inject будет проводиться ручная замена возвращаемых значений, а также будут отправляться сигналы. Программа будет реагировать на приходящие ответы и вести себя согласно описанной структуре.
В Makefile добавим описание команд strace --inject:
@user: strace-pkg/Makefile 
NAME=strace-pkg
VERSION=1.0

PROG=./$(NAME)-$(VERSION)
LOGFILE=/tmp/$(NAME)/log
OUTPUTFILE=/tmp/$(NAME)/output

GENS = /tmp/$(NAME)/
TRASH = *.o *~ o.*
CFLAGS = -Wall
CC = cc

all:	$(PROG)

check:	prep $(PROG)
	strace -o $(LOGFILE) $(PROG)
	diff $(OUTPUTFILE) ./check/test-0
	strace --inject=read:error=EBADF:when=5 -o $(LOGFILE) $(PROG)
	diff $(OUTPUTFILE) ./check/test-1
	strace --inject=close:retval=0:signal=SIGUSR2:when=4+ \
	       --inject=read:retval=6:signal=SIGUSR1:when=3 \
	       -o $(LOGFILE) $(PROG)
	diff $(OUTPUTFILE) ./check/test-2
	strace --inject=rt_sigaction:retval=1:when=1 \
	       --inject=read:retval=0:signal=SIGUSR1:when=3 \
	       -o $(LOGFILE) $(PROG) || true
	grep +++ $(LOGFILE) >> $(OUTPUTFILE)
	diff $(OUTPUTFILE) ./check/test-3

prep:
	mkdir /tmp/$(NAME)
	touch $(LOGFILE) $(OUTPUTFILE)

clean:
	rm -rf $(TRASH)

distclean:	clean
	rm -rf $(GENS)
Секция check состоит из четырех тестов, описанных с помощью strace --inject:
  1. Нулевой тест без дополнительных действий над системными вызовами. Программа должна завершиться корректно, а в выводе должна быть информация о корректном завершении всех десяти итераций;
  2. Проверка обработки системного вызова read: на его пятый вызов будет возвращена ошибка EBADF (некорректный файловый дескриптор), программа должна будет вывести сообщение об ошибке чтения и корректно завершиться;
  3. Обработка сигналов: после третьего вызова read в систему должен будет придти сигнал SIGUSR1, что должно будет отобразиться на выводе, а начиная с четвёртого и далее вызовов close в систему будут поступать сигналы SIGUSR2, которые должны будут привести к досрочному завершению программы;
  4. Проверка на некорректную обработку сигнала: системный вызов sigaction для SIGUSR1 не сработает, и по приходу сигнала после третьего read программа аварийно завершится, что будет отражено в записях strace.
Для проверки тестов добавим файлы с правильным выводом, который ожидается по завершении тестов.
@user: strace-pkg/check/test-0 — корректная работа программы: 
strace-file-0 success
strace-file-1 success
strace-file-2 success
strace-file-3 success
strace-file-4 success
strace-file-5 success
strace-file-6 success
strace-file-7 success
strace-file-8 success
strace-file-9 success
@user: sstrace-pkg/check/test-1 —  read-тест. Заметим, что поскольку до исполнения кода программы производится чтение динамической библиотеки libc (с помощью того же системного вызова read), ошибка должна будет появиться не на пятом, а на четвёртом вызове read программы: 
strace-file-0 success
strace-file-1 success
strace-file-2 success
Bad reading
@user: strace-pkg/check/test-2 — тест сигналов. Аналогичная особенность со «сдвигом» вызовов происходит и с close: до выполнения кода программы открываются (и, соответственно, закрываются) файлы кеша и библиотеки libc: 
strace-file-0 success
SIGUSR1 arrived: 42
strace-file-1 success
SIGUSR2 arrived 1 time(s)
strace-file-2 success
SIGUSR2 arrived 2 time(s)
strace-file-3 success
SIGUSR2 arrived 3 time(s)
@user: strace-pkg/check/test-3 — тест «необработки» сигнала. Для отслеживания ошибок необходимо будет объединить данные из файла вывода и информацию о завершении процесса: 
strace-file-0 success
+++ killed by SIGUSR1 +++
Файл спецификации получается довольно лаконичным:
@user: strace-pkg/strace-pkg.spec 
Name: strace-pkg
Version: 1.0
Release: alt1

Summary: Test pkg with strace

License: GPL-3.0-or-later
Group: Development/Other

Source0: %name-%version.tar.gz

%description
This is a small testing package with Strace check section

%prep
%setup

%build
%make_build

%install
install -D %name-%version %buildroot%_bindir/%name-%version

%check
make check

%files
%_bindir/*

%changelog
* Fri Jul 18 2025 UsamG1t <usamg1t@altlinux.org> 1.0-alt1
- Initial build
@user: .gear/rules 
tar.gz: . name=@name@-@version@
@user: 
[user@VM strace-pkg]$ tree
.
├── check
│   ├── test-0
│   ├── test-1
│   ├── test-2
│   └── test-3
├── Makefile
├── strace-pkg-1.0.c
└── strace-pkg.spec

2 directories, 7 files
[user@VM strace-pkg]$ git add
[user@VM strace-pkg]$ gear-commit
[master (root-commit) 54d15cc] 1.0-alt1
8 files changed, 144 insertions(+)
create mode 100644 .gear/rules
create mode 100644 Makefile
create mode 100644 check/test-0
create mode 100644 check/test-1
create mode 100644 check/test-2
create mode 100644 check/test-3
create mode 100644 strace-pkg-1.0.c
create mode 100644 strace-pkg.spec
[user@VM strace-pkg]$
Пример сборки пакета с секцией %check: 
[user@VM strace-pkg]$ gear-hsh --lazy
<...>
Wrote: /usr/src/in/srpm/strace-pkg-1.0-alt1.src.rpm (w1.gzdio)
Installing strace-pkg-1.0-alt1.src.rpm
<...>
Executing(%check): /bin/sh -e /usr/src/tmp/rpm-tmp.64947
+ umask 022
+ /bin/mkdir -p /usr/src/RPM/BUILD
+ cd /usr/src/RPM/BUILD
+ cd strace-pkg-1.0
+ make check
make: Entering directory '/usr/src/RPM/BUILD/strace-pkg-1.0'
mkdir /tmp/strace-pkg
touch /tmp/strace-pkg/log /tmp/strace-pkg/output
strace -o /tmp/strace-pkg/log ./strace-pkg-1.0
diff /tmp/strace-pkg/output ./check/test-0
strace --inject=read:error=EBADF:when=5 -o /tmp/strace-pkg/log ./strace-pkg-1.0
diff /tmp/strace-pkg/output ./check/test-1
strace --inject=close:retval=0:signal=SIGUSR2:when=4+ \
       --inject=read:retval=6:signal=SIGUSR1:when=3 \
       -o /tmp/strace-pkg/log ./strace-pkg-1.0
diff /tmp/strace-pkg/output ./check/test-2
strace --inject=rt_sigaction:retval=1:when=1 \
       --inject=read:retval=0:signal=SIGUSR1:when=3 \
       -o /tmp/strace-pkg/log ./strace-pkg-1.0 || true
cat /tmp/strace-pkg/log | grep +++ >> /tmp/strace-pkg/output
diff /tmp/strace-pkg/output ./check/test-3
make: Leaving directory '/usr/src/RPM/BUILD/strace-pkg-1.0'
+ exit 0
<...>
Wrote: /usr/src/RPM/SRPMS/strace-pkg-1.0-alt1.src.rpm (w2.lzdio)
Wrote: /usr/src/RPM/RPMS/x86_64/strace-pkg-1.0-alt1.x86_64.rpm (w2.lzdio)
Wrote: /usr/src/RPM/RPMS/x86_64/strace-pkg-debuginfo-1.0-alt1.x86_64.rpm (w2.lzdio)
0.99user 1.29system 0:06.08elapsed 37%CPU (0avgtext+0avgdata 24428maxresident)k
672inputs+1168outputs (0major+142115minor)pagefaults 0swaps
[user@VM strace-pkg]$