spontaneous reboots on bruteforce?

[mnalis]

Hi,

I'm having spontaneous reboots when bruteforce is detected.

I was using this simple program:

Code: Select all

#include <stdio.h>
#include <stdlib.h>
#include <pwd.h>
#include <sys/types.h>

main(int argc, char **argv)
{
  struct passwd *p;

  if (argc != 2) {
    printf ("usage: getpwnam <user>\n");
    exit(1);
  }
  p=getpwnam(argv[1]);

  printf ("pw_name=%s\npw_passwd=%s\npw_uid=%d\npw_gid=%d\npw_gecos=%s\npw_dir=%s\npw_shell=%s\n",
    p->pw_name, p->pw_passwd, p->pw_uid, p->pw_gid, p->pw_gecos, p->pw_dir, p->pw_shell
  );

}


as regular user. However, it has a slight bug, that is it doesn't check if p=NULL which happens when invalid user is supplied. Which is ok, or it should be - so the program segfaults. After it does so few times, CONFIG_GRKERNSEC_BRUTE=y kicks in, and kills my ssh session, which is also great. However, when I try to ssh back in, the server is extremely slow, and after dozen seconds spontaneously reboots:

Code: Select all

Oct 31 21:02:08 data kernel: grsec: From x.x.x.x: (default:D:/) Segmentation fault occurred at 0000000000000028 in /home/mnalis/work/test_getpwnam/getpwnam[getpwnam:14350] uid/euid:500/500 gid/egid:500/500, parent /usr/bin/ltrace[ltrace:14349] uid/euid:500/500 gid/egid:500/500
Oct 31 21:02:08 data kernel: grsec: From x.x.x.x: (default:D:/) possible exploit bruteforcing on /home/mnalis/work/test_getpwnam/getpwnam[getpwnam:14350] uid/euid:500/500 gid/egid:500/500, parent /usr/bin/ltrace[ltrace:14349] uid/euid:500/500 gid/egid:500/500 banning execution for 600 seconds/home/mnalis/work/test_getpwnam/getpwnam[getpwnam:14350] uid/euid:500/500 gid/egid:500/500, parent /usr/bin/ltrace[ltrace:14349] uid/euid:500/500 gid/egid:500/500
Oct 31 21:02:08 data kernel: md: md1 in immediate safe mode
Oct 31 21:02:08 data kernel: grsec: From x.x.x.x: (default:D:/) special role admin (id 1) exited by /bin/zsh4[zsh:1758] uid/euid:0/0 gid/egid:0/0, parent /bin/su[su:1753] uid/euid:0/0 gid/egid:0/0
Oct 31 22:03:41 data syslogd 1.5.0#5: restart.
Oct 31 22:03:41 data kernel: klogd 1.5.0#5, log source = /proc/kmsg started.
Oct 31 22:03:41 data kernel: Linux version 2.6.32.46-grsec201110080819 (mnalis@sabik) (gcc version 4.6.1 (Debian 4.6.1-4) ) #3 SMP Mon Oct 10 13:04:35 UTC 2011


It is repeatable, I've managed to reboot it 2 times before I found out my unprivileged process was causing reboots.
Unfortunately it is production server, so I can't experiment too much if it will probably result in another reboot.

kernel is as log says, vanilla 2.6.32.46 patched with grsec 201110080819

[spender]

I'll look into this. Thanks for the report.

-Brad

[spender]

I'm not able to reproduce this with either the 2.6.32.46 and 3.0.8 kernels. I triggered the bruteforce detection both with and without RBAC enabled, and also with the offending process being in a special role (thus causing the admin role to exit). I'd need to see the logs that appear prior to the server rebooting, as I'm not sure that the log you posted paints the complete picture.

-Brad

[mnalis]

Here is complete kern.log since noon till midnight: http://pastebin.com/raw.php?i=n0bPVjg7

Note that the strange time jumps of one hour on-off (like 20h->21h->20h and like) are due to summer/winter time change that happened to happen that day (and correct time not being updated in CMOS by hwclock as machine was not cleanly shutdown, so on reboot the machine got old time, until NTP corrected it some time after boot).
So first reboot happens at 20:53:27 local time, and the next line when klogd starts at 21:55:05 is actually just one and half minute reboot (20:55:05 localtime)... and then the jump from 21:55:24 to 20:55:44 is just 20 seconds delay when "ntpd -g" kicked in and corrected time.

the first reboot finishes at 20:55:44 when RBAC gets enabled automatically, and at 20:56:01 I already ssh back and su and enable admin role in one screen, while being normal user in another screen (without enabling admin role for mnalis - which I can do only as root) and try to strace and ltrace getpwnam binary... after few segfaults, another reboot is triggered at 21:02:08

