|
|
Dieses Dokument ist verfübar auf: English Deutsch Francais Russian Turkce |
von Guido Socher (homepage) Über den Autor: Guido mag die Möglichkeiten, die ein Open Source System wie Linux beim lösen von Problemen bietet. Man kann wirklich die Ursache des Problems finden, wenn man sich entsprechend viel Zeit dafür nimmt. Übersetzt ins Deutsche von: Katja Socher <katja(at)linuxfocus.org> Inhalt: |
Warum funktioniert das nicht? Wie man Fehler in Linuxapplikationen findet und behebtZusammenfassung:
Alle behaupten, es sei leicht in Programmen, die unter Linux geschrieben wurden, Fehler zu finden und sie zu beheben. Leider ist es sehr schwierig, Dokumentation zu finden, die erklärt, wie man das macht. In diesem Artikel lernst du, wie man Fehler findet und behebt, ohne erst zu lernen, wie die Applikation intern funktioniert.
|
In einem closed source System gibt es normalerweise nur zwei Optionen:
|
Trotz dieser Hindernisse gibt es einige Dinge, die man tun kann, ohne den ganzen Code zu lesen und ohne zu lernen, wie das Programm intern funktioniert.
#include <syslog.h> void openlog(const char *ident, int option, int facility); void syslog(int priority, const char *format, ...); void closelog(void); facility klassifiziert den Typ der Applikation, die die Message sendet. priority entscheidet über die Wichtigkeit der Message. Mögliche Werte in der Reihenfolge der Wichtigkeit sind: LOG_EMERG LOG_ALERT LOG_CRIT LOG_ERR LOG_WARNING LOG_NOTICE LOG_INFO LOG_DEBUGMit diesem C-interface kann jede Applikation, die in C geschrieben wurde, ins System-log schreiben. Andere Sprachen haben ähnliche APIs. Sogar Shellskripte können mit dem folgenden Befehl ins Log schreiben:
logger -p err "this text goes to /var/log/messages"Eine Standard syslog Konfiguration (file /etc/syslog.conf) sollte unter anderem eine Zeile haben, die wie folgt aussieht:
# Log anything (except mail) of level info or higher. # Don't log private authentication messages. *.info;mail.none;authpriv.none /var/log/messagesDas "*.info" logt alles mit einem Prioritätlevel LOG_INFO oder höher. Um mehr Informationen in /var/log/messages zu erhalten, kannst "*.debug" benutzen und syslog erneut starten (/etc/init.d/syslog restart).
1) Laß tail -f /var/log/messages laufen und starte dann die Applikation, die fehlerhaft ist, von einer anderen Shell aus. Vielleicht bekommst du bereits einige Hinweise, was schief läuft. 2) Wenn Schritt 1) nicht ausreicht, dann editiere /etc/syslog.conf und ändere *.info zu *.debug. Laß "/etc/init.d/syslog restart" laufen und wiederhole Schritt 1).Das Problem mit dieser Methode ist, daß sie vollständig davon abhängt, was der Entwickler in seinem Code gemacht hat. Wenn er keine syslog Aufrufe an Schlüsselpunkten hinzugefügt hat, dann siehst du eventuell überhaupt nichts. In anderen Worten, man kann nur Probleme finden, bei denen der Entwickler schon vorhergesehen hat, daß etwas schief gehen könnte.
strace your_applicationHier ist ein Beispiel:
# 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)Was sehen wir hier? Laßt uns z.B. die folgenden Zeilen anschauen:
open("/etc/ld.so.preload", O_RDONLY) = -1 ENOENT (No such file or directory) open("/etc/ld.so.cache", O_RDONLY) = 3Das Programm versucht, /etc/ld.so.preload zu lesen und versagt, dann macht es weiter und liest /etc/ld.so.cache. Hier ist es erfolgreich und bekommt File-descriptor 3 zugewiesen. Nun muß das Scheitern beim Lesen von /etc/ld.so.preload nicht das Problem sein, da das Programm vielleicht nur versucht, die Datei zu lesen und zu benutzen, wenn möglich. In anderen Worten, es ist nicht unbedingt ein Problem, wenn ein Programm eine Datei nicht lesen kann. Es hängt alles vom Aufbau des Programms ab. Laßt uns alle open Aufrufe in der Ausgabe von strace anschauen:
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) = 3Das Programm versucht nun, /usr/conf/uucp/config zu lesen. Oh! Das ist komisch, ich habe das config file in /etc/uucp/config ! ... und es gibt keine Zeile, wo das Programm versucht, /etc/uucp/config zu öffnen. Das ist der Fehler. Offentsichtlich wurde das Programm zur Kompilierzeit für den falschen Speicherplatz des Konfigurationsfiles konfiguriert.
# ulimit -c unlimited # ./lshref -i index.html,index.htm test.html Segmentation fault (core dumped) Exit 139Das core-file kann jetzt mit dem gdb debugger benutzt werden, um herauszufinden, was schiefgeht. Bevor du gdb startest, kannst du überprüfen, daß du wirklich das richtige core-file anschaust:
# file core.16897 core.16897: ELF 32-bit LSB core file Intel 80386, version 1 (SYSV), SVR4-style, from 'lshref'OK, lshref ist ein Programm, das abgestürzt ist, laßt es uns deshalb in gdb laden. Um gdb zum Benutzen mit einem core-file aufzurufen, mußt du nicht nur das core-file spezifizieren, sondern auch den Namen der ausführbaren Datei, die zum core-file dazugehört.
# 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)Jetzt wissen wir, daß das Programm abstürzt, während es versucht, ein strcpy zu machen. Das Problem ist, daß es eventuell viele Stellen im Code gibt, wo strcpy benutzt wird.
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)Jetzt können wir sehen, daß Funktion main() string_to_list() aufgerufen hat und von string_to_list wird strcpy() aufgerufen. Wir gehen zu string_to_list() und schauen uns den Code an:
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);Diese malloc Zeile sieht wie ein Tippfehler aus. Wahrscheinlich sollte sie folgendermaßen lauten:
dat=(char *)malloc(strlen(string)+5000);
#includeWir kompilieren es:#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.cLassen es laufen...
# ./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 sagt uns nun, daß der Fehler in Zeile 6 gefunden wurde und daß Pointer "p" auf Memory zeigt, auf die nicht zugegriffen werden kann.
|
Der LinuxFocus Redaktion schreiben
© Guido Socher, FDL LinuxFocus.org |
Autoren und Übersetzer:
|
2004-07-18, generated by lfparser version 2.38