ASP.NET Web API Twój TraceWriter generującu logi w postaci HTML

16 lutego 2014 ASP.NET

Trace Writer Część NR.5 W poprzednim wpisie omówiliśmy jak można sprawdzać działanie WEB API przy użyciu Fiddler-a.

WCF jak i ASP.NET WEB API ma wbudowany mechanizm śledzenia działania usługi i zapisu logów do określonego źródła.

Do projektu ASP.NET WEB API nie zawsze są dodawane referencję do bibliotek które zawierają ten mechanizm.

Ja swój projekt zbudowałem na bazie template “Empty” więc wiem na pewno, że nie mam tych referencji.

Z pomocą oczywiście przychodzi NuGet. Microsoft w ostatnich latach bardzo zainwestował w model programowania opartych na paczkach.

Aby uaktywnić proste śledzenie, które będzie wyświetlało operacje w oknie output wystarczy do klasy WebApiConfig dodać następującą linijkę.

config.EnableSystemDiagnosticsTracing();

Po uruchomieniu jakiejkolwiek metody w oknie output powinieneś zobaczyć informacje na temat przebiegu zapytania.

Tworzenie własnego TraceWriter

Zabawa zaczyna się gdy napiszemy swoją własną klasę dziedzicząco interfejsie ITraceWriter. Istnieją dwa interfejsy o takie samej nazwie. Nam chodzi o interfejs ITraceWriter z przestrzeni nazwy “System.Wb.Http.Tracing”.

using System;
using System.Web.Http.Tracing;

namespace GameWebApiBlog.TraceWriters
{
    public class AspNetWebApiTrace : ITraceWriter
    {
        public void Trace(System.Net.Http.HttpRequestMessage request, 
            string category, TraceLevel level, Action<TraceRecord> traceAction)
        {
            throw new NotImplementedException();
        }
    }
}

Naszym celem jest zapisanie informacji o danej akcji na podstawie właściwości klasy TraceRecord.

Przed jakikolwiek zapisem warto zwróci uwagę na poziom komunikatu. Gdy ma on poziom Off oznacza to, że śledzenie zostało wyłączone w Web.configu.

Każdy klasa wykonująca metodę Trace powinna w swoim ciele wykonać przekazywaną delegate “traceAction”.

public void Trace(System.Net.Http.HttpRequestMessage request,
    string category, TraceLevel level, Action<TraceRecord> traceAction)
{
    if (level != TraceLevel.Off)
    {
        TraceRecord rec = new TraceRecord(request, category, level);
        traceAction(rec);
        //Zapisz swój stuff
    }
}

Zapis logów do pliku tekstowe to nie koniecznie dobry pomysł. Znalezienie czegokolwiek w pliku tekstowym z logami możemy być uciążliwe. W bazie SQL możemy przynajmniej w łatwy sposób filtrować komunikaty w zależności od ich poziomów. Umieszczenie logów do bazy nie jest więc takim głupim pomysłem.

Z doświadczeniem wiem, że najbardziej interesują nas informacja o zadaniach w których wystąpił błąd.

Jest to tylko przykład zapisu zawartości do pliku XML.

private void WriteStuffToXmlElement(TraceRecord rec)
{
    using (Stream xmlFile = new FileStream(@"D:\Traces.xml", FileMode.Append))
    {
        using (XmlTextWriter writer = new XmlTextWriter(xmlFile, Encoding.UTF8))
        {
            writer.Formatting = Formatting.Indented;
            writer.WriteStartElement("Trace");
            writer.WriteElementString("when", rec.Timestamp.ToString());
            writer.WriteElementString("action", rec.Operation);
            writer.WriteElementString("user", rec.Operator);

            if (!String.IsNullOrWhiteSpace(rec.Message))
            {
                writer.WriteStartElement("message");
                writer.WriteCData(rec.Message);
                writer.WriteEndElement();
            }

            writer.WriteElementString("category", rec.Category);
            writer.WriteEndElement();
            writer.WriteString(Environment.NewLine);
            writer.Flush();
        }
    }
}

