Una instancia a la deriva III: El porque de las cosas

Después de un fin de semana de paseo hoy toca encarar la tercera parte de la saga "Una instancia a la deriva" e intentar descubrir qué pasó a partir de las 2:32 del 23 de Julio y por qué se apagó la instancia 2 horas después.

Para tener un poco mas de contexto si todavía no los leíste, deberías pasar por los posts Una instancia a la deriva I y Una instancia a la deriva II. Acá va un resumen:

• A las 3:33 (02:33 UTC) de la mañana del 23 de Julio recibí 2 emails que indicaban autenticaciones exitosas en la instancia.
• A partir de ese momento, en los gráficos de consumo de recursos provistos por AWS, se puede ver claramente que el comportamiento de la instancia cambió drásticamente. Consumo de CPU, red y acceso a disco se incrementaron.
• A partir del análisis de algunas de las capturas de tcpdump se puede ver un número importante de conexiones SSH iniciadas por la instancia contra direcciones IP de terceros. Esto daría a entender que la instancia fue infectada y ahora se encontraba atacando otras direcciones para propagar el problema.
• Cerca de las 04:40 (UTC) la instancia inicio la secuencia de shutdown. A este punto no está claro qué lo desencadenó si audtitd por espacio insuficiente o el cronjob que controlaba la ejecución de tcpdump.

Analizando el disco y los archivos de la instancia

Dado que la instancia se encuentra apagada le quité el volumen raíz, y lo asocié a otra instancia recién lanzada. A continuación se puede ver el disco /dev/xvdf de 10GB

root@ip-172-31-56-203:/home/ubuntu# lsblk
NAME    MAJ:MIN RM SIZE RO TYPE MOUNTPOINT
xvda    202:0    0   8G  0 disk
`-xvda1 202:1    0   8G  0 part /
xvdf    202:80   0  10G  0 disk
`-xvdf1 202:81   0  10G  0 part
root@ip-172-31-56-203:/home/ubuntu#

Monté el disco en modo solo lectura para evitar modificar o eliminar archivos por error.

root@ip-172-31-56-203:/home/ubuntu# mount -o ro /dev/xvdf1 /mnt/
root@ip-172-31-56-203:/home/ubuntu# mount
/dev/xvda1 on / type ext4 (rw,discard)
...
/dev/xvdf1 on /mnt type ext4 (ro)
root@ip-172-31-56-203:/home/ubuntu#

y lo primero que observé es el espacio de almacenamiento disponible...

root@ip-172-31-56-203:/home/ubuntu# df -h
Filesystem      Size  Used Avail Use% Mounted on
/dev/xvda1      7.8G  782M  6.6G  11% /
none            4.0K     0  4.0K   0% /sys/fs/cgroup
udev            492M   12K  492M   1% /dev
tmpfs           100M  336K   99M   1% /run
none            5.0M     0  5.0M   0% /run/lock
none            497M     0  497M   0% /run/shm
none            100M     0  100M   0% /run/user
/dev/xvdf1      9.8G  9.2G   62M 100% /mnt
root@ip-172-31-56-203:/home/ubuntu#

exacto! 100% utilizado (a penas 62 MB libres) esto parecería tirar por el suelo mi idea de que habían detenido el proceso tcpdump y refuerza a su vez la teoría de auditd deteniendo la instancia por imposibilidad de escribir logs.

No hay archivos creados en el directorio home del usuario comprometido, esto me llamó un poco la atención, esperaba al menos encontrar algo ahí

root@ip-172-31-56-203:~/restored# ls -lah /mnt/home/ubuntu/
total 32K
drwxr-xr-x 4 ubuntu ubuntu 4.0K Jul 19 20:49 .
drwxr-xr-x 3 root   root   4.0K Jul  6 20:42 ..
-rw------- 1 ubuntu ubuntu    9 Jul 19 20:49 .bash_history
-rw-r--r-- 1 ubuntu ubuntu  220 Apr  9  2014 .bash_logout
-rw-r--r-- 1 ubuntu ubuntu 3.6K Apr  9  2014 .bashrc
drwx------ 2 ubuntu ubuntu 4.0K Jul  6 20:43 .cache
-rw-rw-r-- 1 ubuntu ubuntu    0 Jul  6 20:43 .cloud-locale-test.skip
-rw-r--r-- 1 ubuntu ubuntu  675 Apr  9  2014 .profile
drwx------ 2 ubuntu ubuntu 4.0K Jul 21 07:19 .ssh
root@ip-172-31-56-203:~/restored#
En el directorio home de root, donde se guardaban las capturas, podemos ver que las mismas ocuparon del orden de 5GB

root@ip-172-31-56-203:~/restored# du -sch /mnt/root/
5.0G    /mnt/root/
5.0G    total
root@ip-172-31-56-203:~/restored#

y que tenemos 1062 capturas

root@ip-172-31-56-203:~/restored# ls /mnt/root/sample*|wc -l
1062
root@ip-172-31-56-203:~/restored#

para bien o para mal, parece no faltar ninguna.

En cuanto a los archivos de logs parecen estar intactos y en su lugar. Lo mas llamativo es la cantidad de logs generados por auditd:

root@ip-172-31-56-203:~/restored# ls /mnt/var/log/audit/
audit.log     audit.log.16  audit.log.23  audit.log.30  audit.log.38  audit.log.45  audit.log.52  audit.log.6   audit.log.67  audit.log.74
audit.log.1   audit.log.17  audit.log.24  audit.log.31  audit.log.39  audit.log.46  audit.log.53  audit.log.60  audit.log.68  audit.log.75
audit.log.10  audit.log.18  audit.log.25  audit.log.32  audit.log.4   audit.log.47  audit.log.54  audit.log.61  audit.log.69  audit.log.76
audit.log.11  audit.log.19  audit.log.26  audit.log.33  audit.log.40  audit.log.48  audit.log.55  audit.log.62  audit.log.7   audit.log.77
audit.log.12  audit.log.2   audit.log.27  audit.log.34  audit.log.41  audit.log.49  audit.log.56  audit.log.63  audit.log.70  audit.log.78
audit.log.13  audit.log.20  audit.log.28  audit.log.35  audit.log.42  audit.log.5   audit.log.57  audit.log.64  audit.log.71  audit.log.79
audit.log.14  audit.log.21  audit.log.29  audit.log.36  audit.log.43  audit.log.50  audit.log.58  audit.log.65  audit.log.72  audit.log.8
audit.log.15  audit.log.22  audit.log.3   audit.log.37  audit.log.44  audit.log.51  audit.log.59  audit.log.66  audit.log.73  audit.log.9
root@ip-172-31-56-203:~/restored#

