Logging and troubleshooting

<slideshow style="nobleprog" headingmark="⌘" incmark="…" scaled="true" font="Trebuchet MS" >

title

Logging and troubleshooting

author

Sam Bashton (NobleProg Ltd)

</slideshow>

Apache log format ⌘

• **common** log format - NCSA format
• Understood by many (old) programs

• AWstats
• Webalizer

127.0.0.1 user-identifier frank [10/Oct/2000:13:55:36 +0100] "GET /apache_pb.gif HTTP/1.0" 200 2326

• A "-" in a field indicates missing data.
• 127.0.0.1 is the IP address of the client (remote host) which made the request to the server.
• user-identifier is the RFC 1413 identity of the client.
• frank is the username of the person requesting the document.
• [10/Oct/2000:13:55:36 +0100] is the date, time, and time zone when the server finished processing the request, by default in strftime format %d/%b/%Y:%H:%M:%S %z
• "GET /apache_pb.gif HTTP/1.0" is the request line from the client.
• 200 is the HTTP status code returned to the client.
• 2326 is the size of the object returned to the client, measured in bytes.

CustomLog format ⌘

• Commonly you would set your own log format
• Two parts to this:

• Define the format
• Set it as the log output type

Example: `vhost_combined` format ⌘

LogFormat "%v:%p %h %l %u %t \"%r\" %>s %O \"%{Referer}i\" \"%{User-Agent}i\"" vhost_combined`

• `%v` - Canonical ServerName (VirtualHost)
• `%p` - Server Port
• `%h` - Remote Host. Use `%{X-Forwarded-For}i` if behind a proxy
• `%l` - Remote log name (ignore, identd, unused)
• `%u` - User name
• `%r` - Request
• `%>s` - Final status (eg 200, 404)
• `%0` - requested server name
• `%{Referer}i` - URL user visited to find this page
• `%{User-Agent}i` - web browser of the remote user

Other log variables ⌘

• See http://httpd.apache.org/docs/current/mod/mod_log_config.html

Setting the Log Format ⌘

 CustomLog /var/log/httpd/example-access.log vhost_combined

Troubleshooting Apache: Backtrace ⌘

• Apache crashing?
• Messages like this in the log:

child pid 1256 exit signal Segmentation fault (11)

Obtaining a coredump ⌘

• On >=EL6 - /var/spool/abrt will contain it
• On <= EL5 - enable CoreDump directive in Apache config

CoreDumpDirectory /var/spool/coredumps

• Create `/var/spool/coredumps`
• Wait for it to crash again

Backtracing the coredump ⌘

• We can use gdb to obtain a backtrace
• Should at least give us some hints as to what it going wrong

• and/or a file to give to Red Hat support

• We need to enable debugnfo yum repo which contains debugging symbols

• Can be done via RHN or from the command line:

rhn-channel -a -c rhel-`uname -i`-Server-5-debuginfo -u <Your RHN ID> -p <Your Password>

• Also need to install the `yum-utils` package if not installed

Performing the backtrace

• All relevant debugging symbols need to be installed
• gdb will tell you which ones need to be installed and how
• Run `gdb /usr/bin/httpd corefile`
• At the gdb prompt, type `bt`

Sample gdb output: ⌘

(gdb) bt
#0  0x080ca21b in _efree (ptr=0xbfffdb9b) at zend_alloc.c:240
#1  0x080d691a in _zval_dtor (zvalue=0x8186b94) at zend_variables.c:44
#2  0x080cfab3 in _zval_ptr_dtor (zval_ptr=0xbfffdbfc) at zend_execute_API.c:274
#3  0x080f1cc4 in execute (op_array=0x816c670) at ./zend_execute.c:1605
#4  0x080f1e06 in execute (op_array=0x816c530) at ./zend_execute.c:1638
#5  0x080f1e06 in execute (op_array=0x816c278) at ./zend_execute.c:1638
#6  0x080f1e06 in execute (op_array=0x8166eec) at ./zend_execute.c:1638
#7  0x080d7b93 in zend_execute_scripts (type=8, retval=0x0, file_count=3) at zend.c:810
#8  0x0805ea75 in php_execute_script (primary_file=0xbffff650) at main.c:1310
#9  0x0805cdb3 in main (argc=2, argv=0xbffff6fc) at cgi_main.c:753
#10 0x400c91be in __libc_start_main (main=0x805c580 
, argc=2, ubp_av=0xbffff6fc,
              init=0x805b080 <_init>, fini=0x80f67b4 <_fini>, rtld_fini=0x4000ddd0 <_dl_fini>,
              stack_end=0xbffff6ec) at ../sysdeps/generic/libc-start.c:129
(gdb) frame 3
#3  0x080f1cc4 in execute (op_array=0x816c670) at ./zend_execute.c:1605
(gdb) print (char *)(executor_globals.function_state_ptr->function)->common.function_name
$14 = 0x80fa6fa "pg_result_error"
(gdb) print (char *)executor_globals.active_op_array->function_name
$15 = 0x816cfc4 "result_error"
(gdb) print (char *)executor_globals.active_op_array->filename
$16 = 0x816afbc "/home/yohgaki/php/DEV/segfault.php"
(gdb) 

• In this session, frame 3 is the last execute() call. The frame 3 command moves the current working stack to the proper frame.
• In the sample gdb session, the pg_result_error() call is causing the segfault.