I can provide .config file for kernel or raw kernel binary or anything else what might help.

[spender]

You can mail (a link to) the kernel image to spender@grsecurity.net

Thanks,
-Brad

[mnalis]

I've e-mailed it, please let me know if you didn't get it or need more info. Thanks!

[mnalis]

Update: It seems I get the same problem even with 2.6.32.46-grsec201110250925 compiled with "CONFIG_GRKERNSEC_BRUTE is not set"?

I have fresh reboot, force that segfaults, and it gets slow and reboots again:

Code: Select all

Nov  9 18:39:56 data kernel: eth0: no IPv6 routers present
Nov  9 18:40:04 data kernel: warning: `vsftpd' uses 32-bit capabilities (legacy support in use)
Nov  9 18:41:21 data kernel: grsec: (default:D:/sbin/gradm) grsecurity 2.2.2 RBAC system loaded by /sbin/gradm[gradm:10113] uid/euid:0/0 gid/egid:0/0, parent /etc/init.d/grsec[S99x5_grsec:10110] uid/euid:0/0 gid/egid:0/0
Nov  9 18:41:47 data kernel: grsec: (default:D:/sbin/gradm) successful change to special role admin (id 1) by /sbin/gradm[gradm:10546] uid/euid:0/0 gid/egid:0/0, parent /bin/zsh4[zsh:10514] uid/euid:0/0 gid/egid:0/0
Nov  9 18:41:55 data kernel: getpwnam__segfa[10685]: segfault at 28 ip 00000000004005ed sp 000003a8306a3170 error 4 in getpwnam__segfault_reboota_masinu[400000+1000]
Nov  9 18:41:55 data kernel: grsec: (default:D:/) Segmentation fault occurred at 0000000000000028 in /home/mnalis/work/test_getpwnam/getpwnam__segfault_reboota_masinu[getpwnam__segfa:10685] uid/euid:500/500 gid/egid:500/500, parent /bin/zsh4[zsh:10392] uid/euid:500/500 gid/egid:500/500
Nov  9 18:43:33 data kernel: klogd 1.5.0#5, log source = /proc/kmsg started.
Nov  9 18:43:33 data kernel: Linux version 2.6.32.46-grsec201110250925-nobrute2 (mnalis@sabik) (gcc version 4.6.1 (Debian 4.6.1-15) ) #1 SMP Wed Nov 9 17:31:22 UTC 2011


I've checked that CONFIG_GRKERNSEC_BRUTE is not set in that kernel, but I'll doublecheck over weekend and try some more test. But I'm letting you know just in case if it might narrow the problem area.

[spender]

Can you enable netconsole? There may be some useful information in the kernel logs that weren't flushed to disk.

-Brad

[mnalis]

Yes, thanks for the idea. I've also setup the test machine with same userland so I can look into it, and hooked up serial console.

Also, I've found why the problem still happens even when CONFIG_GRKERNSEC_BRUTE is not set in the kernel config - it is because I have "RES_CRASH 3 10m" in my /etc/grsec/policy. It seems to override CONFIG_GRKERNSEC_BRUTE in the kernel. When I disable RES_CRASH in the policy too, segfaults no longer get detected as bruteforce, nor do they cause any problem -- so it is a workaround.

With serial console I've found the part of the explanation of the symptoms.
As you recall, I said that after bruteforce detection kills processes of my user, and then that there is half a minute of great slowdown, and only than reboot happens.

Also, I've found out it seems that the bruteforce detection kills more than the user connection -- I was logged on VTY as root (and in "gradm -a admin" mode) in tty1 and on tty2 as user, and provoked a bruteforce as user.
It closed not only user shell, but also the root one (which printed the message about "exiting special role admin") !

Serial console reveals that reboot happens because of softdog which we use as part of debian watchdog package - it prints "SoftDog: Initiating system reboot." and then machine immediately reboots.
It seems the slowdown or something makes it register as machine lockup.
The softdog params are "Software Watchdog Timer: 0.07 initialized. soft_noboot=0 soft_margin=60 sec (nowayout= 0)"

Armed with that knowledge, I've stopped the watchdog daemon (and most of the others) and provoked bruteforce as a user.
The machine still got very slow, but I managed to re-login as root (slowly) without the reboot, and then the kernel oopsed (and rebooted due to sysctl kernel.panic=60).

here is what serial console logged - from end of one boot to next reboot:

Code: Select all

Running local boot scripts (/etc/rc.local).
grsec: (default:D:/sbin/gradm) grsecurity 2.2.2 RBAC system loaded by /sbin/gradm[gradm:1706] uid/euid:0/0 gid/egid:0/0, parent /etc/init.d/grsec[S99x5_grsec:1705] uid/euid:0/0 gid/egid:0/0
warning: `ntpd' uses 32-bit capabilities (legacy support in use)
grsec: (default:D:/sbin/gradm) successful change to special role admin (id 1) by /sbin/gradm[gradm:18540] uid/euid:0/0 gid/egid:0/0, parent /bin/zsh4[zsh:18451] uid/euid:0/0 gid/egid:0/0
getpwnam__segfa[19675]: segfault at 28 ip 00000000004005ed sp 000003e22f405d70 error 4 in getpwnam__segfault_reboota_masinu[400000+1000]
grsec: (default:D:/) Segmentation fault occurred at 0000000000000028 in /home/mnalis/work/test_getpwnam/getpwnam__segfault_reboota_masinu[getpwnam__segfa:19675] uid/euid:500/500 gid/egid:500/500, parent /bin/zsh4[zsh:18490] uid/euid:500/500 gid/egid:500/500
getpwnam__segfa[19676]: segfault at 28 ip 00000000004005ed sp 000003844d5fe450 error 4 in getpwnam__segfault_reboota_masinu[400000+1000]
grsec: (default:D:/) Segmentation fault occurred at 0000000000000028 in /home/mnalis/work/test_getpwnam/getpwnam__segfault_reboota_masinu[getpwnam__segfa:19676] uid/euid:500/500 gid/egid:500/500, parent /bin/zsh4[zsh:18490] uid/euid:500/500 gid/egid:500/500
getpwnam__segfa[19677]: segfault at 28 ip 00000000004005ed sp 000003ea2183e090 error 4 in getpwnam__segfault_reboota_masinu[400000+1000]
grsec: (default:D:/) Segmentation fault occurred at 0000000000000028 in /home/mnalis/work/test_getpwnam/getpwnam__segfault_reboota_masinu[getpwnam__segfa:19677] uid/euid:500/500 gid/egid:500/500, parent /bin/zsh4[zsh:18490] uid/euid:500/500 gid/egid:500/500
grsec: (default:D:/) possible exploit bruteforcing on /home/mnalis/work/test_getpwnam/getpwnam__segfault_reboota_masinu[getpwnam__segfa:19677] uid/euid:500/500 gid/egid:500/500, parent /bin/zsh4[zsh:18490] uid/euid:500/500 gid/egid:500/500 banning execution for 600 seconds/home/mnalis/work/test_getpwnam/getpwnam__segfault_reboota_masinu[getpwnam__segfa:19677] uid/euid:500/500 gid/egid:500/500, parent /bin/zsh4[zsh:18490] uid/euid:500/500 gid/egid:500/500
grsec: (default:D:/) special role admin (id 1) exited by /bin/zsh4[zsh:18451] uid/euid:0/0 gid/egid:0/0, parent /bin/login[login:1735] uid/euid:0/0 gid/egid:0/0
BUG: soft lockup - CPU#1 stuck for 61s! [migration/1:6]
Modules linked in: xfs exportfs ipv6 nls_iso8859_1 nls_cp437 ext2 ide_generic ide_core isofs vfat fat 8139too r8169 mii sky2 softdog
CPU 1:
Modules linked in: xfs exportfs ipv6 nls_iso8859_1 nls_cp437 ext2 ide_generic ide_core isofs vfat fat 8139too r8169 mii sky2 softdog
Pid: 6, comm: migration/1 Not tainted 2.6.32.46-grsec201110250925-nobrute2 #1 P35-DS3L
RIP: 0010:[<ffffffff8138ecf7>]  [<ffffffff8138ecf7>] schedule+0x7e/0x9f8
RSP: 0000:ffff88010ba81dc0  EFLAGS: 00000282
RAX: ffff880028287490 RBX: ffff88010ba81e70 RCX: 0000000000006db8
RDX: 0000000000000001 RSI: ffff880028290890 RDI: ffff88010ba52350
RBP: ffffffff8100349e R08: ffff880028280000 R09: 0000000000000000
R10: 0000000000000000 R11: ffff880028292e40 R12: 0000000000000001
R13: 0000000000000000 R14: 0000000000000000 R15: ffff880028292e40
FS:  0000000000000000(0000) GS:ffff880028280000(0000) knlGS:0000000000000000
CS:  0010 DS: 0018 ES: 0018 CR0: 000000008005003b
CR2: 00000000007b2e38 CR3: 00000000013a2000 CR4: 00000000000006f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Call Trace:
 [<ffffffff8100336b>] ? retint_restore_args+0x6/0xd
 [<ffffffff8100336b>] ? retint_restore_args+0x6/0xd
 [<ffffffff81033fda>] ? migration_thread+0x0/0x274
 [<ffffffff81034172>] ? migration_thread+0x198/0x274
 [<ffffffff81033fda>] ? migration_thread+0x0/0x274
 [<ffffffff810566ee>] ? kthread+0x87/0x8f
 [<ffffffff81003bef>] ? child_rip+0xf/0x20
 [<ffffffff8100336b>] ? retint_restore_args+0x6/0xd
 [<ffffffff81056667>] ? kthread+0x0/0x8f
 [<ffffffff81003be0>] ? child_rip+0x0/0x20