esto es un gran problema. El número de rotaciones de logs de audit es de 80, lo que significa que es MUY probable que los primeros logs hayan sido desechados... Una miradita rápida al log mas viejo nos confirma esto

root@ip-172-31-56-203:~/restored# aureport -t -if /mnt/var/log/audit/audit.log.79

Log Time Range Report
=====================
/mnt/var/log/audit/audit.log.79: 07/23/15 03:15:20.105 - 07/23/15 03:17:17.037
root@ip-172-31-56-203:~/restored#

El log mas viejo contempla los registros entre las 03:15 y las 03:17 del 23 de Julio. Lo cuál significa que NO vamos a tener información de los primero minutos posteriores a las 02:33 ya que por el número de eventos y la cantidad de rotaciones esos logs fueron perdidos.

Analizando un poco los logs:

El primer paso fue incluir los últimos logs de autenticaciones (/var/log/auth.log) en la BD para poder contabilizarlos de manera mas sencilla. De este paso obtuve la siguiente información:

• 54.196.232.229 realizó 38 intentos fallidos de autenticación entre las 02:32:08 y las 02:33:28.
• 59.188.237.12 no realizó intentos fallidos.

Viendo mas de cerca los logs podemos ver que:

Jul 23 02:33:28 ip-172-31-54-250 sshd[32683]: Accepted password for ubuntu from 54.196.232.229 port 37470 ssh2
Jul 23 02:33:28 ip-172-31-54-250 sshd[32683]: pam_unix(sshd:session): session opened for user ubuntu by (uid=0)
Jul 23 02:33:29 ip-172-31-54-250 sshd[32683]: pam_unix(sshd:session): session closed for user ubuntu
Jul 23 02:33:30 ip-172-31-54-250 sshd[316]: error: Could not load host key: /etc/ssh/ssh_host_ed25519_key
Jul 23 02:33:32 ip-172-31-54-250 sshd[316]: Accepted password for ubuntu from 59.188.237.12 port 2693 ssh2
Jul 23 02:33:32 ip-172-31-54-250 sshd[316]: pam_unix(sshd:session): session opened for user ubuntu by (uid=0)
Jul 23 02:33:33 ip-172-31-54-250 sshd[370]: Received disconnect from 59.188.237.12: 11: Shutdown.
Jul 23 02:33:33 ip-172-31-54-250 sshd[316]: pam_unix(sshd:session): session closed for user ubuntu
Jul 23 02:33:35 ip-172-31-54-250 sshd[380]: error: Could not load host key: /etc/ssh/ssh_host_ed25519_key
Jul 23 02:33:35 ip-172-31-54-250 sshd[381]: error: Could not load host key: /etc/ssh/ssh_host_ed25519_key
Jul 23 02:33:37 ip-172-31-54-250 sshd[380]: Accepted password for ubuntu from 59.188.237.12 port 2697 ssh2
Jul 23 02:33:37 ip-172-31-54-250 sshd[380]: pam_unix(sshd:session): session opened for user ubuntu by (uid=0)
Jul 23 02:33:37 ip-172-31-54-250 sshd[381]: Accepted password for ubuntu from 59.188.237.12 port 2696 ssh2
Jul 23 02:33:37 ip-172-31-54-250 sshd[381]: pam_unix(sshd:session): session opened for user ubuntu by (uid=0)
Jul 23 02:33:41 ip-172-31-54-250 chpasswd[504]: pam_unix(chpasswd:chauthtok): user "butter" does not exist in /etc/passwd
Jul 23 02:33:41 ip-172-31-54-250 sshd[489]: Received disconnect from 59.188.237.12: 11: Shutdown.
Jul 23 02:33:41 ip-172-31-54-250 sshd[381]: pam_unix(sshd:session): session closed for user ubuntu
Jul 23 02:34:44 ip-172-31-54-250 sshd[488]: Received disconnect from 59.188.237.12: 11: Shutdown.
Jul 23 02:34:44 ip-172-31-54-250 sshd[380]: pam_unix(sshd:session): session closed for user ubuntu

• A las 02:33:28 el host 54.196.232.229 dio con el password correcto para el usuario ubuntu.
• 4 segundos después a las 02:33:32 el host 59.188.237.12 inicia una sesión con el usuario y password correcto. Posiblemente para corroborar que sean válidos, dado que la sesión es terminada al segundo.
• A las 02:33:37 se inician dos sesiones desde la IP 59.188.237.12, esta vez duran unos segundos mas. Una de ellas es terminada a las 02:33:41 (4 segundos después de iniciar), mientras que la otra termina a las 02:34:44 (1 minuto y 7 segundos después de iniciar).
• A las 02:33:41 se ejecutó el comando chpasswd, básicamente es utilizado para cambiar passwords en batch. No entiendo para qué harían esto. De hecho el error saltó porque el usuario butter no existe en el sistema. 

Los logs de auditd

De los logs de auditd, lamentablemente no hay mucho para decir ya que la parte más importante (los minutos correspondientes a las sesiones SSH) se perdió por la rotación. A pesar de esto, acá va lo que pude encontrar a partir de los logs que quedaron:

• Analizando el archivo mas viejo

El reporte general a priori no dice demasiado, salvo por el hecho de haber registrado 11314 eventos en casi 2 minutos:

