Почему это не работает!? Способы обнаружения и исправления ошибок в Linux приложениях

ArticleCategory:

UNIXBasics

AuthorImage:[Here we need a little image from you]

TranslationInfo:[Author + translation history. mailto: or http://homepage]

AboutTheAuthor:[A small biography about the author]

Guido нравятся открытые системы, к которым относится ОС Linux за предоставляемые возможности по поиску и исследованию проблем. Если вы готовы потратить немного времени - у вас действительно есть шанс обнаружить проблему.

Abstract:

Многие говорят, что найти и исправить ошибки в приложениях под Linux не так уж и трудно. Но к сожалению очень проблематично найти документацию, рассказывающую о том как это сделать. В этой заметке вы узнаете как найти и исправить ошибки в приложении, не разбираясь как оно работает.

ArticleIllustration:

ArticleBody:

Вступление

С точки зрения пользователя для него не интересно - коммерческое это программное обеспечение или свободно распространяемое до тех пор пока все работает и не возникают ошибки. Но ситуация меняется когда возникают проблемы в эксплуатации программного обеспечения.

Пользуясь закрытым программным обеспечением есть только два пути выхода из подобной ситуации:

отправить запрос об обнаруженной ошибке и позже заплатить за ее исправление;
переустановить программное обеспечение и надеяться, что все заработает.

Если вы работаете под Linux эти пути вам также доступны, но еще есть возможность самому разобраться в чем проблема. Обычно самым большим препятствием является то, что вы не являетесь автором этого приложения и соответственно не знаете как оно устроено и работает.

Несмотря на эти сложности вы можете предпринять кое-какие шаги не разбираясь в коде и внутреннем устройстве приложения.

Логи

Наиболее простой и очевидный путь - посмотреть на файл в каталоге /var/log/... Обратите внимание на файл /var/log/messages в большинстве случаев это именно то, что вам нужно. Большие приложения могут писать логи в свои каталоги ( например /var/log/httpd/ /var/log/exim ... ).
Многие дистрибутивы используют syslog, который настраивается через файл /etc/syslog.conf. Синтаксис этого файла описан в "man syslog.conf".

Ведение приложением лога не что иное как добавление разработчиком нескольких строк в свой код. Это практически то же самое, что и использование функции printf, за исключением того, что запись добавляется в системный лог. В вызове этих функций вы определяете приоритет сообщений для возможности классифицирования их:

       #include 

       void openlog(const char *ident, int option, int facility);
       void syslog(int priority, const char *format, ...);
       void closelog(void);

facility определяет тип приложения посылающего сообщение,
priority - важность сообщения. Перечислим значения в соответствии 
с важностью:

       LOG_EMERG
       LOG_ALERT
       LOG_CRIT
       LOG_ERR
       LOG_WARNING
       LOG_NOTICE
       LOG_INFO
       LOG_DEBUG

С помощью этого интерфейса любое приложение на языке 'С' может вносить записи в системный лог. Другие языки программирования также имеют подобные интерфейсы, например shell скрипты делают это с помощью следующей команды:

logger -p err "this text goes to /var/log/messages"

Стандартный файл настройки syslog'а ( /etc/syslog.conf ) должен обязательно содержать следующую строку:

# Log anything (except mail) of level info or higher.
# Don't log private authentication messages.
*.info;mail.none;authpriv.none     /var/log/messages

Запись "*.info" указывает, что в лог будут внесены все сообщения с приоритетом LOG_INFO или выше. Для получения более подробной информации в /var/log/messages необходимо поменять эту запись на "*.debug" и перезапустить syslog ( /etc/init.d/syslog restart ).

Процедура отладки приложения будет следующей:

1) run tail -f /var/log/messages, после этого запустить приложение в котором возникают
ошибки в другом shell'е. Возможно исследовав полученные записи - вы разберетесь в чем проблема.

2) если действий пункта 1) недостаточно отредактируйте /etc/syslog.conf заменив 
*.info на *.debug. Перезапустите - "/etc/init.d/syslog restart" и повторите пункт 1).

