Home » Eclipse Projects » Eclipse Titan » Logging in Eclipse Titan part I : Configuration
| Logging in Eclipse Titan part I : Configuration [message #1720372] |
Mon, 18 January 2016 09:20  |
|
During execution, details of this execution can be saved for later analysis. By default, Titan offers two channels for this: the console log and the log files. The console log, although it can receive all kinds of details, due to its' volatile nature is typically being used as a superficial feedback: the operator can see that some text is flowing on the display, hence the software is still running. Log files produced by Titan can be stored, post-processed for analytics etc.
Logging being a resource-consuming exercise both during logging and post-processing, it always calls for a compromise: the first instinct is to have everything logged, but that slows down execution and it becomes increasingly difficult to filter out the non-essential information.
In this article we will look into how the logging should be configured in general, and how to extract exactly the kind of information we are after in special.
Configuration of logging is done in the run-time configuration file where a separate section [LOGGING] is reserved for that. Chapter 7.2 of the reference guide describes in detail this section and the parameters to be used here.
The first such parameter to be considered is LogFile; the name of this parameter might be misleading as Titan expects not a file name but rather instructions regarding how the name of the log file/files should be assembled. This name can contain all kinds of information about the environment such as hostname, user login name etc. A typical beginner's mistake here is to set a file name , and this does not work well, especially when executing in multi-component mode as Titan will try to push information from all components into this log: several processes will start to compete for grabbing the log file and writing into it and the result usually is that information is getting lost.
My recommendation is that, maybe surprisingly, one should remove this parameter and let Titan figure it out; power users can play with meta-characters in Table 12 of the refguide.
An easy-to-be neglected but absolutely essential parameter is SourceInfoFormat; this controls the appearance of the location information (TTCN-3 file name:line number) in the log file. Compare the below two snippets:
[LOGGING]
SourceInfoFormat := None
08:33:05.673518 Port IPL4_PCO was mapped to system:IPL4_PCO.
08:33:05.673750 Map operation of 3:IPL4_PCO to system:IPL4_PCO finished.
08:33:05.674591 Message enqueued on IPL4_PCO from system @IPL4asp_Types.ASP_RecvFrom : { connId := 1, remName := "127.0.0.1", remPort := 35000, locName := "127.0.0.1", locPort := 25000, proto := { udp := { } }, userData := 0, msg := '301802010004067075626C6963A00B0201050201010201013000'O } id 1
08:33:05.674698 Matching on port IPL4_PCO succeeded: matched
[LOGGING]
SourceInfoFormat := Single
08:34:11.726017 SNMP_Test.ttcn:79 Port IPL4_PCO was mapped to system:IPL4_PCO.
08:34:11.726273 SNMP_Test.ttcn:79 Map operation of 3:IPL4_PCO to system:IPL4_PCO finished.
08:34:11.727115 SNMP_Test.ttcn:90 Message enqueued on IPL4_PCO from system @IPL4asp_Types.ASP_RecvFrom : { connId := 1, remName := "127.0.0.1", remPort := 35000, locName := "127.0.0.1", locPort := 25000, proto := { udp := { } }, userData := 0, msg := '301802010004067075626C6963A00B0201050201010201013000'O } id 1
08:34:11.727224 SNMP_Test.ttcn:92 Matching on port IPL4_PCO succeeded: matched
With this parameter appropriately set one can follow execution against the TTCN-3 code. The location information has to be generated into the C++ code, which assumes that the code was compiled with the -L flag present into the Makefile. This flag is generated by default by the makefilegen utility.
Events are classified into categories (and subcategories) which can be used to control (via the FileMask and ConsoleMask parameters) what should be logged into the log files or onto the console. Table 13 to 24 contain the list and description of categories and subcategories.
FileMask := LOG_NOTHING switches off the log;
FileMask := LOG_ALL logs (almost ) every category, except MATCHING and DEBUG.
Test ports are often generating events that are visible only when DEBUG is set.
The category USER covers user-defined log() statements in the TTCN-3 code.
If FileMask or ConsoleMask are not set, defaults are assumed (as for all the other parameters as well).
FileMask and ConsoleMask can be set individually for components; e.g.
[LOGGING]
mtc.FileMask := LOG_NOTHING
will switch off logging for MTC only.
[LOGGING]
LogEventTypes := Yes
will include the event categories next to the events:
08:59:21.889244 PORTEVENT SNMP_Test.ttcn:79 Port IPL4_PCO was mapped to system:IPL4_PCO.
08:59:21.889335 PARALLEL SNMP_Test.ttcn:79 Map operation of 3:IPL4_PCO to system:IPL4_PCO finished.
08:59:21.889930 PORTEVENT SNMP_Test.ttcn:90 Message enqueued on IPL4_PCO from system @IPL4asp_Types.ASP_RecvFrom : { connId := 1, remName := "127.0.0.1", remPort := 35000, locName := "127.0.0.1", locPort := 25000, proto := { udp := { } }, userData := 0, msg := '301802010004067075626C6963A00B0201050201010201013000'O } id 1
08:59:21.889979 MATCHING SNMP_Test.ttcn:92 Matching on port IPL4_PCO succeeded: matched
while
[LOGGING]
LogEventTypes := Subcategories
extends this to subcategories:
09:00:25.691722 PARALLEL_UNQUALIFIED SNMP_Test.ttcn:79 Mapping port 3:IPL4_PCO to system:IPL4_PCO.
09:00:25.691877 PORTEVENT_UNQUALIFIED SNMP_Test.ttcn:79 Port IPL4_PCO was mapped to system:IPL4_PCO.
09:00:25.692074 PARALLEL_PORTMAP SNMP_Test.ttcn:79 Map operation of 3:IPL4_PCO to system:IPL4_PCO finished.
09:00:25.692838 PORTEVENT_MQUEUE SNMP_Test.ttcn:90 Message enqueued on IPL4_PCO from system @IPL4asp_Types.ASP_RecvFrom : { connId := 1, remName := "127.0.0.1", remPort := 35000, locName := "127.0.0.1", locPort := 25000, proto := { udp := { } }, userData := 0, msg := '301802010004067075626C6963A00B0201050201010201013000'O } id 1
09:00:25.692947 MATCHING_MMSUCCESS SNMP_Test.ttcn:92 Matching on port IPL4_PCO succeeded: matched
[LOGGING]
LogEntityName := Yes
will add function, testcase, altstep, control part names to the log:
09:04:03.892432 SNMP_Test.ttcn:79(function:f_echo) Mapping port 3:IPL4_PCO to system:IPL4_PCO.
09:04:03.892595 SNMP_Test.ttcn:79(function:f_echo) Port IPL4_PCO was mapped to system:IPL4_PCO.
09:04:03.892762 SNMP_Test.ttcn:79(function:f_echo) Map operation of 3:IPL4_PCO to system:IPL4_PCO finished.
09:04:03.893519 SNMP_Test.ttcn:90(function:f_echo) Message enqueued on IPL4_PCO from system @IPL4asp_Types.ASP_RecvFrom : { connId := 1, remName := "127.0.0.1", remPort := 35000, locName := "127.0.0.1", locPort := 25000, proto := { udp := { } }, userData := 0, msg := '301802010004067075626C6963A00B0201050201010201013000'O } id 1
09:04:03.893633 SNMP_Test.ttcn:92(function:f_echo) Matching on port IPL4_PCO succeeded: matched
TimeStampFormat, ConsoleTimeStampFormat are self-explanatory.
MatchingHints controls the amount and format of log messages
describing template matching failures. These are written during port receive
operations as logging category MATCHING (so only if MATCHING flag is set), and as a response to TTCN-3
log(match(...)) statements as logging category USER.
An example for MatchingHints := DETAILED :
{
{
field_rr1 := 1,
field_rr2 := 2
},
{
field_rr1 := 3,
field_rr2 := 4
}
} with {
{
field_rr1 := 1,
field_rr2 := 2
},
{
field_rr1 := 3,
field_rr2 := 5
}
} unmatched Some hints to find the reason of mismatch:
value elements that have no pairs in the template:
field_rr1 := 3,
field_rr2 := 4
} at index 1,
template elements that have no pairs in the value:
field_rr1 := 3,
field_rr2 := 5
} at index 1,
matching value <-> template index pairs: {
0 <-> 0
},
matching unmatched value <-> template index pairs:
1 <-> 1: {
{
field_rr1 := 3 with 3 matched,
field_rr2 := 4 with 5 unmatched
}
}
}
}
DiskFullAction determines TITAN behavior when writing to the log file fails. Options are: Stop (stop logging, continue test execution), Retry ( continue test execution, re-attempt logging periodically), Delete (continue execution, try to delete some logs).
The default behavior is Error. With this setting, writing error causes a
runtime (dynamic) test case error.
An interesting parameter is EmergencyLogging; let's assume you have a performance test running for a number of days; you switch off all logs as you need maximum performance, but then something happens at the end of the third day: due to a coding fault,
a dynamic test case error is thrown, your test stops and all the information regarding the fault is lost. Total disaster, right?
This is exactly the situation when EmergencyLogging comes to rescue: if activated, log events are stored into a ring buffer which is only dumped into a log file in case of situations Titan interprets as emergencies.
The value of the EmergencyLogging option is the ring buffer size (the
number of log events that are kept). The default value is zero, which turns off
the emergency logging feature.
EmergencyLoggingBehaviour defines whether all or only selected ( by the EmergencyLoggingMask) messages should be buffered.
Titan currently does not have a debugger (we are working on it, but no ETA yet); but due its' versatility and controlled granularity, the logging system, possibly combined with log() statements, was successfully used instead during its' years of industrial practice.
Next we will examine the log-processing command line utilities offered by Titan.
Best regards
Elemer
|
|
|
| Re: Logging in Eclipse Titan part I : Configuration [message #1720573 is a reply to message #1720372] |
Tue, 19 January 2016 12:37  |
|
great article Elemer.
I would like to leave here my preferred logs configuration.
For running my tests I use these settings - they give me info on what is happening in the MTC without giving me too much info if there are any PTCs running:
[LOGGING]
LogFile := "%e.%r.%s"
MatchingHints := Compact
LogEntityName := Yes
LogEventTypes := Yes
mtc.ConsoleMask := VERDICTOP|USER|EXECUTOR|TESTCASE|WARNING|ERROR
*.FileMask :=WARNING|VERDICTOP|TIMEROP|STATISTICS|PORTEVENT|EXECUTOR|ERROR|DEFAULTOP|ACTION|PARALLEL|FUNCTION|USER|TESTCASE|DEBUG;
SourceInfoFormat := Single
TimeStampFormat := DateTime
Now, if I am troubleshooting a specific failure in my ttcn code, I enhance the logging by printing the function calls stack (by changing SourceInfoFormat to Stack) like this:
[LOGGING]
LogFile := "%e.%r.%s"
MatchingHints := Compact
LogEntityName := Yes
LogEventTypes := Yes
mtc.ConsoleMask := VERDICTOP|USER|EXECUTOR|TESTCASE|WARNING|ERROR
*.FileMask :=WARNING|VERDICTOP|TIMEROP|STATISTICS|PORTEVENT|EXECUTOR|ERROR|DEFAULTOP|ACTION|PARALLEL|FUNCTION|USER|TESTCASE|DEBUG;
SourceInfoFormat := Stack
TimeStampFormat := DateTime
Running tests in a suite? I don't need so many logs (and I want a clean console in Jenkins for instance), so I log only TESTCASE and STATISTICS to the console, and everything else to the log file:
[LOGGING]
LogFile := "%e.%r.%s"
MatchingHints := Compact
LogEntityName := Yes
LogEventTypes := Yes
ConsoleMask := TESTCASE | STATISTICS
*.FileMask :=WARNING|VERDICTOP|TIMEROP|STATISTICS|PORTEVENT|EXECUTOR|ERROR|DEFAULTOP|ACTION|PARALLEL|FUNCTION|USER|TESTCASE|DEBUG;
SourceInfoFormat := Single
TimeStampFormat := DateTime
thank you
Gustavo.
[Updated on: Fri, 08 July 2016 11:57] Report message to a moderator |
|
| |
Goto Forum:
Current Time: Fri Apr 19 10:51:32 GMT 2024
Powered by FUDForum. Page generated in 0.01754 seconds |
] 
Search
Help
Register
Login
Home
