Isolating defect in distributed event-driven system

Question

Our system takes an object from external system every time the object gets changed (change event), processes it and put it back processed into this external system. So, end-to-end testing is about making a change to an object on one end and watching the result on the other end. If there is a defect, it might be in our system or in other components with which we interact. Before the message arrives to our system, it goes through a number of queues, queue bridges, and a legacy system. After it is processed it is sent to a chain of Web services that perform additional processing.

Once I find a defect, I start isolating it. Gathering all information is hard because of three issues we have:

• Distributed components, distributed logs. I record input test data, actual test output and then all intermediate queues messages, and Web service requests/responses. I take them from components' log files. Since messages are distributed between multiple components and machines, I work with an "airplane cockpit" of three LCD monitors: three SSH consoles open and tools for monitoring remote queues.

• Parallel conversations. The whole our platform can process a number of messages concurrently, and end-to-end testing environment is shared between many testers so I must instantly monitor what’s going on with my message in the chain. I must not confuse my message with messages of other testers.

• Complex interaction protocols. Interaction protocols between some components are more complex: they include multiple request/response cycles with conditional branches. I must put messages related to a single event in a sequence, to understand what happened after what.

So how do you handle such problems?

Share with me or, if you have patience to read more, comment on my solutions ideas.

Solution ideas

• Getting messages in one place. All components (excluding legacy ones) use Apache log4j for logging messages. It is possible to configure log4j on all machines to sent log entries to a log viewer (e.g., Apache Chainsaw) on a tester's machine. The limitation is that this solution will not monitor messages that were put by external system on queues, but have not been read by our system yet.

• Identifying messages for a single event. An event in our system is a single object change. Each event triggers a conversation in our system thus each conversation can be uniquely identified (e.g., by id of a changed object and the time of change). Including the conversation id in log entries makes filtering/grouping messages by conversation easier. This worked for my small academic project, but might be harder for large system we have here, correct?

• Ordering messages in a sequence. JADE framework provides a sniffer that can "sniff" ongoing conversations and draw a sequence diagram (see image below). This worked for components that used the same framework to communicate each other, but our components are heterogeneous (queues, Web services) and use different transport protocols (e.g. HTTP). Is there a tool that can sniff and record such conversations?

Answer 1

I have worked on a few projects that seem very similar from the description you provide.

One thing that works well that we are doing pretty much everywhere at my current company is storing information about each conversation in a database for the sole purpose of debugging and testing. This approach did take a little more upfront development cost, and some additional maintenance/server costs, but it pays off big in terms of additional insight for QA, ops and support. Each of the 3 departments use the data there for tracking and debugging issues with these "conversations". Finding information about a particular conversation is as easy as executing a query, and we have tools on top of this data, notably operations uses some queries to determine the state of various services. It is invaluable and easy to add additional information if we end up needing it.

In past projects where I did not have such a good infrastructure in place, it definitely was more of a challenge. We tried to add some additional logging, but it was still a difficult process of looking through logs from multiple locations and correlating the data from those different locations into a "conversation". One team I was on did have some success building a custom log parser that parsed logs from various locations and populated a database with information from those various logs, however the ROI from that effort was not nearly as high as my current projects because we were mining this data after the fact instead of building the analytics into our system.

It may be impractical or impossible, but if it is possible, I would highly suggest engaging your development team with the task of better logging and analytics.

Answer 2

This is a common problem for software that spans services across multiple machines. I think you are on the right track.

Each of your three solutions addresses a different part of the problem. The conversation ID is the enabler; the other two parts just make things easier. You will need a way to generate conversation IDs that does not create a synchronization bottleneck.

Inter-machine clock skew can complicate correlating log entries harder if the ordering of operations is non-deterministic. I have seen several seconds worth of clock skew between Amazon EC2 instances.

If this approach breaks down anywhere, I suspect it will be when you put your system under heavy load. You may want to check whether Chainsaw and JADE will scale to your needs. If you are trying to load-test your system, you may also want to watch out for "Heisenberg effects" caused Chainsaw and any other instrumentation software.