[리눅스커널][시스템콜] strace로 시스템콜 디버깅하기
리눅스에서는 시스템콜 디버깅을 위한 strace라는 훌륭한 툴을 제공합니다.
유저 프로그램이 실행할 때 어떤 시스템콜을 실행했는지 확인할 수 있습니다. strace 이란 툴은 리눅스에서 제공하는 강력한 시스템 트레이싱 기능입니다. 물론 라즈베리파이에서도 기본으로 설치되어 있어 바로 사용할 수 있습니다.
strace는 다음 기능을 제공합니다.
1. glibc(GNU C) 라이브러리에서 시스템 콜을 호출하는 함수 이름 출력
2. 시스템콜 실행 후 반환값
이 기능을 쓰기 위해 우선 다음 코드를 시스템 프로그램으로 입력해 봅시다.
1 #include <stdio.h> 2 #include <stdlib.h> 3 #include <unistd.h> 4 #include <sys/types.h> 5 #include <signal.h> 6 #include <string.h> 7 #include <fcntl.h> 8 9 #define PROC_TIMES 2 10 #define SLEEP_DURATION 2 11 #define FORK_MAX_TIMES 3 12 13 #define FILENAME_NAME "/home/pi/sample_text.text" 14 15 void raspbian_proc_process(void); 16 17 void raspbian_proc_process(void) 18 { 19 int proc_times = 0; 20 21 for(proc_times = 0; proc_times < PROC_TIMES; proc_times++) { 22 printf("raspbian tracing ppid:%d pid:%d \n", getppid(), getpid()); 23 sleep(SLEEP_DURATION); 24 } 25 26 exit(EXIT_SUCCESS); 27 } 28 29 void raspbian_file_test() 30 { 31 int fd = 0; 32 ssize_t read_buf_size; 33 off_t new_file_pos; 34 35 char buf[256]; 36 char string[] = "Raspbian Linux!\n"; 37 38 fd = open(FILENAME_NAME, O_RDWR); 39 40 read_buf_size = read(fd, buf, 256); 41 printf("%s", buf); 42 43 memset(buf, 0x0, sizeof(buf)); 44 45 write(fd, string, strlen(string)); 46 47 new_file_pos = lseek(fd, (off_t)0, SEEK_SET); 48 49 read_buf_size = read(fd, buf, 256); 50 printf("read again \n"); 51 printf("[+]read buffer: %s \n", buf); 52 53 close(fd); 54} 55 56 int main() 57 { 58 pid_t pid; 59 int fork_times = 0; 60 61 printf("About to fork process \n"); 62 63 raspbian_file_test(); 64 65 pid = fork(); 66 67 if ( pid == 0 ) { 68 printf("start execution of child process\n"); 69 raspbian_proc_process(); 70 } 71 72 else if ( pid > 0 ) { 73 printf("start execution of parent process\n"); 74 raspbian_proc_process(); 75 } 76 77 return 0; 78 }
이 프로그램은 2가지 동작을 수행합니다.
1. "/home/pi/sample_text.text" 파일을 읽어서 "Raspbian Linux! 스트링을 써줌
: raspbian_file_test() 함수가 이 역할을 수행합니다.
2. 프로세스를 생성한 다음 부모 프로세스와 자식 프로세스에서 raspbian_proc_process() 함수를 실행
위 프로그램을 입력하고 simple_exit.c 파일로 저장하고 다음 Makefile 을 생성해서 빌드를 하겠습니다.
simple_exit: simple_exit.c gcc -g -o simple_exit simple_exit.c
컴파일이 끝나면 simple_exit 파일이 생성됩니다.
이 파일을 생성하고 나서 다음 명령어로 실행해봅시다.
strace –fF ./simple_exit 1 root@raspberrypi:/home/pi # strace -fF ./simple_exit 2 execve("./simple_exit", ["./simple_exit"], [/* 20 vars */]) = 0 3 brk(NULL) = 0x32c000 4 uname({sysname="Linux", nodename="raspberrypi", ...}) = 0 5 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory) 6 mmap2(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x76f72000 7 access("/etc/ld.so.preload", R_OK) = 0 8 open("/etc/ld.so.preload", O_RDONLY|O_CLOEXEC) = 3 9 fstat64(3, {st_mode=S_IFREG|0644, st_size=42, ...}) = 0 10 mmap2(NULL, 42, PROT_READ|PROT_WRITE, MAP_PRIVATE, 3, 0) = 0x76f71000 11 close(3) = 0 12 open("/usr/lib/arm-linux-gnueabihf/libarmmem.so", O_RDONLY|O_CLOEXEC) = 3 ... 13 mprotect(0x20000, 4096, PROT_READ) = 0 14 mprotect(0x76f75000, 4096, PROT_READ) = 0 15 munmap(0x76f1b000, 81634) = 0 16 fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0 17 brk(NULL) = 0x32c000 18 brk(0x34d000) = 0x34d000 19 write(1, "About to fork process \n", 23About to fork process 20 ) = 23 21 open("/home/pi/sample_text.text", O_RDWR) = 3 22 read(3, "Raspberri linux\nRaspbian Linux!\n"..., 256) = 80 23 write(1, "Raspberri linux\nRaspbian Linux!\n"..., 80Raspberri linux 24 Raspbian Linux! 25 ) = 80 26 write(3, "Raspbian Linux!\n", 16) = 16 27 lseek(3, 0, SEEK_SET) = 0 28 read(3, "Raspberri linux\nRaspbian Linux!\n"..., 256) = 96 29 write(1, "\1read again \n", 13 30 read again 31 ) = 13 32 write(1, "[+]read buffer: Raspberri linux\n"..., 112[+]read buffer: Raspberri linux 33 Raspbian Linux! 34 ) = 112 35 write(1, " \n", 2 36 ) = 2 37 close(3) = 0 38 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x76f70068) = 897 39 write(1, "start execution of parent proces"..., 34start execution of parent process 40 ) = 34 41 getppid() = 894 42 getpid() = 896 43 write(1, "raspbian tracing ppid:894 pid:89"..., 35raspbian tracing ppid:894 pid:896 44 ) = 35 45 nanosleep({tv_sec=2, tv_nsec=0}, strace: Process 897 attached 46 <unfinished ...> 47 [pid 897] write(1, "start execution of child process"..., 33start execution of child process 48 ) = 33 49 [pid 897] getppid() = 896 50 [pid 897] getpid() = 897 51 [pid 897] write(1, "raspbian tracing ppid:896 pid:89"..., 35raspbian tracing ppid:896 pid:897 52 ) = 35 53 [pid 897] nanosleep({tv_sec=2, tv_nsec=0}, <unfinished ...> 54 [pid 896] <... nanosleep resumed> 0x7ec6b5f8) = 0 55 [pid 896] getppid() = 894 56 [pid 896] getpid() = 896 57 [pid 896] write(1, "raspbian tracing ppid:894 pid:89"..., 35raspbian tracing ppid:894 pid:896 58 ) = 35 59 [pid 896] nanosleep({tv_sec=2, tv_nsec=0}, <unfinished ...> 60 [pid 897] <... nanosleep resumed> 0x7ec6b5f8) = 0 61 [pid 897] getppid() = 896 62 [pid 897] getpid() = 897 63 [pid 897] write(1, "raspbian tracing ppid:896 pid:89"..., 35raspbian tracing ppid:896 pid:897 64 ) = 35 65 [pid 897] nanosleep({tv_sec=2, tv_nsec=0}, <unfinished ...> 66 [pid 896] <... nanosleep resumed> 0x7ec6b5f8) = 0 67 [pid 896] exit_group(0) = ? 68 [pid 896] +++ exited with 0 +++ 67<... nanosleep resumed> 0x7ec6b5f8) = 0 exit_group(0) = ? +++ exited with 0 +++
1~18번째 줄 로그는 simple_exit 프로그램을 실행할 때 공유 라이브러리를 로딩하는 과정을 출력합니다. 이 로그를 제외하고 simple_exit.c 코드에서 작성한 함수 트레이싱 로그는 19번째 줄 부터 시작합니다.
19번째 줄 로그를 봅시다.
19 write(1, "About to fork process \n", 23About to fork process 20 ) = 23
이 로그는 다음 코드를 실행할 때 출력합니다.
printf("About to fork process \n");
printf() 이란 라이브러리 함수 내부에서 write() 함수를 호출한다는 의미이며 23개만큼 스트링을 썼다는 의미입니다. read() 함수도 마찬가지입니다. 읽어들인 스트링 갯수를 출력합니다.
다음 로그를 보겠습니다.
38 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x76f70068) = 897
위 로그는 아래 코드가 실행했을때 출력합니다.
65 pid = fork();
fork() 함수를 호출했는데 glibc 내부에서 clone() 이란 함수를 호출했다는 의미입니다.
clone() 함수를 호출할 때 전달하는 인자 중 플래그 정보를 다음과 같이 알 수 있습니다.
flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD
clone() 함수에서 반환하는 PID는 897입니다.
위와 같은 로그로 glibc 내부 코드가 어떤 흐름으로 동작하는지 알 수 있습니다.
이번에는 63~66번째 줄 로그를 봅시다.
63 [pid 897] write(1, "raspbian tracing ppid:896 pid:89"..., 35raspbian tracing ppid:896 pid:897 64 ) = 35 65 [pid 897] nanosleep({tv_sec=2, tv_nsec=0}, <unfinished ...> 66 [pid 896] <... nanosleep resumed> 0x7ec6b5f8) = 0
위 로그는 다음 코드를 실행할 때 출력합니다.
17 void raspbian_proc_process(void) 18 { 19 int proc_times = 0; 20 21 for(proc_times = 0; proc_times < PROC_TIMES; proc_times++) { 22 printf("raspbian tracing ppid:%d pid:%d \n", getppid(), getpid()); 23 sleep(SLEEP_DURATION); 24 }
63번째 줄 write 로그는 raspbian_proc_process() 함수 22번째 줄 코드와 같이 printf() 함수를 호출할 때 동작을 출력합니다. printf() 내부 코드에서 write() 이란 시스템 콜을 실행함을 알 수 있습니다.
65번째 줄 로그는 raspbian_proc_process() 함수 sleep(SLEEP_DURATION); 코드를 실행할 때 출력합니다. 리눅스 저수준 함수로 sleep() 함수룰 호출하면 glibc 라이브러리 내에서 nanosleep() 시스템 콜 함수를 호출함을 알 수 있습니다.
strace 프로그램을 쓰면 유저 모드에서 리눅스 시스템 저수준 함수를 호출하면 실제 어떤 시스템콜 함수를 호출하는지 추적할 수 있습니다.
(개인블로그)
http://rousalome.egloos.com
댓글 달기