The Test Log collects the operational messages generated by the TAS and the test servers from the time a test session is started until it is complete. Test Log collects the messages related to the control of the test session and test cases, as well messages from the Test Servers specific to the testing. The Test Log is provided in the Test Results as the log.txt file, e.g. 23-03-30_16.13.03__RID-1__Single_TC1.log.txt. The Test Log (Run Log) differs from the Real-Time Logs (System Logs), which are not focused on individual Test Sessions. The Real-Time Logs collect system-level actions and some session-level messages and is not associated with Test Sessions.
The Logs tab... is added to the Test Session window and displayed when you click Run. You can monitor the test's progress as the messages are added to the log. These messages include:
The test control messages sent from the TAS to the test servers
The actions performed by each test case as it transitions from the Started to the Running state and from Running to Stopped as reported by the test server
Test session state changes as reported by the TAS
System and test session errors and warnings
Results of periodic queries sent to a SUT
While the test session is running, two logs are available in the Logs tab that display the messages generated while you are connected to the test session: Current Logs tab and the Log History tab.
| Current Logs | Displays only the most recent 200 messages, and the Log History tab contains the messages not displayed in Current Logs. |
| Log History | Available even after the test is complete, and it then displays all messages collected throughout the duration of the test. If you reconnect to a disconnected session, you can retrieve the entire test log, which is then displayed on the TAS Logs tab. |
|
Errors/Warnings |
Available when running of a test, if the TAS or TS reports errors or warnings. See Test Server CPU Utilization Reporting below for additional details when test sessions print test server High CPU Utilization Warnings in the Logs tab of the test sessiors. |
When the test is complete, the Test Log is automatically saved on the TAS and you can view or download it at any time.
Test Log messages are color-coded to indicate whether the message contains informational (white), warning, (yellow), or error (orange) data. The messages follow a common format:
|
Prefix String Provided inside the end of test log.txt file, to indicate the log type. |
log - Informational level log. Example : log: 04/02 15:53:53.909:ts0(Coast70):p2(2)::tc6: Begin Test Case
warning – Warning level log. Example : warning: 04/02 16:24:08.505:TS(Coast70[1]): The Test Server status indicates the test stopped running and is now ready
|
| Time stamp |
month, day, hour, minute, second, millisecond, converted to the test system's local time zone. Format MM/dd HH:mm:ss.SSS, e.g. 03/31 13:41:01.257 |
| The message source |
TAS e.g. 03/31 13:41:01.257:TAS:ts1(CI092) eth2 capturing started or e.g. 04/02 15:54:16.387:ts0(Coast70):p3(3)::tc11: ERROR: Requested connect rate (3000.00) is too high |
| Message text | Begin Test Case, State=INITIALIZING, State=INITIALIZED, STARTED, etc. |
|
NOTE: The message queue from the TAS to the Client for a given test session is reported as Session-to-client message queue. These messages are informational and sometimes may be dropped to allow the higher priority messages (progress, state, measurements) to get through/to be reported. The logs are only dropped from being sent to the Client, but they are stored on the TAS. You may retrieve the complete TAS Run Log, via Logs->Get TAS Log, or wait till the test is over and Retrieve-All-Results. The Session-to-client message queue is full, log message (s) from TAS to Client will be dropped indicates one or more of the following:
When the blockage clears up, you should get a message, Queue is nominal, N log message from TAS to Client lost to indicate how many logs were dropped. |
|
TS_INDEX_IN_TEST |
Index of the Test Server within the Test Session configuration |
|
TS_NAME |
Name of the test server |
|
TS_PROCESS_INDEX |
Index of the Test Server Process within the Test Server |
|
TEST_PROCESS_INDEX |
Index of the Test Server Process within the Test Session |
|
TS_INDEX_IN_TEST |
Index of the Test Server within the Test Session configuration |
|
TS_PROCESS_INDEX |
May be 0, 1, 2, the actual process on the TS that the test case is running on. |
|
TEST_PROCESS_INDEX |
May be 0, 1, 2, the relative index of the process within the test session’s process indexes. For example if three test session are running on a test server, each on their own process, the logs would look like this:
log: 02/06 11:03:51.892:ts1(Coast88):p0(0):tc0: State=INITIALIZING
log: 02/06 11:03:51.892:ts1(Coast88):p1(0):tc0: State=INITIALIZING
log: 02/06 11:03:51.892:ts1(Coast88):p2(0):tc0: State=INITIALIZING |
Example: For Command Sequencer
|
Test Case Sub-state indicates Current Command indexTest Case Sub-state indicates Current Command index (For Command Sequencer) log: 07/02 15:20:41.711:ts1(Coast45 10.8.45.1):p0(0):tc0: State=STARTED tc_state: TS[0] TC[0] -> RUNNING log: 07/02 15:20:41.766:ts0(Coast44 10.8.44.1):p0(0):tc0: State=RUNNING tc_state: TS[1] TC[0] -> RUNNING log: 07/02 15:20:41.754:TAS: Switching to step RUNNING log: 07/02 15:20:41.711:ts1(Coast45 10.8.45.1):p0(0):tc0: State=RUNNING test_state:RUNNING:07/02 15:20:41.754:RUNNING test_progress: 100:Running indefinitely, stop test manually log: 07/02 15:20:42.766:ts0(Coast44 10.8.44.1):p0(0):tc0: MME/PGW Nodes connected: true log: 07/02 15:20:42.766:ts0(Coast44 10.8.44.1):p0(0):tc0: Starting GTP Protocol... tc_state: TS[0] TC[0] -> RUNNING log: 07/02 15:20:42.766:ts0(Coast44 10.8.44.1):p0(0):tc0: State=RUNNING log: 07/02 15:20:42.766:ts0(Coast44 10.8.44.1):p0(0):tc0: Executing Command Sequencer... tc_state: TS[0] TC[0] -> RUNNING:0#0 log: 07/02 15:20:42.766:ts0(Coast44 10.8.44.1):p0(0):tc0: State=RUNNING:0#0 log: 07/02 15:20:42.766:ts0(Coast44 10.8.44.1):p0(0):tc0: Executing Command 0 log: 07/02 15:20:42.766:ts0(Coast44 10.8.44.1):p0(0):tc0: onDemandCommand { ControlBearer { "Attach" "100.0" "1" "10" } } log: 07/02 15:20:42.767:ts0(Coast44 10.8.44.1):p0(0):tc0: Starting Attach ... log: 07/02 15:20:42.867:ts0(Coast44 10.8.44.1):p0(0):tc0: Attach done ... log: 07/02 15:20:42.867:ts0(Coast44 10.8.44.1):p0(0):tc0: Getting the next command... tc_state: TS[0] TC[0] -> RUNNING:1#1 log: 07/02 15:20:42.867:ts0(Coast44 10.8.44.1):p0(0):tc0: State=RUNNING:1#1 log: 07/02 15:20:42.867:ts0(Coast44 10.8.44.1):p0(0):tc0: Executing Command 1 log: 07/02 15:20:42.867:ts0(Coast44 10.8.44.1):p0(0):tc0: Delaying 5 seconds tc_state: TS[0] TC[0] -> RUNNING:2#2 log: 07/02 15:20:47.867:ts0(Coast44 10.8.44.1):p0(0):tc0: State=RUNNING:2#2 log: 07/02 15:20:47.867:ts0(Coast44 10.8.44.1):p0(0):tc0: Executing Command 2 log: 07/02 15:20:47.867:ts0(Coast44 10.8.44.1):p0(0):tc0: onDemandCommand { ControlBearer { "PdnConnect" "100.0" "1" "10" "2" "2" } } log: 07/02 15:20:47.867:ts0(Coast44 10.8.44.1):p0(0):tc0: Starting PdnConnect ... log: 07/02 15:20:47.967:ts0(Coast44 10.8.44.1):p0(0):tc0: PdnConnect done ... log: 07/02 15:20:47.967:ts0(Coast44 10.8.44.1):p0(0):tc0: Getting the next command... tc_state: TS[0] TC[0] -> RUNNING:3#3 log: 07/02 15:20:47.967:ts0(Coast44 10.8.44.1):p0(0):tc0: State=RUNNING:3#3 log: 07/02 15:20:47.967:ts0(Coast44 10.8.44.1):p0(0):tc0: Executing Command 3 log: 07/02 15:20:47.967:ts0(Coast44 10.8.44.1):p0(0):tc0: Delaying 5 seconds log: 07/02 15:20:47.967:ts0(Coast44 10.8.44.1):p0(0):tc0: All Dedicated Bearers are Established tc_state: TS[0] TC[0] -> RUNNING:4#4 log: 07/02 15:20:52.967:ts0(Coast44 10.8.44.1):p0(0):tc0: State=RUNNING:4#4 log: 07/02 15:20:52.967:ts0(Coast44 10.8.44.1):p0(0):tc0: Executing Command 4 log: 07/02 15:20:52.967:ts0(Coast44 10.8.44.1):p0(0):tc0: Start DMF 0 log: 07/02 15:20:52.968:ts0(Coast44 10.8.44.1):p0(0):tc0: Resuming traffic for DMF 0 log: 07/02 15:20:52.968:ts0(Coast44 10.8.44.1):p0(0):tc0: Starting traffic for Paused DMF 0 log: 07/02 15:20:52.968:ts0(Coast44 10.8.44.1):p0(0):tc0: processResumeData - startingInstance:20, endingInstance:29. DataResumeRate:3000.0. log: 07/02 15:20:52.972:ts0(Coast44 10.8.44.1):p0(0):tc0: Traffic Reconfiguration Complete log: 07/02 15:20:52.972:ts0(Coast44 10.8.44.1):p0(0):tc0: Getting the next command... tc_state: TS[0] TC[0] -> RUNNING:4#5 log: 07/02 15:20:52.972:ts0(Coast44 10.8.44.1):p0(0):tc0: State=RUNNING:4#5 log: 07/02 15:20:52.972:ts0(Coast44 10.8.44.1):p0(0):tc0: Executing Command 4 log: 07/02 15:20:52.972:ts0(Coast44 10.8.44.1):p0(0):tc0: Start DMF 1 log: 07/02 15:20:52.973:ts0(Coast44 10.8.44.1):p0(0):tc0: Resuming traffic for DMF 1 log: 07/02 15:20:52.973:ts0(Coast44 10.8.44.1):p0(0):tc0: Starting traffic for Paused DMF 1 log: 07/02 15:20:52.973:ts0(Coast44 10.8.44.1):p0(0):tc0: processResumeData - startingInstance:30, endingInstance:39. DataResumeRate:3000.0. log: 07/02 15:20:52.977:ts0(Coast44 10.8.44.1):p0(0):tc0: Traffic Reconfiguration Complete log: 07/02 15:20:52.977:ts0(Coast44 10.8.44.1):p0(0):tc0: Getting the next command... tc_state: TS[0] TC[0] -> RUNNING:4#6 log: 07/02 15:20:52.977:ts0(Coast44 10.8.44.1):p0(0):tc0: State=RUNNING:4#6 tc_state: TS[0] TC[0] -> RUNNING:4#4 log: 07/02 15:20:52.967:ts0(Coast44 10.8.44.1):p0(0):tc0: State=RUNNING:4#4 ts<TS_INDEX_IN_TEST>(<TS_NAME>)P<TS_PROCESS_INDEX>(<TEST_PROCESS_INDEX>):tc<TC_INDEX_WITHIN_TS>: State=<RUNNING:INDEX#COUNT> |
|
|
Test Case Sub-state Current Command index with SyncPointTest Case Sub-state Current Command index with SyncPoint (For Command Sequencer step SyncPoint) tc_state: TS[0] TC[1] -> RUNNING:0#0 log: 02/22 00:59:39.962:ts0(Coast04):p0(0):tc1: State=RUNNING:0#0 tc_progress: TS[0] TC[1] -> 16:5 Sec(s) remaining (Delay) log: 02/22 00:59:44.951:ts0(Coast04):p0(0):tc0: Executing Command 1 log: 02/22 00:59:44.951:ts0(Coast04):p0(0):tc0: Reached SyncPoint 0 tc_state: TS[0] TC[0] -> RUNNING:1#1:Sync_0 log: 02/22 00:59:44.951:ts0(Coast04):p0(0):tc0: State=RUNNING:1#1:Sync_0 log: 02/22 00:59:44.961:TAS: ts0::tc0 Reached SyncPoint: 0 log: 02/22 00:59:44.962:TAS: Shared test cases not in sync yet log: 02/22 00:59:44.962:ts0(Coast04):p0(0):tc1: Executing Command 1 log: 02/22 00:59:44.962:ts0(Coast04):p0(0):tc1: Reached SyncPoint 0 tc_state: TS[0] TC[1] -> RUNNING:1#1:Sync_0 log: 02/22 00:59:44.962:ts0(Coast04):p0(0):tc1: State=RUNNING:1#1:Sync_0 log: 02/22 00:59:44.965:TAS: ts0::tc1 Reached SyncPoint: 0 log: 02/22 00:59:44.965:TAS: All TCs are in sync log: 02/22 00:59:44.968:ts0(Coast04):p0(0):tc0: Resuming Sequencer from SyncPoint 0 log: 02/22 00:59:44.968:ts0(Coast04):p0(0):tc0: Executing Command 2 log: 02/22 00:59:44.968:ts0(Coast04):p0(0):tc0: Delaying 20 seconds tc_state: TS[0] TC[0] -> RUNNING:2#2 log: 02/22 00:59:44.968:ts0(Coast04):p0(0):tc0: State=RUNNING:2#2 tc_progress: TS[0] TC[0] -> 4:20 Sec(s) remaining (Delay) log: 02/22 00:59:44.968:ts0(Coast04):p0(0):tc1: Resuming Sequencer from SyncPoint 0 log: 02/22 00:59:44.968:ts0(Coast04):p0(0):tc1: Executing Command 2 log: 02/22 00:59:44.968:ts0(Coast04):p0(0):tc1: Delaying 20 seconds tc_state: TS[0] TC[1] -> RUNNING:2#2 log: 02/22 00:59:44.951:ts0(Coast04):p0(0):tc0: Reached SyncPoint 0 tc_state: TS[0] TC[0] -> RUNNING:1#1:Sync_0 log: 02/22 00:59:44.951:ts0(Coast04):p0(0):tc0: State=RUNNING:1#1:Sync_0 |
|
|
Command Sequencer Auto-StopCommand Sequencer Auto-Stop
01/10 02:26:04.121:ts0(Coast04):p0(0):tc0: State=RUNNING 01/10 02:26:04.121:ts0(Coast04):p0(0):tc0: Auto-stopping test case |
|
RUNNING:INDEX#COUNT |
0#0, 1#1,...n#n. Indicates the exact step in the Sequencer (being executed by the TS).
For example, If you have loops in your sequence, INDEX and COUNT will eventually differ, this is because command #5 may be being executed for the 10th time.
|
|
NOTES:
|