locked
Web Log using HTTPModule - Need to log bad requests as well as good ones - good ones are working ok RRS feed

  • Question

  • User8809227 posted

    Hi,

     

    I need help with my HTTPModule.  I am using vb.net 2003 to do web logging rather than using IIS web log files due to work requirements.  I am storing the same information that IIS would store using the W3C Extended Log File Format.  My problem is that all successful web requests are logged to the database table ok (status of 200), but nothing other than that gets logged.  I want to log all requests, good and bad (301, 404, 401, etc. ... all other than 200 as well), and then have the error pages that are set up in IIS be displayed after the info is logged to the database.  Here is the code I am using:

    Imports System

    Imports System.Configuration

    Imports System.Data

    Imports System.Data.SqlClient

    Imports System.Web

    Imports System.Net

    Imports System.Net.Dns

    Imports System.IO

    Imports System.Text

    Imports System.Collections.Specialized

     

    Public Class LogWebUsage

    Implements IHttpModule

    Private streamWatcher As TransparentStream

    ' Fields in W3C Extended Log Format

    Private sStartRequestDate As String = "" ' (date)

    Private sStartRequestTime As String = "" ' (time)

    Private sClientIP As String = "" ' (c-ip)

    Private sAuthUserName As String = "" ' (cs-username)

    Private sServiceName As String = "" ' (s-sitename)

    Private sServerName As String = "" ' (s-computername)

    Private sServerIP As String = "" ' (s-ip)

    Private iServerPort As Integer = Nothing ' (s-port)

    Private sHTTPMethod As String = "" ' (cs-method)

    Private sURLVisited As String = "" ' (cs-uri-stem)

    Private sQueryString As String = "" ' (cs-uri-query)

    Private iProtocolStatusCode As Integer = Nothing ' (sc-status)

    Private iWin32StatusCode As Integer = Nothing ' (sc-win32-status)

    Private iBytesSentByServer As Long = 0 ' (sc-bytes)

    Private iBytesReceivedByServer As Long = 0 ' (cs-bytes)

    Private iProcessingTime As Long = 0 ' (time-taken)

    Private sRequestProtocol As String = "" ' (cs-version)

    Private sHostHeader As String = "" ' (cs-host)

    Private sUserAgent As String = "" ' (cs(User-Agent))

    Private sCookie As String = "" ' (cs(Cookie))

    Private sReferer As String = "" ' (cs(Referer))

    ' Additional Useful Fields

    Private sServerSoftware As String = ""

    Private sW3CExtendedLogFormatVersion As String = ""

    Private dStartProcessDateTime As DateTime

    Private dEndProcessDateTime As DateTime

    Private sBrowserPlatform As String = ""

    Private sBrowserType As String = ""

    Private sBrowserName As String = ""

    Private sBrowserVersion As String = ""

    Private sBrowserMajorVersion As String = ""

    Private sBrowserMinorVersion As String = ""

    Private sRequestContentType As String = ""

    Private sResponseContentType As String = ""

    Private sCrawler As String = ""

    ' dsn is in machine.config files

    Private dsn As String = CType(ConfigurationSettings.AppSettings("WebLoggerDSN"), String)

    Private conn As SqlConnection

    Private cmd As SqlCommand

    Public Sub Init(ByVal app As HttpApplication) Implements IHttpModule.Init

    AddHandler app.BeginRequest, AddressOf BeginRequest

    AddHandler app.EndRequest, AddressOf EndRequest

    AddHandler app.Error, AddressOf OnError

    End Sub

    Public Sub Dispose() Implements IHttpModule.Dispose

    ' add clean-up code here if required

    dsn = Nothing

    cmd = Nothing

    conn.Close()

    conn = Nothing

    End Sub

    Public Sub BeginRequest(ByVal sender As Object, ByVal e As EventArgs)

    dStartProcessDateTime = DateTime.Now

    ' Get access to the request context

    Dim context As HttpApplication

    context = CType(sender, HttpApplication)

    ' Create stream watcher so we can get bytes downloaded

    Dim app As HttpApplication = DirectCast(sender, HttpApplication)

    streamWatcher = New WebLogger.TransparentStream(app.Response.Filter)

    app.Response.Filter = streamWatcher

    ''============= Code Meanings ===============

    ' Prefix - Meaning

    ' s - Server actions.

    ' c - Client actions.

    ' cs - Client-to-server actions.

    ' sc - Server-to-client actions.

    '===========================================

    '

    '=================== Fields in W3C Extended Log Format ============================

    '

    ' Date (date) - The date that the activity occurred.

    sStartRequestDate = dStartProcessDateTime.ToString("yyyy-MM-dd")

    ' Time (time) - The time that the activity occurred.

    sStartRequestTime = dStartProcessDateTime.ToString("HH:mm:ss")

    ' Client IP (c-ip) - The IP address of the client that accessed your server.

    sClientIP = context.Request.ServerVariables("HTTP_X_FORWARDED_FOR")

    If sClientIP = "" Or sClientIP = Nothing Then

    sClientIP = context.Request.ServerVariables("REMOTE_ADDR")

    End If

    ' User Name (cs-username) - The name of the authenticated user who accessed your server.

    ' This does not include anonymous users, who are represented by a hyphen (-).

    sAuthUserName = context.Request.ServerVariables("AUTH_USER")

    ' Service Name (s-sitename) - The Internet service and instance number that was accessed by a client.

    sServiceName = context.Request.ServerVariables("INSTANCE_META_PATH")

    ' Server Name (s-computername) - The name of the server on which the log entry was generated.

    'sServerName = context.Request.ServerVariables("SERVER_NAME")

    Try

    sServerName = Dns.GetHostName()

    Catch

    sServerName = Nothing

    End Try

    ' Server IP Address (s-ip) - The IP address of the server on which the log entry was generated.

    sServerIP = context.Request.ServerVariables("LOCAL_ADDR")

    ' Server Port (s-port) - The port number the client is connected to.

    iServerPort = context.Request.ServerVariables("SERVER_PORT")

    ' Method (cs-method) - The action the client was trying to perform (for example, a GET method).

    sHTTPMethod = context.Request.ServerVariables("REQUEST_METHOD")

    ' URI Stem (cs-uri-stem) - The resource accessed; for example, Default.htm.

    sURLVisited = context.Request.ServerVariables("URL")

    ' URI Query (cs-uri-query) - The query, if any, the client was trying to perform.

    sQueryString = context.Request.ServerVariables("QUERY_STRING")

    ' Protocol Status (sc-status) - The status of the action, in HTTP or FTP terms.

    iProtocolStatusCode = context.Response.StatusCode

    ' Win32® Status (sc-win32-status) - The status of the action, in terms used by Microsoft Windows®.

    iWin32StatusCode = Nothing

    ' Bytes Sent (sc-bytes) - The number of bytes sent by the server.

    ' [This value is retrieved in EndRequest]

    iBytesSentByServer = 0

    ' Bytes Received (cs-bytes) - The number of bytes received by the server.

    iBytesReceivedByServer = context.Request.ServerVariables("CONTENT_LENGTH")

    ' Time Taken (time-taken) - The duration of time, in milliseconds, that the action consumed.

    ' [This value is retrieved in EndRequest]

    iProcessingTime = 0

    ' Protocol Version (cs-version) - The protocol (HTTP, FTP) version used by the client. For

    ' HTTP this will be either HTTP 1.0 or HTTP 1.1.

    sRequestProtocol = context.Request.ServerVariables("SERVER_PROTOCOL")

    ' Host (cs-host) - Displays the content of the host header.

    sHostHeader = context.Request.Headers("Host")

    ' User Agent (cs(User-Agent)) - The browser used on the client.

    sUserAgent = context.Request.ServerVariables("HTTP_USER_AGENT")

    ' Cookie (cs(Cookie)) - The content of the cookie sent or received, if any.

    sCookie = context.Request.Headers("Cookie")

    ' Referrer (cs(Referer)) - The previous site visited by the user. This site provided a link to

    ' the current site.

    sReferer = context.Request.ServerVariables("HTTP_REFERER")

    '

    '====================== Additional Useful fields =========================

    '

    ' Server Software

    sServerSoftware = context.Request.ServerVariables("SERVER_SOFTWARE")

    ' Version - The version of the W3C Extended Log Format used.

    ' This is based on version 1.0.

    sW3CExtendedLogFormatVersion = "1.0"

    ' Request Start DateTime

    'dStartProcessDateTime already set at the beginning

    ' OS - Browser Platform Operating system Client

    sBrowserPlatform = context.Request.Browser.Platform

    ' Browser Type -

    sBrowserType = context.Request.Browser.Type

    ' Browser Name

    sBrowserName = context.Request.Browser.Browser

    ' Browser Version

    sBrowserVersion = context.Request.Browser.Version

    ' Browser Major Version

    sBrowserMajorVersion = context.Request.Browser.MajorVersion

    ' Browser Minor Version

    sBrowserMinorVersion = context.Request.Browser.MinorVersion

    ' Request Content Type

    sRequestContentType = context.Request.ServerVariables("CONTENT_TYPE")

    ' Response Content Type

    sResponseContentType = context.Response.ContentType

    ' Crawler - Is a Crawler

    sCrawler = context.Request.Browser.Crawler

    ' Request End DateTime

    'dEndProcessDateTime set in the End Request

    conn = New SqlConnection(dsn)

    conn.Open()

    cmd = New SqlCommand("InsertLogEntry", conn)

    cmd.CommandType = CommandType.StoredProcedure

    '==================================================

    ' Set Fields used for W3C Extended Log Format

    '==================================================

    cmd.Parameters.Add("@StartRequestDate", SqlDbType.VarChar, 10)

    cmd.Parameters("@StartRequestDate").Value = sStartRequestDate

    cmd.Parameters.Add("@StartRequestTime", SqlDbType.VarChar, 8)

    cmd.Parameters("@StartRequestTime").Value = sStartRequestTime

    cmd.Parameters.Add("@ClientIP", SqlDbType.VarChar, 20)

    cmd.Parameters("@ClientIP").Value = sClientIP

    cmd.Parameters.Add("@AuthUserName", SqlDbType.VarChar, 255)

    cmd.Parameters("@AuthUserName").Value = IIf(sAuthUserName = Nothing, "-", sAuthUserName)

    cmd.Parameters.Add("@ServiceName", SqlDbType.VarChar, 100)

    cmd.Parameters("@ServiceName").Value = sServiceName

    cmd.Parameters.Add("@ServerName", SqlDbType.VarChar, 100)

    cmd.Parameters("@ServerName").Value = IIf(sServerName = Nothing, "-", sServerName)

    cmd.Parameters.Add("@ServerIP", SqlDbType.VarChar, 20)

    cmd.Parameters("@ServerIP").Value = sServerIP

    cmd.Parameters.Add("@ServerPort", SqlDbType.Int)

    cmd.Parameters("@ServerPort").Value = IIf(iServerPort = Nothing, DBNull.Value, iServerPort)

    cmd.Parameters.Add("@HTTPMethod", SqlDbType.VarChar, 10)

    cmd.Parameters("@HTTPMethod").Value = sHTTPMethod

    cmd.Parameters.Add("@Url", SqlDbType.VarChar, 1024)

    cmd.Parameters("@Url").Value = sURLVisited

    cmd.Parameters.Add("@QueryString", SqlDbType.VarChar, 2048)

    cmd.Parameters("@QueryString").Value = IIf(sQueryString = Nothing, "-", sQueryString)

    cmd.Parameters.Add("@ProtocolStatusCode", SqlDbType.Int)

    cmd.Parameters("@ProtocolStatusCode").Value = IIf(iProtocolStatusCode = Nothing, DBNull.Value, iProtocolStatusCode)

    cmd.Parameters.Add("@Win32StatusCode", SqlDbType.Int)

    cmd.Parameters("@Win32StatusCode").Value = IIf(iWin32StatusCode = Nothing, DBNull.Value, iWin32StatusCode)

    cmd.Parameters.Add("@RequestContentLength", SqlDbType.BigInt)

    cmd.Parameters("@RequestContentLength").Value = iBytesReceivedByServer

    cmd.Parameters.Add("@RequestProtocol", SqlDbType.VarChar, 50)

    cmd.Parameters("@RequestProtocol").Value = sRequestProtocol

    cmd.Parameters.Add("@HostHeader", SqlDbType.VarChar, 255)

    cmd.Parameters("@HostHeader").Value = IIf(sHostHeader = Nothing, "-", sHostHeader)

    cmd.Parameters.Add("@UserAgent", SqlDbType.VarChar, 255)

    ' If there are spaces in the User Agent string and replace them with "+"

    cmd.Parameters("@UserAgent").Value = sUserAgent.Replace(" ", "+")

    cmd.Parameters.Add("@Cookie", SqlDbType.Text)

    ' If there are spaces in the Cookie string and replace them with "+"

    cmd.Parameters("@Cookie").Value = IIf(sCookie = Nothing, "-", sCookie.Replace(" ", "+"))

    cmd.Parameters.Add("@Referer", SqlDbType.VarChar, 1024)

    cmd.Parameters("@Referer").Value = IIf(sReferer = Nothing, "-", sReferer)

    '=======================================

    ' Set Additional Useful Fields

    '=======================================

    cmd.Parameters.Add("@ServerSoftware", SqlDbType.VarChar, 50)

    cmd.Parameters("@ServerSoftware").Value = sServerSoftware

    cmd.Parameters.Add("@W3CExtendedLogFormatVersion", SqlDbType.VarChar, 10)

    cmd.Parameters("@W3CExtendedLogFormatVersion").Value = sW3CExtendedLogFormatVersion

    cmd.Parameters.Add("@StartProcessDateTime", SqlDbType.DateTime)

    cmd.Parameters("@StartProcessDateTime").Value = dStartProcessDateTime

    cmd.Parameters.Add("@BrowserPlatform", SqlDbType.VarChar, 50)

    cmd.Parameters("@BrowserPlatform").Value = sBrowserPlatform

    cmd.Parameters.Add("@BrowserType", SqlDbType.VarChar, 50)

    cmd.Parameters("@BrowserType").Value = sBrowserType

    cmd.Parameters.Add("@BrowserName", SqlDbType.VarChar, 50)

    cmd.Parameters("@BrowserName").Value = sBrowserName

    cmd.Parameters.Add("@BrowserVersion", SqlDbType.VarChar, 20)

    cmd.Parameters("@BrowserVersion").Value = sBrowserVersion

    cmd.Parameters.Add("@BrowserMajorVersion", SqlDbType.VarChar, 10)

    cmd.Parameters("@BrowserMajorVersion").Value = sBrowserMajorVersion

    cmd.Parameters.Add("@BrowserMinorVersion", SqlDbType.VarChar, 10)

    cmd.Parameters("@BrowserMinorVersion").Value = sBrowserMinorVersion

    cmd.Parameters.Add("@RequestContentType", SqlDbType.VarChar, 100)

    cmd.Parameters("@RequestContentType").Value = IIf(sRequestContentType = Nothing, "-", sRequestContentType)

    cmd.Parameters.Add("@ResponseContentType", SqlDbType.VarChar, 100)

    cmd.Parameters("@ResponseContentType").Value = sResponseContentType

    cmd.Parameters.Add("@Crawler", SqlDbType.VarChar, 10)

    cmd.Parameters("@Crawler").Value = sCrawler

    End Sub

    Public Sub OnError(ByVal sender As Object, ByVal e As EventArgs)

    ' Get access to the request context

    Dim context As HttpApplication

    context = CType(sender, HttpApplication)

    If (context.Server.GetLastError.GetType() Is GetType(System.Web.HttpException)) Then

    Dim httpErrorCode As Integer

    Dim LastError As HttpException

    LastError = HttpContext.Current.Server.GetLastError()

    httpErrorCode = LastError.GetHttpCode()

    If (Not httpErrorCode > 0) Then

    LastError = CType(LastError.InnerException, Exception)

    httpErrorCode = LastError.ErrorCode

    End If

    iProtocolStatusCode = httpErrorCode

    cmd.Parameters.Add("@ProtocolStatusCode", SqlDbType.Int)

    cmd.Parameters("@ProtocolStatusCode").Value = IIf(iProtocolStatusCode = Nothing, DBNull.Value, iProtocolStatusCode)

    cmd.ExecuteNonQuery()

    End If

    End Sub

    Public Sub EndRequest(ByVal sender As Object, ByVal e As EventArgs)

    dEndProcessDateTime = DateTime.Now

    Dim context As HttpApplication

    context = CType(sender, HttpApplication)

    ' Bytes Sent (sc-bytes) - The number of bytes sent by the server.

    'now we can see the number of bytes written to the response stream

    iBytesSentByServer = streamWatcher.BytesWritten

    If Not streamWatcher Is Nothing Then streamWatcher.Close()

    cmd.Parameters.Add("@ResponseContentLength", SqlDbType.BigInt)

    cmd.Parameters("@ResponseContentLength").Value = iBytesSentByServer

    ' Request End DateTime

    cmd.Parameters.Add("@EndProcessDateTime", SqlDbType.DateTime)

    cmd.Parameters("@EndProcessDateTime").Value = dEndProcessDateTime

    ' Time Taken (time-taken) - The duration of time, in milliseconds, that the action consumed.

    Try

    Dim ts As New TimeSpan(dEndProcessDateTime.Ticks - dStartProcessDateTime.Ticks)

    iProcessingTime = (ts.Days * (24 * 60 * 60 * 1000)) + (ts.Hours * (60 * 60 * 1000)) + (ts.Minutes * (60 * 1000)) + (ts.Seconds * (1000)) + ts.Milliseconds

    Catch

    iProcessingTime = 0

    End Try

    cmd.Parameters.Add("@ProcessingTime", SqlDbType.BigInt)

    cmd.Parameters("@ProcessingTime").Value = iProcessingTime

    cmd.ExecuteNonQuery()

    End Sub

    End Class

    'this stream acts like a decorator and defers the bulk of the work to the stream that it wraps

    Public Class TransparentStream

    Inherits System.IO.Stream

    Private _innerStream As System.IO.Stream

    Private _bytesWritten As Long = 0

    Public Sub New(ByVal value As System.IO.Stream)

    _innerStream = value

    End Sub

    Public ReadOnly Property BytesWritten() As Long

    Get

    Return _bytesWritten

    End Get

    End Property

    Public Overrides ReadOnly Property CanRead() As Boolean

    Get

    Return _innerStream.CanRead

    End Get

    End Property

    Public Overrides ReadOnly Property CanSeek() As Boolean

    Get

    Return _innerStream.CanSeek

    End Get

    End Property

    Public Overrides ReadOnly Property CanWrite() As Boolean

    Get

    Return _innerStream.CanWrite

    End Get

    End Property

    Public Overrides Sub Flush()

    _innerStream.Flush()

    End Sub

    Public Overrides ReadOnly Property Length() As Long

    Get

    Return _innerStream.Length

    End Get

    End Property

    Public Overrides Property Position() As Long

    Get

    Return _innerStream.Position

    End Get

    Set(ByVal value As Long)

    _innerStream.Position = value

    End Set

    End Property

    Public Overrides Function Read(ByVal buffer() As Byte, ByVal offset As Integer, ByVal count As Integer) As Integer

    _innerStream.Read(buffer, offset, count)

    End Function

    Public Overrides Function Seek(ByVal offset As Long, ByVal origin As System.IO.SeekOrigin) As Long

    _innerStream.Seek(offset, origin)

    End Function

    Public Overrides Sub SetLength(ByVal value As Long)

    _innerStream.SetLength(value)

    End Sub

    Public Overrides Sub Write(ByVal buffer() As Byte, ByVal offset As Integer, ByVal count As Integer)

    'here is where our stream decorator does its actual work.

    _bytesWritten += count '<--- this is all were interested in

    _innerStream.Write(buffer, offset, count)

    End Sub

    End Class

    Tuesday, December 26, 2006 2:09 PM

