Correlate MSMQ End-to-End trace with WCF Trace and application level logging

Question

Background:

I'm troubleshooting a problem where messages sent by WCF over transactional MSMQ (with netMsmqBinding) seem to disappear. The code that uses WCF is in a third-party assembly which I cannot change. I have few clues to what the problem is, but plan to enable various tracing capabilities in order to pin-point where the problem relies.

Context:

1. I have enabled MSMQ End-to-End Tracing. It logs two events for every message that gets sent.

   • One event when a message is written to the outgoing queue. This message contain the MSMQ message id (which is composed by a guid and an integer, ie 7B476ADF-DEFD-49F2-AF5A-0CF27C5152C0\6481271).
   • Another event when that message is sent across the network.

2. I have enabled verbose WCF Tracing.

3. I also have application level logging that logs a message IDs defined by the application code (let's call this the "application message id").

4. I have enabled positive and negative source journaling on the MSMQ messages that get sent.

5. I have enabled journaling on the receiving queue.

Problem:

When messages go missing, I know the missing message's application id (it's logged by the sending side). I would now like to look at the End-to-End trace to see whether the message was written to the outgoing queue or not.

How can I correlate the events in the End-to-End trace with the application level logs and WCF traces?

Ideas:

• When sending a MSMQ message using the managed MSMQ API in System.Messaging, the message's MSMQ id is available after the message is sent. However, I have not found a way to log this when WCF is performing the send operation. The WCF trace logs a MSMQMessageId guid, but this value is, surprisingly, not the actual MSMQ id as I guessed it would be. Is it possible to access the actual MSMQ message id and log it?

• Log the native thread id in the application log along with the application level id and a time stamp. The native thread id is logged to the End-to-End trace by MSMQ, so this might actually be sufficient to correlate. This is plan B for me if I don't find a more elegant solution.

Jordanson

Did you check the Dead-Letter queue? – Crabby

Yes I did. It was empty. – Jordanson

I like using perfmon to help track the lifetime of a message. Queue counters, system counters, etc. Should be able to see various outgoing and destination queue go up and down as messages flow through them. How many messages go missing? – Zajac

A few messages every now and then are "lost". Are you able to figure out what happened to specific messages with perfmon? – Jordanson

Answer 1

You sounds like you're on the right track. However you could bump up a bit with this:

Using SvcConfigEditor.exe

1. Configure WCF Verbose Tracing for Propagate ACtiveity and Activity tracing
2. Configure WCF MessageLogging for "Malformed Messages, Service Messages, Transport Messages"

Use LogEntireMessage

In End to End, trace it All

Make sure you enable these *.config on BOTH sides, yours and the 3rd party executable.

Collect your logs files, and add them ALL to SvcTraceViewer.exe

Electrolyte

Answer 2

You can configure windows MSMQ to sense subjects of messages and if subjects contains a key word fire an application. This application can logs incoming messages. In sender side you can write actual message id into subject of message and add your key word to subject. In receiver side fired application can access to actual message id near added key word in subject.

Carreon

Answer 3

It looks like your message is being discarded by WCF because it is malformed in some way (i.e. contract mismatch, one of the WCF message size limits exceeded).

To trap this error you could write an ErrorHanlder that audits these errors. Here a link to a sample of doing that.

Another option ,if you are using Win 2008 R2 and up, is to use the built in poison message handling. here`s a link to the the docs.

To the question, to trace end to end with an application trace identifier: I would pass the application trace id in the message header (look here for an example).

To audit the message header on the service side i would use WCF's IOperationInvoker to intercept each call, and audit the id in the messaged header.

This can be configured in the config file for the process without altering the third party code.here`s an example of how to implement an invoker and how to set it in config.

Alishiaalisia

Answer 4

I am also troubleshooting net.msmq MsmqActivation WCF based communication right now, and I also saw some lost messages.

• I increased maxReceivedMessageSize setting before, but it didn't help fully. The messages were sent and they were received by the w3wp.exe MSMQ WCF service (.svc) code.
• I therefore created a client -> service (hosted in IIS) test repro to create 1-n messages of 1-n size with configurable custom tracing and message dumping, and there I saw that it happened for messages over 1MB in size.

What I did was to "trace" with ProcDump memory dump tool. It is a really nice tool to do error tracing with. I check the PID# of the w3wp (appcmd list wp) and then I attach to the PID# with this command :

procdump.exe -ma -e 1 -f "" PID# >> C:\temp\%computername%-procdumplog.txt

Then I saw an unhandled error related to exceeded WCF string size.

:::

[15:13:31] Exception: E0434F4D.System.Xml.XmlException ("The maximum string content length quota (1048576) has been exceeded while reading XML data. This quota may be increased by changing the MaxStringContentLength property on the XmlDictionaryReaderQuotas object used when creating the XML reader.")

[15:13:31] Exception: E0434F4D.System.ServiceModel.Dispatcher.NetDispatcherFaultException ("The formatter threw an exception while trying to deserialize the message: Error in deserializing body of request message for operation 'Process'. The maximum string content length quota (1048576) has been exceeded while reading XML data. This quota may be increased by changing the MaxStringContentLength property on the XmlDictionaryReaderQuotas object used when creating the XML reader.")

:::

<binding name="msmqNoTx" exactlyOnce="false" useActiveDirectory="true" maxBufferPoolSize="10485760" maxReceivedMessageSize="41943040" queueTransferProtocol="Native">
    <readerQuotas maxDepth="32" maxStringContentLength="10485760" maxArrayLength="10485760" maxBytesPerRead="10485760" maxNameTableCharCount="10485760" />
    <security mode="None">
        <!--<transport msmqAuthenticationMode="None" msmqProtectionLevel="None"/>-->
    </security>
</binding>

So maxReceivedMessageSize="4194304" and maxStringContentLength="4194304" may be what is needed in other cases as well.

Since both HTTP and net.msmq add more headers to the messages, the 4194304 limit should be 200 KB (or less) more than the actual message size, so I would recommend to check the message sizes on the sender, and make sure it is less than e.g. 3800000.

The extra headers' sizes may depend on e.g. computer name sizes and on whether certain msmqm properties are set or not, so there is no exact size for the added headers that is known ahead of time.

Orleanist