E
Empty Trace is another trivial missing pattern that we need to add to make the software log analysis pattern system complete. It ranges from an empty trace message list where only a meta-trace header (if any) describing overall trace structure is present to a few messages where we expect thousands. It is also an extreme case of Truncated Trace, No Activity and Missing Component patterns for a trace taken as a whole. Note that an empty trace file does not necessarily have a zero file size because a tracing architecture may preallocate some file space for block data writing.
Some trace and log messages may have different grammatical structure and content but similar semantics. Therefore, we can create a table listing equivalent messages (using some equivalence relation50) and use it to construct simpler traces and logs as depicted in this picture:
One trivial example of Equivalent Messages analysis pattern is Quotient Trace. Another example is Inter-Correlational analysis of logs that have different structure and format. In such a case Equivalent Messages simplify the analysis of higher Trace Dimensions.
Sometimes we need to pay attention to Error Distribution, for example, the distribution of the same error across a software log space or different Error Messages in different parts of the same software log or trace (providing effective partition):
While working on Accelerated Windows Software Trace Analysis training,51 we discovered some missing patterns needed for completeness despite their triviality. One of them is called Error Message. Here an error is reported either explicitly (“operation failed”) or implicitly as an operation status result such as 0xC00000XX. Sometimes, a trace message designer specifies that the number value is supplied for information only and should be ignored. Some Error Messages may contain information that is not relevant to the current software incident, the so-called False Positive Errors. Some tracing architectures and tools include message information category for errors, such as Citrix CDF, where we can filter by error category52 to get Adjoint Thread. Please note that the association of a trace statement with an error category is left to the discretion of an engineer writing code. Also, information category messages may contain implicit errors such as the last error and return status reports.
Typical software trace may contain several Error Messages with different error codes and different exception names with Exception Stack Traces. Searching for individual codes or exceptions in problem databases may show many matches. Searching for all of them may show nothing. Therefore, we can construct the set of all subsets of the set of codes and exceptions (a power set53) and perform analytic reasoning (and a search) based on certain subsets based on the problem description, Trace Viewpoints such as Use Case Trails, Motifs, Focus of Tracing, Foreground Components, (Adjoint) Threads of Activity, and simply some Activity Regions and Message Sets.
The following picture illustrates Error Powerset analysis pattern with a trace that has 4 error messages where two messages have the same error code.
When we see Error Message or Exception Stack Trace in a log file, we might want to explore the sequence of messages from the same Thread of Activity that led to the error. Such Message Set has an analogy with memory analysis patterns such as Execution Residue (of partial stack traces without overwrites54) and Stack Trace (where the error message is a top stack frame55):
In any system, this pattern is expected as a precondition to its normal behavior. Any out-of-order events should raise the suspicion bar as they might result or lead to synchronization problems. It needs not to be a sequence of trace messages from different threads but also between processes. For example, image load events in CDF / ETW traces can indicate the wrong configuration of a service startup order. The following diagram depicts a possible pattern scenario:
Sometimes we have several use case instances traced into one log file. Messages and Activity Regions from many Use Case Trails intermingle and make analysis difficult especially with the absence of UCID (Use Case ID), any other identification tags, or Linked Messages. However, initially, most of the time, we are interested in a sequence of Significant Events. After finding Anchor Messages, we can use Time Deltas to differentiate between trace statements from different Use Case Trails. Here we assume the correct Event Sequence Order. We call this pattern Event Sequence Phase by analogy with wave phases56. All such individual “waves” may have different “shapes” due to various delays between different stages of their use case and implementation narratives:
In the picture above, we also identified Dominant Event Sequence for use case instance C.
Often the analysis of software traces starts with searching for short textual patterns, like a failure or an exception code or simply the word “exception.” Also, some software components can record their own exceptions or exceptions that were propagated to them, including full stack traces. It is all common in .NET and Java environments. Here is a synthetic and beautified example based on real software traces:
N PID TID Message
[...]
265799 8984 4216 ComponentA.Store.GetData threw exception: ‘System.Reflection.TargetInvocationException: DCOM connection to server failed with error: ‘Exception from HRESULT: 0×842D0001′ —> System.Runtime.InteropServices.COMException (0×842D0001): Exception from HRESULT: 0×842D0001
at ComponentA.GetData(Byte[] pKey)
at System.RuntimeMethodHandle._InvokeMethodFast(Object target, Object[] arguments, SignatureStruct& sig, MethodAttributes methodAttributes, RuntimeTypeHandle typeOwner)
at System.RuntimeMethodHandle.InvokeMethodFast(Object target, Object[] arguments, Signature sig, MethodAttributes methodAttributes, RuntimeTypeHandle typeOwner)
at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture, Boolean skipVisibilityChecks)
at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)
at ComponentB.Connections.ComInterfaceProxy.Invoke(IMessage message)’
265800 8984 4216 === Begin Exception Dump ===
265801 8984 4216 ComponentB.Exceptions.ConnectionException: DCOM connection to server failed with error: ‘Exception from HRESULT: 0×842D0001′ —> System.Runtime.InteropServices.COMException (0×842D0001): Exception from HRESULT: 0×842D0001
265802 8984 4216 at ComponentA.Store.GetData(Byte[] pKey)
[...]
265808 8984 4216 Exception rethrown at [0]:
265809 8984 4216 at System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg)
265810 8984 4216 at System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type)
265811 8984 4216 at ComponentA.Store.GetData(Byte[] pKey)
265812 8984 4216 at ComponentA.App.EnumBusinessObjects()
[...]
265816 8984 4216 ===> InnerException:
265817 8984 4216 ** COM Exception Error Code: 0×842d0001
265818 8984 4216 System.Runtime.InteropServices.COMException (0×842D0001): Exception from HRESULT: 0×842D0001
265819 8984 4216 at ComponentA.Store.GetData(Byte[] pKey)
265820 8984 4216 === End Exception Dump ===
[...]
In the embedded stack trace, we see that App object was trying to enumerate business objects and asked Store object to get some data. The latter object was probably trying to communicate with the real data store via DCOM. The communication attempt failed with HRESULT.
In the previous pattern example, a stack trace was inside a single trace message but can also be split such as each frame has its own message (date and time columns were removed for clarity):
E/AndroidRuntime(31416): java.lang.NullPointerException
E/AndroidRuntime(31416): at android.view.MotionEvent.writeToParcel(MotionEvent.java:1596)
E/AndroidRuntime(31416): at com.example.nullpointer.FullscreenActivity$1.onTouch(FullscreenActivity.java:139)
E/AndroidRuntime(31416): at android.view.View.dispatchTouchEvent(View.java:3881)
E/AndroidRuntime(31416): at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:869)
E/AndroidRuntime(31416): at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:869)
E/AndroidRuntime(31416): at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:869)
E/AndroidRuntime(31416): at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:869)
E/AndroidRuntime(31416): at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:869)
E/AndroidRuntime(31416): at com.android.internal.policy.impl.PhoneWindow$DecorView. superDispatchTouchEvent(PhoneWindow.java:1750)
E/AndroidRuntime(31416): at com.android.internal.policy.impl.PhoneWindow. superDispatchTouchEvent(PhoneWindow.java:1135)
E/AndroidRuntime(31416): at android.app.Activity.dispatchTouchEvent(Activity.java:2096)
E/AndroidRuntime(31416): at com.android.internal.policy.impl.PhoneWindow$DecorView. dispatchTouchEvent(PhoneWindow.java:1734)
E/AndroidRuntime(31416): at android.view.ViewRoot.deliverPointerEvent(ViewRoot.java:2216)
E/AndroidRuntime(31416): at android.view.ViewRoot.handleMessage(ViewRoot.java:1887)
E/AndroidRuntime(31416): at android.os.Handler.dispatchMessage(Handler.java:99)
E/AndroidRuntime(31416): at android.os.Looper.loop(Looper.java:130)
E/AndroidRuntime(31416): at android.app.ActivityThread.main(ActivityThread.java:3687)
E/AndroidRuntime(31416): at java.lang.reflect.Method.invokeNative(Native Method)
E/AndroidRuntime(31416): at java.lang.reflect.Method.invoke(Method.java:507)
E/AndroidRuntime(31416): at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:867)
E/AndroidRuntime(31416): at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:625)
E/AndroidRuntime(31416): at dalvik.system.NativeStart.main(Native Method)