Auditar logs de accesos de servidores ISA utilizando LogParser

La semana pasada me tocó auditar accesos a Internet para buscar visitas a sitios Web maliciosos o inadecuados y detectar desvíos de seguridad. Para llevar a cabo esta tarea tuve que filtrar los logs de un servidor ISA que se utiliza como proxy para obtener información útil de acuerdo a diferentes criterios de búsqueda.

En este artículo voy a proveer información sobre cómo obtener de forma rápida y precisa esta información utilizando herramientas de línea de comandos. Estas herramientas permiten redirigir la salida a archivos de texto, y realizar el trabajo de forma eficiente y automágica.


Definiciones preliminares

ISA Server: Gateway integrado de seguridad perimetral que permite proteger el entorno de TI frente a las amenazas de Internet, además de proporcionar a los usuarios un acceso remoto seguro a las aplicaciones y datos corporativos (Fuente: Microsoft).

LogParser: LogParser es una herramienta de línea de comandos que provee consultas universales a archivos de texto tales como archivos de logs, archivos XML y CSV y fuentes de datos del sistema operativo Windows tales como logs de eventos, registry, el sistema de archivos y Active Directory (Fuente: Microsoft).

Bash: Programa cuya función consiste en interpretar órdenes. Está basado en la shell de Unix y es compatible con POSIX. Fue escrito para el proyecto GNU y es el intérprete de comandos por defecto en la mayoría de las distribuciones de Linux (Fuente: Wikipedia).


Filtrado de logs

Los logs de acceso de los servidores ISA generalmente se encuentran en la carpeta:

C:\Program Files\Microsoft ISA Server\ISALogs

Para obtener información útil de estos logs utilizaremos la herramienta LogParser provista por Microsoft de forma gratuita. LogParser toma una expresión SQL como parámetro en la línea de comandos, y muestra como resultado las líneas que contienen coincidencias para la misma. Utilizando esta herramienta es posible filtrar los logs de los servidores ISA para obtener información útil de forma resumida.

Al ejecutar LogParser desde el menú de inicio se abre una consola en el directorio donde se instaló y muestra la ayuda:

Microsoft (R) Log Parser Version 2.2.10
Copyright (C) 2004 Microsoft Corporation. All rights reserved.

Usage: LogParser [-i:] [-o:] |
file:[?param1=value1+...]
[] []
[-q[:ON|OFF]] [-e:] [-iw[:ON|OFF]]
[-stats[:ON|OFF]] [-saveDefaults] [-queryInfo]

LogParser -c -i: -o:
[] []
[] [-multiSite[:ON|OFF]]
[-q[:ON|OFF]] [-e:] [-iw[:ON|OFF]]
[-stats[:ON|OFF]] [-queryInfo]

-i: : one of IISW3C, NCSA, IIS, IISODBC, BIN, IISMSID,
HTTPERR, URLSCAN, CSV, TSV, W3C, XML, EVT, ETW,
NETMON, REG, ADS, TEXTLINE, TEXTWORD, FS, COM (if
omitted, will guess from the FROM clause)
-o: : one of CSV, TSV, XML, DATAGRID, CHART, SYSLOG,
NEUROVIEW, NAT, W3C, IIS, SQL, TPL, NULL (if omitted,
will guess from the INTO clause)
-q[:ON|OFF] : quiet mode; default is OFF
-e: : max # of parse errors before aborting; default is -1
(ignore all)
-iw[:ON|OFF] : ignore warnings; default is OFF
-stats[:ON|OFF] : display statistics after executing query; default is
ON
-c : use built-in conversion query
-multiSite[:ON|OFF] : send BIN conversion output to multiple files
depending on the SiteID value; default is OFF
-saveDefaults : save specified options as default values
-restoreDefaults : restore factory defaults
-queryInfo : display query processing information (does not
execute the query)


Examples:
LogParser "SELECT date, REVERSEDNS(c-ip) AS Client, COUNT(*) FROM file.log
WHERE sc-status<>200 GROUP BY date, Client" -e:10
LogParser file:myQuery.sql?myInput=C:\temp\ex*.log+myOutput=results.csv
LogParser -c -i:BIN -o:W3C file1.log file2.log "ComputerName IS NOT NULL"