root@ip-172-31-56-203:/home/ubuntu# aureport -i -if /mnt/var/log/audit/audit.log.79

Summary Report
======================
Range of time in logs: 07/23/15 03:15:20.105 - 07/23/15 03:17:17.037
Selected time for report: 07/23/15 03:15:20 - 07/23/15 03:17:17.037
Number of changes in configuration: 0
Number of changes to accounts, groups, or roles: 0
Number of logins: 0
Number of failed logins: 0
Number of authentications: 0
Number of failed authentications: 0
Number of users: 3
Number of terminals: 2
Number of host names: 1
Number of executables: 5
Number of files: 26
Number of AVC's: 0
Number of MAC events: 0
Number of failed syscalls: 0
Number of anomaly events: 0
Number of responses to anomaly events: 0
Number of crypto events: 0
Number of keys: 1
Number of process IDs: 226
Number of events: 11314

root@ip-172-31-56-203:/home/ubuntu#

Podemos identificar esos 5 ejecutables que se mencionan en el reporte general con el flag -x de la siguiente manera:

root@ip-172-31-56-203:/home/ubuntu# aureport -x --summary -if /mnt/var/log/audit/audit.log.79

Executable Summary Report
=================================
total  file
=================================
11264  /tmp/squid64 (deleted)
15  /usr/sbin/cron
12  /bin/rm
11  /usr/sbin/tcpdump (deleted)
11  /bin/tar
root@ip-172-31-56-203:/home/ubuntu#

De los 5 ejecutables solo uno me resulta sospechoso y claramente es /tmp/squid64. Lamentablemente el archivo ya no se encuentra en /tmp, debe haber sido eliminado después de lanzarse el proceso probablemente, y no logré recuperarlo. Los otros ejecutables son parte de los procesos de control y monitoreo explicados en el primer post.

Podemos ver también cuáles fueron los archivos mas utilizados en estos eventos:

root@ip-172-31-56-203:/home/ubuntu# aureport -f --summary -if /mnt/var/log/audit/audit.log.79

File Summary Report
===========================
total  file
===========================
11264  /etc/passwd
23  /root/
11  /root
2  /root/sample295.jpg
2  /root/sample296.jpg
2  /root/sample297.jpg
2  /root/sample298.jpg
2  /root/sample299.jpg
2  /root/sample300.jpg
2  /root/sample301.jpg
2  /root/sample302.jpg
2  /root/sample303.jpg
2  /root/sample304.jpg
2  /root/sample305.jpg
1  /root/sample294.jpg
1  sample296
1  sample297
1  sample298
1  sample299
1  sample300
1  sample301
1  sample302
1  sample303
1  sample304
1  sample305
1  sample306
root@ip-172-31-56-203:/home/ubuntu#

Parece mucha coincidencia que el proceso /tmp/squid64 y el archivo /etc/passwd se hayan registrado en la misma cantidad de eventos.

De hecho si filtramos el reporte por eventos vemos:

root@ip-172-31-56-203:/home/ubuntu# aureport -e -i --summary -if /mnt/var/log/audit/audit.log.79

Event Summary Report
======================
total  type
======================
11298  SYSCALL
3  USER_END
3  USER_START
3  CRED_DISP
3  CRED_ACQ
3  USER_ACCT
1  CWD
root@ip-172-31-56-203:/home/ubuntu#

El evento SYSCALL (tipo 1300) se registró 11298 veces. A partir del reporte de las syscalls utilizadas vemos que la mas registrada fue open (syscall 2):

root@ip-172-31-56-203:/home/ubuntu# aureport -s -i --summary -if /mnt/var/log/audit/audit.log.79

Syscall Summary Report
==========================
total  syscall
==========================
11275  open
12  unlinkat
11  creat
root@ip-172-31-56-203:/home/ubuntu#


De las 11275 llamadas a open, 11264 fueron para el archivo /etc/passwd, y llamada por el binario /tmp/squid64.

Por último miramos el registro de eventos por usuario y vemos claramente que la mayoría de los eventos fueron generados por el usuario comprometido (ubuntu):

root@ip-172-31-56-203:/home/ubuntu# aureport -u --summary -i -if /mnt/var/log/audit/audit.log.79

User Summary Report
===========================
total  auid
===========================
11264  ubuntu
34  root
15  unset
root@ip-172-31-56-203:/home/ubuntu#

• Analizando un evento particular

A modo de ejemplo tomé uno de los 11264 eventos que implicaron el archivo /etc/passwd y el binario /tmp/squid64, se puede ver a continuación:

root@ip-172-31-56-203:/home/ubuntu# ausearch -a "513448" -i -if /mnt/var/log/audit/audit.log.79
----
type=PATH msg=audit(07/23/15 03:15:20.113:513448) : item=0 name=/etc/passwd inode=397875 dev=ca:01 mode=file,644 ouid=root ogid=root rdev=00:00 nametype=NORMAL
type=CWD msg=audit(07/23/15 03:15:20.113:513448) :  cwd=/home/ubuntu
type=SYSCALL msg=audit(07/23/15 03:15:20.113:513448) : arch=x86_64 syscall=open success=yes exit=26 a0=0x7f0beb4fd35c a1=O_RDONLY|O_CLOEXEC a2=0x1b6 a3=0x7f0bd0000078 items=1 ppid=1 pid=1588 auid=ubuntu uid=ubuntu gid=ubuntu euid=ubuntu suid=ubuntu fsuid=ubuntu egid=ubuntu sgid=ubuntu fsgid=ubuntu tty=(none) ses=30 comm=squid64 exe=/tmp/squid64 (deleted) key=(null)
root@ip-172-31-56-203:/home/ubuntu#

En esencia, el proceso PID 1588 ejecutado del binario /tmp/squid64 abre el archivo /etc/passwd en modo lectura (no entiendo con qué objetivo hace eso...). El hecho de que el PPID del proceso sea 1 (init) significa que el proceso padre fue terminado e init pasó a ser el padre del mismo. Muy probablemente el proceso padre original fue la shell abierta por SSH.

