Arquivos Deletados Presos Por Processo

Cenário


O cenário é conhecido , voce tem um ambiente com espaço em disco baixo e o volume da partição de logs esta quase cheio , voce verifica que tem um arquivo de log ocupando bastante espaço:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
ahfalo:/var/log# df -h
Filesystem            Size  Used Avail Use% Mounted on
/dev/mapper/VolGroup00-root
                       38G   26G   11G  71% /
tmpfs                 2.0G  4.0K  2.0G   1% /lib/init/rw
udev                  2.0G  216K  2.0G   1% /dev
tmpfs                 2.0G  624K  2.0G   1% /dev/shm
/dev/sda1             274M  134M  127M  52% /boot
/dev/mapper/VolGroup00-tmp
                      5.6G  614M  4.7G  12% /tmp
/dev/mapper/VolGroup00-var
                       56G   48G  5.2G  91% /var
/dev/mapper/VolGroup01-chroot
                       82G   60G   19G  77% /var/chroots
1
2
ferraz@ahfalo:~$ ls -lah /var/log/daemonlog
-rw-r--r-- 1 root root 10G 2010-12-11 01:19 /var/log/daemonlog

Até ae sem novidades, voce remove o arquivo e verifica novamente o espaço em disco disponivel:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
ahfalo:/var/log# df -h
Filesystem            Size  Used Avail Use% Mounted on
/dev/mapper/VolGroup00-root
                       38G   26G   11G  71% /
tmpfs                 2.0G  4.0K  2.0G   1% /lib/init/rw
udev                  2.0G  216K  2.0G   1% /dev
tmpfs                 2.0G  624K  2.0G   1% /dev/shm
/dev/sda1             274M  134M  127M  52% /boot
/dev/mapper/VolGroup00-tmp
                      5.6G  614M  4.7G  12% /tmp
/dev/mapper/VolGroup00-var
                       56G   48G  5.2G  91% /var
/dev/mapper/VolGroup01-chroot
                       82G   60G   19G  77% /var/chroots

O que aconteceu ?


Nesse momento fica a duvida porque o espaço em disco não foi liberado , voce executa o lsof para analisar os arquivos que estão abertos pelo processo do Daemon e encontra esse caso:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
root@ahfalo:~# lsof -p 14567

COMMAND    PID USER   FD   TYPE DEVICE SIZE/OFF   NODE NAME
mydaemon 14567 root  cwd    DIR    8,2     4096  65409 /root
mydaemon 14567 root  rtd    DIR    8,2     4096      2 /
mydaemon 14567 root  txt    REG    8,2  2279976   3799 /usr/bin/python2.6
mydaemon 14567 root  mem    REG    8,2     9736    143 /lib/libdl-2.12.1.so
mydaemon 14567 root  mem    REG    8,2     9748   4068 /lib/libutil-2.12.1.so
mydaemon 14567 root  mem    REG    8,2   121578    824 /lib/libpthread-2.12.1.so
mydaemon 14567 root  mem    REG    8,2  1353652   4282 /lib/libcrypto.so.0.9.8
mydaemon 14567 root  mem    REG    8,2   149392    152 /lib/libm-2.12.1.so
mydaemon 14567 root  mem    REG    8,2  1421892    134 /lib/libc-2.12.1.so
mydaemon 14567 root  mem    REG    8,2   294696   4281 /lib/libssl.so.0.9.8
mydaemon 14567 root  mem    REG    8,2    79476    119 /lib/libz.so.1.2.3.4
mydaemon 14567 root  mem    REG    8,2   118084    120 /lib/ld-2.12.1.so
mydaemon 14567 root  mem    REG    8,2  2768240 155207 /usr/lib/locale/locale-archive
mydaemon 14567 root    0u   CHR  136,0      0t0      3 /dev/pts/0
mydaemon 14567 root    1u   CHR  136,0      0t0      3 /dev/pts/0
mydaemon 14567 root    2u   CHR  136,0      0t0      3 /dev/pts/0
mydaemon 14567 root    3w   REG    8,2     1060 131921 /var/log/daemon.log (deleted)

O que importa para nos é essa ultima linha:

1
mydaemon 14567 root    3w   REG    8,2     1060 131921 /var/log/daemon.log (deleted)

O lsof esta informando que o processo mydaemon com o pid 15567 esta com o arquivo daemon.log aberto em modo de escrita (w) , muitas vezes a aplicação precisa realmente estar com o arquivo aberto durante o tempo todo para poder escrever alguma informação , por isso que o lsof esta exibindo o status deleted, pois o processo esta ainda com o arquivo aberto, nesse caso podemos reiniciar o daemon para que ele possa liberar esse File Descriptor e o SO possa liberar o espaço que o antigo arquivo de log estava consumindo.

O problema é muitas vezes não podemos reiniciar o Daemon naquele momento, o que podemos fazer então?

/proc Filesystem


