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

37
votes

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.

3
wcfmsmq
Did you check the Dead-Letter queue? – Petar Vučetin
Yes I did. It was empty. – Lars Andreas Ek
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? – John Breakwell
A few messages every now and then are "lost". Are you able to figure out what happened to specific messages with perfmon? – Lars Andreas Ek

3 Answers

1
votes

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"

WCF 1

Use LogEntireMessage

WCF 3

In End to End, trace it All WCF 2

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

0
votes

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.

0
votes

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.