• El verdadero porque del shutdown

Aquí se devela de manera concreta el shutdown!!! A las 04:40:21 el demonio de audit decidió apagar el distema por la falta de espacio libre para poder escribir los eventos, esto quedó registrado en la ĺtima linea del log mas reciente de audit

root@ip-172-31-56-203:/mnt# ausearch -a "1708" -i -if /mnt/var/log/audit/audit.log
----
type=DAEMON_END msg=audit(07/23/15 04:40:21.000:1708) : auditd normal halt, sending auid=root pid=13214 subj=l=3.13.0-48-generic auid=root pid=18333 subj=unconfined  res=success res=success
root@ip-172-31-56-203:/mnt#

También se puede ver el reflejo de esto en /var/log/syslog, a las 04:39:56 se registró el primer mensaje indicando poco espacio disponible en el disco:

root@ip-172-31-56-203:/mnt# grep auditd var/log/syslog
Jul 23 04:39:04 ip-172-31-54-250 auditd[18333]: message repeated 108 times: [ Audit daemon rotating log files]
Jul 23 04:39:56 ip-172-31-54-250 auditd[18333]: Audit daemon is low on disk space for logging
Jul 23 04:40:01 ip-172-31-54-250 auditd[18333]: Audit daemon is low on disk space for logging
Jul 23 04:40:03 ip-172-31-54-250 auditd[18333]: Audit daemon rotating log files
Jul 23 04:40:05 ip-172-31-54-250 auditd[18333]: Audit daemon is low on disk space for logging
Jul 23 04:40:19 ip-172-31-54-250 auditd[18333]: The audit daemon is now halting the system
root@ip-172-31-56-203:/mnt#
 

Analizando un poco las capturas de red

Como mencioné antes, las capturas de red se encuentran totalmente disponibles y aparentemente intactas dentro del directorio home del usuario root. En el post anterior, me había quedado mucha intriga con respecto a la captura número 105, ya que no había sido enviada por email y era la que debería haber capturado toda la actividad de los dos hosts mencionados. Utilizando wireshark y su análisis de conversaciones podemos ver lo siguiente

Las muchas intervenciones hechas por la dirección 54.196.232.229:

• Se puede apreciar la similitud de todas las conversaciones TCP siempre con la misma cantidad de paquetes y bytes transferidos, estas conexiones son los intentos fallidos de login. La excepción es la última conexión que intercambió 6 paquetes mas y unos bytes mas también.
• La última conexión es la última actividad registrada para esta IP y muy probablemente se trate de la conexión con que se adivinó el password del usuario.

Las 3 intervenciones hechas por la dirección 59.188.237.12:

• En la primer conexión apenas se intercambiaron unos 7758 bytes, esta es la conexión que podría haber sido para comprobar la tupla ip, usuario, password
• La segunda conexión ya tuvo bastante mas tráfico 2.3MB aproximadamente, de los cuales 2.24 MB se movieron desde 59.188.237.12 a la instancia. Esto indica la subida de uno o mas archivos.
• No hay mucho para suponer de la 3er conexión, es significativamente mas chica que la segunda, pero el doble de la primera. Posiblemente para recolectar alguna información del host infectado.

Técnicamente las conexiones 2 y 3 se inician con una diferencia de milisegundos entre ellas.

Un dato muy interesante es que no todo en las capturas resulta ser tráfico SSH encriptado!!! Escripteando un poco con tcpdump, encontré tráfico HTTP entre la instancia y el host 59.188.237.12. Y adivinen qué se envía por este medio? sin cifrado y con un simple HTTP POST!!!!

Si... nada mas y nada menos que las tuplas ip, usuario, passowrd encontradas y de hecho con mi instancia encontraron varias xD. Se puede ver claramente como mediante una petición POST desde la intancia se cargan los valores en cuestión. Esto refuerza mas aún la hipótesis de que el host 59.188.237.12 se encarga de recolectar e infectar constantemente.

Intenté encontrar llamadas a curl o wget que se pudieran estar usando para este paso, pero no logré encontrar nada en los logs de audit, así que al parecer esta operación debe estar manejado por el mismo binario squid64.

Y /tmp/squid64 dónde está?

Después de tanto revuelo, wireshark, tcpdump y demás hierbas no pude encontrar el archivo que subieron y ejecutaron en la instancia, el famoso squid64. Así que con buena parte del misterio resuelto me puso a invertir unas horas mas en intentar saber algo mas sobre el archivo.

Haciendo uso de autopsy pude obtener una lista de Orphan files del volumen y uno de ellos me resultó muy interesante:

Inode: 13931   Type: regular    Mode:  0755   Flags: 0x80000
Generation: 3210820034    Version: 0x00000000:00000001
User:  1000   Group:  1000   Size: 0
File ACL: 0    Directory ACL: 0
Links: 0   Blockcount: 0
Fragment:  Address: 0    Number: 0    Size: 0
 ctime: 0x55b07036:ba627a40 -- Thu Jul 23 04:40:22 2015
 atime: 0x55b052ba:5086de40 -- Thu Jul 23 02:34:34 2015
 mtime: 0x55b07036:ba627a40 -- Thu Jul 23 04:40:22 2015
crtime: 0x55b05286:a843ce40 -- Thu Jul 23 02:33:42 2015
dtime: 0x55b07036 -- Thu Jul 23 04:40:22 2015
Size of extra inode fields: 28
EXTENTS:
(END)
A pesar de que los bloques ya no se encuentran asoaciados al inodo 13931, podemos ver los metadatos

• Usuario 1000 (ubuntu)
• Fecha de creación: 02:33:42 del 23 de Juli
• Fecha de última modificación 04:40:22 del 23 de Julio

y todo indica que se trata de un archivo creado por el mismo usuario comprometido justo después de haberse iniciado una sessión SSH desde el host 59.188.237.12 y que casualmente fue eliminado a la misma hora en que fue apagado el sistema. Es mucha casualidad! Potencialmente el inodo 13931 perteneció al archivo squid64.