Kernel panic - not syncing: softlockup: hung tasks
Pid: 6, comm: migration/1 Not tainted 2.6.32.46-grsec201110250925-nobrute2 #1
Call Trace:
 <IRQ>  [<ffffffff81387c18>] panic+0x75/0x14e
 [<ffffffff8100349e>] ? apic_timer_interrupt+0xe/0x30
 [<ffffffff8107c965>] softlockup_tick+0x17c/0x193
 [<ffffffff810490ed>] run_local_timers+0x18/0x20
 [<ffffffff81049124>] update_process_times+0x2f/0x5a
 [<ffffffff81062ce0>] tick_sched_timer+0x6d/0x93
 [<ffffffff8105992c>] __run_hrtimer+0xd0/0x165
 [<ffffffff81062c73>] ? tick_sched_timer+0x0/0x93
 [<ffffffff8105a152>] hrtimer_interrupt+0xd1/0x1a9
 [<ffffffff8105a081>] ? hrtimer_interrupt+0x0/0x1a9
 [<ffffffff81003cfc>] ? call_softirq+0x1c/0x2c
 [<ffffffff8105a081>] ? hrtimer_interrupt+0x0/0x1a9
 [<ffffffff81017ef3>] smp_apic_timer_interrupt+0x9f/0xbc
 [<ffffffff81033fda>] ? migration_thread+0x0/0x274
 [<ffffffff810034b8>] apic_timer_interrupt+0x28/0x30
 <EOI>  [<ffffffff8138ecf7>] ? schedule+0x7e/0x9f8
 [<ffffffff8100336b>] ? retint_restore_args+0x6/0xd
 [<ffffffff8100336b>] ? retint_restore_args+0x6/0xd
 [<ffffffff81033fda>] ? migration_thread+0x0/0x274
 [<ffffffff81034172>] ? migration_thread+0x198/0x274
 [<ffffffff81033fda>] ? migration_thread+0x0/0x274
 [<ffffffff810566ee>] ? kthread+0x87/0x8f
 [<ffffffff81003bef>] ? child_rip+0xf/0x20
 [<ffffffff8100336b>] ? retint_restore_args+0x6/0xd
 [<ffffffff81056667>] ? kthread+0x0/0x8f
 [<ffffffff81003be0>] ? child_rip+0x0/0x20
