Skip to main content


Eclipse Community Forums
Forum Search:

Search      Help    Register    Login    Home
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 Go to next message
Elemer Lelik is currently offline Elemer LelikFriend
Messages: 1120
Registered: January 2015
Senior Member
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 Go to previous messageGo to next message
Gustavo Gonnet is currently offline Gustavo GonnetFriend
Messages: 35
Registered: October 2015
Location: Montreal, Quebec, Canada
Member
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

Re: Logging in Eclipse Titan part I : Configuration [message #1720574 is a reply to message #1720573] Tue, 19 January 2016 12:57 Go to previous message
Elemer Lelik is currently offline Elemer LelikFriend
Messages: 1120
Registered: January 2015
Senior Member
This is a good addition, Gustavo,

Thank you.
Previous Topic:Encoding TTCN type
Next Topic:Logging in Eclipse Titan part II: Postprocessing utilities
Goto Forum:
  


Current Time: Tue Aug 03 01:57:42 GMT 2021

Powered by FUDForum. Page generated in 0.02047 seconds
.:: Contact :: Home ::.

Powered by: FUDforum 3.0.2.
Copyright ©2001-2010 FUDforum Bulletin Board Software

Back to the top