Yendo un poco mas profundo y buscando cadenas (strings) dentro de los bloques de disco no asignados encontré algunas cosas interesantes:

[-] ERROR: could not create SSH session
SUXX
/dev/urandom
/dev/random
socket error:
POST %s  HTTP/1.1
Host: %s
Host: %s:%d
Mozilla/5.0 (X11; U; Linux x86_64; en-US; rv:1.9.1.3) Gecko/20090913 Firefox/3.5
.3
User-Agent: %s
Content-Length: %d
zhangyan7tian
data=%s %s %s
/stat.asp
59.188.237.12
ask_userauth
entering function %s line %d in /root/sshcrack/libssh-0.5.3/src/auth.c
ssh-userauth
leaving function %s line %d in /root/sshcrack/libssh-0.5.3/src/auth.c
...
Receiving banner: too large banner
ssh_send_banner
SSH-1.5-libssh-0.5.2
SSH-2.0-libssh-0.5.2
Received SSH_KEXDH_REPLY

Entre tantas cadenas podemos ver

• El banner SSH-2.0-libssh-0.5.2 con que se identifica el cliente SSH que realiza las conexiones de manera masiva.
• Un path de archivos fuente /root/sshcrack/libssh-0.5.3/src/auth.c parece tratarse del path the compilación de la aplicación sshcrack. Lo raro es que utiliza libssh-0.5.3 en lugar del 0.5.2.
• Vemos el encabezado HTTP con la llamada POST completa e incluso pareciera estar hardcodeada la IP de recolección e infección (59.188.237.12).

y un poco mas adelante lo que parece ser un diccionario de usuarios/passwords, si prestan atención se darán cuenta que los usuarios probados son los que mencioné cerca del final del primer post:

zhangyan
zhangyan7tian
3rddf
root
12345
root
admin
root
password
root
123muie123
root
root
root
1234
root
root123
root
123456
root
...
qwerty123
root
qwerty
root
pa55w0rd
root
1qaz2wsx
root
root
toor
...
root
^%$#@!
root
^&*()
root
5mmQ

En fin, no pude obtener el archivo, pero quedaron muchos rastros que podrían formar parte del mismo. Desafortunadamente no contemplé en ningún momento la posibilidad de perder logs de auditd, incluso sabiendo de la rotación, creí que 80 era un número mas que suficiente.

Resumen

Hasta aquí llegó mi amor! A modo de resumen para cerrar la saga es dejo los siguientes puntos:

• Está claro que hay al menos 2 tipos de nodos en este proceso. Los nodos (tipo A) como 54.196.232.229 que buscan usuarios con passwords triviales y nodos como 59.188.237.12 (tipo B) que se encargan de infectar y recolectar las tuplas obtenidas por los nodos tipo A.
• Cuando un nodo tipo A consigue un usuario y password lo reporta instantaneamente al nodo tipo B, mediante un mensaje POST HTTP.
• El nodo tipo B se conecta al host y realiza una serie de operaciones que no pudieron ser determinadas con precisión, pero que convierten al host en un nodo tipo A.

En los próximos días iniciaré la instancia por primera vez luego de la infección para corroborar si hay algún mecanismo que haga persistir la infección.

Una instancia a la deriva II: Crónica de una muerte anunciada

Aquí va la segunda parte, si estás leyendo esto, te recomiendo que primero pases por Una instancia a la deriva I .

Primer contacto del mas allá

No pasó mucho tiempo hasta que alguien del país de la gran muralla diera con el password de mi usuario ubuntu. Para ser mas preciso luego de 56 intentos a las 06:40 del 21 de Julio don 106.2.197.34 dió con el password correcto.

Al parecer esta IP está hosteando un sitio web que por las imágenes (porque no entiendo nada) me da a pensar que se trata de un sitio de cambio de monedas.

Luego de haber encontrado el password la IP dejó de insistir y no pasó a mayores. Esto último me da a pensar que podría ser un sistema infectado a los efectos de encontrar y recolectar usuarios/passwords de otros sistemas, probablemente parte de una botnet. En particular esta nueva IP siguió el mismo diccionario que las IPs (108.51.89.92, 180.250.223.10 y 77.222.137.46) mencionadas en Una instancia a la deriva I.

Pasó un día y no hubo novedades, al punto que supuse que había hecho algo mal.

Guess who's back!

Ayer por la mañana mientras desayunaba y leía los mails me encontré con esto

Lo primero que pensé fue "Que! casualidad dos IPs diferentes adivinaron el password del usuario ubuntu al mismo tiempo!" No tenía ganas de husmear demasiado en ese momento para que no se me hiciera tarde, pero no me resistí a logearme en la instancia para ver qué habían hecho y...

juan@moon:~/Escritorio/SH$ ssh root@52.6.74.XXX
ssh: connect to host 52.6.74.XXX port 22: Connection timed out
juan@moon:~/Escritorio/SH$

booom! La instancia estaba inaccesible! A este punto ya era irresistible y abrí la consola de AWS, para encontrarme con la siguiente imagen

La instancia se apagó por si sola. Esto era lo que debía pasar en caso de que se detuviera el proceso que capturaba el tráfico de red que entraba y salía de la instancia o por ejemplo en caso de que se diera una condición desfavorable para audit (como disco lleno...).

Desde la misma consola controlé el uso de recursos para ver si encontraba algo interesante

se puede ver claramente como poco antes de las 02:30 algo se desencadenó dentro de la instancia que incrementó el trafico de red en ambos sentidos. Si vemos el mismo período, pero en este caso las estadísticas del volumen se puede apreciar un incremento en todas las operaciones

Un comportamiento análogo se puede ver también en la utilización de CPU

Sea lo que sea que pasó, comenzó poco antes de las 02:30 y terminó tempestivamente poco después de las 04:30. Por último pegué una mirada a los console logs para ver si había algo interesante y...