Metodę zapisującą informację do pliku XML umieszczamy w metodzie Trace.

public void Trace(System.Net.Http.HttpRequestMessage request,
    string category, TraceLevel level, Action<TraceRecord> traceAction)
{
    if (level != TraceLevel.Off)
    {
        TraceRecord rec = new TraceRecord(request, category, level);
        traceAction(rec);
        //Zapisz swój stuff
        WriteStuffToXmlElement(rec);
    }
}

Aby użyć swojej klasy Trace musimy nadpisać już istniejącą. Robimy to w klasie WebApiConfig.

config.Services.Replace(typeof(ITraceWriter), new AspNetWebApiTrace());

Oto fragment zapisanego logu.

<Trace> 
  <when>2014-02-15 14:29:56</when> 
  <action>GetPerRequestFormatterInstance</action> 
  <user>JsonMediaTypeFormatter</user> 
  <message><![CDATA[Will use same 'JsonMediaTypeFormatter' formatter]]></message> 
  <category>System.Net.Http.Formatting</category> 
</Trace>

Możesz zapisywać logi tylko o określonym statusie.

//Zapisz swój stuff
if (TraceLevel.Fatal == level || TraceLevel.Error == level)
    WriteStuffToXmlElement(rec);

Możesz w swoich kontrolerach WEB API zapisywać swoje własne informacje o przebiegu zapytania.

Jest to tylko przykład.

public class GamesController : ApiController
{
    private readonly ITraceWriter traceWriter = null;

    public GamesController()
    {
        this.traceWriter = GlobalConfiguration.Configuration.Services.GetTraceWriter();
    }

    // GET api/Games
    [AcceptVerbs("GET")]
    public IEnumerable<Game> AllGames()
    {
        if (traceWriter != null)
            traceWriter.Info(Request, "GamesController", String.Format("AllGames Requested"));
        if (traceWriter != null)
            traceWriter.Trace(
            Request, "System.Web.Http.Controllers", System.Web.Http.Tracing.TraceLevel.Info,
            (traceRecord) =>
            {
                traceRecord.Message =
                String.Format("AllGames");
                traceRecord.Operation = "AllGames()";
                traceRecord.Operator = "GamesController";
            });

        return list;
    }

Logi można wykorzystać jeszcze w bardziej konstruktywny sposób.

Przechwycenie czasu trwania otwarcia i zamknięcia połączenia

Idea o przechwycie czasu trwania operacji w trakcie połączenia z Web API nie jest nowa. Oto oficjalny poradnik jak stworzyć taką klasę.

http://www.asp.net/web-api/overview/testing-and-debugging/tracing-in-aspnet-web-api

Na bazie tego artykułu stworzyłem Tracera, który zapisuje do swojej tablicy ostatnie 1000 wywołań. Kolejność zapisu ma znaczenie ze względu na zmianę wskaźnika do tablic. Przy zapisie korzystamy więc ze słowa kluczowego “lock”.

Jeśli wskaźnik do tablicy przekroczy liczbę 1000 jest on zerowany.

public class PerfTracer : ITraceWriter
{
    TraceRecord[] records = new TraceRecord[PossibleSizeOfCollection];
    private const int PossibleSizeOfCollection = 1000;
    int pointer = PossibleSizeOfCollection - 1;
    private readonly object lockobj = new object();

    public void Trace(HttpRequestMessage request, string category, TraceLevel level,
        Action<TraceRecord> traceAction)
    {
        TraceRecord rec = new TraceRecord(request, category, level);
        traceAction(rec);
        WriteTrace(rec);
    }

    private void MovePointer()
    {
        pointer = (pointer + 1) % PossibleSizeOfCollection;
    }

    // Collect traces in memory.
    protected void WriteTrace(TraceRecord rec)
    {
        lock (lockobj)
        {
            records[pointer] = rec;
            MovePointer();
        }
    }

