Debugging errors using Polarion log files

Depending on the situation you’re analyzing, you may enable different loggers. Here are some recommendations we have found valuable over the past years doing support for OSLC Connect for Jira.

Prepare your logs with some specific notes

When doing debug sessions, it’s always valuable to easily identify what actions were undertaken when a specific log message appears. The start of the session deserves a specific notice, as would any action that one would perform, e.g. the last click before a given problem appears or the modification of a specific configuration key. This will help review the logs immediately after the session, but also will help with retaining a certain level of understanding weeks on months later.

Since Siemens does not offer the same level of features as does Atlassian in their Jira product, we have to resort to using administrator tricks here! Our suggestion for this is to:

identify which files you wish to supervise
log into these files with the following script

Linux

CODE

#!/bin/sh
for i in "${@:2}"
do
    echo -ne "\n\n\n**** ${1}\n\n" >> ${i}  # mark the nth log file
done
exit

Create the marklogs.sh file inside the logs folder (typically <Polarion installation dir>/data/logs then make it executable (using chmod u+x marklogs.sh). You can then mark any log file by specifying the comment as the first argument, and every log file you want to impact as subsequent arguments:

CODE

./marklogs.sh "Starting the OSLC debug session" ldx.log ldx-internalSso.log

Windows (Powershell)

CODE

$log_mark=$args[0];
for ($i = 1; $i -lt $args.count; $i++) {
    $logfile = $args[$i];
    Add-Content "$logfile" "`n`n`n*** $log_mark`n`n";
}

Create the marklogs.ps1 file inside the logs folder (typically <Polarion installation dir>/data/logs. You can then mark any log file by specifying the comment as the first argument, and every log file you want to impact as subsequent arguments:

CODE

./marklogs.ps1 "Starting the OSLC debug session" main/log4j-20211018-1137-19.log main/log4j-oslc-20211028-1235-14.log

Windows (Batch)

CODE

@echo off
setlocal enabledelayedexpansion
set argCount=0

for %%x in (%*) do (
   set /A argCount+=1
   set "argVec[!argCount!]=%%~x"
)

for /L %%i in (2,1,%argCount%) do (
   (echo:& echo:& echo:& (echo *** %~1)& echo:& echo:)>>"!argVec[%%i]!"
)

Create the marklogs.bat file inside the logs folder (typically <Polarion installation dir>/data/logs. You can then mark any log file by specifying the comment as the first argument, and every log file you want to impact as subsequent arguments:

CODE

./marklogs.bat "Starting the OSLC debug session" main/log4j-20211018-1137-19.log main/log4j-oslc-20211028-1235-14.log

The result will look like this:

CODE

2021-10-27 18:37:54,336 [Monitoring] INFO  com.polarion.platform.monitoring  - Executing action 'system.info.memory.oldGen.free'
2021-10-27 18:37:54,336 [Monitoring] INFO  com.polarion.platform.monitoring  - system.info.memory.oldGen.free (Free Old Gen memory after GC) = Java Heap Memory
Old Gen pool has  88.51% memory free after GC.
 [Wed Oct 27 18:37:54 CEST 2021]
2021-10-27 18:37:54,505 [Monitoring] INFO  com.polarion.platform.monitoring  - Finished with actions from stage PERIODIC: {OK=6}


*** Starting the OSLC debug session

<new logs will appear here>

Decide on what to review

Review incoming requests to Polarion

Incoming requests are listed in the access log. Polarion comes bundled with a tool that dispatches all incoming requests to the Polarion app. That tool is called the Apache HTTP Server. This is the tool which provides the log for incoming requests, called the access log.

Logs for this are either available at <Polarion installation dir>/data/logs/apache or /var/log/httpd, depending on the underlying operating system. You should have some access.log.<year>-<week_number> file or a access_log file.

For an advanced access log format, you can expand this section.

The LogFormat directive can be highly customized to include as much data as possible.

This has been tested successfully on Linux deployments.

This directive can be updated in the httpd.conf file, in the <IfModule log_config_module> block.

CODE

LogFormat "\"%h\" \"%u\" \"%t\" \"%D\" \"%r\" \"%s\" \"%B\" \"%m\" \"%U\" \"%q\" \"%a\" \"%A\" \"%C\" \"%{Referer}i\" \"%{User-Agent}i\" \"%{Cookie}i\" \"%{Authorization}o\" \"%{Set-Cookie}i\" \"%{oslc_config.context}i\" \"%{OSLC-Core-Version}i\" \"%{Content-Length}i\" \"%{Accept}i\" \"%{Content-Type}i\" \"%{If-Match}i\" \"%{If-Modified-Since}i\" \"%{X-If-Modified-Since-XSD}i\" \"%{Forwarded}i\" \"%{X-Forwarded-For}i\" \"%{Location}o\" \"%{Content-Location}o\" \"%{Content-Disposition}o\" \"%{eTag}o\" \"%{x-com-sodius-logout-url}o\" \"%{x-com-sodius-logout-method}o\" \"%{X-com-sodius-oauth-redirect-location}o\" \"%{X-com-ibm-team-repository-web-auth-msg}o\" \"%{X-Sodius-Resource}o\" \"%{WWW-Authenticate}o\" \"%{Last-Modified}o\" \"%{Access-Control-Allow-Origin}o\" \"%{Vary}o\" \"%{Origin}o\" \"%{X-Frame-Options}o\" \"%{Content-Security-Policy}o\" common

Which gives out the following log:

CODE

"10.100.99.5" "-" "[16/Jun/2020:07:41:36 +0200]"  "628158" "GET /secollab/web/clm/review/67082340-c545-4c86-acd7-7cd1ea2fda08/finalize?oslc_config.context=https:%2F%2Fclm-605.sodius.cloud:9443%2Fsecollab%2Fclm%2Fservices%2Fconfig%2Fstream%2F213e8151-5010-4722-a996-d1f64df4944e HTTP/1.1" "307" "0" "GET" "/secollab/web/clm/review/67082340-c545-4c86-acd7-7cd1ea2fda08/finalize" "?oslc_config.context=https:%2F%2Fclm-605.sodius.cloud:9443%2Fsecollab%2Fclm%2Fservices%2Fconfig%2Fstream%2F213e8151-5010-4722-a996-d1f64df4944e" "10.100.99.5" "10.100.2.102" "JSESSIONID:0000Voxgdm9kVpWRykb_1CGRSVN:5c53c125-1133-4b4d-ba65-e9e16fe6471e LtpaToken2:fjhBhxSwdPdirZzMIvZrff57j4FlS+lk/AtmCinLpdV/MER1cRHFvfAU2yrQF/YbxHEEZOKBDrrgN2BDEuOMkgVJBIjBOmM7pnioeXweRou7h9RnMMYdeCy2ePd02Ix8n8i2pUZyrfwd55apC6rQLsWIZFWjJN9lpRZrrIq5Ok3vsKsIzfv9idGIJpFhOUx6jTQuqfVOpYX4wpJ+jUuHYTDu6slRDe9pQBlw7OT5qWn8TW59WeKDVXrtFbWRo7POvNEfH1uEd4Ec3RBc5bxihsWPnKPL3eGGmLuFsaxatkMNgJkCKd5HUwAgz3YGRXeb" "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:77.0) Gecko/20100101 Firefox/77.0" "JSESSIONID=0000Voxgdm9kVpWRykb_1CGRSVN:5c53c125-1133-4b4d-ba65-e9e16fe6471e; LtpaToken2=fjhBhxSwdPdirZzMIvZrff57j4FlS+lk/AtmCinLpdV/MER1cRHFvfAU2yrQF/YbxHEEZOKBDrrgN2BDEuOMkgVJBIjBOmM7pnioeXweRou7h9RnMMYdeCy2ePd02Ix8n8i2pUZyrfwd55apC6rQLsWIZFWjJN9lpRZrrIq5Ok3vsKsIzfv9idGIJpFhOUx6jTQuqfVOpYX4wpJ+jUuHYTDu6slRDe9pQBlw7OT5qWn8TW59WeKDVXrtFbWRo7POvNEfH1uEd4Ec3RBc5bxihsWPnKPL3eGGmLuFsaxatkMNgJkCKd5HUwAgz3YGRXeb" "-" "-" "-" "-" "text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8" "-" "-" "-" "-" "-" "-" "https://clm-605.sodius.cloud:9443/ccm/oauth-authorize?oauth_token=fdfb3353c8ae4387880b5e63aa6095f4" "-" "-" "-" "-" "-" "-" "-" "-" "-" "-" "-" "-" "-" "-" "-" "-"

Log parameters used in this recommendation are:

%h Remote host
%u Remote user according to the WebSphere Application Server specific $WSRU header
%t NCSA format of the start time of the request
%D The elapsed time of the request - millisecond accuracy, microsecond precision
%r First line of the request
%s Status code of the response
%B Response size in bytes excluding headers. 0 is printed instead of - if no value is found.
%m Request method
%U URL Path, not including the query string
%q Output the query string with any password escaped
%a Remote IP address
%A Local IP address
%C Cookie

Retained HTTP request headers are:

Referer
User-Agent
Authorization
Cookie
Set-Cookie
oslc_config.context
OSLC-Core-Version
Content-Length
Accept
Content-Type
If-MatchIf-Modified-Since
X-If-Modified-Since-XSD
Forwarded
X-Forwarded-For

Retained HTTP response headers are:

Location
Content-Location
Content-Disposition
eTag
x-com-sodius-logout-url
x-com-sodius-logout-method
X-com-sodius-oauth-redirect-location
X-com-ibm-team-repository-web-auth-msg
X-Sodius-Resource
WWW-Authenticate
Last-Modified
Access-Control-Allow-Origin
Vary
Origin
X-Frame-Options
Content-Security-Policy

To make use of the output in Excel:

Copy the below header line to the first line of an Excel Sheet

CODE

'Remote host' 'Remote user' 'Request start time' 'Request log time' 'Request duration' 'Request 1st line' 'Status' 'Response size' 'Method' 'URL' 'Query string' 'Cross Component Tracing (XCT) Context ID' 'Remote IP addr' 'Local IP addr' 'Cookie' 'i_Referer' 'i_User-Agent' 'i_Authorization' 'i_Cookie' 'i_Set-Cookie' 'i_oslc_config.context' 'i_OSLC-Core-Version' 'i_Content-Length' 'i_Accept' 'i_Content-Type' 'i_If-Match' 'i_If-Modified-Since' 'i_X-If-Modified-Since-XSD' 'i_Forwarded' 'i_X-Forwarded-For' 'o_Location' 'o_Content-Location' 'o_Content-Disposition' 'o_eTag' 'o_x-com-sodius-logout-url' 'o_x-com-sodius-logout-method' 'o_X-com-sodius-oauth-redirect-location' 'o_X-com-ibm-team-repository-web-auth-msg' 'o_X-Sodius-Resource' 'o_WWW-Authenticate' 'o_Last-Modified' 'o_Access-Control-Allow-Origin' 'o_Vary' 'o_Origin' 'o_X-Frame-Options' 'o_Content-Security-Policy'

Copy the lines you want to investigate to the 2nd+ line of the Excel Sheet

if the copied header or lines are not automatically expanded to columns

Select column Accept
In the "Data" banner, click the button called "Text to Column"
Choose "delimited", then Next

Review outgoing requests sent by Polarion, and Polarion processing

Polarion logs are located at <Polarion installation dir>/data/logs/

As suggested here in the “Polarion log4j log files” section, you can override the default log4j configuration by copying it to the right place.

Once done, one can enable additional logging to help debug potential problems by adding the following block at the end of the newly copied log4j.properties:

CODE

# APPENDER OSLCSODIUS
# ==================
log4j.appender.OSLCSODIUS=org.apache.log4j.DailyRollingDotMetadataFileAppender
log4j.appender.OSLCSODIUS.threshold=DEBUG
log4j.appender.OSLCSODIUS.file=log4j-oslc-sodius.log
log4j.appender.OSLCSODIUS.append=false
log4j.appender.OSLCSODIUS.layout=org.apache.log4j.PatternLayout
log4j.appender.OSLCSODIUS.layout.ConversionPattern=%d [%t] %-5p %c %x - %m%n
log4j.appender.OSLCSODIUS.datePattern='.'yyyy-ww

# Outgoing requests
log4j.logger.org.apache.http=DEBUG, OSLCSODIUS

# OSLC processing: anything that is Lyo related
log4j.logger.org.eclipse.lyo=DEBUG, OSLCSODIUS

# OSLC processing: plugin providing most of the OSLC 
log4j.logger.com.polarion.alm.oslc=DEBUG, OSLCSODIUS

You can add everything or just keep the sections that matter to you, depending on whether you wish to investigate OSLC processing issues or outgoing requests issues.

Finishing the debug session

Restore your system’s previous logging features

In the log4j.properties file, update the threshold to OFF:

CODE

log4j.appender.OSLCSODIUS.threshold=OFF

Then you may OFF all the related loggers:

CODE

# Outgoing requests
log4j.logger.org.apache.http=OFF, OSLCSODIUS

# OSLC processing: anything that is Lyo related
log4j.logger.org.eclipse.lyo=OFF, OSLCSODIUS

# OSLC processing: plugin providing most of the OSLC 
log4j.logger.com.polarion.alm.oslc=OFF, OSLCSODIUS

Retrieving Polarion logs

Open the following most recent log files with this below pattern to see the log entries:

<Polarion installation dir>/data/logs/log4j-oslc-sodius*.log

We suggest attaching the log file(s) to a Jira ticket on our customer support portal if you think these provide insight into the problem you have identified, or if they were requested.