A las 04:40 del 23 de Julio se inició un shutdown. Esto me dio a entender que posiblemente pudieron matar el proceso tcpdump que corría como root (oO) y cuando el cronjob detectó que tcpdump ya no corría mandó a apagar el sistema a las 04:40.

En este punto terminé el desayuno y partí a mis obligaciones xD.

Antes de abrir la caja de pandora

Antes de ir directamente a analizar el volumen raíz de la instancia o siquiera volver a prenderla vamos a mirar qué información se pudo obtener desde las capturas de tráfico y los logs.

Desde los logs de audit que se enviaban por mail

El último archivo de logs de auditd fue enviado por mail a las 02:00 del 23 de Julio, una hora y media antes del acceso (en principio absolutamente inútil). Sumado a eso por algún motivo el archivo contiene el siguiente time frame de logs

root@moon:/home/juan/Escritorio/SH/logs/audit# aureport -t -if audit.log.1

Log Time Range Report
=====================
audit.log.1: 19/07/15 20:13:01.249 - 21/07/15 07:35:55.417
root@moon:/home/juan/Escritorio/SH/logs/audit#

más inútil todavía. Al parecer cometí un error leyendo la documentación y estuve mandando por correo el mismo archivo cada 2hs, en lugar de mandar el archivo con los últimos logs... shit happens.

Desde las capturas de tráfico con tcpdump

La salvación debería estar en las capturas!! Viendo los mails, a las 02:32 del 23 de Julio se subió la captura número 104 (la captura previa, la 103, se había subido a las 17:05 del día anterior, 22 de Julio) y a partir de allí comenzaron a generarse capturas de manera increíble hasta que a las 04:36 se subí la última, la número 1099!!! Es decir que en 2 horas se generaron al menos 995 capturas de 5 MB (~5GB), esto me hace pensar que es poco probable que se haya llenado el disco de la instancia ya que si no me equivoco quedaba mas espacio libre.

Lamentablemente por el número de capturas generadas, y consecuentemente la cantidad de mails enviados, muchas de ellas fueron rebotadas por los mecanismos de google anti spam.

A pesar de que muchas no llegaron a ser enviadas a la cuenta, es probable que aún se encuentren en el volumen de la instancia.

 En la cuenta de correo se puede esto por el orden en que llegaron los correos:

File sample104 Thu Jul 23 02:32:31 UTC 2015
File sample106 Thu Jul 23 02:35:29 UTC 2015
File sample129 Thu Jul 23 02:43:26 UTC 2015
File sample111 Thu Jul 23 02:37:39 UTC 2015
File sample108 Thu Jul 23 02:36:26 UTC 2015
File sample157 Thu Jul 23 02:50:11 UTC 2015

el 105 que posiblemente sería el mas interesante nunca llegó. La captura 108 llegó después que la 129 que llegó antes que la 111 xD, en fin...

Un análisis simple de las capturas 103, 104, 106 y 108 muestra que la IP 54.196.232.229 actuó entre las 17:05 del 22 de Julio (fin captura 103) y antes de las 02:35 del 23 de Julio (fin captura 106). Esto comprende las capturas 104 y 105, no hay rastros de dicha IP en la captura 106 ni en la 108.

juan@moon:~/Escritorio/SH/traffic captures/root$ tcpdump -r sample103 host 54.196.232.229 | wc -l
reading from file sample103, link-type EN10MB (Ethernet)
0
juan@moon:~/Escritorio/SH/traffic captures/root$ tcpdump -r sample104 host 54.196.232.229 | wc -l
reading from file sample104, link-type EN10MB (Ethernet)
339
juan@moon:~/Escritorio/SH/traffic captures/root$ tcpdump -r sample106 host 54.196.232.229 | wc -l
reading from file sample106, link-type EN10MB (Ethernet)
0
juan@moon:~/Escritorio/SH/traffic captures/root$ tcpdump -r sample108 host 54.196.232.229 | wc -l
reading from file sample108, link-type EN10MB (Ethernet)
0
juan@moon:~/Escritorio/SH/traffic captures/root$

Dado que los logs de ese día no fueron enviados por correo, tampoco fueron cargados en la BD así que aún no puedo saber cuantos intentos fallidos se realizaron. 

Misteriosamente no hay rastos de la IP 59.188.237.12 en ninguna de las capturas anteriores...

juan@moon:~/Escritorio/SH/traffic captures/root$ tcpdump -r sample103 host 59.188.237.12 | wc -l
reading from file sample103, link-type EN10MB (Ethernet)
0
juan@moon:~/Escritorio/SH/traffic captures/root$ tcpdump -r sample104 host 59.188.237.12 | wc -l
reading from file sample104, link-type EN10MB (Ethernet)
0
juan@moon:~/Escritorio/SH/traffic captures/root$ tcpdump -r sample106 host 59.188.237.12 | wc -l
reading from file sample106, link-type EN10MB (Ethernet)
0
juan@moon:~/Escritorio/SH/traffic captures/root$ tcpdump -r sample108 host 59.188.237.12 | wc -l
reading from file sample108, link-type EN10MB (Ethernet)
0
juan@moon:~/Escritorio/SH/traffic captures/root$

esto podría indicar que dicha IP tuvo intervención durante la captura 105 (entre las 02:32:31 y las 02:35:29) y fue lo suficientemente breve como para no aparecer en la 106.

Viendo las capturas con wireshark con un poco de paciencia noté que en la captura 106 parecía haber conexiones SSH iniciadas desde la instancia hacia un número razonable de IPs. Aca va un ejemplo:

Ahora era mi instancia la que se encontraba disparando al mundo conexiones SSH utilizando el cliente libssh-0.5.2 !!! Para que se den una idea, miren esto

