[Apparmor-general] Failed to change_hat to
'HANDLING_UNTRUSTED_INPUT'
Christian Boltz
apparmor at cboltz.de
Wed Jan 9 18:15:35 MST 2008
Hello,
last january, I posted the following log line here:
(with different timestamp of course)
[Thu Jan 10 01:27:20 2008] [error] Failed to change_hat
to 'HANDLING_UNTRUSTED_INPUT'
The reaction from Seth and Crispin was basically "shouldn't happen, and
if it really happens more than once on your server, you should play in
the lottery ;-)"
Now I got tousands of these lines (the logdigest mail has 11 MB today...)
and had a chance to check what happens.
The strange thing first:
# ps Zaux |grep httpd
unconstrained root 4123 0.0 2.2 287684 23228 ? Ss Jan02
5:23 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
unconstrained wwwrun 3131 0.5 3.7 308928 38052 ? S 00:20
0:22 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
unconstrained wwwrun 3840 0.4 3.5 305984 36772 ? S 00:21
0:18 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
unconstrained wwwrun 4740 0.6 2.6 296876 27272 ? S 00:39
0:18 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
unconstrained wwwrun 5629 0.5 2.5 295992 26396 ? S 00:59
0:10 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
unconstrained wwwrun 5972 0.6 2.6 295256 27592 ? S 01:08
0:08 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
unconstrained wwwrun 6006 0.5 3.2 302800 33624 ? S 01:09
0:06 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
unconstrained wwwrun 6110 0.6 3.3 303216 34008 ? S 01:11
0:08 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
unconstrained wwwrun 6123 0.4 2.9 296932 30416 ? S 01:11
0:05 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
unconstrained wwwrun 6169 0.5 4.8 319316 49580 ? S 01:13
0:05 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
unconstrained wwwrun 6171 0.7 2.5 296136 26484 ? S 01:13
0:07 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
unconstrained root 7005 0.0 0.0 8260 816 pts/0 R+ 01:31 0:00 grep --color=auto httpd
Huh? The apache profile exists (with lots of hats, one per vHost).
And it should be protected by AppArmor.
I have straced all apache processes in this state for some minutes,
which includes lots of "Failed to change_hat" messages.
Question: Why did apache fall to unconstrained? This should never happen!
The "fix" is also interesting: after a simple "rcapache2 restart", it
seems to work again - at least, I didn't see any of the "Failed to
change_hat" error messages.
ps Zaux also looks correct now:
/usr/sbin/httpd2-prefork root 7085 0.0 1.4 281264 15372 ? Ss 01:31
0:00 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
/usr/sbin/httpd2-prefork^HANDLING_UNTRUSTED_INPUT wwwrun 7086 0.5 4.3 313608 45044 ? S 01:31
0:03 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
/usr/sbin/httpd2-prefork^HANDLING_UNTRUSTED_INPUT wwwrun 7087 0.6 3.4 303820 35228 ? S 01:31
0:03 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
/usr/sbin/httpd2-prefork^HANDLING_UNTRUSTED_INPUT wwwrun 7088 0.3 2.2 290492 22852 ? S 01:31
0:02 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
/usr/sbin/httpd2-prefork^HANDLING_UNTRUSTED_INPUT wwwrun 7089 0.3 1.6 284384 16616 ? S 01:31
0:02 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
/usr/sbin/httpd2-prefork^HANDLING_UNTRUSTED_INPUT wwwrun 7090 0.6 2.3 291260 23724 ? S 01:31
0:04 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
/usr/sbin/httpd2-prefork^HANDLING_UNTRUSTED_INPUT wwwrun 7093 0.5 1.7 286512 17800 ? S 01:31
0:03 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
/usr/sbin/httpd2-prefork^HANDLING_UNTRUSTED_INPUT wwwrun 7138 0.6 4.2 314328 43500 ? S 01:32
0:03 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
/usr/sbin/httpd2-prefork^HANDLING_UNTRUSTED_INPUT wwwrun 7140 0.5 2.3 292600 23988 ? S 01:32
0:02 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
/usr/sbin/httpd2-prefork^HANDLING_UNTRUSTED_INPUT wwwrun 7141 0.3 1.6 284332 16648 ? S 01:32
0:01 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
/usr/sbin/httpd2-prefork^HANDLING_UNTRUSTED_INPUT wwwrun 7352 0.4 1.6 284152 16592 ? S 01:39
0:00 /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DSSL
Two small samples from one of the strace logs: (directory names and IPs changed)
In the "middle" of the strace log, I have things like
lstat("/home/www/domain1/httpdocs/typo3", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
open("/home/www/domain1/httpdocs/typo3/.htaccess", O_RDONLY) = -1 ENOENT (No such file or directory)
lstat("/home/www/domain1/httpdocs/typo3/foobar.html", 0x7ffff8dde270) = -1 ENOENT (No such file or directory)
gettid() = 3840
open("/proc/3840/attr/current", O_WRONLY) = 210
write(210, "changehat f40d0f3d^vhost_ljrhp", 30) = -1 EPERM (Operation not permitted)
close(210) = 0
gettid() = 3840
open("/proc/3840/attr/current", O_WRONLY) = 210
write(210, "changehat f40d0f3d^", 19) = -1 EPERM (Operation not permitted)
close(210) = 0
gettid() = 3840
open("/proc/3840/attr/current", O_WRONLY) = 210
write(210, "changehat f40d0f3d^/mittendrin.h"..., 35) = -1 EPERM (Operation not permitted)
close(210) = 0
gettid() = 3840
open("/proc/3840/attr/current", O_WRONLY) = 210
write(210, "changehat f40d0f3d^", 19) = -1 EPERM (Operation not permitted)
close(210) = 0
gettid() = 3840
open("/proc/3840/attr/current", O_WRONLY) = 210
write(210, "changehat f40d0f3d^DEFAULT_URI", 30) = -1 EPERM (Operation not permitted)
close(210) = 0
gettid() = 3840
open("/proc/3840/attr/current", O_WRONLY) = 210
write(210, "changehat f40d0f3d^", 19) = -1 EPERM (Operation not permitted)
close(210) = 0
stat("/home/www/domain1/httpdocs/typo3/foobar.html", 0x7ffff8dde180) = -1 ENOENT (No such file or directory)
stat("/home/www/domain1/httpdocs/typo3/index.php", {st_mode=S_IFREG|0644, st_size=2826, ...}) = 0
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={60, 0}}, NULL) = 0
rt_sigaction(SIGPROF, {0x2b96b74ca3a0, [PROF], SA_RESTORER|SA_RESTART, 0x2b96b39ab5b0}, {0x2b96b74ca3a0, [PROF],
SA_RESTORER|SA_RESTART, 0x2b96b39ab5b0}, 8) = 0
foobar.html is rewritten to index.php using mod_rewrite
Note that there is nothing written to the error log (or it is in another
section of the strace, I didn't check that).
There are also log sections where the log message is written:
writev(209, [{" 1px solid\n#CCCCCC;background-co"..., 2042}, {"\r\n", 2}], 2) = 2044
rt_sigaction(SIGPIPE, {SIG_IGN}, {SIG_IGN}, 8) = 0
poll([{fd=210, events=POLLIN|POLLPRI}], 1, 0) = 0
setsockopt(210, SOL_SOCKET, SO_SNDTIMEO, "\2003\341\1\0\0\0\0\0\0\0\0\0\0\0\0", 16) = 0
write(210, "\1\0\0\0\1", 5) = 5
shutdown(210, 2 /* send and receive */) = 0
close(210) = 0
rt_sigaction(SIGPIPE, {SIG_IGN}, {SIG_IGN}, 8) = 0
brk(0x555557a16000) = 0x555557a16000
brk(0x555557895000) = 0x555557895000
brk(0x555557795000) = 0x555557795000
brk(0x5555574d5000) = 0x5555574d5000
open("/dev/urandom", O_RDONLY) = 210
read(210, "rC\213\23", 4) = 4
close(210) = 0
open("/dev/urandom", O_RDONLY) = 210
read(210, "\276\336Qf", 4) = 4
close(210) = 0
open("/dev/urandom", O_RDONLY) = 210
read(210, "\21Z\24A", 4) = 4
close(210) = 0
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
read(209, 0x555556d27438, 8000) = -1 EAGAIN (Resource temporarily unavailable)
writev(209, [{"0\r\n\r\n", 5}], 1) = 5
write(187, "100.123.45.67 - - [10/Jan/2008:"..., 152) = 152
gettid() = 3840
open("/proc/3840/attr/current", O_WRONLY) = 210
write(210, "changehat f40d0f3d^", 19) = -1 EPERM (Operation not permitted)
close(210) = 0
gettid() = 3840
open("/proc/3840/attr/current", O_WRONLY) = 210
write(210, "changehat f40d0f3d^HANDLING_UNTR"..., 43) = -1 EPERM (Operation not permitted)
close(210) = 0
gettid() = 3840
open("/proc/3840/attr/current", O_WRONLY) = 210
write(210, "changehat f40d0f3d^", 19) = -1 EPERM (Operation not permitted)
close(210) = 0
write(2, "[Thu Jan 10 01:28:58 2008] [erro"..., 86) = 86
Do you have any ideas what could have caused this strange behaviour?
If you think the strace logs are useful for debugging, just ask and
I'll mail them to you. (I don't want to make them public as they might
contain customer data.)
The server is running 10.2 64bit, all updates are installed.
Regards,
Christian Boltz
--
LINUX wird nie zum meistinstallierten System -
so oft wie man Win98 neu installieren darf!
More information about the Apparmor-general
mailing list