    public IList<TraceRecord> ShowMeCopyOfTraceRecords()
    {
        lock (lockobj)
        {
            var copy = new List<TraceRecord>(records.Where(t => t != null));
            return copy;
        }
    }
}

Metoda “ShowMeCopyOfTraceRecords” zwraca kopię tablicy logów. Będziemy te logi wyświetlać na stronie internetowej w postaci pliku HTML.

Aby użyć nowej klasy śledzącej musimy tak jak w poprzednim przypadku nadpisać istniejącego Tracer-a.

config.Services.Replace(typeof(ITraceWriter), new PerfTracer());

Teraz przechodzimy do serca całego pomysłu. Idea jest prosta. Coś w naszej usłudze nie działa lub chcemy zmierzyć prędkość działania samego Web API. Włączamy tymczasowo metody WEB API które będą nam wyświetlały te statystki. Po zakończeniu działań wyłączamy te metody.

Oto TraceController, który będzie wyświetlał logi w postaci kodu HTML. Jest on prymitywny, ale nie oczekujcie od mnie prawdziwego pięknego rozwiązania, które napisałem w godzinne.

Metody AppendSpaces dodaje HTML białe znaki. Metoda AppendMessage drukuje rekord do przekazanej klasy StringBuilder.

public class TraceController : ApiController
{
    private StringBuilder AppendSpaces(StringBuilder content,int indent)
    {
        for (int i = 0; i < indent; i++)
        {
            content.Append("&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;");
        }

        return content;
    }