Help:
-h GRAMMAR : SQL Language Grammar
-h FUNCTIONS [ ] : Functions Syntax
-h EXAMPLES : Example queries and commands
-h -i: : Help on
-h -o: : Help on
-h -c : Conversion help


Ejemplos de consultas típicas

El servidor ISA guarda cada acceso en un registro, el cual tiene una cantidad fija de campos. Por ejemplo para cada pedido: c-ip contiene la ip que lo realizó; date contiene la fecha; time la hora; r-host el nombre del servidor al cual se accedió; etc. Cada registro es una línea y cada campo se separa con un tabulador, de acuerdo al formato W3C.
Los logs del servidor ISA que me tocó auditar comienzan con la siguiente cabecera, que declara la versión del servidor y los nombres de los campos:

#Software: Microsoft(R) Internet Security and Acceleration Server 2000
#Version: 1.0
#Date: 2011-02-06 00:00:02
#Fields: c-ip cs-username c-agent sc-authenticated date time s-svcname s-computername cs-referred r-host r-ip r-port time-taken cs-bytes sc-bytes cs-protocol cs-transport s-operation cs-uri cs-mime-type s-object-source sc-status s-cache-info rule#1 rule#2

Al utilizar LogParser para filtrar logs de un servidor ISA, se debe indicar que el formato de entrada es W3C, y que los campos se separan con tab. Luego de estos parámetros opcionales (tipo de entrada y separador) se indica la consulta SQL que se desea realizar.
El archivo de log se pasa como parámetro dentro de la consulta SQL, puede ser un archivo local o un share. Además se puede utilizar asterisco para leer de múltiples archivos de log.
Debido a que el nombre de archivo no puede contener espacios, se deben reemplazar los mismos con '\u0020'.
Los nombres de los campos de los registros se obtienen directamente desde el archivo de log (en la 3er línea del archivo que se encuentra comentada con numeral). Es posible redireccionar la salida a un archivo utilizando el caracter '>' o desde la consulta SQL utilizando la orden "INTO".


Ver todos los sitios visitados por la IP 192.168.1.100:

C:\Program Files\Log Parser 2.2>Logparser -i:W3C -separator:'tab' "SELECT DISTINCT r-host AS Site FROM C:\Program\u0020Files\Microsoft\u0020ISA\u0020Server\ISALogs\*.log WHERE c-ip='192.168.1.100'"

El identificador DISTINCT delante del campo r-host se utiliza para que no repita resultados.


Ver todas las IP que ingresaron a facebook:

C:\Program Files\Log Parser 2.2>Logparser -i:W3C -separator:'tab' "SELECT DISTINCT c-ip AS IP, r-host AS URL FROM \\logserver\ISALogs\*.log WHERE r-host LIKE '%facebook.com%'"


Ver la cantidad de visitas por sitio:

C:\Program Files\Log Parser 2.2>Logparser -i:W3C -separator:'tab' "SELECT COUNT(*) AS Hits, r-host AS Site FROM \\logserver\ISALogs\*.log GROUP BY Site ORDER BY Hits DESC" > hits.txt

La orden COUNT(*) en conjunto con GROUP BY suman la cuenta para cada valor distinto del campo r-host. La orden ORDER BY en conjunto con DESC se utilizan para ordenar el resultado de forma descendente.


Ver las visitas que realizó la IP 192.168.1.50 entre la 1:00 AM y 2:00 AM:

C:\Program Files\Log Parser 2.2>Logparser -i:W3C -rtp:-1 -separator:'tab' "SELECT time AS Time, cs-uri AS URI FROM C:\Program\u0020Files\Microsoft\u0020ISA\u0020Server\ISALogs\*.log WHERE c-ip='192.168.1.50' AND (TO_TIME(time) BETWEEN TIMESTAMP('01:00:00','hh:mm:ss') AND TIMESTAMP('02:00:00','hh:mm:ss'))" > filtered_log.txt

Por defecto, LogParser muestra la salida paginada. La opción -rtp:-1 se utiliza para evitar esto y poder redireccionar la salida.


Ver los clientes del Proxy:

C:\Program Files\Log Parser 2.2>Logparser -i:W3C -separator:'tab' "SELECT c-ip as Client INTO clients.csv FROM C:\Program\u0020Files\Microsoft\u0020ISA\u0020Server\ISALogs\*.log GROUP BY Client ORDER BY Client" -o:CSV