Проблема использования этого метода отладки в том, что он напрямую завистит от разработчика - насколько он хорошо создал свое приложение. Если он не добавил функции работы с логом в наиболее важные участки приложения, то естественно никакой отладочной информации вы не получите. Другими словами - вы сможете обнаружить проблемы только в том случае, если разработчик предусматривал их появление.

Трассирование

В приложение работающем под ОС Linux, можно использовать 3 типа функций:

Собственные функции приложения
Библиотечные функции
Системные вызовы

Библиотечные подобны собственным за исключением того, что находятся в другом пакете. Системные вызовы предназначены для взаимодействия приложения с ядром - это необходимо в случаях использования приложением аппаратных средств - напрмер вывести информацию на дисплей, прочитать файл, получить информацию от клавиатуры, послать сообщение по сети и т.д...

Системные вызовы можно прервать, проанализировать полученную информацию и продолжить взаимодействие приложения и ядра.

Наиболее распространенные проблемы - отсутствие конфигурационного файла или прав записи в каталог. Эти проблемы легко обнаружить трассированием. Ключевое название системного вызова в этом случае "open".

Трассирование выполняется следующим образом:

strace your_application

Приведем пример:

# strace /usr/sbin/uucico
execve("/usr/sbin/uucico", ["/usr/sbin/uucico", "-S", "uucpssh", "-X", "11"], 
       [/* 36 vars */]) = 0
uname({sys="Linux", node="brain", ...}) = 0
brk(0)                                 = 0x8085e34
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, 
     MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40014000
open("/etc/ld.so.preload", O_RDONLY)  = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)    = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=70865, ...}) = 0
mmap2(NULL, 70865, PROT_READ, MAP_PRIVATE, 3, 0) = 0x40015000
close(3)                              = 0
open("/lib/libnsl.so.1", O_RDONLY)    = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\300;\0"..., 1024) 
     = 1024
