WCF Trace & View Trace Logs

2008-12-02

이미 관련글들이 많습니다만 일단 정보를 한곳에 모은다는 생각으로 글을 올립니다.

WCF 응용프로그램을 작성하고 테스트를 진행하다 보면 메시지의 흐름이나 실제 패킨의 생김새를 확인하면서 진행해야 할 경우 생기게 됩니다.

Configuring Tracing

https://msdn2.microsoft.com/en-us/library/ms733025.aspx

이때 아래의 링크를 이용해서 Application 이나 Service의 configuration 파일의 내용을 변경하고 실행하게 되면 .svclog 파일들이 생성됩니다.

Configuration 파일의 대략적인 샘플은 아래와 같습니다. 아래에서 {LogFolder} 를 실제 작업 폴더로 설정하시면 됩니다. 당연히 관련 폴더에 대해서 실행 프로세스의 권한으로 파일을 읽고 쓸 수 있도록 권한도 주셔야 합니다.

<?xml version="1.0" encoding="utf-8" ?>

<system.diagnostics>

<source name="System.ServiceModel"

switchValue="Information,ActivityTracing"

propagateActivity="true">

<add type="System.Diagnostics.DefaultTraceListener"

name="Default">

</add>

</add>

</listeners>

</source>

<source name="System.ServiceModel.MessageLogging"

switchValue="Information,ActivityTracing">

<add type="System.Diagnostics.DefaultTraceListener"

name="Default">

</add>

</add>

</listeners>

</source>

</sources>

<add initializeData=" {LogFolder}\app_tracelog.svclog"

type="System.Diagnostics.XmlWriterTraceListener, System, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089"

name="ServiceModelTraceListener"

traceOutputOptions="Timestamp">

</add>

<add initializeData=" {LogFolder} \app_messages.svclog"

type="System.Diagnostics.XmlWriterTraceListener, System, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089"

name="ServiceModelMessageLoggingListener"

traceOutputOptions="Timestamp">

</add>

</sharedListeners>

</system.diagnostics>

<system.serviceModel>

<messageLogging

logEntireMessage="true"

logMalformedMessages="true"

logMessagesAtServiceLevel="true"

logMessagesAtTransportLevel="true"/>

</diagnostics>

</system.serviceModel>

</configuration>

만일 실제 이동되는 실제 자료까지 확인이 필요하고 netmon등의 사용이 여의치 않은 경우는 아래 설정을 해주시면 비슷한 효과를 보실 수 있습니다. 물론 정확한 자료는 netmon이나 WhireShark등을 통해서 가능 하겠지요.

처음 설정예와 달리 각 Source들의 로깅 레벨을 한군데에 모아서 변하게 변경하려면 아래와 같이 Switches를 이용하면 됩니다.

물론 위의 설정으로 수집되는 파일들을 저장할 listener 도 등록이 되어야 겠지요.

아래는 위의 설정에서 수집된 자료의 예 입니다.

연결되는 서버와 전달되는 헤더, 데이터가 보여지고 있네요.