En este caso se exporta la salida como un archivo CSV directamente en la consulta utilizando la orden "INTO". La opción -o:CSV se utiliza para indicarle a LoggParser que la salida se exporta a un archivo CSV.


Filtrado de logs utilizando bash

Si se dispone de acceso a una consola bash, es posible realizar esta misma tarea utilizando herramientas libres como grep, sed, awk, sort, etc. Está fuera del alcance de este artículo explicar el funcionamiento de cada una de estas herramientas. A continuación se muestra un ejemplo práctico.


Ver todos los sitios visitados por la IP 192.168.1.100:

$ time grep '192.168.1.100' WEBEXTD20120101.log | awk –F"\t" '{print $10}' | sort | uniq

Con grep se buscan todos los registros que contienen la dirección IP 192.168.1.100. Luego se utiliza awk para extraer la décima columna (separadas por tab), que corresponde con el campo r-host. Finalmente se ordena el resultado y se eliminan los registros repetidos.
Se utiliza el comando time para medir el tiempo que tarda en realizar el trabajo. Tanto utilizando LogParser como bash scripts los tiempos de ejecución son bajos.

Tunear logs de SQL Server

Hace un par de semanas vengo trabajando en crear logs de SQL Server que valgan la pena para así poder realizar trabajos de revisión y auditoría de lo que sucede en los servidores de base de datos de la empresa. El tema es que, aunque a uno le parezca totalmente simple activar los logs de un sistema tan utilizado y (supuestamente) fácil de administrar, esto no es así.
Por defecto SQL Server no loguea casi nada útil, solamente cuando ocurre un error grave o cuando se hace backup de la base de datos. Si piensan que su motor de base de datos está (como debería) logueando información para poder controlar las acciones... piensen de nuevo!, revisen los logs y diganme si encuentran algo en los logs que les sirva!

Por supuesto que el DBMS en cuestión cuenta con sistema de logueo de eventos, pero hay que activarlo a mano y conocer un poco sobre el funcionamiento de algunos store procedures creados para esto. Una de las primeras cosas que uno se encuentra cuando busca logs de SQL Server, es el modo de auditoría C2, pero existen otra forma más efectiva de loguear, la cual es usando los traces de SQL Server. A continuación explico un poco de estas dos modalidades de logueo.

Cabe destacar que activar sistemas de logueo siempre generan una sobrecarga en el sistema. Dependiendo lo que deseemos loguear, la sobrecarga será mayor o menor, pero es un punto a tener en cuenta.


Modo de auditoría C2

Este modo fue diseñado para poder cumplir con la clase C2 del Criterio de evaluación de confianza de un sistema computacional creado por el Department of Defence yankee (DoD). Cuando se activa esta modalidad de logueo, todos los eventos y todas las columnas pertenecientes a cada evento se loguearan. Como se podrán imaginar, este nivel de logging es extremo y poco útil para la mayoría de los sistemas. Revisar estos logs es para un monje Shaolin drogado, porque por más filtros que pongamos, seguiremos teniendo miles de entradas repetitivas e inútiles.
Para que se den una idea del nivel de logueo C2, lo probamos en una base de datos con relativo poco movimiento de datos y el log creció a más de 1GB en un par de horas! 1GB de texto! se imaginan lo que es??? pues mucho!

Si luego de toda esa introducción al modo audit C2 todavía tienen ganas de probarlo, lo pueden hacer ejecutando las siguientes sentencias T-SQL:

SP_CONFIGURE 'show advanced options', 1;
GO
RECONFIGURE
GO
SP_CONFIGURE 'c2 audit mode', 1;
GO
RECONFIGURE
GO
SP_CONFIGURE 'show advanced options', 1;
GO

Luego de ejecutar las sentencias anteriores, deberán reiniciar el motor de base de datos, así que haganlo en algún momento donde no tengan mucho movimiento de datos.
Para revisar que el modo quedó activado, pueden ejecutar la siguiente sentencia:

SELECT value FROM sys.configurations
WHERE name = 'c2 audit mode';
GO