    private StringBuilder AppendMessage(string color,string Beg,
        StringBuilder content,TraceRecord entry,string millis)
    {
        content.AppendFormat("<span style=\"color:"+color+";\">{0}</span>"
        +"{1} <span style=\"color:"+color+";\">{2}</span>",
            Beg,entry.RequestId, entry.Operator, entry.Operation);

        if (!string.IsNullOrWhiteSpace(millis))
            content.AppendFormat("<span style=\"background-color:#F0C6FF\">"
                + "&nbsp;&nbsp;{0}&nbsp;&nbsp;"
                +"</span>Milliseconds", millis);

        content.Append("<br />");

        return content;
    }

Logi wydają się być bezużyteczne bez wydrukowania właściwości Message. W zależności czy jest ona pusta czy nie zostanie ona wydrukowana.

private StringBuilder AppendMoreInfo(StringBuilder content, TraceRecord entry, int indent)
{
    if (!string.IsNullOrWhiteSpace(entry.Message))
    {
        AppendSpaces(content, indent);
        content.Append("&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;" + entry.Message + "<br />");
    }

    return content;
}

Czas na mózg tego rozwiązania czyli metodę która zwróci kod HTML z logami.

[[HttpGet]
public HttpResponseMessage ShowTraces()
{
    StringBuilder content = new StringBuilder();
    PerfTracer tracer = (PerfTracer)
        GlobalConfiguration.Configuration.Services.GetTraceWriter();

    var entries = tracer.ShowMeCopyOfTraceRecords();
    if (entries != null && entries.Count > 0)
    {
        int indent = 0;
        foreach (var entry in entries)
        {
            if (!String.IsNullOrEmpty(entry.Operation) &&
            !String.IsNullOrEmpty(entry.Operator) &&
            !String.IsNullOrEmpty(entry.Category))
            {
                if (entry.Operator.Contains("Trace"))
                    continue;

                if (entry.Kind == TraceKind.Begin)
                {
                    var end = entries.FirstOrDefault(e =>
                    entry.RequestId.Equals(e.RequestId) &&
                    entry.Operator.Equals(e.Operator) &&
                    entry.Operation.Equals(e.Operation) &&
                    entry.Category.Equals(e.Category) &&
                    e.Kind == TraceKind.End);

                    string millis = String.Empty;
                    if (end != null)
                        millis =
                        (end.Timestamp - entry.Timestamp).TotalMilliseconds.ToString();

                    AppendSpaces(content, indent);
                    AppendMessage("blue","BEG", content, entry, millis);
                    AppendMoreInfo(content, entry, indent);
                    indent++;
                }
                else
                {
                    if (indent != 0)
                    indent--;
                    AppendSpaces(content, indent);
                    AppendMessage("green","END", content, entry, null);
                    AppendMoreInfo(content, entry, indent);
                }
            }
        } 
    }
    string html = "<html><head></head><body>" + content.ToString() + "</body></html>";
    HttpResponseMessage r = new HttpResponseMessage();
    r.Content = new StringContent(html);
    r.Content.Headers.ContentType  = new MediaTypeHeaderValue("text/html");

    return r;
}

Aby uzyskać sensowne informację o czasie trwania wykonywanych operacji musimy powiązać ich otwarcia i zamknięcia ze sobą. Jeżeli zamknięcie istnieje różnica zostaje zapisana w zmiennej millis.

Później wcześniej pokazane metody zapisują rekordy w formie tekstowej.

Na końcu zawartość klasy StringBuilder zapisuje do właściwości Content klasy reprezentującą odpowiedź HTTP. Ustawiam jeszcze nagłówek odpowiedzi “content-type” na “text/html”. Tak aby przeglądarka wiedziała, że zwróciłem dla niej tekst w formie HTML.

Do testu wystarczy uruchomić jakąkolwiek metodę naszego WEB API a potem uruchomić kontroler Trace.

http://localhost:4000/api/game/

http://localhost:4000/api/trace/

Oto rezultat naszych działania. Czas trwania odpowiednich operacji został podkreślony na fioletowo. Jest on bardzo krótki.

A tak wygląda rezultat jeśli będziemy także drukować właściwość Message.

Do swoich własnych kontrolerów i metod możesz także dodać swój kod śledzenie w taki sposób, aby wydzielić otwarcie i zamknięcie naszych operacji.

W trakcie wykonywania operacji dodałem Thread.Sleep(6000). Uśpi on wątek na 6 sekund. Teraz będziemy mogli zobaczyć prawdziwe opóźnienia w tej metodzie.

[AcceptVerbs("GET")]
public Game RetriveGame(int id)
{
    Game game = null;
    if (traceWriter != null)
    {
        traceWriter.TraceBeginEnd(
        Request,
        TraceCategories.FormattingCategory,
        System.Web.Http.Tracing.TraceLevel.Info,
        "GamesController",
        "Get",
        beginTrace: (tr) =>
        {
            tr.Message = "RetriveGame - BEGIN";
        },
        execute: () =>
        {
            System.Threading.Thread.Sleep(6000); 
            game = list.First(e => e.Id == id);
        },
        endTrace: (tr) =>
        {
            tr.Message = "RetriveGame - END";
        },
        errorTrace: null);
    }

    return game;
}

Do testu tego nowego patentu wywołań tą funkcje w Web API.

http://localhost:4000/api/games/1234

Co widać na poniższymi zapisie. Nasze własne wiadomości zostały także zapisane.

Dosyć użyteczna wynalazek trzeba przyznać.

To wszystko jeśli chodzi o wykorzystanie klasy TraceWriter.

Ten wpis jest częścia cyklu:

ASP.NET Web API

Web Api

Podstawy prostego API i co na to wujek WCF

Get/List

Udostępnianie listy elementów

WebApiConfig

Konfiguracja klasa WebApiConfig

Debug

Debugowanie fiddler i inne narzędzia

Trace Writer

Twój TraceWriter generujący logi HTML

Zobacz wszystkie wpisy

O Autorze

Nazywam się Cezary Walenciuk.

Pracuję w Warszawie przy różnych projektach webowych i mobilnych

Moim marzeniem jest pomaganie innym osobom, które zaczynają swoją przygodę z programowaniem. Jeśli chcesz mi pomóc użyj któregoś z przycisków na dole bądź dodaj komentarz.

ASP.NET Web API Twój TraceWriter generującu logi w postaci HTML

Tworzenie własnego TraceWriter

Przechwycenie czasu trwania otwarcia i zamknięcia połączenia

Ten wpis jest częścia cyklu:

O Autorze

Wszystkie Kategorie