System.Net Verbose: 0 : [12488] WebRequest::Create(https://yonghp08-wcf/SequencalDataTransfer/SequencalDataTransfer.svc)

System.Net Verbose: 0 : [12488] HttpWebRequest#61381290::HttpWebRequest(https://yonghp08-wcf/SequencalDataTransfer/SequencalDataTransfer.svc#2064498314)

System.Net Verbose: 0 : [12488] Exiting HttpWebRequest#61381290::HttpWebRequest()

System.Net Verbose: 0 : [12488] Exiting WebRequest::Create() -> HttpWebRequest#61381290

System.Net Verbose: 0 : [12488] WebRequest::Create(https://korproxy.fareast.corp.microsoft.com/wpad.dat)

System.Net Verbose: 0 : [12488] HttpWebRequest#36848977::HttpWebRequest(https://korproxy.fareast.corp.microsoft.com/wpad.dat#1165780135)

System.Net Verbose: 0 : [12488] Exiting HttpWebRequest#36848977::HttpWebRequest()

System.Net Verbose: 0 : [12488] Exiting WebRequest::Create() -> HttpWebRequest#36848977

System.Net Information: 0 : [12488] Associating HttpWebRequest#36848977 with ServicePoint#22452836

System.Net Verbose: 0 : [12488] HttpWebRequest#36848977::GetResponse()

System.Net.Cache Verbose: 0 : [12488] RequestCacheProtocol#46153895::GetRetrieveStatus(HttpWebRequest#36848977)

System.Net.Cache Information: 0 : [12488] Request#36848977, Policy = Level:Default, Cache Uri = https://korproxy.fareast.corp.microsoft.com/wpad.dat

System.Net.Cache Information: 0 : [12488] Request Method = GET.

System.Net.Cache Information: 0 : [12488] Selected cache Key = https://korproxy.fareast.corp.microsoft.com/wpad.dat

System.Net.Cache Verbose: 0 : [12488] WinInetCache.Retrieve(key = https://korproxy.fareast.corp.microsoft.com/wpad.dat)

System.Net.Cache Information: 0 : [12488] WinInetCache.Retrieve() -> Filename = C:\Users\yonghp\AppData\Local\Microsoft\Windows\Temporary Internet Files\Content.IE5\IZ02TYFR\wpad[1].dat, Status = Success.

System.Net.Cache Verbose: 0 : [12488] Exiting WinInetCache.Retrieve()() Status = Success

System.Net.Cache Information: 0 : [12488] WinInetReadStream.Close(), Key = https://korproxy.fareast.corp.microsoft.com/wpad.dat.

System.Net.Cache Information: 0 : [12488] ...Dumping Cache Context...

System.Net.Cache Information: 0 : [12488] IsPrivateEntry = True

System.Net.Cache Information: 0 : [12488] IsPartialEntry = False

System.Net.Cache Information: 0 : [12488] StreamSize = 17517

System.Net.Cache Information: 0 : [12488] Expires = Mon, 01 Dec 2008 08:28:42 GMT

System.Net.Cache Information: 0 : [12488] LastAccessed = Mon, 01 Dec 2008 07:44:26 GMT

System.Net.Cache Information: 0 : [12488] LastModified =

System.Net.Cache Information: 0 : [12488] LastSynchronized = Mon, 01 Dec 2008 07:38:42 GMT

System.Net.Cache Information: 0 : [12488] MaxStale(sec) = 0

System.Net.Cache Information: 0 : [12488] HitCount = 13

System.Net.Cache Information: 0 : [12488] UsageCount = 0

System.Net.Cache Information: 0 : [12488] EntryMetadata:

System.Net.Cache Information: 0 : [12488] HTTP/1.1 200 OK

System.Net.Cache Information: 0 : [12488] Content-Type: application/x-ns-proxy-autoconfig

System.Net.Cache Information: 0 : [12488] ---

System.Net.Cache Information: 0 : [12488] SystemMetadata:

System.Net.Cache Information: 0 : [12488] Entry Status Line = HTTP/1.1 200 OK.

System.Net.Cache Information: 0 : [12488] Cache Cache-Control = .

System.Net.Cache Information: 0 : [12488] [Now Time (UTC)] = Mon, 01 Dec 2008 07:45:15 GMT.

System.Net.Cache Information: 0 : [12488] [Age1] Now - LastSynchronized + AgeHeader = 393, Last Synchronized: Mon, 01 Dec 2008 07:38:42 GMT.

System.Net.Cache Information: 0 : [12488] [MaxAge] Cache Expires - Date = 3000, Expires: Mon, 01 Dec 2008 08:28:42 GMT.

System.Net.Cache Information: 0 : [12488] ValidateFreshness(), result = Fresh.

System.Net.Cache Information: 0 : [12488] Cache Age = 393, Cache MaxAge = 3000.

System.Net.Cache Information: 0 : [12488] Valid as fresh or because of Cache Policy = Level:Default.

System.Net.Cache Information: 0 : [12488] ValidateCache(), result = ReturnCachedResponse.

System.Net.Cache Verbose: 0 : [12488] Exiting RequestCacheProtocol#46153895::GetRetrieveStatus() -> result = ReturnCachedResponse

System.Net Verbose: 0 : [12488] Exiting HttpWebRequest#36848977::GetResponse() -> HttpWebResponse#46418718

System.Net Verbose: 0 : [12488] HttpWebResponse#46418718::GetResponseStream()

System.Net Information: 0 : [12488] ContentLength=17517

System.Net Verbose: 0 : [12488] Exiting HttpWebResponse#46418718::GetResponseStream() -> SingleItemRequestCache+ReadOnlyStream#50920718

System.Net Verbose: 0 : [12488] HttpWebResponse#46418718::Close()

System.Net Verbose: 0 : [12488] Exiting HttpWebResponse#46418718::Close()

System.Net Information: 0 : [12488] Associating HttpWebRequest#61381290 with ServicePoint#29803642

System.Net Verbose: 0 : [12488] HttpWebRequest#61381290::GetRequestStream()

System.Net Information: 0 : [12488] Associating Connection#36899882 with HttpWebRequest#61381290

System.Net.Sockets Verbose: 0 : [12488] Socket#23318221::Socket(InterNetwork#2)

System.Net.Sockets Verbose: 0 : [12488] Exiting Socket#23318221::Socket()

System.Net.Sockets Verbose: 0 : [12488] Socket#60865449::Socket(InterNetworkV6#23)

System.Net.Sockets Verbose: 0 : [12488] Exiting Socket#60865449::Socket()

System.Net.Sockets Verbose: 0 : [12488] Socket#23318221::Connect(112:80#1879653581)

System.Net.Sockets Verbose: 0 : [12488] Exiting Socket#23318221::Connect()

System.Net.Sockets Verbose: 0 : [12488] Socket#60865449::Close()

System.Net.Sockets Verbose: 0 : [12488] Socket#60865449::Dispose()

System.Net.Sockets Verbose: 0 : [12488] Exiting Socket#60865449::Close()

System.Net Information: 0 : [12488] Associating HttpWebRequest#61381290 with ConnectStream#28079681

System.Net Information: 0 : [12488] HttpWebRequest#61381290 - Request: POST /SequencalDataTransfer/SequencalDataTransfer.svc HTTP/1.1

System.Net.Sockets Verbose: 0 : [12488] Socket#23318221::Send()

System.Net.Sockets Verbose: 0 : [12488] Data from Socket#23318221::Send

System.Net.Sockets Verbose: 0 : [12488] 00000000 : 50 4F 53 54 20 2F 53 65-71 75 65 6E 63 61 6C 44 : POST /SequencalD

System.Net.Sockets Verbose: 0 : [12488] 00000010 : 61 74 61 54 72 61 6E 73-66 65 72 2F 53 65 71 75 : ataTransfer/Sequ

System.Net.Sockets Verbose: 0 : [12488] 00000020 : 65 6E 63 61 6C 44 61 74-61 54 72 61 6E 73 66 65 : encalDataTransfe

System.Net.Sockets Verbose: 0 : [12488] 00000030 : 72 2E 73 76 63 20 48 54-54 50 2F 31 2E 31 0D 0A : r.svc HTTP/1.1..

System.Net.Sockets Verbose: 0 : [12488] 00000040 : 4D 49 4D 45 2D 56 65 72-73 69 6F 6E 3A 20 31 2E : MIME-Version: 1.

System.Net.Sockets Verbose: 0 : [12488] 00000050 : 30 0D 0A 43 6F 6E 74 65-6E 74 2D 54 79 70 65 3A : 0..Content-Type:

System.Net.Sockets Verbose: 0 : [12488] 00000060 : 20 6D 75 6C 74 69 70 61-72 74 2F 72 65 6C 61 74 : multipart/relat

System.Net.Sockets Verbose: 0 : [12488] 00000070 : 65 64 3B 20 74 79 70 65-3D 22 61 70 70 6C 69 63 : ed; type="applic

System.Net.Sockets Verbose: 0 : [12488] 00000080 : 61 74 69 6F 6E 2F 78 6F-70 2B 78 6D 6C 22 3B 73 : ation/xop+xml";s

System.Net.Sockets Verbose: 0 : [12488] 00000090 : 74 61 72 74 3D 22 3C 68-74 74 70 3A 2F 2F 74 65 : tart="<https://te

System.Net.Sockets Verbose: 0 : [12488] 000000A0 : 6D 70 75 72 69 2E 6F 72-67 2F 30 3E 22 3B 62 6F : mpuri.org/0>";bo

System.Net.Sockets Verbose: 0 : [12488] 000000B0 : 75 6E 64 61 72 79 3D 22-75 75 69 64 3A 31 61 38 : undary="uuid:1a8

System.Net.Sockets Verbose: 0 : [12488] 000000C0 : 63 37 34 37 65 2D 34 62-37 63 2D 34 33 61 36 2D : c747e-4b7c-43a6-

System.Net.Sockets Verbose: 0 : [12488] 000000D0 : 62 36 32 31 2D 66 30 64-65 34 38 36 66 66 65 30 : b621-f0de486ffe0

System.Net.Sockets Verbose: 0 : [12488] 000000E0 : 30 2B 69 64 3D 31 22 3B-73 74 61 72 74 2D 69 6E : 0+id=1";start-in

System.Net.Sockets Verbose: 0 : [12488] 000000F0 : 66 6F 3D 22 74 65 78 74-2F 78 6D 6C 22 0D 0A 53 : fo="text/xml"..S

System.Net.Sockets Verbose: 0 : [12488] 00000100 : 4F 41 50 41 63 74 69 6F-6E 3A 20 22 68 74 74 70 : OAPAction: "http

System.Net.Sockets Verbose: 0 : [12488] 00000110 : 3A 2F 2F 74 65 6D 70 75-72 69 2E 6F 72 67 2F 49 : ://tempuri.org/I

System.Net.Sockets Verbose: 0 : [12488] 00000120 : 44 61 74 61 54 72 61 6E-73 66 65 72 53 65 72 76 : DataTransferServ

System.Net.Sockets Verbose: 0 : [12488] 00000130 : 69 63 65 2F 52 65 63 69-76 65 44 61 74 61 22 0D : ice/ReciveData".

System.Net.Sockets Verbose: 0 : [12488] 00000140 : 0A 48 6F 73 74 3A 20 79-6F 6E 67 68 70 30 38 2D : .Host: yonghp08-

System.Net.Sockets Verbose: 0 : [12488] 00000150 : 77 63 66 0D 0A 54 72 61-6E 73 66 65 72 2D 45 6E : wcf..Transfer-En

System.Net.Sockets Verbose: 0 : [12488] 00000160 : 63 6F 64 69 6E 67 3A 20-63 68 75 6E 6B 65 64 0D : coding: chunked.

System.Net.Sockets Verbose: 0 : [12488] 00000170 : 0A 45 78 70 65 63 74 3A-20 31 30 30 2D 63 6F 6E : .Expect: 100-con

System.Net.Sockets Verbose: 0 : [12488] 00000180 : 74 69 6E 75 65 0D 0A 43-6F 6E 6E 65 63 74 69 6F : tinue..Connectio

System.Net.Sockets Verbose: 0 : [12488] 00000190 : 6E 3A 20 4B 65 65 70 2D-41 6C 69 76 65 0D 0A 0D : n: Keep-Alive...

System.Net.Sockets Verbose: 0 : [12488] 000001A0 : 0A : .

System.Net.Sockets Verbose: 0 : [12488] Exiting Socket#23318221::Send() -> 417#417

System.Net Information: 0 : [12488] ConnectStream#28079681 - Sending headers
{
MIME-Version: 1.0

Content-Type: multipart/related; type="application/xop+xml";start="<https://tempuri.org/0>";boundary="uuid:1a8c747e-4b7c-43a6-b621-f0de486ffe00+id=1";start-info="text/xml"

SOAPAction: "https://tempuri.org/IDataTransferService/ReciveData"

Host: yonghp08-wcf

Transfer-Encoding: chunked

Expect: 100-continue

Connection: Keep-Alive

System.Net.Sockets Verbose: 0 : [12488] Socket#23318221::Receive()

System.Net.Sockets Verbose: 0 : [12488] Data from Socket#23318221::Receive

System.Net.Sockets Verbose: 0 : [12488] 00000000 : 48 54 54 50 2F 31 2E 31-20 31 30 30 20 43 6F 6E : HTTP/1.1 100 Con

System.Net.Sockets Verbose: 0 : [12488] 00000010 : 74 69 6E 75 65 0D 0A 0D-0A : tinue....

생성된 로그들은 SvcTraceViewer를 통해서 파싱후 각메시지별 이나 전체 흐름의 관점에서 확인 할 수 있습니다.

Service Trace Viewer Tool (SvcTraceViewer.exe)

https://msdn2.microsoft.com/en-us/library/ms732023.aspx