Rebooting in 60 seconds..Linux version 2.6.32.46-grsec201110250925-nobrute2 (mnalis@sabik) (gcc version 4.6.1 (Debian 4.6.1-15) ) #1 SMP Wed Nov 9 17:31:22 UTC 2011
Command line: BOOT_IMAGE=/boot/vmlinuz-2.6.32.46-grsec201110250925-nobrute2 root=/dev/sda2 ro elevator=cfq console=tty0 console=ttyS0,115200
KERNEL supported cpus:


I hope some of that helps tracing it down

[spender]

Thanks for the detailed report -- this should help a lot. I'll give the RBAC bruteforcing code a look.

-Brad

[spender]

Can you try the latest patch? I changed the behavior of RES_CRASH. Previously, it went through the task listing, killing any process whose subject referenced the same path as the subject with RES_CRASH. Therefore, if RES_CRASH was used in a subject like / (which I think was probably the case here), it would likely cause most processes to get killed, potentially including init and kernel threads. The new behavior will only kill processes having the same binary and subject as the crashing process with RES_CRASH.

-Brad

[spender]

Please let me know if this has been resolved.

Thanks,
-Brad

[mnalis]

Thanks Brad!

Please let me know if this has been resolved.

Of course; however it will be two weeks before I can try and test it, sorry.
I'll followup as soon as I can get back to the city and test it.

Thanks again,
Matija

[mnalis]

Therefore, if RES_CRASH was used in a subject like / (which I think was probably the case here), it would likely cause most processes to get killed, potentially including init and kernel threads. The new behavior will only kill processes having the same binary and subject as the crashing process with RES_CRASH.

