Mostrando entradas con la etiqueta syscalls. Mostrar todas las entradas
Mostrando entradas con la etiqueta syscalls. Mostrar todas las entradas

lunes, 30 de abril de 2018

Where do your bytes go when you send them to /dev/null?


I've been playing around with some interesting tools lately so decided to use one of them to answer a rather ontological question. No, I'm not talking about the meaning of life and stuff, but the one on the title!

I'm pretty sure you have at least once come across the idea of running some IO benchmark (I didn't say this is a good idea, but lets face it... you've done it) of your drive and decided to run something like the following:

dd if=/home/juan/myfile of=/dev/null

You know, trying to measure the read throughput of the device where myfile file is stored. Or maybe you've redirected some annoying stderr output to prevent it from showing up on your stdout. The point is that I've always blindly assumed /dev/null is a kind of black hole or one way ticket for your bytes, but never actually understood how it works.

Spoiler alert, I've written this article while working on my Ubuntu Trusty VM, so all the kernel source links will be pointing to kernel 3.19 however, most (if not all) of the code/content should be valid in newer kernels. If it's not valid then, sorry xD I'm not going write this again, so get your hands dirty and read some source code.

What's /dev/null after all?


According to Wikipedia:

The null device is typically used for disposing of unwanted output streams of a process, or as a convenient empty file for input streams. This is usually done by redirection.

Something interesting is the concept of "device", /dev/null isn't a regular file, but a special device file, particularly a character device file. You may have heard the concept of "in Unix everything is a file" (ok, except Network cards :P), that's quite accurate and there are several different file types, being the most common the following:

  • Regular files
  • Directory
  • Named Pipe
  • Socket
  • Symbolic Link
  • Device file
    • Character
    • Block
Lets have a quick look at this special file and see what's so special about it! Using stat we already have some nice details about it:

juan@test:~$ stat /dev/null
  File: ‘/dev/null’
  Size: 0             Blocks: 0          IO Block: 4096   character special file
Device: 6h/6d    Inode: 1029        Links: 1     Device type: 1,3
Access: (0666/crw-rw-rw-)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2018-04-17 18:57:48.359574000 +0100
Modify: 2018-04-17 18:57:48.359574000 +0100
Change: 2018-04-17 18:57:48.359574000 +0100
 Birth: -
juan@test:~$

What does "Device type: 1,3"  stand for? Well that's the key here, these two numbers are the Major (identifies the driver used) and the Minor number (identifies the device).

According to Linux Devices documentation, the character device with Major number 1 and Minor Number 3 is the Memory character device /dev/null (aka Null device). If you feel like getting your hands really dirty, you can see the Memory character implementation code here :P.

So what happens when you send stuff to /dev/null?


As with every file intervention, at least the following things have to happen:

- Open the file and get a file descriptor
- Write to the file using the file descriptor obtained previously
- Close the file using the file descriptor obtained previously

these 3 actions require kernel intervention and they map directly to syscalls open, write and close. Lets have a look at this with strace:

