How to Read Debug logs of Visual Studio Client

This article is aimed to explain how you can read the debug log of IBM Rational Team Concert Microsoft Visual Studio Client to find out the root cause of the problem a user is experiencing.

Logs Concept, What is saved in the log files?

To investigate the logs for a potential problem or root cause, You need to know what is saved in the log files.

The trace consists of two main elements.

1. Visual Studio Client log.

2. Daemon process logs.

Visual Studio Client log.

This trace contains the information about all the functions and core tasks that are invoked during start-up of the IBM Rational Team Concert Microsoft Visual Studio client or when user performs a certain action in client.

The file is named as trace--<time-stamp>.txt

Example:

trace-20141013-1031.txt

Its located in the root of the zip that is generated while saving the log files in Visual Studio Client.

For reference on how to generate the debug trace please check Enable debug trace logs

Lets take a use case as follows:

In Visual Studio Client,

1. Login to the Team Concert repository.

2. After Login, Set Current Sandbox.

When you have the verbose trace enabled you will see the following core tasks get executed:

11/06/2014 07:05:53 Core: Task Connecting to 'https://<HOST>:9443/ccm/'... required requests 12,####2:1
11/06/2014 07:05:54 Core: Task Log on... required requests 4,5,13,####2:3
11/06/2014 07:06:10 Core: Task Setting sandbox to 'C:\SCM-Projects' required requests 14,15,18,####2:3
11/06/2014 07:06:10 Core: Task Setting the maximum number of changes visible for a change set... required requests 21,22,####2:2
11/06/2014 07:06:11 Core: Task Refreshing Local Changes required requests 25,####2:1
11/06/2014 07:06:12 Core: Task Updating pending changes... required requests 23,24,26,27,####2:4
11/06/2014 07:06:14 Core: Task Updating pending changes... required requests 28,29,####2:2
11/06/2014 07:06:18 Core: Task Updating pending changes... required requests 30,31,####2:2
11/06/2014 07:06:18 Core: Task Refreshing Local Changes required requests 35,####2:1
11/06/2014 07:06:19 Core: Task Updating pending changes... required requests 36,37,####2:2
11/06/2014 07:06:20 Core: Task Refreshing Local Changes required requests 39,####2:1
11/06/2014 07:06:21 Core: Task Updating pending changes... required requests 40,####2:1
11/06/2014 07:06:22 Core: Task Computing pending changes... required requests 41,####2:1
11/06/2014 07:06:22 Core: Task Computing pending changes... required requests 42,####2:1
11/06/2014 07:06:35 Core: Task Updating pending changes... required requests 47,48,####2:2
11/06/2014 07:06:35 Core: Task Computing pending changes... required requests 49,####2:1
11/06/2014 07:06:37 Core: Task Updating pending changes... required requests 52,53,####2:2
11/06/2014 07:06:37 Core: Task Computing pending changes... required requests 54,####2:1

Note: After opening the trace--<time-stamp>.txt in notepad++ You can search string "Core: Task" and click "Find All in Current Document" This makes is easier to find all the core tasks that were executed.

Above you notice the core tasks:

11/06/2014 07:05:53 Core: Task Connecting to 'https://<HOST>:9443/ccm/'... required requests 12,####2:1
11/06/2014 07:05:54 Core: Task Log on... required requests 4,5,13,####2:3

are executed and they are reflecting the user action which is connection to the Team Concert repository with address it used. The second core task is the Log on. You also notice this "Log on" task is depended on more requests which are 4, 5 and 13. Each task you observe has a required requested to be completed. if you search for request 4, you notice the following execution.