juan@moon:~/Escritorio/SH/traffic captures/root$ tcpdump -n -r sample103 src host 172.31.54.250 and "tcp[13] & 2 != 0" and "tcp[13] & 16 == 0"| wc -l
reading from file sample103, link-type EN10MB (Ethernet)
0
juan@moon:~/Escritorio/SH/traffic captures/root$ tcpdump -n -r sample104 src host 172.31.54.250 and "tcp[13] & 2 != 0" and "tcp[13] & 16 == 0"| wc -l
reading from file sample104, link-type EN10MB (Ethernet)
0
juan@moon:~/Escritorio/SH/traffic captures/root$ tcpdump -n -r sample106 src host 172.31.54.250 and "tcp[13] & 2 != 0" and "tcp[13] & 16 == 0"| wc -l
reading from file sample106, link-type EN10MB (Ethernet)
28457
juan@moon:~/Escritorio/SH/traffic captures/root$ tcpdump -n -r sample108 src host 172.31.54.250 and "tcp[13] & 2 != 0" and "tcp[13] & 16 == 0"| wc -l
reading from file sample108, link-type EN10MB (Ethernet)
22196
juan@moon:~/Escritorio/SH/traffic captures/root$ tcpdump -n -r sample111 src host 172.31.54.250 and "tcp[13] & 2 != 0" and "tcp[13] & 16 == 0"| wc -l
reading from file sample111, link-type EN10MB (Ethernet)
19930
juan@moon:~/Escritorio/SH/traffic captures/root$ 

Las capturas 103 y 104 no registraron conexiones SSH iniciadas desde la instancia, sin embargo las capturas 106, 108 y 111 registraron y MUCHAS.

En este punto parece que el acceso se produjo entre las capturas 104 y 105 y que la infección y ejecución del software malicioso se podría haber producido durante la captura 105, dado que en la 106 ya se registra el comportamiento anómalo.

La primer hipótesis es que la IP 54.196.232.229 (USA) dio con la clave en el lapso de las capturas 104 y 105, para que luego la IP 59.188.237.12 (HNK) se encargue de la infección durante lo que fue la captura 105. Una vez infectado el sistema no se registraron mas contactos de ninguna de estas dos direcciones.

Pensamientos en el aire...

•  54.196.232.229 parece ser un sistema infectado comportándose como se comportó mi instancia. De hecho, sin hacer demasiado escándalo, es otra instancia en EC2.
• 59.188.237.12 podría ser el nodo recolector de las tuplas usuario,password,ip para proceder a infectar.

Para la próxima, abriré la caja de pandora para ver qué quedó en el disco de la instancia y ver con más precisión qué fue lo que pasó.

Una instancia a la deriva I: preparación y primeros logs

Hace hoy 12 días, haciendo uso de la Free tier de AWS, se me ocurrió (con fines educativos, obvio xD) lanzar una instancia y dejarla a la deriva, como quien dice a la buena de Dios.

La idea es poner en práctica algunas herramientas y ver qué se puede aprender de los logs y como segundo paso analizar una "intrusión" exitosa (si eventualmente la hay). Una suerte de honeypot pero mas rústico.

La instancia lanzada corre Ubuntu 14.04 con las siguientes características:

• Instancia t2.micro (es gratis xD)
• El servicio SSH se encuentra activo y permite autenticación por password (a los fines de permitir una intrusión "controlada" dejando un password sencillo). Es el único servicio de acceso público.
• Al usuario por defecto (ubuntu) le fueron removidos los permisos de sudo, de forma tal que no pueda convertirse en root tan fácilmente, ni ejecutar comandos como tal.
• Tanto el usuario ubuntu como root tienen passwords fuertes, de momento.
• Auditd está configurado y corriendo, con un subconjunto de reglas obtenidas del archivos lspp.rules (/usr/share/doc/auditd/examples/lspp.rules.gz). Labeled Security Protection Profile (LSPP).
• Fail2ban se encuentra corriendo y analizando los logs (/var/log/auth.log), pero solo a fines de reportar los accesos exitosos (en lugar de los fallidos). Esto es para ser consciente del momento en que la instancia sea accedida por un tercero.
• En background corre tcpdump capturando todo el tráfico que entra y sale de la instancia. Cada 5 MB de tráfico capturado el archivo es comprimido y copiado fuera de la instancia. Si por algún motivo esta captura es detenida, la instancia se apagará.
• Los archivos auth.log y mail.log son rotados  diariamente y copiados fuera de la instancia.
• Los logs de auditd son copiados a fuera de la instancia cada 2hs.
• Por si no lo saben la Free Tier es free hasta cierto consumo de recursos, en particular lo que mas me preocupa es el consumo de tráfico de red que está acotado a 15GB de tráfico saliente mensuales. En caso de que este límite se supere y se me generen gastos asociados, una alarma de Cloudwatch me lo avisará y podré tomar acciones (apagar la instancia xD).

Configuración de auditd

Dado que no pensaba ponerme a escribir todas las reglas desde cero se me ocurrió (sugerencia de Red Hat de hecho xD) utilizar uno de los archivos de ejemplos que vienen con el paquete en su instalación (/usr/share/doc/auditd/examples/). En particular elegí lspp.rules porque la mayoría de las reglas coincidían con lo que yo pretendía que audit registrara. Sin entrar en detalles:

• Se registraran eventos sobre archivos y directorios críticos del sistema, /etc/passwd, /etc/cron*, /etc/init.d/, /root/, /etc/audit/ entre otros.
• Se registraran las actividades del usuario ubuntu (usuario que será expuesto con contraseña débil). Procesos creados, archivos, etc.
• Ante eventos adversos auditd lanzará un kernel panic, lo que esencialmente detendrá el funcionamiento de la instancia. Es decir, si no hay logs no habrá instancia.
• Los logs son rotados por el mismo auditd y existe un cronjob que cada 2hs manda el archivo rotado por mail. De esta manera los logs son almacenados para analizar posteriormente.

Configuración de tcpdump

La idea de correr una captura de tráfico en background es para contar con los detalles de la actividad de red durante la potencial intrusión. Acá tampoco hay nada de magia, tcpdump es lanzado de la siguiente manera

tcpdump -n not port 25 -w sample -C 5M -z /sbin/reader 2>/dev/null & echo $! > /var/run/reader.pid

