Ugh – I went to patch my machines today, and it looks like the smpatch(1m) utility is broken again:
Nov 25 17:18:50 tigger root: [ID 702911 user.crit] => com.sun.patchpro.interpreter.PatchListExpressionTree@128635 <=Internal error within exression Interpreter...
Nov 25 17:18:50 tigger root: [ID 702911 user.crit] => com.sun.patchpro.interpreter.PatchListExpressionTree@128635 <=com.sun.patchpro.interpreter.ParseException: Encountered "haspackage " SUNWust1 11.10.0,REV=2005.08.10.02.13" at line 1, column 2.
Nov 25 17:18:50 tigger Was expecting one of:
Nov 25 17:18:50 tigger "n" ...
Nov 25 17:18:50 tigger ...
Nov 25 17:18:50 tigger ...
Nov 25 17:18:50 tigger root: [ID 702911 user.crit] => com.sun.patchpro.interpreter.PatchListExpressionTree@128635 <= "haspackage" ...
Nov 25 17:18:50 tigger "haspackage" """ """ ...
Nov 25 17:18:50 tigger "haspatch" ...
Nov 25 17:18:50 tigger "hasexactpatch" ...
Nov 25 17:18:50 tigger "haspatchbasecode" ...
Nov 25 17:18:50 tigger root: [ID 702911 user.crit] => com.sun.patchpro.interpreter.PatchListExpressionTree@128635 <= "isosname" ...
Nov 25 17:18:50 tigger "isosversion" ...
Nov 25 17:18:50 tigger "isplatform" ...
Nov 25 17:18:50 tigger "isarchitecture" ...
Nov 25 17:18:50 tigger "hasrealization" ...
Nov 25 17:18:50 tigger root: [ID 702911 user.crit] => com.sun.patchpro.interpreter.PatchListExpressionTree@128635 <= "hasexactrealization" ...
I appreciate what Sun is trying to do with this utility, but it is causing users and administrators a lot of pain. If anyone from Sun is reading this, can you please revert back to Recommended patch clusters until smpatch is permanently fixed?
While looking around the Apache module directory yesterday I came across the mod_log_forensic module. This module will log the request headers from each connection, which can be useful for investigating problematic connections and security incidents. To enable mod_log_forensic during the Apache configuration process, the “–enable-log_forensic=shared” option can be passed as an argument to the configure script:
$ configure --prefix=/tmp/apache --enable-mods-shared=most --enable-log_forensic=shared
To enable mod_log_forensic, the ForensicLog command needs to be added to indicate the location to log the request headers:
$ grep ForensicLog httpd.conf
ForensicLog logs/forensic_log
Once the forensic module is setup, each request to the server will generate a log entry similar to the following:
+q4ViwcCoAQMAAEqfC5MAAAAC|GET /apache_pb.gif
HTTP/1.1|Accept:*/*|Accept-Language:en|Accept-Encoding:gzip,
deflate|Referer:http%3a//192.168.1.3%3a8080/|User-Agent:Mozilla/5.0
(Macintosh; U; PPC Mac OS X; en) AppleWebKit/416.11 (KHTML, like Gecko)
Safari/416.12|Connection:keep-alive|Host:192.168.1.3%3a8080
-q4ViwcCoAQMAAEqfC5MAAAAC
The funny looking string of characters (the forensic id) is written before and after each request, and the headers are printed between the identifiers. This is nifty stuff!
I use a variety of hardware in my day-to-day activities, and was curious to see how they compared to each other. While I could run a micro benchmarking tool to get detailed information on memory, cpu, network and disk throughput, I thought it would be easier to use openssl’s ‘speed’ option to get a rough approximation of each machines capabilities. The results are listed below:
Ultra 10 with (1) 440 MHZ UltraSPARC IIi CPU:
$ openssl speed blowfish
Doing blowfish cbc for 3s on 16 size blocks: 3028371 blowfish cbc's in 2.98s
Doing blowfish cbc for 3s on 64 size blocks: 835818 blowfish cbc's in 2.98s
Doing blowfish cbc for 3s on 256 size blocks: 214738 blowfish cbc's in 2.99s
Doing blowfish cbc for 3s on 1024 size blocks: 54125 blowfish cbc's in 2.99s
Doing blowfish cbc for 3s on 8192 size blocks: 6279 blowfish cbc's in 2.98s
OpenSSL 0.9.7d 17 Mar 2004
built on: date not available
options:bn(64,32) md2(int) rc4(ptr,char) des(ptr,risc1,16,long) aes(partial) blowfish(ptr)
compiler: information not available
available timing options: TIMES TIMEB HZ=100 [sysconf value]
timing function used: times
The 'numbers' are in 1000s of bytes per second processed.
type 16 bytes 64 bytes 256 bytes 1024 bytes 8192 bytes
blowfish cbc 16259.71k 17950.45k 18385.59k 18536.45k 17260.93k
Fujitsu 250 with (1) 900 MHZ UltraSPARC64V CPU:
$ openssl speed blowfish
Doing blowfish cbc for 3s on 16 size blocks: 4086473 blowfish cbc's in 3.00s
Doing blowfish cbc for 3s on 64 size blocks: 1095008 blowfish cbc's in 3.00s
Doing blowfish cbc for 3s on 256 size blocks: 278583 blowfish cbc's in 3.00s
Doing blowfish cbc for 3s on 1024 size blocks: 69931 blowfish cbc's in 3.00s
Doing blowfish cbc for 3s on 8192 size blocks: 8754 blowfish cbc's in 2.99s
OpenSSL 0.9.7d 17 Mar 2004
built on: Wed Mar 17 14:57:19 EST 2004
options:bn(64,32) md2(int) rc4(ptr,char) des(idx,cisc,16,long) aes(partial) idea(int) blowfish(ptr)
compiler: gcc -fPIC -DOPENSSL_THREADS -D_REENTRANT -DDSO_DLFCN -DHAVE_DLFCN_H -DOPENSSL_NO_KRB5 -O3 -fomit-frame-pointer -Wall -DB_ENDIAN -DBN_DIV2W
available timing options: TIMES TIMEB HZ=100 [sysconf value]
timing function used: times
The 'numbers' are in 1000s of bytes per second processed.
type 16 bytes 64 bytes 256 bytes 1024 bytes 8192 bytes
blowfish cbc 21794.52k 23360.17k 23772.42k 23869.78k 23984.20k
Powerbook G4 with (1) 1.5 GHZ G4:
$ openssl speed blowfish
To get the most accurate results, try to run this
program when this computer is idle.
Doing blowfish cbc for 3s on 16 size blocks: 6564697 blowfish cbc's in 2.28s
Doing blowfish cbc for 3s on 64 size blocks: 1781080 blowfish cbc's in 2.23s
Doing blowfish cbc for 3s on 256 size blocks: 482751 blowfish cbc's in 2.35s
Doing blowfish cbc for 3s on 1024 size blocks: 118350 blowfish cbc's in 2.29s
Doing blowfish cbc for 3s on 8192 size blocks: 15444 blowfish cbc's in 2.38s
OpenSSL 0.9.7g 11 Apr 2005
built on: Mon Aug 22 04:38:18 PDT 2005
options:bn(64,32) md2(int) rc4(ptr,char) des(idx,cisc,16,long) aes(partial) blowfish(ptr)
compiler: cc -arch i386 -arch ppc -g -Os -pipe -arch i386 -arch ppc -pipe -DOPENSSL_NO_IDEA -DFAR=
available timing options: TIMEB USE_TOD HZ=100 [sysconf value]
timing function used: getrusage
The 'numbers' are in 1000s of bytes per second processed.
type 16 bytes 64 bytes 256 bytes 1024 bytes 8192 bytes
blowfish cbc 45997.30k 51100.78k 52532.67k 52895.72k 53053.47k
IBM HS20 Blade with (1) 3.0 GHZ Intel Xeon CPU w/ Hyperthreading:
$ /usr/sfw/bin/openssl speed blowfish
Doing blowfish cbc for 3s on 16 size blocks: 14394701 blowfish cbc's in 2.99s
Doing blowfish cbc for 3s on 64 size blocks: 3827438 blowfish cbc's in 3.00s
Doing blowfish cbc for 3s on 256 size blocks: 979301 blowfish cbc's in 3.00s
Doing blowfish cbc for 3s on 1024 size blocks: 250691 blowfish cbc's in 3.00s
Doing blowfish cbc for 3s on 8192 size blocks: 31586 blowfish cbc's in 3.00s
OpenSSL 0.9.7d 17 Mar 2004
built on: date not available
options:bn(64,32) md2(int) rc4(ptr,char) des(ptr,cisc,16,long) aes(partial) blowfish(ptr)
compiler: information not available
available timing options: TIMES TIMEB HZ=100 [sysconf value]
timing function used: times
The 'numbers' are in 1000s of bytes per second processed.
type 16 bytes 64 bytes 256 bytes 1024 bytes 8192 bytes
blowfish cbc 77028.50k 81652.01k 83567.02k 85569.19k 86250.84k
In an attempt to learn how DTrace probes and Apache work, I called up my friend Clay last week, and we sat down to integrate some probes into Apache. After looking through the Apache source code and analyzing the available documentation on statically defined probes, we determined that adding probes would be simple, but getting apache to build would be a bit tedious (luckily Clay is an autoconf/libtool expert!!). After mucking with the build process for a few hours, Clay was able to tweak the APR (Apache Portable Runtime) Makefile.in, and we were able to integrate numerous DTrace probes into Apache. The first probe we added was in the apr_palloc() routine:
$ dtrace -l | grep apr_palloc
10 apache_apr1940 libapr-0.so.0 apr_palloc apr_palloc-entry
17 apache_apr17002 libapr-0.so.0 apr_palloc apr_palloc-entry
36851 apache_apr1939 libapr-0.so.0 apr_palloc apr_palloc-entry
This probe would be helpful for figuring out which pools were accessed, and for determing the number of bytes allocated to each pool:
$ dtrace -n '::apr_palloc: { printf("Allocated %d bytes to pool %s", (*(int *)(copyin(arg0,sizeof(int)))), copyinstr(arg1)); }'
dtrace: description '::apr_palloc: ' matched 3 probes
CPU ID FUNCTION:NAME
0 10 apr_palloc:apr_palloc Allocated 16 bytes to pool transaction
0 10 apr_palloc:apr_palloc Allocated 84 bytes to pool transaction
0 10 apr_palloc:apr_palloc Allocated 340 bytes to pool transaction
0 10 apr_palloc:apr_palloc Allocated 280 bytes to pool transaction
0 10 apr_palloc:apr_palloc Allocated 60 bytes to pool transaction
0 10 apr_palloc:apr_palloc Allocated 16 bytes to pool transaction
0 10 apr_palloc:apr_palloc Allocated 16 bytes to pool transaction
0 10 apr_palloc:apr_palloc Allocated 16 bytes to pool transaction
0 10 apr_palloc:apr_palloc Allocated 20 bytes to pool transaction
0 10 apr_palloc:apr_palloc Allocated 20 bytes to pool transaction
0 10 apr_palloc:apr_palloc Allocated 392 bytes to pool request
0 10 apr_palloc:apr_palloc Allocated 16 bytes to pool request
0 10 apr_palloc:apr_palloc Allocated 20 bytes to pool request
0 10 apr_palloc:apr_palloc Allocated 8 bytes to pool request
We can also use this probe to understand how frequently apr_palloc() gets called:
$ dtrace -q -n '::apr_palloc: { @calls[probefunc,pid] = count(); } dtrace:::END { printa(@calls); }'
^C
apr_palloc 1939 4
apr_palloc 1940 156
apr_palloc 17002 654
After toying with the memory management layer (the really interesting stuff comes from the Apache allocator() routines – but that is a BLOG entry in and of itself), we decided to add a probe to display incoming connections:
$ dtrace -l | grep apr_socket_accept
5 apache_apr9965 libapr-0.so.0 apr_socket_accept apr_socket_accept
12 apache_apr9966 libapr-0.so.0 apr_socket_accept apr_socket_accept
36845 apache_apr9976 libapr-0.so.0 apr_socket_accept apr_socket_accept
$ dtrace -q -n '::apr_socket_accept: { printf(" Pid: %d
Result: %d
IP Address: %x
SRC Port %d “,pid, *(int *)copyin(arg0,4), *(int *)copyin(arg1,4), *(short int *)copyin(arg2,4)); }‘`
Pid: 9999
Result: 10
IP Address: c0a80103
SRC Port 33874
Pid: 9976
Result: 10
IP Address: c0a80108
SRC Port 61918
Pid: 9966
Result: 10
IP Address: c0a80108
SRC Port 61919
This probe will display the httpd process id that accept()‘ed the
connection along with the SRC port ad IP address of the client. Since we
could get this information from either snoop(1m) or the dtrace syscall
provider, we decided to move on to the request processing routines.
After analyzing the files in
APACHE_SRC_ROOT/srclib/apr/network_io/unix, we decided to add
probes to the APR send and receive routines:
$ dtrace -l | egrep '(apr_socket_recv|apr_socket_send)'
6 apache_apr9965 libapr-0.so.0 apr_socket_recv apr_socket_recv
7 apache_apr9965 libapr-0.so.0 apr_socket_send apr_socket_send
13 apache_apr9966 libapr-0.so.0 apr_socket_recv apr_socket_recv
14 apache_apr9966 libapr-0.so.0 apr_socket_send apr_socket_send
36846 apache_apr9976 libapr-0.so.0 apr_socket_recv apr_socket_recv
36847 apache_apr9976 libapr-0.so.0 apr_socket_send apr_socket_send
Once the probes were integrated into the send and receive routines, we could use our probes to view the data read and written by each httpd process (this information can also be obtained from the syscall provider’s read and write probes):
$ dtrace -q -n '::apr_socket_recv: { printf("Received the following
buffer
%s
“,copyinstr(arg0)); }‘`
Received the following buffer
Received the following buffer
GET / HTTP/1.1
Host: 192.168.1.3:8080
User-Agent: Mozilla/5.0 (Macintosh; U; PPC Mac OS X Mach-O; en-US;
rv:1.8) Gecko/20051111 Firefox/1.5
Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
Acc
Received the following buffer
Received the following buffer
GET /apache_pb.gif HTTP/1.1
Host: 192.168.1.3:8080
User-Agent: Mozilla/5.0 (Macintosh; U; PPC Mac OS X Mach-O; en-US;
rv:1.8) Gecko/20051111 Firefox/1.5
Accept: image/png,*/*;q=0.5
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept
Received the following buffer
HTTP/1.1 304 Not Modified
Date: Mon, 21 Nov 2005 00:08:30TGMT:00-04:00
Server: Apache
Connection: Keep-Alive
Keep-Alive: timeout=15, max=99
ETag: "4be83-916-a64a7c40"
- [20/Nov/2005:19:08:30 -0500] "GET / HTTP/1.1" 304 -
y: negotiate,accept-language,accept
I was amazed at how easy it was to add probes, and found this excercise extremely beneficial! While I learned after the fact that the pid provider would do everything we wanted, it was still a fun learning experience, and helped me understand Apache at a more granular level! Viva la DTrace!
It seems like yesterday that I purchased War on casette tape to listen to Sunday Bloody Sunday. War was a great album, Sunday Bloody Sunday was an awesome tune, and I eventually wore out the casette tape! Well – all of my War listening momenets came back to me Friday night when I saw U2 live, and I must say they were awesome! U2 opened up with the City of blinding lights, and proceeded to play the following setlist:
City Of Blinding Lights Vertigo / Rockaway Beach (snippet) / Rock ‘N’ Roll Nigger (snippet) Elevation Beautiful Day / Sgt. Pepper’s Lonely Hearts Club Band (snippet) / Blackbird (snippet) I Still Haven’t Found What I’m Looking For / In A Little While (snippet) Mysterious Ways Original Of The Species Sometimes You Can’t Make It On Your Own / The Black Hills of Dakota (snippet) Love And Peace Or Else Sunday Bloody Sunday / Rock The Casbah (snippet) Bullet The Blue Sky / When Johnny Comes Marching Home (snippet) / The Hands That Built America (snippet) Miss Sarajevo Pride (In The Name Of Love) Where The Streets Have No Name One / Ol’ Man River (snippet) Until The End Of The World The Fly With Or Without You Stuck In A Moment You Can’t Get Out Of Yahweh All Because Of You 40
The show was awesome, the people were friendly, and the opening band (Institute featuring Gavin Rosdale) was awesome! If you get a chance to see U2 live, do it! They rock!