-Brad

Thanks Brad,

I'll only be able to test the patch in two weeks, but I can confirm the RES_CRASH was indeed in "subject /" for that role.

[mnalis]

I've managed to test 2.6.32.48-grsec201111201943 remotely and I can confirm it no longer causes system instability problems. It looks like this now:

Code: Select all

grsec: From x.x.x.x: (default:D:/sbin/gradm) grsecurity 2.2.2 RBAC system reloaded by /sbin/gradm[gradm:6195] uid/euid:0/0 gid/egid:0/0, parent /bin/zsh4[zsh:2164] uid/euid:0/0 gid/egid:0/0
getpwnam__segfa[10940]: segfault at 28 ip 00000000004005ed sp 000003a32992f690 error 4 in getpwnam__segfault_reboota_masinu[400000+1000]
grsec: From x.x.x.x: (default:D:/) Segmentation fault occurred at 0000000000000028 in /home/mnalis/work/test_getpwnam/getpwnam__segfault_reboota_masinu[getpwnam__segfa:10940] uid/euid:500/500 gid/egid:500/500, parent /bin/zsh4[zsh:1645] uid/euid:500/500 gid/egid:500/500
getpwnam__segfa[10958]: segfault at 28 ip 00000000004005ed sp 00000382f5615d80 error 4 in getpwnam__segfault_reboota_masinu[400000+1000]
grsec: From x.x.x.x: (default:D:/) Segmentation fault occurred at 0000000000000028 in /home/mnalis/work/test_getpwnam/getpwnam__segfault_reboota_masinu[getpwnam__segfa:10958] uid/euid:500/500 gid/egid:500/500, parent /bin/zsh4[zsh:1645] uid/euid:500/500 gid/egid:500/500
getpwnam__segfa[10959]: segfault at 28 ip 00000000004005ed sp 000003e79f1f1390 error 4 in getpwnam__segfault_reboota_masinu[400000+1000]
grsec: From x.x.x.x: (default:D:/) Segmentation fault occurred at 0000000000000028 in /home/mnalis/work/test_getpwnam/getpwnam__segfault_reboota_masinu[getpwnam__segfa:10959] uid/euid:500/500 gid/egid:500/500, parent /bin/zsh4[zsh:1645] uid/euid:500/500 gid/egid:500/500
grsec: From x.x.x.x: (default:D:/) possible exploit bruteforcing on /home/mnalis/work/test_getpwnam/getpwnam__segfault_reboota_masinu[getpwnam__segfa:10959] uid/euid:500/500 gid/egid:500/500, parent /bin/zsh4[zsh:1645] uid/euid:500/500 gid/egid:500/500 banning execution for 600 seconds
getpwnam__segfa[10960]: segfault at 28 ip 00000000004005ed sp 0000039055fbfd40 error 4 in getpwnam__segfault_reboota_masinu[400000+1000]
grsec: From x.x.x.x: (default:D:/) Segmentation fault occurred at 0000000000000028 in /home/mnalis/work/test_getpwnam/getpwnam__segfault_reboota_masinu[getpwnam__segfa:10960] uid/euid:500/500 gid/egid:500/500, parent /bin/zsh4[zsh:1645] uid/euid:500/500 gid/egid:500/500
grsec: From x.x.x.x: (default:D:/) possible exploit bruteforcing on /home/mnalis/work/test_getpwnam/getpwnam__segfault_reboota_masinu[getpwnam__segfa:10960] uid/euid:500/500 gid/egid:500/500, parent /bin/zsh4[zsh:1645] uid/euid:500/500 gid/egid:500/500 banning execution for 600 seconds
getpwnam__segfa[10961]: segfault at 28 ip 00000000004005ed sp 000003bcfc38f3a0 error 4 in getpwnam__segfault_reboota_masinu[400000+1000]



I'm not completely sure how the new bruteforce code is supposed to work, though -- it should kill all of my instances of that binary for that role (which it might be doing, but there is in this case only one copy and it already segfaulted itself). What I cam not sure is the banning part -- the second invocation was a few seconds after the process was supposed to be banned, but it seems it still got executed (and segfaulted again) despite "banning execution for 600 seconds" message. If I repeat it several times it just prints every time the same message "possible exploit bruteforcing on /home/mnalis/work/test_getpwnam/getpwnam__segfault_reboota_masinu[getpwnam__segfa:10960] uid/euid:500/500 gid/egid:500/500, parent /bin/zsh4[zsh:1645] uid/euid:500/500 gid/egid:500/500 banning execution for 600 seconds" but it doesn't seems to ban it.

Is it to be expected or?