Dentro do ambiente Linux, quando o Linux é inicializado alem das partições em disco e de rede que montamos existem algumas partições virtuais que o sistema monta, uma delas é o procfs , dentro desse filesystem podemos pegar muitas informações sobre o que esta sendo executado no seu ambiente , e mais ainda sobre um PID específico. Se usarmos como exemplo o PID do nosso daemon de exemplo (pid 14567):

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
root@urubu:~# ls -lah /proc/14567
total 0
dr-xr-xr-x   7 root root 0 2010-12-12 16:12 .
dr-xr-xr-x 163 root root 0 2010-12-01 01:42 ..
dr-xr-xr-x   2 root root 0 2010-12-12 16:39 attr
-r--------   1 root root 0 2010-12-12 16:39 auxv
-r--r--r--   1 root root 0 2010-12-12 16:39 cgroup
--w-------   1 root root 0 2010-12-12 16:39 clear_refs
-r--r--r--   1 root root 0 2010-12-12 16:12 cmdline
-rw-r--r--   1 root root 0 2010-12-12 16:39 comm
-rw-r--r--   1 root root 0 2010-12-12 16:39 coredump_filter
-r--r--r--   1 root root 0 2010-12-12 16:39 cpuset
lrwxrwxrwx   1 root root 0 2010-12-12 16:16 cwd -> /root
-r--------   1 root root 0 2010-12-12 16:39 environ
lrwxrwxrwx   1 root root 0 2010-12-12 16:16 exe -> /usr/bin/python2.6
dr-x------   2 root root 0 2010-12-12 16:12 fd
dr-x------   2 root root 0 2010-12-12 16:16 fdinfo
-r--r--r--   1 root root 0 2010-12-12 16:39 io
-r--r--r--   1 root root 0 2010-12-12 16:39 latency
-r--------   1 root root 0 2010-12-12 16:39 limits
-rw-r--r--   1 root root 0 2010-12-12 16:39 loginuid
-r--r--r--   1 root root 0 2010-12-12 16:16 maps
-rw-------   1 root root 0 2010-12-12 16:39 mem
-r--r--r--   1 root root 0 2010-12-12 16:39 mountinfo
-r--r--r--   1 root root 0 2010-12-12 16:39 mounts
-r--------   1 root root 0 2010-12-12 16:39 mountstats
dr-xr-xr-x   5 root root 0 2010-12-12 16:39 net
-rw-r--r--   1 root root 0 2010-12-12 16:39 oom_adj
-r--r--r--   1 root root 0 2010-12-12 16:39 oom_score
-r--------   1 root root 0 2010-12-12 16:39 pagemap
-r--------   1 root root 0 2010-12-12 16:39 personality
lrwxrwxrwx   1 root root 0 2010-12-12 16:16 root -> /
-rw-r--r--   1 root root 0 2010-12-12 16:39 sched
-r--r--r--   1 root root 0 2010-12-12 16:39 schedstat
-r--r--r--   1 root root 0 2010-12-12 16:39 sessionid
-r--r--r--   1 root root 0 2010-12-12 16:39 smaps
-r--------   1 root root 0 2010-12-12 16:39 stack
-r--r--r--   1 root root 0 2010-12-12 16:12 stat
-r--r--r--   1 root root 0 2010-12-12 16:39 statm
-r--r--r--   1 root root 0 2010-12-12 16:12 status
-r--------   1 root root 0 2010-12-12 16:39 syscall
dr-xr-xr-x   3 root root 0 2010-12-12 16:39 task
-r--r--r--   1 root root 0 2010-12-12 16:39 wchan

Dentro de cada arquivo ou diretorio temos uma serie de informações desse processo relacionado ao SO , um desses diretorios é o fd:

1
2
3
4
5
6
7
8
root@urubu:~# ls -lah /proc/14567/fd
total 0
dr-x------ 2 root root  0 2010-12-12 16:12 .
dr-xr-xr-x 7 root root  0 2010-12-12 16:12 ..
lrwx------ 1 root root 64 2010-12-12 16:13 0 -> /dev/pts/0
lrwx------ 1 root root 64 2010-12-12 16:13 1 -> /dev/pts/0
lrwx------ 1 root root 64 2010-12-12 16:13 2 -> /dev/pts/0
l-wx------ 1 root root 64 2010-12-12 16:13 3 -> /var/log/daemon.log (deleted)

A partir dessa informação podemos realmente liberar o espaço em disco, lembrando que não podemos remover o file descriptor, apenas truncar a informação do arquivo

1
2
root@ahfalo:~# cd /proc/14567/fd
root@ahfalo:~# > 3

Ou podemos abrir o arquivo em modo de escrita :

1
2
3
4
5
6
ahfalo:/proc/14567/fd# python
Python 2.6.6 (r266:84292, Dec 12 2010, 15:15:09) 
[GCC 4.4.5] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> open("3","w")
<open file '3', mode 'w' at 0x7fb77d428c90>

Depois que realizamos um desses procedimentos agora sim o espaço foi liberado:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
ahfalo:/var/log# df -h
Filesystem            Size  Used Avail Use% Mounted on
/dev/mapper/VolGroup00-root
                       38G   26G   11G  71% /
tmpfs                 2.0G  4.0K  2.0G   1% /lib/init/rw
udev                  2.0G  216K  2.0G   1% /dev
tmpfs                 2.0G  624K  2.0G   1% /dev/shm
/dev/sda1             274M  134M  127M  52% /boot
/dev/mapper/VolGroup00-tmp
                      5.6G  614M  4.7G  12% /tmp
/dev/mapper/VolGroup00-var
                       56G   38G   16G  72% /var
/dev/mapper/VolGroup01-chroot
                       82G   60G   19G  77% /var/chroots

Esse é um cenário relativamente comum, alguns daemons deixam o fd aberto e não possuem um processo de receber algum sinal via kill e reabrir os arquivos de log ou similares, então nessa situação em vez de remover o arquivo e ter que trunca-lo e ter que reiniciar o processo mais tarde para poder ter um novo arquivo de log apenas trunque o arquivo quando estiver ocupando muito espaço em disco, assim voce reutiliza o arquivo ja aberto pelo processo para continuar a escrever nele

OBS: nos testes que realizei via Ubuntu o procedimento de truncar via shell com “> 3” não funcionou, ainda não tenho certeza o que pode ser , imaginei que fosse algo relacionado ao ext4 e o flush em disco mas eu não consegui reproduzir numa vm Fedora que tenho com ext4 também, logo que tiver maiores informações posto um update.

Comments