Los logs se almacenan en el directorio \MSSQL\Data (osea, donde está instalado el SQL Server) y son archivos .trc de 200MB cada uno. Los archivos se van generando a medida que se van llenando, osea, se arranca con un archivo, cuando llega a 200MB, se cierra y se abre uno nuevo.
Recuerden lo que les dije al principio, estos logs son monstruosos, así que si tienen poco espacio en el disco, vigilenlos! Sino les comerá el disco y al almacenarse en la misma partición que la base de datos, puede que les genere un Denial of Service si el disco se llena!


SQL Traces

Para no volvernos locos con los logs generados por el modo C2, podemos customizar lo que deseamos loguear utilizando trazas (traces), las cuales creamos con una serie de store procedures que trae SQL Server. La explicación de cada uno de estos store procedures la pueden encontrar en la página oficial de MS, dependiendo la versión de SQL Server que tengan, puede variar un poco, pero hasta donde vi es bastante similar en todas las versiones. Yo voy a explicar el sistema para SQL Server 2005, pero no debería variar mucho para SQL Server 2008.

SQL Server basa su funcionamiento en eventos y por ello, los logs se arman en base a los eventos que queremos loguear. Por cada evento tenemos una serie de atributos que podemos loguear. Muchos atributos son comunes para todas los eventos, pero algunos son específicos para cierta clase de eventos. Nuestro trabajo trata sobre ver que eventos queremos loguear y qué atributo de cada evento deseamos... no es un trabajo fácil, porque existen como 200 eventos a loguear, y contamos con 64 atributos posibles, encontrar lo que realmente necesitamos llevará un tiempo de pruebas.

Para comenzar les puedo dar el formato de como crear una traza básica:

-- declaramos las variables necesarias
DECLARE @traceID int
DECLARE @maxFileSize bigint
DECLARE @traceFile nvarchar(245)
DECLARE @on bit
DECLARE @date nvarchar(25)

-- seteamos el tamanio para los archivos donde se almacenan los logs
set @maxfilesize = 200
-- seteamos la localización de los logs
set @date = convert(nvarchar(25), GETDATE())
set @date = REPLACE(@date,':','.')
set @date = REPLACE(@date,' ','_')
set @traceFile = N'D:\SQL_Traces\trace_'+@date+'.trc'


-- creamos la traza, obtienendo un id que se almacenara en @traceID. Indicamos que cuando se alcance el maximo del archivo, se cree otro archivo nuevo.
EXEC sp_trace_create @traceID OUTPUT, 2, @traceFile, @maxFileSize, NULL

-- decimos que queremos activar el evento
set @on = 1

-- activamos el evento 109 (auditar cuando se agrega un login a la base de datos) y queremos guardar las columnas 1 (el texto generado por el evento) y 11 (el nombre de login).
EXEC sp_trace_setevent @traceID, 109, 1, @on
EXEC sp_trace_setevent @traceID, 109, 11, @on

-- activamos el evento 110 (agregar un miembro a un rol) con las mismas columnas que antes.
EXEC sp_trace_setevent @traceID, 110, 1, @on
EXEC sp_trace_setevent @traceID, 110, 11, @on

-- iniciamos la traza
EXEC sp_trace_setstatus @traceID, 1
GO

Traté de comentar todo lo relevante en el código, pero es interesante destacar el significado de algunas líneas. Por un lado al principio decimos el tamaño máximo que debe alcanzar cada archivo de log (se utiliza el formato propietario .trc). Luego creamos un nombre para estos archivos. Como no deseamos pisar trazas anteriores, le agregué la fecha al nombre de archivo.
Una vez seteadas las variables, creamos la traza con el store procedure sp_trace_create, al cual debemos pasarle una variable donde nos retornará el id de la traza creada. Con el siguiente valor le podemos especificar opciones, yo coloqué 2 para indicar que una vez que se llena el archivo de log (osea, alcanzamos los 200MB), que se cree un nuevo archivo... es decir, vamos creando archivos de 200MB. Como se imaginarán, el siguiente parámetro especifica el nombre del archivo donde guardar las trazas, y el que se encuentra al lado es el tamaño de los archivos. Por último, como no nos interesan los valores stoptime y filecount, colocamos un NULL.
Ahora pasamos a setear los eventos que queremos loguear. Primero utilizamos una variable del tipo bit que nos servirá para decir que queremos poner en on el evento... esa variable la utilizaremos en el store procedure sp_trace_setevent. Las siguientes líneas simplemente activan los eventos agregar un login y agregar usuario a un rol utilizando la citada sp_trace_setevent. Para ambos casos logueamos las columnas 1 y 11, las cuales nos dicen el texto del evento (osea, lo que pasó) y el nombre del usuario de login que causó el evento. La lista completa de eventos que pueden loguear y las columnas que se pueden loguear, vean el mismo manual de sp_trace_setevent... armense de paciencia porque son muchos...
Por último, iniciamos la traza utilizando el store procedure sp_trace_setstatus, donde le damos el id de la traza que queremos activar, y le pasamos un 1 para indicar que iniciamos, si pusiéramos un 0 estaríamos deteniendo y con un 2 la eliminamos del sistema.