de tal forma que el tráfico al puerto 25 es ignorado (esto es para cortar el loop que se formaría al capturar el tráfico del mail), la captura es fraccionada cada 5MB y procesada por el script /sbin/reader, que sencillamente comprime el archivo le da un nombre mas mailfriendly y lo envía por correo. Como mencioné antes, hay un cronjob que a cada minuto controla la existencia del proceso señalado por el contenido del archivo reader.pid, si no encuentra un proceso con ese pid apaga el sistema. Claramente esto no es infalible, pero es una medida de protección mas.

En algún momento analicé la idea de mandar los logs y demás archivos a un bucket S3. El problema es que la free tier solo da 5GB de almacenamiento gratuito en S3 y limita el número de operaciones PUT a 2000, que podrían no ser suficientes, por eso me opté por envío por mail (rústico, I know xD).

Logs de autenticación

Dado que parte de la idea de esto es analizar los logs, había que ver qué analizar y cómo. De momento el análisis es completamente offline, los archivos /var/log/auth.log y /var/log/mail.log son rotados diariamente y el archivo rotado es enviado por mail. A ciencia cierta el único utilizado de momento es auth.log, que luego de obtenido es utilizado para poblar una BD con los registros de intentos fallidos de autenticación en el servidor.

Un script en perl recorre los logs e inserta cada autenticación fallida en una tabla, para que sea un poco mas sencillo el análisis.

Primeros resultados

Después de 12 días de logs, acá va un pequeño resumen de lo que encontré:

• Se registraron 46556 intentos de autenticación fallidos, provenientes de 664 direcciones diferentes.
• De las 664 direcciones, 
• 159 pertenecen a la India con 297 intentos. Los 3 usuarios mas probados fueron admin (46), user (10), support (5).
• 112 pertenecen a Rusia  con 246 intentos). Los 3 usuarios mas probados fueron admin (52), login (12) y MGR (12).
• 106 pertenecen a Bahrain (unas islas del Golfo Pérsico) con 195 intentos. Los 3 usuarios mas probados fueron admin (67), MGR (11), User (8)
• 105 pertenecen a Brasil con 200 intentos. Los 3 usuarios mas probados fueron admin (72), MANAGER (7), User (6)
• 70 pertenecen a Italia con 123 intentos. Los 3 usuarios mas probados fueron admin (22), MGR (11), FIELD (7) (seguido por MANAGER(6)).
• 43 pertenecen a China con 10884 intentos. Los 3 usuarios mas probados fueron root (10601), oracle (21), ubuntu (19).
• 21 pertenecen a Pakistan con 35 intentos. Los 3 usuarios mas probados fueron admin (6), MAIL (5), maint (4).
• 11 pertenecen a USA con 11732 intentos. Los 3 usuarios mas probados fueron root (11101), test (110), nagios (68).
• y el resto a otros países con un total de 22844 intentos (un número muy chico de IPs realizó muchos intentos).
• Del punto anterior hay una serie de similitudes a la vista, los intentos recibidos de Bahrain, Brasil, Italia y Rusia tienen usuarios en común como admin, MANAGER y MGR.
• Las IPs de China y USA apuntaron casi completamente al usuario root. De hecho:
• De USA 108.51.89.92 hizo 10409 intentos el 16 de Julio seguida por 198.154.62.59 con 539 el 7 de Julio.
• Del lado de China la cosa está mas distribuida, 
• 218.65.30.217 hizo 539 el 7 de Julio, 15 el 9, 90 el 11, 1065 el 12, 166 el 16 y 285 el 17. 
• 218.87.111.109 hizo 539 intentos el 8 de Julio, 539 el 10, 32 el 11 y 3 el 15. 
• 59.63.192.196 hizo 540 intentos el 10 de Julio, 539 el 12 y 10 el 13. 
• Reincidencia y coincidencia con el número de intentos, eso podría indicar el uso de las mismas herramientas, incluso muchos coinciden en la frecuencia de las pruebas entre 8 y 10 segundos.
• Los 3 usuarios mas probados son root (43428 veces, 93% de las veces), test (352 veces) y admin (348 veces). Claramente root es el usuario mas deseado, lo cual es lógico ya que ganar acceso de root de esta manera sería una manera MUY sencilla de obtener control total del sistema.
• Las 3 IPs con mas intentos son:
• 108.51.89.92 de USA con 10832 intentos durante el 16 de Julio, a razón de 1 intento cada 2-4 segundos.
• 180.250.223.10 de Indonesia con 10832 intentos durante el 16 de Julio, a razón de 1 intento cada 2-4 segundos.
• 77.222.137.46 de Ucrania con 10832 intentos durante el 13 de Julio, a razón de 1 intento cada 2-4 segundos.
• Seguidos por las IPs chinas del punto anterior.
• Las 3 IPs del punto anterior parecen haber utilizado el mismo diccionario, ya que además de coincidir el número de intentos coinciden los usuarios utilizados exactamente, incluso el orden en que fueron probados. Se probó:
• zhangyan 1 vez
• dff 1 vez
• root 10409 veces
• oracle 2 veces
• test 102 veces
• ubuntu 9 veces
• y a continuación usuarios como: git, boot, 123456, 123, apache, bash r00t, etc.
• 53 direcciones fueron identificadas al menos 2 días, 2 de las IPs registraron intentos 6 días diferentes.
• En cuanto a los clientes utilizados:
• El 77% utilizó libssh-0.5.2 .
• El 18% utilizó PUTTY . 
• El 3% utilizó libssh-0.1
• El 1,8% utilizó libssh2_1.4.3, libssh2_1.4.2 o libssh2_1.4.1
• Luego siguen algunos como: JSCH-0.1.51 y paramiko_1.14.0

A partir de este momento y para hacer las cosas mas interesantes, queda expuesto el usuario ubuntu con un password MUY sencillo. Veremos cuánto tiempo les toma lograr una autenticación exitosa y cómo se comportan.