[Apparmor-general] Failed to change_hat
to 'HANDLING_UNTRUSTED_INPUT'
Crispin Cowan
crispin at mercenarylinux.com
Wed Jan 9 19:03:06 MST 2008
Christian Boltz wrote:
> 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!
>
Good question. Hard to diagnose from here. Ways that you could get an
unconfined Apache:
* There is some alias for Apache that does not have a profile, and
it is being executed from an unconfined context.
* You have "Ux" somewhere in your Apache profile.
* You have "Ux" in some other profile that executes Apache.
* You've found an unknown kernel bug.
I have never seen this bug before, either in my own systems, or from any
other user except you, so my guess is that the problem is in the policy.
But there is no way to know for sure without doing a bunch of
investigating of your system.
Note: I've never seen "unconstrained" in the "ps Z" output, mine says
"unconfined". Maybe it got changed somewhere when I wasn't looking, or
maybe it is a symptom of something important.
> 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
>
It is interesting that a restart fixes the symptom.
> 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).
>
I don't see anything exciting in that log sample. What are you seeing in it?
> 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?
>
I'm not sure what you think is strange. The change_hat() is likely
failing because this process is unconfined. The question is how did you
get unconfined Apache processes? I think the interesting evidence is
going to come before this.
Crispin
--
Crispin Cowan, Ph.D. http://crispincowan.com/~crispin
Itanium. Vista. GPLv3. Complexity at work.
More information about the Apparmor-general
mailing list