Muy bien, con todo lo anterior ya tenemos la traza en ejecución y logueando eventos. Qué pasa si queremos detenerla? utilizamos el citado sp_trace_setstatus. Como habrán visto, sp_trace_setstatus necesita dos parámetros, el id de la traza y el indicador de qué hacer con la traza (comenzar, detener, eliminar). Pues cómo obtenemos el id de la traza que deseamos? acuerdense que antes utilizábamos la variable @traceID, pero esa variable la perdemos una vez q termina la ejecución de las sentencias anteriores. No desesperen, hay una forma de hacer esto.
Dado que pueden haber varias trazas en ejecución al mismo tiempo, primero tenemos que buscar la que deseamos. Para esto podemos usar la sentencia:

select * from fn_trace_getinfo(0)

Esta sentencia nos devuelve todos los ids de las trazas existentes. Busquen la que desean detener mirando los atributos de cada una (pueden buscar el nombre del archivo donde se guardan los logs por ejemplo). Una vez que obtenemos el id de la traza simplemente ejecutamos:

EXEC sp_trace_setstatus elID, 0

si queremos solamente detenerla, o bien:

EXEC sp_trace_setstatus elID, 0
EXEC sp_trace_setstatus elID, 2

si queremos detenerla y eliminarla del sistema.

Lo último que me queda por decir acerca de las trazas es que estas se detienen cada vez que reiniciamos el motor de base de datos y no se arrancan solas. Si queremos que nuestra traza se inicie cada vez que iniciamos el motor de base de datos, podemos meter todo el código anterior en un store procedure de la base de datos master:

USE [MASTER]
GO

CREATE PROCEDURE usp_trace
AS

... TODO EL CODIGO ANTERIOR ...

Una vez creado el store procedure, debemos configurarlo para que se ejecute al inicio. Para esto, necesitamos oooootro store procedure llamado sp_procoption. Por suerte esto SP es muy simple, debemos pasarle el nombre del SP que queremos ejecutar, un valor indicando lo que queremos hacer (en nuestro caso que se ejecute al inicio del sistema) y el valor de la opción (true para activarlo). Asumiento el nombre del store procedure que utilice en el ejemplo (usp_trace), deberíamos ejecutar lo siguiente:

EXEC sp_procoption ups_trace, StartUp, True

Cómo leemos los archivos .trc?

Para variar, nuestros amigos de MS nos entregan un formato propietario el cual no se puede abrir con otra cosa que no sea el SQL Profiler, osea, un programa provisto por ellos...
El SQL Profiler es bastante completo y permite realizar distintos niveles de filtrado para poder visualizar la información que nos interesa, pero igualmente preferiría un formato de archivo visible con cualquier editor, o desde una base de datos.

Cabe destacar que es posible volcar los valores del log a una base de datos para que sean más fáciles de administrar, aunque ahora no recuerdo exactamente en donde estaba explicado, si lo encuentro en estos días, actualizo el artículo =)

También es interesante saber que las trazas se pueden crear desde el SQL Profiler, desde una GUI bien bonita... aunque siempre es mejor hacerlo a mano y estar seguro de qué se está activando. Además el SQL Profiler incurre en un overhead extra en el sistema para ejecutar las trazas...


Referencias

El gran artículo que me ayudó muchísimo a entender todo este sistema de log de eventos fue Get Compliant with SQL Server 2005 Audit, muchas gracias Larry Clark por tan buen artículo.
Por supuesto que el resto lo tuve que hacer solo mirando los manuales de MS que pueden encontrar en SQL Server Profiler Stored Procedures (Transact-SQL).