root@test:/home/juan# strace -e "open,read,write,close,dup2" dd if=/dev/zero of=/dev/null count=1
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
close(3)                                = 0
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P \2\0\0\0\0\0"..., 832) = 832
close(3)                                = 0
open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
close(3)                                = 0
open("/dev/zero", O_RDONLY)             = 3
dup2(3, 0)                              = 0
close(3)                                = 0
open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
dup2(3, 1)                              = 1
close(3)                                = 0
read(0, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
write(1, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
close(0)                                = 0
close(1)                                = 0
open("/usr/share/locale/locale.alias", O_RDONLY|O_CLOEXEC) = 0
read(0, "# Locale name alias data base.\n#"..., 4096) = 2570
read(0, "", 4096)                       = 0
close(0)                                = 0
open("/usr/share/locale/en_IE/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/share/locale/en/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/share/locale-langpack/en_IE/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/share/locale-langpack/en/LC_MESSAGES/coreutils.mo", O_RDONLY) = 0
close(0)                                = 0
write(2, "1+0 records in\n1+0 records out\n", 311+0 records in
1+0 records out
) = 31
write(2, "512 bytes (512 B) copied", 24512 bytes (512 B) copied) = 24
write(2, ", 0.000607882 s, 842 kB/s\n", 26, 0.000607882 s, 842 kB/s
) = 26
close(2)                                = 0
+++ exited with 0 +++
root@test:/home/juan# 

So /dev/null file was opened and in return we got FD 3, which was then copied to FD 1 (dup2(3,1)). Right after this, write call was used to write on it, we can see the exact lines here:

open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
dup2(3, 1)                              = 1
close(3)                                = 0
read(0, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
write(1, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512

Once the process hands over control to the kernel to execute the syscalls code we totally loose track of what's going on. To be honest that's the whole point of an API like the syscall layer, however sometimes is good to have the chance to see how things work in the background, and in order to answer the question we need to understand it.

Ftrace, like strace but way more fun!


Ftrace was introduced on the Linux kernel long ago, somewhere around late 2008 on Kernel 2.6.27. It allows users to trace certain Kernel functions given an incredible visibility of what's going and how things really work.

In order for ftrace to be available, the kernel needs to be compiled with this tracing feature. You can confirm by looking for CONFIG_FUNCTION_TRACER, like:

juan@test:~$ grep FUNCTION_TRACER /boot/config-3.19.0-51-generic
CONFIG_HAVE_FUNCTION_TRACER=y
CONFIG_FUNCTION_TRACER=y
juan@test:~$

Many distributions ship their kernels with ftrace enabled and even the debugfs (the way to access ftrace data) file system mounted (Ubuntu for example):

juan@test:~$ mount | grep debug
none on /sys/kernel/debug type debugfs (rw)
juan@test:~$

What essentially happens is pretty much summed up in these lines:

It uses a compiler feature to insert a small, 5-byte No-Operation instruction to the beginning of every kernel function, which NOP sequence is then dynamically patched into a tracer call when tracing is enabled by the administrator. 

so these few extra bytes are used later on to hook a tracing function that will gather the details of the invoked functions, pretty neat!

There's a LOT of ftrace documentation around so I won't waste time repeating any of it. I do suggest you to read it though. In this particular case I'll be using trace-cmd frontend tool instead of directly use the files under the debugfs directory.

BTW: ftrace is a great way to inspect and learn about the Linux Kernel, so do give it a go.

SHOW ME THE MONEY!

Ok, ok,... In order to track the kernel functions I'm going to use function_graph plugin with a little of filtering to only get the events related to the write syscall:

root@test:/home/juan# trace-cmd record -p function_graph -g "SyS_write" dd if=/dev/zero of=/dev/null count=1
  plugin 'function_graph'
1+0 records in
1+0 records out
512 bytes (512 B) copied, 0.00255381 s, 200 kB/s
Kernel buffer statistics:
  Note: "entries" are the entries left in the kernel ring buffer and are not
        recorded in the trace data. They should all be zero.

CPU: 0
entries: 0
overrun: 0
commit overrun: 0
bytes: 2476
oldest event ts: 180098.264687
now ts: 180098.267521
dropped events: 0
read events: 468

CPU: 1
entries: 0
overrun: 0
commit overrun: 0
bytes: 2184
oldest event ts: 180098.266223
now ts: 180098.267677
dropped events: 0
read events: 1882

CPU0 data recorded at offset=0x42b000
    20480 bytes in size
CPU1 data recorded at offset=0x430000
    77824 bytes in size
root@test:/home/juan# 

The execution of the command creates a "trace.dat" file were the captured events are written. Then you can access to these events using "trace-cmd report". Since we know we are looking for the first Write call done by dd command I will limit the output of the report to the following:

root@test:/home/juan# trace-cmd report | grep "dd-" | head -25
              dd-3770  [001] 180098.263240: funcgraph_entry:                   |  SyS_write() {
              dd-3770  [001] 180098.263269: funcgraph_entry:                   |    __fdget_pos() {
              dd-3770  [001] 180098.263269: funcgraph_entry:        0.077 us   |      __fget_light();
              dd-3770  [001] 180098.263270: funcgraph_exit:         0.669 us   |    }
              dd-3770  [001] 180098.263270: funcgraph_entry:                   |    vfs_write() {
              dd-3770  [001] 180098.263270: funcgraph_entry:                   |      rw_verify_area() {
              dd-3770  [001] 180098.263271: funcgraph_entry:                   |        security_file_permission() {
              dd-3770  [001] 180098.263271: funcgraph_entry:                   |          apparmor_file_permission() {
              dd-3770  [001] 180098.263271: funcgraph_entry:                   |            common_file_perm() {
              dd-3770  [001] 180098.263272: funcgraph_entry:        0.087 us   |              aa_file_perm();
              dd-3770  [001] 180098.263272: funcgraph_exit:         0.679 us   |            }
              dd-3770  [001] 180098.263272: funcgraph_exit:         1.230 us   |          }
              dd-3770  [001] 180098.263273: funcgraph_exit:         1.783 us   |        }
              dd-3770  [001] 180098.263273: funcgraph_exit:         2.330 us   |      }
              dd-3770  [001] 180098.263273: funcgraph_entry:        0.068 us   |      write_null();
              dd-3770  [001] 180098.263274: funcgraph_entry:                   |      __fsnotify_parent() {
              dd-3770  [001] 180098.263274: funcgraph_entry:        0.103 us   |        dget_parent();
              dd-3770  [001] 180098.263275: funcgraph_entry:        0.078 us   |        dput();
              dd-3770  [001] 180098.263275: funcgraph_exit:         1.255 us   |      }
              dd-3770  [001] 180098.263276: funcgraph_entry:                   |      fsnotify() {
              dd-3770  [001] 180098.263276: funcgraph_entry:        0.308 us   |        __srcu_read_lock();
              dd-3770  [001] 180098.263277: funcgraph_entry:        0.087 us   |        __srcu_read_unlock();
              dd-3770  [001] 180098.263277: funcgraph_exit:         1.548 us   |      }
              dd-3770  [001] 180098.263278: funcgraph_exit:         7.318 us   |    }
              dd-3770  [001] 180098.263278: funcgraph_exit:         9.498 us   |  }
root@test:/home/juan#

Pretty neat, right? we can clearly see the entry and exit of "every" kernel function within the SyS_write syscall. Now, with the function names we can go to our one and only https://elixir.bootlin.com and read the code of each function to have a better picture:
  • SyS_write Write syscall enter
  • vfs_write VFS generic write path, security checks and permissions validation (among other things :))
  •  write_null this function is the write function for the specific device /dev/null (indicated by the file_operations structure of the device), if this was a regular file we would see here a File System specific write function.
Now if we explore the code of write_null, we can see the following:

static ssize_t write_null(struct file *file, const char __user *buf,
     size_t count, loff_t *ppos)
{
 return count;
}

the parameters:
  • *file the file structure (created during the open syscall and linked to the fd)
  • *buf the buffer that keeps the data that is supposed to be written
  • count the number of bytes to write 
  • *ppos the position within the file where to start writing. 

As you can see the function itself doesn't do a thing (which was kind of expected after all xD), it just returns the number of bytes that were supposed to be written as some sort of acknowledgement and confirming the write operation did actually take place.

So not only now you know about /dev/null :P but you can go and have fun with ftrace exploring the Linux Kernel!!!

To answer the question, your bytes literally go nowhere!

martes, 21 de febrero de 2017

Process mating season 102 - Fork and Clone

It's been a while since I posted Process mating season 101 where I reviewed how processes are created in Linux systems showing examples of the behavior of fork() syscall. At the very end of the post I mentioned glibc is not using fork() syscall anymore when you call the fork() wrapper, but now is calling clone() syscall instead. Even though you can still use the old fork syscall, if you call the syscall directly, clone provides the same features and many more!

So what's the difference between clone and fork?


Since you already know what to expect from fork() (because you have read Process mating season 101) I will only talk about clone now. Similarly to fork, clone creates processes... wait..., what? Yes, the peculiarity of clone() is that the new child process has the possibility of sharing part of the execution context like the memory space (excluding stuff like, stack and CPU registers) with its parent process. Therefore this special feature of clone() is the one used to implement the concept of threads in Linux, basically several processes running in the same memory space.

To give a bit more of context to how clone() works, I think is worth mentioning the following concepts:
  • tgid: thread group ID, this ID represents the thread group a task belongs to. This ID is also known as PID, since kernel 2.4 getpid() function actually returns TGID 
  • tid: thread ID, this is a unique identifier for a given task, clone() returns the TID of the newly created process/thread. You can obtain the current task TID by using gettid() function. 
  • When clone() is called specifying CLONE_THREAD flag, the new task is created under the same TGID, a new unique TID is assigned to the thread (task). On the contrary, when clone() is called without CLONE_THREAD flag, the new task is placed in a new thread group whose TGID is the TID of the new task (remember TID is unique system-wide).
lets see this in a classic example you may find in your system right now:

juan@test:~$ ps -eLF |grep "PID\|rsyslog"
UID        PID  PPID   LWP  C NLWP    SZ   RSS PSR STIME TTY          TIME CMD
syslog     568     1   568  0    4 65534  3040   1 18:41 ?        00:00:00 rsyslogd
syslog     568     1   570  0    4 65534  3040   0 18:41 ?        00:00:00 rsyslogd
syslog     568     1   571  0    4 65534  3040   1 18:41 ?        00:00:00 rsyslogd
syslog     568     1   572  0    4 65534  3040   0 18:41 ?        00:00:00 rsyslogd
juan      2358  1938  2358  0    1  3987  2168   0 19:53 pts/1    00:00:00 grep --color=auto PID\|rsyslog
juan@test:~$

Rsyslogd is our lovely syslog service and seems to be spawning 4 LWP (light weight process, aka threads). Please note that LWP is an alias for TID, and NLWP is the number of threads under the particular TGID which as we said before is the PID value as well :D, a bit tricky right?

Let me re phrase that putting some time context on it:
  1. rsyslog's parent is process 1 as we can see from PPID column. This means at some point in time init process fork()ed itself (actually fork+execve :D), giving birth to a new task (rsyslogd) with TID 568 (LWP) which was placed under a new thread group identified by PID 568.
  2. later on rsyslogd TID 568 decided more threads were necessary to take care of our logs and spawn a few more tasks (this time using clone(CLONE_THREAD)). This way three new threads were spawn TID 570, 571 and 572, all of them of course under the same thread group 568.
I hope it is more clear now, you can't said I haven't tried! If by any chance you don't believe any of this, about PID being TGID, and LWP being TID I'd strongly suggest to have a look at map ps.

Show me an example in C god damn it!!


Well... I have to be honest, I thought it would be as simple as it was for the previous post, but once again I was wrong xD. That said I came up with an extremely simple example anyways, just for the sake of writing some C and probing myself I'm not thaaaat lazy.

The example doesn't do anything meaningful, it only proves that threads can access to memory on the process that spawned them.

Here it goes the code, again is heavily commented:

#include <stdio.h>
#include <errno.h>
#include <linux/sched.h>
#include <sys/types.h>
#include <sys/wait.h>
#include <unistd.h>
#include <string.h>
#include <stdlib.h>
#include <sys/syscall.h>

#define STACK_SIZE (1024*1024)
#define THREADS 5

int myFunction(void *arg);

int main(int argc, char *argv[])
{
        int aux, i, childtid, array[THREADS];
        char *stack_low, *stack_high;

        for(i=0;i<THREADS;i++)
        {
                *(array+i)=0;//Initializing array with zero, position by position, just for the fun of it

                //Allocate some bytes for the cloned child, since STACK
                // grows downward we want to know the last memory position
                // to use it on clone().
                stack_low=malloc(STACK_SIZE);
                stack_high=stack_low+STACK_SIZE;

                //When CLONE_THREAD is set, CLONE_SIGHAND and CLONE_VM have to be set as well, have a look at https://linux.die.net/man/2/clone.
                childtid=clone(myFunction,(void *)stack_high,CLONE_THREAD|CLONE_VM|CLONE_SIGHAND,(void *)(array+i));
                aux=errno;
                if(childtid == -1)
                {
                        printf("Clone failed: \"%s\"\n",strerror(aux));
                        return 2;
                }
        }
        sleep(2);//We just wait... synching the threads is a pain...

        //We print all the TID values stored in the array by every thread
        for(i=0;i<THREADS;i++)
        {
                printf("Spawned thread %d\n",*(array+i));
        }
        return 0;
}

// This function is used to run every new thread, it receives a pointer to the place where the thread should store its TID
int myFunction(void *arg)
{
        int *aux;
        aux=(int *)arg;
        *aux=syscall(SYS_gettid);//Stores the thread TID in the memory possition passed as argument.
        pause();
}

As you can see clone() requires a few more parameters than fork() in order to create life in your system. Essentially these:
  • A pointer to the function that will be the code the thread will execute. In the example the function is called myFunction (I'm great at naming stuff, right?) and all it does is to write the TID value of the thread to a position in memory that comes in the arg argument.
  • The next parameter is the stack, as I mentioned before the stack is one of those things that can't be shared among threads, simply because it keeps the current execution context, local variables, etc. So, you need to allocate a certain amount of memory to act as stack on the new thread, in this case I'm reserving 1024*1024 bytes, nothing fancy on the number, smaller numbers caused Segmentation faults xD. Another interesting thing here is that due to the way stack works, you have to pass the highest memory  position as argument not the lowermost as usually happens.
  • As third parameter we have the flags that will define clone()'s behavior, since we want it to spawn a process with shared context I set CLONE_THREAD, and the other 2 (CLONE_VM and CLONE_SIGHAND) have to be there as well because of CLONE_THREAD (more details about that here).
  • Parameter number 4 is the argument that will be passed to the function in parameter number 1, in the case of this example is just a memory position where the thread should store the TID value.
 So reading the code you can kind of understand what's going to happen:
  1. 5 threads should be spawned, unless something goes terrible wrong during the clone call.
  2. Each thread should write its TID in a particular position on array[], for example the first spawned thread should write its TID in array[0], the second thread in array[1] and so on. NOTE: array[] is placed in the stack of the leader thread, yet threads can access it!
  3. After writing the TID in that memory position the threads will just pause themselves to prevent them from exiting and terminating the rest of the threads, including the leader thread.
  4. The leader thread after spawning the 5 threads just sleeps for 2 seconds waiting for the threads to hopefully execute, and then prints the results. Sending signals between threads turned out to be way harder than I thought so I gave up and went down the easy road, just wait for it.
No big deal, but now lets see if that works:

juan@test:~/clone_fork$ gcc -o clone_test_simplified clone_test_simplified.c
juan@test:~/clone_fork$ ./clone_test_simplified
Spawned thread 2934
Spawned thread 2935
Spawned thread 2936
Spawned thread 2937
Spawned thread 2938
juan@test:~/clone_fork$

indeed it did!!! (the fun part here is that you have no idea how many times I had to compile this stuff to make it work xD).

For the fun of it, I increased the sleep time and captured the output of ps as I did with rsyslogd before so we can have a look at the threads created and the other values. Here we have the output:

juan@test:~/clone_fork$ gcc -o clone_test_simplified clone_test_simplified.c
juan@test:~/clone_fork$ ./clone_test_simplified &
[1] 2945
juan@test:~/clone_fork$ ps -eLF |grep "PID\|clone"
UID        PID  PPID   LWP  C NLWP    SZ   RSS PSR STIME TTY          TIME CMD
juan      2945  1938  2945  0    6  2334   628   1 22:04 pts/1    00:00:00 ./clone_test_simplified
juan      2945  1938  2946  0    6  2334   628   0 22:04 pts/1    00:00:00 ./clone_test_simplified
juan      2945  1938  2947  0    6  2334   628   1 22:04 pts/1    00:00:00 ./clone_test_simplified
juan      2945  1938  2948  0    6  2334   628   0 22:04 pts/1    00:00:00 ./clone_test_simplified
juan      2945  1938  2949  0    6  2334   628   0 22:04 pts/1    00:00:00 ./clone_test_simplified
juan      2945  1938  2950  0    6  2334   628   0 22:04 pts/1    00:00:00 ./clone_test_simplified
juan      2952  1938  2952  0    1  3987  2268   1 22:04 pts/1    00:00:00 grep --color=auto PID\|clone
juan@test:~/clone_fork$ Spawned thread 2946
Spawned thread 2947
Spawned thread 2948
Spawned thread 2949
Spawned thread 2950

[1]+  Done                    ./clone_test_simplified
juan@test:~/clone_fork$

So we see now NLWP states there are 6 threads under TGID 2945, you can see how 5 LWP match with the ones printed by the binary right afterwards, these were the ones spawned by the leader thread TID 2945.

Wrap up


Processes in Linux are created by either fork() or clone() syscall, and not only they are called different but they provide different features as well. Fork will result in two identical copies of the original process, while clone (when used with CLONE_THREAD) will instead create what is usually called light weight process, that shares part of the execution context with its creator process.

The main difference between processes created with fork and "threads" created with clone is that threads share the same memory space and therefore communication between them is way easier, improving cache and TLB usage since page tables are shared. However you have to be careful when dealing with shared memory spaces and using proper locking mechanisms unless you want to have some headaches. On the contrary processes spawned from fork run in completely different an isolated memory spaces, therefore communication between them is more expensive (pipes, shared memory, other IPC mechanisms).

Bibliography


https://linux.die.net/man/2/clone
http://man7.org/linux/man-pages/man2/syscall.2.html
http://blog.man7.org/
http://www.google.com

domingo, 18 de diciembre de 2016

Process mating season 101 - Fork and Clone

Yeah, I know, the title is awesome, isn't it? Come on! at least it should be if you understand what fork() and clone() do in the context of Linux syscalls.

These two calls are the ones in charge of creating life on your system, basically spawning new processes. We'll have a look at the fundamental differences, some examples to understand them and some interesting facts

That said, before moving forward I'd like to outline the following:
  • Syscalls are the interface the kernel exposes to the user space processes, or if you want, they are the way processes access to the kernel services.
  • Usually processes don't use syscalls directly but they use them through some wrapper functions provided by glibc (in GNU/Linux at least). This wrapper functions provide sort of an abstraction layer, handling syscall parameters, return values and other situations.
Note: btw I've already talked a bit about syscalls here maybe you want to have a look.

Fork, the processes mitosis process

[off topic] I'm getting extremely good at writing titles![/off topic]

Pretty much like the eukaryotic cells replication process, the result of a fork call is a new almost identical process known as child process. The "almost" is key here, there are some properties that will be different, like (for an exhaustive list, please have a look at this):
  • PID will be different, the kernel will assign a new/unused PID to the child process. The parent PID of the child process will be its parent's PID (kind of makes sense, doesn't it?)
  • The child process doesn't inherit timers or memory locks.
  • Others
On the other side of the "almost" we have:
  • The child process will have an exact copy of its parent entire virtual address space (fork() is implemented using copy-on-write pages, so the only penalty that it incurs is the time and memory required to duplicate the parent's page tables, and to create a unique task structure for the child.). 
  • The child process inherits copies of structures like open file descriptors, open directory streams, etc.
Right after the fork() call the processes will be, although they are still sharing some resources,  two different entities, and they could be running two different code paths. This will be easier to understand with a simple example.

Simple fork() example


The code is self explanatory (or at least I tried) so I won't explain it in details
#include <stdio.h>
#include <sys/types.h>
#include <unistd.h>
#include <sys/syscall.h>
#include <errno.h>
#include <string.h>

int main()
{
        int pid,ppid,childpid,keep_it;
        pid=getpid();//Get process ID
        ppid=getppid();//Get parent process ID

        childpid=fork();//fork() returns the child PID on the parent's code path and 0 on the child's. On failure returns -1
        //From this point on, there are 2 processes running, unless fork failed of course :D.
        keep_it=errno;
        if(childpid==-1)//Check if fork() failed
        {
                printf("Fork failed due to \"%s\"\n",strerror(keep_it));//print the system error that corresponds to errno
                return -1;
        }

        if(childpid==0)//Here is where the paths change, it could be done differently.
        {//Child code path here
                printf("Child process: \nPID\tPPID\n%d\t%d\n",pid,ppid);
                pid=getpid();
                ppid=getppid();
                printf("Child process: \nPID\tPPID\n%d\t%d\n",pid,ppid);
                sleep(5);
        }
        else
        {//Parent code path here
                sleep(10);
                printf("Parent process: \nPID\tPPID\n%d\t%d\n",pid,ppid);
                printf("Parent process: child PID was %d\n",childpid);
        }
        return 1;
}

lets run it to see what happens:
juan@test:~/clone_fork$ gcc -o fork_simple_example fork_simple_example.c
juan@test:~/clone_fork$ ./fork_simple_example
Child process:
PID     PPID
3213    2965
Child process:
PID     PPID
3214    3213
Parent process:
PID     PPID
3213    2965
Parent process: child PID was 3098
juan@test:~/clone_fork$
on a different shell I also captured the processes with ps:
juan@test:~$ ps axo stat,user,comm,ppid,pid|grep fork
S+   juan     fork_simple_exa  2965  3213
S+   juan     fork_simple_exa  3213  3214
juan@test:~$
So, what do we see from both outputs? The child process printed twice its PID and PPID just for the sake of showing how the first time the values on those variables were actually the ones collected by its father before the fork() call.

 File descriptors are preserved example


As we mentioned before, certain kernel structures are copied to the new child process, one of them are the open file descriptors. Now lets see that in an example using a pipe.

Note: a pipe is a type of Inter Process Communication mechanism, you can think the pipe as that simply a pipe with two ends, one where you can write to and one where you can read from. For more details please have a look at this.

The code is:
#include <stdio.h>
#include <sys/types.h>
#include <unistd.h>
#include <sys/syscall.h>
#include <errno.h>
#include <string.h>
#define SIZE 250

int main()
{
        char buffer[SIZE],ch;
        int keep_it,childpid,aux,count;
        int my_pipe[2];//my_pipe[] will keep two FD, my_pipe[1] to write into the pipe and my_pipe[0] to read from the pipe.

        aux=pipe(my_pipe);//Note how the pipe is created BEFORE the fork() call

        if(aux==-1)//Check if pipe() failed
        {
                printf("Pipe failed due to \"%s\"\n",strerror(keep_it));//print the system error that corresponds to errno
                return -1;
        }

        childpid=fork();//fork() returns the child PID on the parent's code path and 0 on the child's. On failure returns -1
        //From this point on, there are 2 processes running, unless fork failed of course :D.
        keep_it=errno;
        if(childpid==-1)//Check if fork() failed
        {
                printf("Fork failed due to \"%s\"\n",strerror(keep_it));//print the system error that corresponds to errno
                return -1;
        }

        if(childpid==0)//Here is where the paths change, it could be done differently.
        {//Child code path here
                close(my_pipe[0]);//On the child process we can close the read end of the pipe
                printf("Hi, this is the child process, insert message here (:P less than %d letters please): ",SIZE);
                fgets(buffer,sizeof(buffer),stdin);
                count=write(my_pipe[1],buffer,SIZE);
                printf("message sent to parent process.\n");
        }
        else
        {//Parent code path here
                close(my_pipe[1]);//On the parent process we can close the write end of the pipe
                read(my_pipe[0],buffer,SIZE);
                printf("Parent process received message: %s",buffer);
        }
        return 1;
}

This code is a bit more complex, but the comments should help.

You can see how the pipe was open on the parent process (Line 15) and yet it was used on the child process (Line 37) without any problems! Also worth noting how the pipe requires 2 file descriptors, one to read from the pipe (stored in my_pipe[0]) and one to write into the pipe (stored in my_pipe[1]). After the fork() call since child and parent process have copies of these open file descriptors they can safely close the ones they won't use, and then they end up with a unidirectional inter process communication channel (child -> PIPE -> parent).

A funny fact

 
At this point I was tempted to run some straces to show how the fork syscall was being used (using strace) and noticed the following, this is the strace output of running the first simple example:
juan@test:~/clone_fork$ strace ./fork_simple_example
execve("./fork_simple_example", ["./fork_simple_example"], [/* 22 vars */]) = 0
brk(0)                                  = 0x16ba000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa76a34a000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=95253, ...}) = 0
mmap(NULL, 95253, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fa76a332000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P \2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1840928, ...}) = 0
mmap(NULL, 3949248, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fa769d65000
mprotect(0x7fa769f1f000, 2097152, PROT_NONE) = 0
mmap(0x7fa76a11f000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1ba000) = 0x7fa76a11f000
mmap(0x7fa76a125000, 17088, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fa76a125000
close(3)                                = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa76a331000
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa76a32f000
arch_prctl(ARCH_SET_FS, 0x7fa76a32f740) = 0
mprotect(0x7fa76a11f000, 16384, PROT_READ) = 0
mprotect(0x600000, 4096, PROT_READ)     = 0
mprotect(0x7fa76a34c000, 4096, PROT_READ) = 0
munmap(0x7fa76a332000, 95253)           = 0
getpid()                                = 4981
getppid()                               = 4978
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fa76a32fa10) = 4982
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
nanosleep({10, 0}, Child process:
PID     PPID
4981    4978
Child process:
PID     PPID
4982    4981
{4, 995479188})      = ? ERESTART_RESTARTBLOCK (Interrupted by signal)
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=4982, si_status=1, si_utime=0, si_stime=0} ---
restart_syscall(<... resuming interrupted call ...>
) = 0
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 8), ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa76a349000
write(1, "Parent process: \n", 17Parent process:
)      = 17
write(1, "PID\tPPID\n", 9PID    PPID
)              = 9
write(1, "4981\t4978\n", 104981 4978
)            = 10
write(1, "Parent process: child PID was 49"..., 35Parent process: child PID was 4982
) = 35
exit_group(1)                           = ?
+++ exited with 1 +++
juan@test:~/clone_fork$