fstat64(3, {st_mode=S_IFREG|0755, st_size=89509, ...}) = 0
mmap2(NULL, 84768, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x40027000
mprotect(0x40039000, 11040, PROT_NONE)  = 0
mmap2(0x40039000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x11) 
     = 0x40039000
mmap2(0x4003a000, 6944, PROT_READ|PROT_WRITE, 
      MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 
     0x4003a000
close(3)                                = 0
open("/lib/libc.so.6", O_RDONLY)        = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0`X\1\000"..., 1024)
       = 1024
fstat64(3, {st_mode=S_IFREG|0755, st_size=1465426, ...}) = 0
mmap2(NULL, 1230884, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x4003c000
mprotect(0x40163000, 22564, PROT_NONE)  = 0
mmap2(0x40163000, 12288, PROT_READ|PROT_WRITE, 
      MAP_PRIVATE|MAP_FIXED, 3, 0x126) = 0x40163000
mmap2(0x40166000, 10276, PROT_READ|PROT_WRITE, 
      MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x40166000
close(3)                                = 0
munmap(0x40015000, 70865)               = 0
brk(0)                                  = 0x8085e34
brk(0x8086e34)                          = 0x8086e34
brk(0)                                  = 0x8086e34
brk(0x8087000)                          = 0x8087000
open("/usr/conf/uucp/config", O_RDONLY) = -1 ENOENT (No such file or directory)
rt_sigaction(SIGINT, NULL, {SIG_DFL}, 8) = 0
rt_sigaction(SIGINT, {0x806a700, [], 
             SA_RESTORER|SA_INTERRUPT, 0x40064d58}, NULL, 8) = 0
rt_sigaction(SIGHUP, NULL, {SIG_DFL}, 8) = 0
rt_sigaction(SIGHUP, {0x806a700, [], 
             SA_RESTORER|SA_INTERRUPT, 0x40064d58}, NULL, 8) = 0
rt_sigaction(SIGQUIT, NULL, {SIG_DFL}, 8) = 0
rt_sigaction(SIGQUIT, {0x806a700, [], 
             SA_RESTORER|SA_INTERRUPT, 0x40064d58}, NULL, 8) = 0
rt_sigaction(SIGTERM, NULL, {SIG_DFL}, 8) = 0
rt_sigaction(SIGTERM, {0x806a700, [], 
             SA_RESTORER|SA_INTERRUPT, 0x40064d58}, NULL, 8) = 0
rt_sigaction(SIGPIPE, NULL, {SIG_DFL}, 8) = 0
rt_sigaction(SIGPIPE, {0x806a700, [], 
             SA_RESTORER|SA_INTERRUPT, 0x40064d58}, NULL, 8) = 0
getpid()                                = 1605
getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=1024}) = 0
close(3)                                = -1 EBADF (Bad file descriptor)
close(4)                                = -1 EBADF (Bad file descriptor)
close(5)                                = -1 EBADF (Bad file descriptor)
close(6)                                = -1 EBADF (Bad file descriptor)
close(7)                                = -1 EBADF (Bad file descriptor)
close(8)                                = -1 EBADF (Bad file descriptor)
close(9)                                = -1 EBADF (Bad file descriptor)
fcntl64(0, F_GETFD)                     = 0
fcntl64(1, F_GETFD)                     = 0
fcntl64(2, F_GETFD)                     = 0
uname({sys="Linux", node="brain", ...}) = 0
umask(0)                                = 022
socket(PF_UNIX, SOCK_STREAM, 0)         = 3
connect(3, {sa_family=AF_UNIX, 
    path="/var/run/.nscd_socket"}, 110) = -1 ENOENT (No such file or directory)
close(3)                                = 0
open("/etc/nsswitch.conf", O_RDONLY)    = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=499, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, 
      MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40015000
read(3, "# /etc/nsswitch.conf:\n# $Header:"..., 4096) = 499
read(3, "", 4096)                       = 0
close(3)                                = 0
munmap(0x40015000, 4096)                = 0
open("/etc/ld.so.cache", O_RDONLY)      = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=70865, ...}) = 0
mmap2(NULL, 70865, PROT_READ, MAP_PRIVATE, 3, 0) = 0x40015000
close(3)                                = 0
open("/lib/libnss_compat.so.2", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\300\25"..., 1024) 
     = 1024
fstat64(3, {st_mode=S_IFREG|0755, st_size=50250, ...}) = 0
mmap2(NULL, 46120, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x40169000
mprotect(0x40174000, 1064, PROT_NONE)   = 0
mmap2(0x40174000, 4096, PROT_READ|PROT_WRITE, 
      MAP_PRIVATE|MAP_FIXED, 3, 0xa) = 0x40174000
close(3)                                = 0
munmap(0x40015000, 70865)               = 0
uname({sys="Linux", node="brain", ...}) = 0
brk(0)                                  = 0x8087000
brk(0x8088000)                          = 0x8088000
open("/etc/passwd", O_RDONLY)           = 3
fcntl64(3, F_GETFD)                     = 0
fcntl64(3, F_SETFD, FD_CLOEXEC)         = 0
fstat64(3, {st_mode=S_IFREG|0644, st_size=1864, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, 
      MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40015000
_llseek(3, 0, [0], SEEK_CUR)            = 0
read(3, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1864
close(3)                                = 0
munmap(0x40015000, 4096)                = 0
getuid32()                              = 10
geteuid32()                             = 10
chdir("/var/spool/uucp")                = 0
open("/usr/conf/uucp/sys", O_RDONLY)    = -1 ENOENT (No such file or directory)
open("/var/log/uucp/Debug", O_WRONLY|O_APPEND|O_CREAT|O_NOCTTY, 0600) = 3
fcntl64(3, F_GETFD)                     = 0
fcntl64(3, F_SETFD, FD_CLOEXEC)         = 0
fcntl64(3, F_GETFL)                     = 0x401 (flags O_WRONLY|O_APPEND)
fstat64(3, {st_mode=S_IFREG|0600, st_size=296, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, 
     MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40015000
_llseek(3, 0, [0], SEEK_CUR)            = 0
open("/var/log/uucp/Log", O_WRONLY|O_APPEND|O_CREAT|O_NOCTTY, 0644) = 4
fcntl64(4, F_GETFD)                     = 0
fcntl64(4, F_SETFD, FD_CLOEXEC)         = 0
fcntl64(4, F_GETFL)                     = 0x401 (flags O_WRONLY|O_APPEND)

Посмотрите внимательно на следующие строки:

open("/etc/ld.so.preload", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)   = 3

Приложение пытается прочитать файл /etc/ld.so.preload, но неудачно и затем читает файл /etc/ld.so.cache, получая дескриптор 3. Теперь неудачная попытка чтения файла уже не проблема, потому что теперь приложение может пробовать читать и использовать этот файл если это возможно. Другими словами - ошибка чтения файла не обязательно является проблемой - дело в том как устроено само приложение. Давайте посмотрим на все вызовы "open":

open("/usr/conf/uucp/config", O_RDONLY)= -1 ENOENT (No such file or directory)
open("/etc/nsswitch.conf", O_RDONLY)   = 3
open("/etc/ld.so.cache", O_RDONLY)     = 3
open("/lib/libnss_compat.so.2", O_RDONLY) = 3
open("/etc/passwd", O_RDONLY)          = 3
open("/usr/conf/uucp/sys", O_RDONLY)   = -1 ENOENT (No such file or directory)
open("/var/log/uucp/Debug", O_WRONLY|O_APPEND|O_CREAT|O_NOCTTY, 0600) = 3
open("/var/log/uucp/Log", O_WRONLY|O_APPEND|O_CREAT|O_NOCTTY, 0644) = 4
open("/etc/ld.so.preload", O_RDONLY)   = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)     = 3

Приложение пытается прочитать файл /usr/conf/uucp/config. Странно! Этот файл существует! но в приложении нет кода с обращением к нему. Это уже ошибка. Возможно приложение было скомпилировано с ошибочным путем к конфигурационному файлу.

Можно сказать, что трассирование достаточно эффективный метод. Проблемой данного метода является необходимость знакомства с программированием на языке 'C'.

gdb и core файлы

Иногда приложение внезапно завершает свою работу с сообщением "Segmentation fault ( core dumped )". Это значит, что приложение попыталось ( вследствие ошибки разработчика ) записать данные за пределами выделенной памяти.

Когда возникает ошибка "Segmentation fault" создается core файл в текущем каталоге приложения ( обычно это ваш домашний каталог ). Этот файл является дампом памяти на момент возникновения ошибки в приложении. Некоторые shell'ы предоставляют возможность определения места, где будут создаваться эти файлы. В bash по умолчанию запрещено создание core файлов. Чтобы разрешить их создание - используйте следующую команду:

# ulimit -c unlimited

# ./lshref -i index.html,index.htm test.html
Segmentation fault (core dumped)
Exit 139

Созданный core файл можно посмотреть отладчиком gdb, чтобы попытаться выяснить в чем проблема. Перед запуском отладчика убедитесь, что вы собираетесь изучать именно тот файл:

# file core.16897 
core.16897: ELF 32-bit LSB core file Intel 80386, version 1 (SYSV), SVR4-style, 
from 'lshref'

Рассмотрим пример - приложение lshref завершило свою работу с ошибкой, попробуем использовать gdb для выяснения причины. Чтобы использовать gdb для просмотра core файла необходимо в качестве аргументов указать и core файл и исполняемый.

# gdb ./lshref core.23061 
GNU gdb Linux (5.2.1-4)
Copyright 2002 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.  Type "show warranty" for details.
Core was generated by `./lshref -i index.html,index.htm test.html'.
Program terminated with signal 11, Segmentation fault.
Reading symbols from /lib/libc.so.6...done.
Loaded symbols for /lib/libc.so.6
Reading symbols from /lib/ld-linux.so.2...done.
Loaded symbols for /lib/ld-linux.so.2
#0  0x40095e9d in strcpy () from /lib/libc.so.6
(gdb)

Теперь видно, что приложение рушится при попытке вызвать функцию strcpy. Проблема может возникнуть в любом месте приложения, где происходит вызов этой функции.

Существует 2 варианта обнаружения места в коде, где именно возникает ошибка.

Перекомпилировать приложение включив отладочную информацию (gcc option -g)
Сделать трассирование в gdb

В этом конкретном случае проблема в том, что функция strcpy является библиотечной и даже перекомпиляция абсолютно всего приложения ( включая libc ) ничего не даст - мы все равно получим ошибку указывающую на определенную строку в библиотеке 'С'.

Что нам действительно может помочь - так это трассирование, в этом случае мы узнаем какая функция вызывалась перед использованием strcpy. Команда трассирования в gdb называется "backtrace". Для обнаружения ошибки таким способом недостаточно просто исследовать core файл. Необходимо запустить приложение в gdb ( для повтора ошибки ):

gdb ./lshref core.23061 
GNU gdb Linux (5.2.1-4)
Copyright 2002 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.  Type "show warranty" for details.
Core was generated by `./lshref -i index.html,index.htm test.html'.
Program terminated with signal 11, Segmentation fault.
Reading symbols from /lib/libc.so.6...done.
Loaded symbols for /lib/libc.so.6
Reading symbols from /lib/ld-linux.so.2...done.
Loaded symbols for /lib/ld-linux.so.2
#0  0x40095e9d in strcpy () from /lib/libc.so.6
(gdb) backtrace
#0  0x40095e9d in strcpy () from /lib/libc.so.6
Cannot access memory at address 0xbfffeb38
(gdb) run ./lshref -i index.html,index.htm test.html
Starting program: /home/guido/lshref ./lshref -i index.html,index.htm test.html

Program received signal SIGSEGV, Segmentation fault.
0x40095e9d in strcpy () from /lib/libc.so.6
(gdb) backtrace
#0  0x40095e9d in strcpy () from /lib/libc.so.6
#1  0x08048d09 in string_to_list ()
#2  0x080494c8 in main ()
#3  0x400374ed in __libc_start_main () from /lib/libc.so.6
(gdb)

Из приведенного выше видно, что функция main() вызывает string_to_list() откуда и вызывается функция strcpy(). Открываем приложение и смотрим на функцию:

char **string_to_list(char *string){
        char *dat;
        char *chptr;
        char **array;
        int i=0;

        dat=(char *)malloc(strlen(string))+5000;
        array=(char **)malloc(sizeof(char *)*51);
        strcpy(dat,string);

Думаю нам будет интересна строка с вызовом функции malloc. Перепишем ее следующим образом:

dat=(char *)malloc(strlen(string)+5000);

Меняем, производим перекомпиляцию и смотрим... работает.

Рассмотрим еще один пример, где проблема будет не в библиотечной, а в собственной функции. Компилируем приложение так "gcc -g" и gdb покажет нам строку, где возникает ошибка.

#include 
#include 

int add(int *p,int a,int b)
{
  *p=a+b;
  return(*p);
}

int main(void)
{
  int i;
  int *p = 0;   /* a null pointer */
  printf("result is %d\n", add(p,2,3));
  return(0);
}

Компилируем:

gcc -Wall -g -o exmp exmp.c

Запускаем...

# ./exmp
Segmentation fault (core dumped)
Exit 139

gdb exmp core.5302 
GNU gdb Linux (5.2.1-4)
Copyright 2002 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.  Type "show warranty" for details.
Core was generated by `./exmp'.
Program terminated with signal 11, Segmentation fault.
Reading symbols from /lib/libc.so.6...done.
Loaded symbols for /lib/libc.so.6
Reading symbols from /lib/ld-linux.so.2...done.
Loaded symbols for /lib/ld-linux.so.2

#0  0x08048334 in add (p=Cannot access memory at address 0xbfffe020
) at exmp.c:6
6         *p=a+b;

gdb указывает на строку 6, указатель "p" обращается к недоступной области памяти.

Это простой пример - нельзя записывать данные в null указатель. Исправить ошибку не составит большого труда.

Вывод

Мы рассмотрели случаи, которые показывают, что обнаружить ошибку можно не зная внутреннего устройства приложения.

Я исключил примеры функциональных ошибок - например кнопка графического интерфейса находится в неверном положении, но работает. В таких ситуациях надо разбираться как работает приложение. Это может занять много времени и универсального рецепта здесь нет.

Тем не менее рассмотренные способы обнаружения ошибок можно использовать в самых разных ситуациях.

Удачного поиска ошибок!