All replies

  • User8809227 posted

    I changed my OnError event handler as follows and it seems to be mostly working.  At least now it logs status codes of 404:

     

    Public Sub OnError(ByVal sender As Object, ByVal e As EventArgs)

    Dim context As HttpContext = HttpContext.Current

    Dim exception As Exception

    exception = context.Server.GetLastError()

    If (exception.GetType Is GetType(HttpException)) Then

    Dim HttpEx As HttpException

    Dim iHTTPCode As Integer = Nothing

    HttpEx = CType(exception, HttpException)

    iHTTPCode = HttpEx.GetHttpCode()

    cmd.Parameters("@ProtocolStatusCode").Value = iHTTPCode

    cmd.ExecuteNonQuery()

    bErrorLogged = True

    'Throw httpexception after we log it so correct error page appears.

    HttpException.CreateFromLastError("")

    End If

    End Sub

    Tuesday, December 26, 2006 6:35 PM
  • User8809227 posted

    I also forgot to mention I changed my EndRequest event handler too.  I am using bErrorLogged to prevent logging if it already was logged in the OnError method as follows (I would appreciate any suggestions on improving this HTTPModule for web logging...Thanks):

     

    Public Sub EndRequest(ByVal sender As Object, ByVal e As EventArgs)

    dEndProcessDateTime = DateTime.Now

    Dim context As HttpApplication

    context = CType(sender, HttpApplication)

    ' Bytes Sent (sc-bytes) - The number of bytes sent by the server.

    'now we can see the number of bytes written to the response stream

    iBytesSentByServer = streamWatcher.BytesWritten

    If Not streamWatcher Is Nothing Then streamWatcher.Close()

    cmd.Parameters.Add("@ResponseContentLength", SqlDbType.BigInt)

    cmd.Parameters("@ResponseContentLength").Value = iBytesSentByServer

    ' Request End DateTime

    cmd.Parameters.Add("@EndProcessDateTime", SqlDbType.DateTime)

    cmd.Parameters("@EndProcessDateTime").Value = dEndProcessDateTime

    ' Time Taken (time-taken) - The duration of time, in milliseconds, that the action consumed.

    Try

    Dim ts As New TimeSpan(dEndProcessDateTime.Ticks - dStartProcessDateTime.Ticks)

    iProcessingTime = (ts.Days * (24 * 60 * 60 * 1000)) + (ts.Hours * (60 * 60 * 1000)) + (ts.Minutes * (60 * 1000)) + (ts.Seconds * (1000)) + ts.Milliseconds

    Catch

    iProcessingTime = 0

    End Try

    cmd.Parameters.Add("@ProcessingTime", SqlDbType.BigInt)

    cmd.Parameters("@ProcessingTime").Value = iProcessingTime

    If (Not bErrorLogged) Then

    cmd.ExecuteNonQuery()

    End If

    End Sub

    Tuesday, December 26, 2006 6:41 PM
  • User113421904 posted

    Hi,

    I don't think you can do this, since a lot of error is process in lower level, they don't even have chance to be passed to ASP.NET.

    hope it helps!

    Wednesday, January 10, 2007 3:47 AM