do you see any fork() call there? ... exactly there's no fork call!!! But I said fork is a Linux syscall and blah blah blah, right? Well, worry not, I wasn't lying :D all I said is true however...

Since version 2.3.3, rather than invoking the kernel's fork() system call, the glibc fork() wrapper that is provided as part of the NPTL threading implementation invokes clone(2) with flags that provide the same effect as the traditional system call. (A call to fork() is equivalent to a call to clone(2) specifying flags as just SIGCHLD.) 

that's the reason why we do see a clone call instead!

Now my brain needs some rest so I'll finish this post here, any feedback will be more than welcome!

On the next post I'll describe clone() and we'll see some examples to understand even better the differences with fork().

jueves, 17 de noviembre de 2016

Where did my disk space go??? Is df lying to me? or is it du lying?

I had an interesting situation today and thought might be a good idea to share it here. Basically the problem was more or less the following:
  1. A critical production system was running out of disk space and things were going downhills scarcely fast, df was showing utilization at 99% already.
  2. The user decided to delete some big log files in order to free up some space.
  3. After that df was still showing 99% , however running du on the root directory would show less space being utilized.
You can imagine now how unhappy the user was when realized that deleting files was not freeing any disk space and he was about to see the system become totally useless. On top of that he couldn't explain why df and du wouldn't come into an agreement in terms of free space on the system.