11/06/2014 07:05:44 ServiceInterfaceProxy: Executing Request 4, 11/6/2014 7:05:44 AM: https://clm-50.rcsnl.ams.nl.ibm.com:9443/ccm/service/com.ibm.team.repository.service.internal.IServerStatusRestService/ServerInfo? 
11/06/2014 07:05:44 ServiceInterfaceProxy: -----------
11/06/2014 07:05:44 ServiceInterfaceProxy: {
    "__type": "Envelope:http:\/\/schemas.xmlsoap.org\/soap\/envelope\/",
    "soapenv:Body": {
        "__type": "Body:http:\/\/schemas.xmlsoap.org\/soap\/envelope\/",
        "response": {
            "__type": "Response:http:\/\/com\/ibm\/team\/core\/services.ecore",
            "returnValue": {
                "__type": "ComplexDataArg:http:\/\/com\/ibm\/team\/core\/services.ecore",
                "value": {
                    "__type": "ServerInfoDTO:http:\/\/repository_DTO\/dto.ecore",
                    "vmName": "IBM J9 VM",
                    "publicURI": "https:\/\/<HOST>:9443\/ccm",
                    "maxMemory": 4294967296,
                    "totalMemory": 4294967296,
                    "vmInfo": "JRE 1.6.0 IBM J9 2.4 Windows Server 2008 R2 amd64-64 jvmwa6460sr15-20131231_180656 (JIT enabled, AOT enabled)\nJ9VM - 20131231_180656\nJIT  - r9_20130920_46510ifx3\nGC   - GA24_Java6_SR15_20131231_1152_B180656_CMPRSS",
                    "uptime": 515390031,
                    "buildId": "RJF-I20140509-1319",
                    "_eQualifiedClassName": "http:\/\/\/repository_DTO\/dto.ecore:ServerInfoDTO",
                    "freeMemory": 1562880776,
                    "serverState": {
                        "__type": "ServerStateDTO:com.ibm.team.repository",
                        "serverStateId": null,
                        "_eQualifiedClassName": "com.ibm.team.repository:ServerStateDTO"
                    },
                    "databaseAvailable": true,
                    "usingRepositoryRoles": false,
                    "vmErrorMessage": null,
                    "javaVersion": "1.6.0",
                    "version": "5.0",
                    "vmVendor": "IBM Corporation"
                },
                "type": "COMPLEX",
                "_eQualifiedClassName": "http:\/\/\/com\/ibm\/team\/core\/services.ecore:ComplexDataArg"
            },
            "method": "getServerInfo",
            "interface": "com.ibm.team.repository.service.internal.IServerStatusRestService",
            "_eQualifiedClassName": "http:\/\/\/com\/ibm\/team\/core\/services.ecore:Response"
        },
        "_eQualifiedClassName": "http:\/\/schemas.xmlsoap.org\/soap\/envelope\/:Body"
    },
    "_eQualifiedClassName": "http:\/\/schemas.xmlsoap.org\/soap\/envelope\/:Envelope"
}
11/06/2014 07:05:44 ServiceInterfaceProxy: -----------
11/06/2014 07:05:44 ServiceInterfaceProxy: Request 4: Duration 0.14 sec ####1:4:0.1367188:1260

This request is completed without any problem with 0.14 secs. As you have noticed this request is getting the information about the server its contacting.

Similarly you can trace rest of the request that were required for the "Log on" task to be completed and also can check how long the duration was for that request.