What was happening here? Was df or du lying to the user?


Well... software in general doesn't lie, usually what actually happens is that we don't really understand how it works and therefore we expect a different behavior. The root cause of the problem mentioned before is the unlink syscall, why? we can get the answer by asking the oracle (man 2 unlink):
DESCRIPTION
       unlink() deletes a name from the filesystem.  If that name was the last
       link to a file and no processes have the file open, the file is deleted
       and the space it was using is made available for reuse.

       If  the  name  was the last link to a file but any processes still have
       the file open, the file will remain in existence until  the  last  file
       descriptor referring to it is closed.

       ...
Yes :D, turns out that if you delete a file and there's at least one process that has a file descriptor pointing to that file, the space of the file won't be available right away.

Lets reproduce this:


The easiest way to understand this is by actually reproducing the behavior. I just used dd to fill-up the drive and the result was this:
[ec2-user@ip-172-31-16-117 ~]$ df -h
Filesystem      Size  Used Avail Use% Mounted on
devtmpfs        3.9G   56K  3.9G   1% /dev
tmpfs           3.9G     0  3.9G   0% /dev/shm
/dev/xvda1      7.8G  7.7G     0 100% /
[ec2-user@ip-172-31-16-117 ~]$ du -sch / 2>/dev/null
7.7G    /
7.7G    total
[ec2-user@ip-172-31-16-117 ~]$ echo a > file
-bash: echo: write error: No space left on device
[ec2-user@ip-172-31-16-117 ~]$
the system has clearly ran out of disk space at this point and we can't even add a single byte to a file. Now the next step would be to free up some space, so we check with du where we can find some files to delete:
[ec2-user@ip-172-31-16-117 ~]$ du -sch /* 2>/dev/null
7.0M    /bin
25M     /boot
4.0K    /cgroup
56K     /dev
9.1M    /etc
6.7G    /home
46M     /lib
23M     /lib64
4.0K    /local
16K     /lost+found
4.0K    /media
4.0K    /mnt
43M     /opt
0       /proc
4.0K    /root
8.0K    /run
12M     /sbin
4.0K    /selinux
4.0K    /srv
0       /sys
8.0K    /tmp
802M    /usr
48M     /var
7.7G    total
[ec2-user@ip-172-31-16-117 ~]$
the size of /home is a bit crazy considering the size of the partition itself so lets delete some files from /home/ec2-user:
[ec2-user@ip-172-31-16-117 ~]$ ls -lah
total 6.7G
drwx------ 3 ec2-user ec2-user 4.0K Nov 17 20:10 .
drwxr-xr-x 3 root     root     4.0K Nov 17 18:42 ..
-rw-r--r-- 1 ec2-user ec2-user   18 Aug 15 23:52 .bash_logout
-rw-r--r-- 1 ec2-user ec2-user  193 Aug 15 23:52 .bash_profile
-rw-r--r-- 1 ec2-user ec2-user  124 Aug 15 23:52 .bashrc
-rw-rw-r-- 1 ec2-user ec2-user 306M Nov 17 20:09 big_file
-rw-rw-r-- 1 ec2-user ec2-user    0 Nov 17 20:10 file
-rw-rw-r-- 1 ec2-user ec2-user 6.4G Nov 17 18:44 fillingup
-rwxrwxr-x 1 ec2-user ec2-user 7.0K Nov 17 20:09 service
-rw-rw-r-- 1 ec2-user ec2-user  309 Nov 17 20:09 service.c
drwx------ 2 ec2-user ec2-user 4.0K Nov 17 18:42 .ssh
-rw------- 1 ec2-user ec2-user 2.1K Nov 17 20:09 .viminfo
[ec2-user@ip-172-31-16-117 ~]$ rm big_file
[ec2-user@ip-172-31-16-117 ~]$
[ec2-user@ip-172-31-16-117 ~]$ echo a > file
-bash: echo: write error: No space left on device
[ec2-user@ip-172-31-16-117 ~]$
I've just deleted a 306Mbytes file and can't even write 1 single byte!!! Having a look at df and du things look like:
[ec2-user@ip-172-31-16-117 ~]$ df -h
Filesystem      Size  Used Avail Use% Mounted on
devtmpfs        3.9G   56K  3.9G   1% /dev
tmpfs           3.9G     0  3.9G   0% /dev/shm
/dev/xvda1      7.8G  7.7G     0 100% /
[ec2-user@ip-172-31-16-117 ~]$ du -sch / 2>/dev/null
7.4G    /
7.4G    total
[ec2-user@ip-172-31-16-117 ~]$
while du shows the expected size, df insists in saying the partition is at 100% utilization. Cool, with just a few steps we have reproduced the situation!

The reason behind the difference between df and du is in the fact that du calculates the size of the folders by adding up the size of the files inside and big_file does not exist anymore on the folder (has been removed from the directory entry), while df shows the real available space of the file system.

With all this in mind, the only reason why the file system size wouldn't change after deleting a file is because there's at least one process that keeps a file descriptor pointing to the deleted file (you can read more about open files and file descriptors in Linux limits 102 - Open Files). We can easily identify the process that holds the file descriptor by simple using our lovely lsof:
[ec2-user@ip-172-31-16-117 ~]$ lsof |grep "\(deleted\)"
service   23177 ec2-user    3r      REG  202,1 319934464  14708 /home/ec2-user/big_file (deleted)
[ec2-user@ip-172-31-16-117 ~]$
ja! turns out process "service" with PID 23177 has a file descriptor that points to file /home/ec2-user/big_file and that file has been deleted!!! So if we get rid of process service then the space should be finally available, lets confirm that:
[ec2-user@ip-172-31-16-117 ~]$ kill -9 23177
[ec2-user@ip-172-31-16-117 ~]$ 
[1]+  Killed                  ./service
[ec2-user@ip-172-31-16-117 ~]$ df -h
Filesystem      Size  Used Avail Use% Mounted on
devtmpfs        3.9G   56K  3.9G   1% /dev
tmpfs           3.9G     0  3.9G   0% /dev/shm
/dev/xvda1      7.8G  7.4G  306M  97% /
[ec2-user@ip-172-31-16-117 ~]$ du -sch / 2>/dev/null
7.4G    /
7.4G    total
[ec2-user@ip-172-31-16-117 ~]$
and magic happened!!! When the processes was terminated the fd was finally closed and the last reference to the file disappeared causing the space to bee available now and therefore df matches with du now.

Depending on which process is keeping the file open you may have other options besides killing it, for example:
  • Restarting it if it's a service.
  • Perhaps sending another signal (for example to rotate logs?). 
  • If for some reason (uninterruptible state) you can't kill the process then the only easy way here is to restart the whole system.

jueves, 25 de junio de 2015

Jugando con Linux Audit System Parte II

En la entrada anterior veíamos los cimientos de Linux Audit System, ahora vamos a ver un par de aplicaciones prácticas como para hacernos una idea mas clara de para qué se puede utilizar.

La instalación por defecto de Ubuntu no trae ninguna regla pre configurada en audit. Podemos ver las reglas que se encuentran cargadas utilizando auditctl -l de la siguiente manera:

root@ubuntu:/home/juan# auditctl -l
No rules
root@ubuntu:/home/juan#

Reglas de audit

Existen 3 tipos de reglas en audit
  • Reglas de control: permiten modificar el comportamiento de audit.
  • Reglas de archivos (File system): permiten registrar los accesos y modificaciones a archivos y directorios.
  • Reglas de syscalls:  permiten registrar la utilización de las llamadas al system por parte de los procesos.

Reglas de control

Estas reglas van a definir el comportamiento de audit en lineas generales. Por ejemplo la cantidad de buffers disponibles, el comportamiento ante errores críticos, etc.

En el siguiente ejemplo configuramos  audit para que ante un evento crítico genere un kernel panic

root@ubuntu:/home/juan# auditctl -f 2
AUDIT_STATUS: enabled=1 flag=2 pid=882 rate_limit=0 backlog_limit=320 lost=0 backlog=0
root@ubuntu:/home/juan#


Ahora con la opción "-e 2" bloqueamos la configuración para que no pueda ser modificada salvo con un reinicio:

root@ubuntu:/home/juan# auditctl -e 2
AUDIT_STATUS: enabled=2 flag=2 pid=882 rate_limit=0 backlog_limit=320 lost=0 backlog=0
root@ubuntu:/home/juan# auditctl -e 1
Error sending enable request (Operation not permitted)
root@ubuntu:/home/juan# auditctl -e 0
Error sending enable request (Operation not permitted)
root@ubuntu:/home/juan# auditctl -f 1
Error sending failure mode request (Operation not permitted) root@ubuntu:/home/juan#


ninguna operación que modifique el comportamiento de audit estará permitida, la única forma de solucionar esto es reiniciar el sistema. Una vez reiniciado el sistema, enabled vuelve a ser 1, es decir se vuelve a habilitar el cambio de configuración.

root@ubuntu:/home/juan# auditctl -s
AUDIT_STATUS: enabled=1 flag=1 pid=880 rate_limit=0 backlog_limit=320 lost=0 backlog=0
root@ubuntu:/home/juan#

Reglas de archivos

Las reglas de archivos o directorios tienen 3 componentes, el path del archivos indicado por "-w", los permisos indicados por "-p" y una cadena indicada por "-k".

Ejemplo 1: para reportar cada vez que un usuario ejecuta el comando ping hacemos:

root@ubuntu:/home/juan# auditctl -w /bin/ping -p x -k "haciendo ping xD"
root@ubuntu:/home/juan# auditctl -l
LIST_RULES: exit,always watch=/bin/ping perm=x key=haciendo ping xD
root@ubuntu:/home/juan#  


Podemos ver que la regla fue agregada y si ahora hacemos ping

juan@ubuntu:~$ ping -c 1 8.8.8.8
PING 8.8.8.8 (8.8.8.8) 56(84) bytes of data.
64 bytes from 8.8.8.8: icmp_seq=1 ttl=58 time=62.0 ms

--- 8.8.8.8 ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 62.040/62.040/62.040/0.000 ms
juan@ubuntu:~$


veremos las siguientes líneas en /var/log/audit/audit.log

type=EXECVE msg=audit(1435008355.184:39): argc=4 a0="ping" a1="-c" a2="1" a3="8.8.8.8"
type=CWD msg=audit(1435008355.184:39):  cwd="/home/juan"
type=PATH msg=audit(1435008355.184:39): item=0 name="/bin/ping" inode=130121 dev=08:01 mode=0104755 ouid=0 ogid=0 rdev=00:00 nametype=NORMAL
type=PATH msg=audit(1435008355.184:39): item=1 name=(null) inode=130569 dev=08:01 mode=0100755 ouid=0 ogid=0 rdev=00:00 nametype=NORMAL


Y qué demonios significa todo eso...??? Vamos a desmenuzar un poco las líneas para entender qué nos está diciendo audit con ese log:

  • Los logs comienzan con un campo tipo type que indica el tipo de registro en cuestión.
  • A continuación viene el campo msg que se encuentra formado por el audit unique ID (los logs que formen parte de un mismo evento se pueden reconocer porque llevarán el mismo audit unique ID) compuesto por el timestamp (1435008355.184) y un identificador (39). Luego de esta campo veremos una lista variable de valores tipo name=value que dependerán del tipo de registro y harán referencia a los distintos campos informativos provistos por el kernel o las aplicaciones en espacio de usuario
Entonces si con esto analizamos las 3 lineas que registró audit daemon vemos:
  • El primer registro es de tipo EXECVE, este registra los parámetros de la syscall execve con la que se ejecutó ping.
  • El segundo registro es de tipo CWD y obtuvo el current working directory del evento /home/juan.
  • El tercer registro (item=0 de la syscall) es de tipo PATH y obtuvo información acerca del archivo /bin/ping, por ejemplo 
    • El inodo del archivo (130569)
    • El dispositivo donde se encuentra (08:01)
    • Los permisos del archivo 4755
    • OUID y OGID ID del usuario dueño y grupo del usuario dueño 0 y 0 en este caso.
  • El cuerto registro (item=1 de la syscall) hace referencia a la llamada al dynamic linker ld que es utilizado para cargar las librerias compartidas que precisa ping para ejecutarse.
    • Vemos el inodo del archivos utilizado (130569)
    • Los permisos (0755)
Ahora podemos comprobar todo esto que vimos en los logs de audit consultando directamente a los archivos en cuestión:

root@ubuntu:/home/juan# ls -lai /bin/ping
130121 -rwsr-xr-x 1 root root 38932 May  7  2014 /bin/ping
root@ubuntu:/home/juan# ls -lai /lib/i386-linux-gnu/ld-2.19.so
130569 -rwxr-xr-x 1 root root 134380 Feb 25 16:58 /lib/i386-linux-gnu/ld-2.19.so
root@ubuntu:/home/juan#  


Por suerte la información es consistente.

Ejemplo 2: ahora algo un poco más sencillo, registremos las alteraciones a un determinado archivo, por ejemplo /etc/resolv.conf

root@ubuntu:/home/juan# auditctl -w /etc/resolv.conf -p wa -k "resolv.conf"
root@ubuntu:/home/juan# auditctl -l
LIST_RULES: exit,always watch=/bin/ping perm=x key=haciendo ping xD
LIST_RULES: exit,always watch=/etc/resolv.conf perm=wa key=resolv.conf
root@ubuntu:/home/juan#


Ahora simplemente agregamos una linea al final con un comentario de la siguiente manera:

root@ubuntu:/home/juan# echo "#comentario" >> /etc/resolv.conf
root@ubuntu:/home/juan#


y vemos qué hay en los logs:

type=SYSCALL msg=audit(1435095642.812:48): arch=40000003 syscall=5 success=yes exit=3 a0=9fba768 a1=8441 a2=1b6 a3=9fba768 items=4 ppid=1033 pid=1034 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts0 ses=1 comm="bash" exe="/bin/bash" key="resolv.conf"
type=CWD msg=audit(1435095642.812:48):  cwd="/home/juan"
type=PATH msg=audit(1435095642.812:48): item=0 name="/etc/" inode=6957 dev=00:10 mode=040755 ouid=0 ogid=0 rdev=00:00 nametype=PARENT
type=PATH msg=audit(1435095642.812:48): item=1 name=(null) inode=260560 dev=08:01 mode=0120777 ouid=0 ogid=0 rdev=00:00 nametype=NORMAL
type=PATH msg=audit(1435095642.812:48): item=2 name=(null) inode=8112 dev=00:10 mode=0100644 ouid=0 ogid=0 rdev=00:00 nametype=NORMAL
type=PATH msg=audit(1435095642.812:48): item=3 name=(null) inode=8112 dev=00:10 mode=0100644 ouid=0 ogid=0 rdev=00:00 nametype=NORMAL


A decir verdad esperaba un log un poco mas humano y simple para este escenario, pero viene genial para aprender a usar otra de las herramientas de audit. La herramienta es ausearch, y nos permitirá buscar dentro de los logs determinados eventos y hasta es capaz de interpretar buena parte de los valores y reemplazarlos por palabras mas humanas, por ejemplo si buscamos eventos con la key resolv.conf veremos lo siguiente:

root@ubuntu:/home/juan# ausearch -i -k "resolv.conf"
----
type=CONFIG_CHANGE msg=audit(06/23/15 22:37:40.856:45) : auid=juan ses=1 op="add rule" key=resolv.conf list=exit res=yes
----
type=CONFIG_CHANGE msg=audit(06/23/15 22:38:05.520:46) : auid=juan ses=1 op="add rule" key=resolv.conf list=exit res=yes
----
type=PATH msg=audit(06/23/15 22:40:42.812:48) : item=3 name=(null) inode=8112 dev=00:10 mode=file,644 ouid=root ogid=root rdev=00:00 nametype=NORMAL
type=PATH msg=audit(06/23/15 22:40:42.812:48) : item=2 name=(null) inode=8112 dev=00:10 mode=file,644 ouid=root ogid=root rdev=00:00 nametype=NORMAL
type=PATH msg=audit(06/23/15 22:40:42.812:48) : item=1 name=(null) inode=260560 dev=08:01 mode=link,777 ouid=root ogid=root rdev=00:00 nametype=NORMAL
type=PATH msg=audit(06/23/15 22:40:42.812:48) : item=0 name=/etc/ inode=6957 dev=00:10 mode=dir,755 ouid=root ogid=root rdev=00:00 nametype=PARENT
type=CWD msg=audit(06/23/15 22:40:42.812:48) :  cwd=/home/juan
type=SYSCALL msg=audit(06/23/15 22:40:42.812:48) : arch=i386 syscall=open success=yes exit=3 a0=0x9fba768 a1=O_WRONLY|O_CREAT|O_APPEND a2=0666 a3=0x9fba768 items=4 ppid=1033 pid=1034 auid=juan uid=root gid=root euid=root suid=root fsuid=root egid=root sgid=root fsgid=root tty=pts0 ses=1 comm=bash exe=/bin/bash key=resolv.conf
root@ubuntu:/home/juan#


ahora se puede ver como muchos campos fueron reemplazados por valores un poco mas conocidos (se reemplazo syscall 5 por open, los ouid y ogid por root, etc).

Reglas de syscalls

Estas reglas ya implican un mayor detalle a la hora de definirlas. Son necesarios los siguientes parámetros:
  • -a action,filter: la acción puede ser always o never. Cuando se elige never, no se generan registros para este evento.
  • -S syscall: indica la syscall he se registrará.
  • -F name=value: permite afinar aún mas el filtro para desencadenar el regirstro de la syscall, por ejemplo se podría filtrar una determinada syscall para el proceso con pid=1000.
  • -k key: una clave para facilitar las búsqueda dentro de los logs.
Por ejemplo, vamos a crear una regla para registrar todos los eventos donde el usuario Juan elimine un archivo

root@ubuntu:/home/juan# grep juan /etc/passwd
juan:x:1000:1000:juan,,,:/home/juan:/bin/bash
root@ubuntu:/home/juan# auditctl -a always,exit -S unlink -F uid=1000 -k juan_delete
root@ubuntu:/home/juan# auditctl -l
LIST_RULES: exit,always uid=1000 (0x3e8) key=juan_delete syscall=unlink
root@ubuntu:/home/juan# 


una vez agregada la regla probamos eliminando un archivo:

juan@ubuntu:~$ touch file
juan@ubuntu:~$ ll -i file
158216 -rw-rw-r-- 1 juan juan 0 Jun 25 22:25 file
juan@ubuntu:~$ rm file
juan@ubuntu:~$


y controlamos los logs con ausearch interpretado (-i)

root@ubuntu:/home/juan# ausearch -i -k juan_delete
----
type=CONFIG_CHANGE msg=audit(06/25/15 22:19:59.309:35) : auid=juan ses=1 op="add rule" key=juan_delete list=exit res=yes 

----
type=PATH msg=audit(06/25/15 22:31:40.089:62) : item=1 name=file inode=158216 dev=08:01 mode=file,664 ouid=juan ogid=juan rdev=00:00 nametype=DELETE
type=PATH msg=audit(06/25/15 22:31:40.089:62) : item=0 name=/home/juan inode=149893 dev=08:01 mode=dir,755 ouid=juan ogid=juan rdev=00:00 nametype=PARENT
type=CWD msg=audit(06/25/15 22:31:40.089:62) :  cwd=/home/juan
type=SYSCALL msg=audit(06/25/15 22:31:40.089:62) : arch=i386 syscall=unlinkat success=yes exit=0 a0=0xffffff9c a1=0x86bdab8 a2=0x0 a3=0x0 items=2 ppid=1209 pid=1241 auid=juan uid=juan gid=juan euid=juan suid=juan fsuid=juan egid=juan sgid=juan fsgid=juan tty=pts1 ses=2 comm=rm exe=/bin/rm key=juan_delete
root@ubuntu:/home/juan#


a partir de los logs del evento, podemos averiguar bastante información de lo que sucedió como: el nombre del archivo eliminado, sus permisos, el comando utilizado la syscall, etc. Queda claro que no pudimos evitar la eliminación, sin embargo quedó bien registrada y documentada.

Rompamos

Bien a modo de última prueba se me ocurrió comprobar el funcionamiento de la opción "-f 2" que ante un evento desafortunado debería generar un kernel panic. Para forzar el evento desafortunado vamos a setear un rate limit the mensajes bajo, 2 por seguno:

root@ubuntu:/home/juan# auditctl -s
AUDIT_STATUS: enabled=1 flag=1 pid=885 rate_limit=0 backlog_limit=320 lost=0 backlog=0
root@ubuntu:/home/juan# auditctl -r 2
AUDIT_STATUS: enabled=1 flag=1 pid=885 rate_limit=2 backlog_limit=320 lost=0 backlog=0
root@ubuntu:/home/juan# auditctl -f 2
AUDIT_STATUS: enabled=1 flag=2 pid=885 rate_limit=2 backlog_limit=320 lost=0 backlog=0
root@ubuntu:/home/juan#

ahora con el nuevo rate limit y la opción de flag 2 seteada forzamos unos cuantos mensajes y boala:


la VM quedó completamente inutilizable.

Resumen

Linux System Audit es sin lugar a dudas una muy buena opción para registrar eventos en el sistema. Sin embargo hay algunas cosas para tener en cuenta:
  • Audit no proveé protección extra, solo reporta eventos. No sustituye ni a SELinux ni Apparmor, los complementa en todo caso.
  • Como toda medida de seguridad, puede afectar la performance del sistema si se aplica desmedidamente. El mismo man de auditcl lo confirma con "Syscall  rules get evaluated for each syscall for every program. If you have 10 syscall rules, every program on your system will delay during a syscall  while  the  audit system evaluates each rule. Too many syscall rules will hurt performance."
  • Las reglas se pueden poner de manera permanente en un archivo dentro de /etc/audit/rules.d/