11/06/2014 07:05:52 ServiceInterfaceProxy: Executing Request 13, 11/6/2014 7:05:52 AM: https://<HOST>:9443/ccm/service/com.ibm.team.repository.service.internal.ILicenseAdminRestService/LicenseInfo? 
11/06/2014 07:05:52 ServiceInterfaceProxy: -----------
11/06/2014 07:05:52 ServiceInterfaceProxy: {
    "__type": "Envelope:http:\/\/schemas.xmlsoap.org\/soap\/envelope\/",
    "soapenv:Body": {
        "__type": "Body:http:\/\/schemas.xmlsoap.org\/soap\/envelope\/",
        "response": {
            "__type": "Response:http:\/\/com\/ibm\/team\/core\/services.ecore",
            "returnValue": {
                "__type": "ComplexDataArg:http:\/\/com\/ibm\/team\/core\/services.ecore",
                "value": {
                    "__type": "EditorPresentationDTO:com.ibm.team.workitem.rest.dto",
...
...
...
11/06/2014 07:05:53 ServiceInterfaceProxy: -----------
11/06/2014 07:05:54 ServiceInterfaceProxy: Request 13: Duration 1.52 sec ####1:13:1.5214844:79011

Above we can see the request was made to get the license information and it took 1.52 seconds to complete.

Lets have a look at setting the sandbox:

11/06/2014 07:06:10 Core: Task Setting sandbox to 'C:\SCM-Projects' required requests 14,15,18,####2:3

The sandbox is being set as "C:\SCM-Projects" and it is dependent on request 14, 15 and 18.

All these requests are completed OK before the Sandbox is set. You will also notice that before executing the request 14 we are setting up the daemon process.

11/06/2014 07:05:58 FilesystemCommon: Unlocked file C:\Users\Administrator\AppData\Local\jazz-scm\daemons\lock
11/06/2014 07:05:58 FilesystemService: Running daemon with arguments -nl en_US daemon start "C:\SCM-Projects" -c 120000 -i 1000
11/06/2014 07:05:58 FilesystemService: FileSystemDaemon: trying to start a new daemon process
11/06/2014 07:06:00 FilesystemService: FileSystemDaemon: trying to create connection info from command 
11/06/2014 07:06:02 FilesystemService: FileSystemDaemon: trying to create connection info from command 
11/06/2014 07:06:03 FilesystemService: FileSystemDaemon: trying to create connection info from command Port: 52045
Key: 01742B0C4A7E7EBED44D56AEBD82C1EB

11/06/2014 07:06:03 FilesystemService: FSDaemonConnectionInfo: Command Line 1 from FSDaemon
11/06/2014 07:06:03 FilesystemService: FSDaemonConnectionInfo: Command Line 2 from FSDaemon
11/06/2014 07:06:03 FilesystemService: Started new SCM daemon (C:\Program Files\IBM\Rational Team Concert Client for Microsoft Visual Studio IDE\3rd Party\scmtools\eclipse\scm.exe) at C:\SCM-Projects: URI: http://localhost:52045/, Key: 01742B0C4A7E7EBED44D56AEBD82C1EB
11/06/2014 07:06:03 FilesystemService: FilesystemDaemonController:Started daemon for sandbox C:\SCM-Projects
11/06/2014 07:06:03 FilesystemClient: CopyFileArea: Daemon C:\SCM-Projects logging in for repository jazzadmin@clm-50

We will discuss about the Daemon process below in separate section.

In order to find out why a login is failing or why we could not set the current sandbox we need to check all the requests that were executed to make sure there were no errors reported and if there was an error reported then what request is failing.

Each request has detailed information about what are the values for the properties that are being used. For example , while logging in for request 5, we have this information for the repository connection that was created:

11/06/2014 07:05:49 FilesystemService: progressNotificationReceiver: Key = key-rs.5, CallState = 100, Task = , SubTask = , Cancelled = False 
11/06/2014 07:05:49 ServiceInterfaceProxy: -----------
11/06/2014 07:05:49 ServiceInterfaceProxy: {
    "__type": "Envelope:http:\/\/schemas.xmlsoap.org\/soap\/envelope\/",
    "soapenv:Body": {
        "__type": "Body:http:\/\/schemas.xmlsoap.org\/soap\/envelope\/",
        "response": {
            "__type": "Response:http:\/\/com\/ibm\/team\/core\/services.ecore",
            "returnValue": {
                "__type": "ComplexDataArg:http:\/\/com\/ibm\/team\/core\/services.ecore",
                "value": {
                    "__type": "TeamRepositoryDTO:com.ibm.team.filesystem.rest.client.core",
                    "stateLoggingOut": false,
                    "errorStateNone": true,
                    "repositoryURI": "https:\/\/<HOST>:9443\/ccm\/",
                    "connectionTimeout": 480,
                    "repositoryId": "_nXlmcmDfEeSD988h9x_HfA",
                    "userId": "jazzadmin",
                    "ContributorItemIdLoggedInContributor": "_COvPEGDgEeSsybppVfaldg",
                    "name": "clm-50",
                    "_eQualifiedClassName": "com.ibm.team.filesystem.rest.client.core:TeamRepositoryDTO",
                    "errorStateIO": false,
                    "errorStateAuth": false,
                    "repositoryItemIdId": "_nXlmcmDfEeSD988h9x_HfA",
                    "stateLoggingIn": false,
                    "stateLoggedIn": true,
                    "stateLoggedOut": false
                },
                "type": "COMPLEX",
                "_eQualifiedClassName": "http:\/\/\/com\/ibm\/team\/core\/services.ecore:ComplexDataArg"
            },
            "method": "postLogin",
            "interface": "com.ibm.team.filesystem.rcp.core.internal.rest.FilesystemRestClient",
            "_eQualifiedClassName": "http:\/\/\/com\/ibm\/team\/core\/services.ecore:Response"
        },
        "_eQualifiedClassName": "http:\/\/schemas.xmlsoap.org\/soap\/envelope\/:Body"
    },
    "_eQualifiedClassName": "http:\/\/schemas.xmlsoap.org\/soap\/envelope\/:Envelope"
}
11/06/2014 07:05:49 ServiceInterfaceProxy: -----------
11/06/2014 07:05:49 FilesystemService: Removing Key: key-rs.5
11/06/2014 07:05:49 ServiceInterfaceProxy: Request 5: Duration 5.04 sec ####1:5:5.0439453:1028

Notice the core task "Log on" had the required requests 4 , 5 and 13. Above you have the snippet of the request 5 that was executed. You can see what is the timeout value used , What was the repository connection and what is the user name.

Right after this request is completed you get the confirmation:

11/06/2014 07:05:49 RepositoryClient: TeamRepositoryEventMediator::OnRepositoryLoginPhase1 - Repository log in complete for https://<HOST>:9443/ccm/

The trace above is to help you understand how you can follow a particular transaction or event in the trace and find out where it fails. For performance related problem , you can also identify which request is taking a long time to complete.

Daemon Process logs.

When you start Visual Studio with Rational Team Concert plugin installed, a daemon process is started. Its is scm.exe process that you can also verify in the Task manager of Microsoft Windows.

This process is responsible for all the source code management activities that are performed from the Visual Studio client.

Example:

- Setting Sandbox

- Loading Workspace

- Accepting Change sets

and more.

This process log is saved separately in the RTCNetlogs.zip file under "Trace" folder.

The files is saved with name

"Date"-"Time".daemontrace

There can be multiple files saved in this directory with different time stamps.

When you are looking at a problem and suspect the Daemon process might need to be looked at , you can check the file for the communication it performed from the Visual Studio Client to Server for a particular request noticed in the Visual Studio Client log.

For instance from the above section trace we have "Log on" core task which required request 4 , 5, and 13.

If we want to check what SCM daemon process was doing for that particular request we can open the Daemon trace file and look for the Request 5 (Identified here as key-rs.5)

2014/Nov/06 07:05:44.646 - JSON_REQUEST - 52038 - Request, Progress-Key: key-rs.5
    repositoryUrl = https://HOST:9443/ccm/
    name = clm-50
    userId = jazzadmin
    password = {redacted}
    smartCard = false
    connectionTimeoutInSeconds = 480
....
....

Similarly for when setting the Sandbox if we look at request 15: (Identified here as key-rs.15)

2014/Nov/06 07:06:09.110 - REQUEST - 52050 - POST /service/com.ibm.team.filesystem.client.rest.IFilesystemRestClient/SandboxListeningEnablement
2014/Nov/06 07:06:09.117 - JSON_REQUEST - 52050 - Request, Progress-Key: key-rs.15
   enable = true
2014/Nov/06 07:06:09.136 - NOTIFICATION QUEUED - -1 - Type: progress, Progress-Key: key-rs.15
   TYPE = progress
   taskName = 
   progress = 0.0
   cancelled = false
2014/Nov/06 07:06:09.143 - NOTIFICATION SENT - 52051 - Type: progress, Progress-Key: key-rs.15
   TYPE = progress
   taskName = 
   progress = 0.0
   cancelled = false
2014/Nov/06 07:06:09.149 - CONNECT - 52056 - Client connected

The POST request was completed.

The above examples are when things are working OK. But it gives you an idea how to follow a particular transaction or a client action in the verbose logging.

Example Problem:

While changing the flow target for a workspace user saw status code 500 Internal Error with not much information about the problem and where the problem is.

After inspecting the log we observed:

10/15/2014 10:36:50 FilesystemClient: CopyFileArea: Daemon C:\Sandbox1 logging in for repository jazzadmin@clm-50
10/15/2014 10:36:51 Core: Task Setting sandbox to 'C:\Sandbox1' required requests 86,87,88,91,####2:4
10/15/2014 10:37:15 Core: Task Searching added flow targets... required requests 116,####2:1
10/15/2014 10:37:16 Core: Task Fetching workspaces... required requests 118,####2:1
10/15/2014 10:37:21 Core: Task Saving changes... required requests 119,####2:1
10/15/2014 10:37:02 Core: Task Updating same occurrences... required requests 115,####2:1
10/15/2014 10:37:15 UiUtils: ### Executing... com.ibm.team.filesystem.ui.handlers.ChangeFlowTargetHandler

Notice the Change Flow Target was executed

and then we notice after the change was made to select a new flow target, the "Pending changes" synchronize the views to get the updated data but it fails:

10/15/2014 10:37:27 ServiceInterfaceProxy: Executing Request 129, 10/15/2014 10:37:27 AM: http://localhost:51578/service/com.ibm.team.filesystem.client.rest.IFilesystemRestClient/SyncView?
10/15/2014 10:37:27 FilesystemService: AddListener: Registered Listener with Key key-rs.129
10/15/2014 10:37:27 FilesystemService: Removing Key: key-rs.129
10/15/2014 10:37:27 ServiceInterfaceProxy: Request 129: Duration 0.04 sec ####1:129:0.0390039:0
10/15/2014 10:37:27 ServiceInterfaceProxy: Request 129: com.ibm.team.repository.TeamRepositoryException: Internal error
Status code:
500
Remote exception type:
java.lang.NullPointerException
Request URI:
http://localhost:51578/service/com.ibm.team.filesystem.client.rest.IFilesystemRestClient/SyncView?
Remote stack trace:
[
    "com.ibm.team.filesystem.rcp.core.internal.rest.util.SyncViewDTOUtil.getBaselineSyncDTO(SyncViewDTOUtil.java:351)",
    "com.ibm.team.filesystem.rcp.core.internal.rest.util.SyncViewDTOUtil.getComponentSyncDTO(SyncViewDTOUtil.java:318)",
    "com.ibm.team.filesystem.rcp.core.internal.rest.util.SyncViewDTOUtil.getWorkspaceSyncDTO(SyncViewDTOUtil.java:283)",
    "com.ibm.team.filesystem.rcp.core.internal.rest.util.SyncViewDTOUtil.getSyncView(SyncViewDTOUtil.java:190)",
    "com.ibm.team.filesystem.rcp.core.internal.rest.FilesystemRestClient.getSyncView(FilesystemRestClient.java:619)",
    "sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)",
    "sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60)",
    "sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)",
    "java.lang.reflect.Method.invoke(Method.java:611)",
    "com.ibm.team.filesystem.client.daemon.JSONHandler.handle(JSONHandler.java:322)",
    "com.ibm.team.filesystem.client.internal.http.HttpConnection.readNextRequest(HttpConnection.java:628)",
    "com.ibm.team.filesystem.client.internal.http.HttpConnection$1.run(HttpConnection.java:470)",
    "org.eclipse.core.internal.jobs.Worker.run(Worker.java:54)

If we track this particular execution in Daemon process we notice that its the daemon process that is failing to get the information from the server.

2014/Oct/15 10:37:27.726 - REQUEST - 51584 - GET /service/com.ibm.team.filesystem.client.rest.IFilesystemRestClient/SyncView?
2014/Oct/15 10:37:27.726 - JSON_REQUEST - 51584 - Request, Progress-Key: key-rs.129
2014/Oct/15 10:37:27.757 - JSON_RESPONSE - 51584 - Response (500)
{
    "errorClass": "java.lang.NullPointerException",
    "errorCode": 500,
    "errorMessage": null,
    "errorTrace": [
        "com.ibm.team.filesystem.rcp.core.internal.rest.util.SyncViewDTOUtil.getBaselineSyncDTO(SyncViewDTOUtil.java:351)",
        "com.ibm.team.filesystem.rcp.core.internal.rest.util.SyncViewDTOUtil.getComponentSyncDTO(SyncViewDTOUtil.java:318)",
        "com.ibm.team.filesystem.rcp.core.internal.rest.util.SyncViewDTOUtil.getWorkspaceSyncDTO(SyncViewDTOUtil.java:283)",
        "com.ibm.team.filesystem.rcp.core.internal.rest.util.SyncViewDTOUtil.getSyncView(SyncViewDTOUtil.java:190)",
        "com.ibm.team.filesystem.rcp.core.internal.rest.FilesystemRestClient.getSyncView(FilesystemRestClient.java:619)",
        "sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)",
        "sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60)",
        "sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)",
        "java.lang.reflect.Method.invoke(Method.java:611)",
        "com.ibm.team.filesystem.client.daemon.JSONHandler.handle(JSONHandler.java:322)",
        "com.ibm.team.filesystem.client.internal.http.HttpConnection.readNextRequest(HttpConnection.java:628)",
        "com.ibm.team.filesystem.client.internal.http.HttpConnection$1.run(HttpConnection.java:470)",
        "org.eclipse.core.internal.jobs.Worker.run(Worker.java:54)"
    ],

Hence the problem with Daemon process in which there is a Null Pointer Exception while trying to get Baseline of the component which was changed in the flow target.

Note: The above trace is taken from an example which was identified as a defect.

Related topics: Deployment web home, Deployment web home

External links:

• IBM

Additional contributors: TWikiUser, TWikiUser, ZeeshanChoudhry