Skip to main content
BenPerry
BenPerry15-Moonstone
15-Moonstone
August 27, 2015
Solved

Timestamps in MethodServer Log Files

  • August 27, 2015
  • 20 replies
  • 8784 views

I'm running Windchill on a Unix server.  I try to log something to an external file, but I also print information to the MethodServer at the same time.

  • In the MethodServer, the information is printed with timestamp "2015-08-27 08:49:56" using System.out.println().
  • In my log file, the timestamp is printed as "2015-08-27 13:49:56" using output.println(new java.sql.Timestamp(System.currentTimeMillis()) + "information").

I've tried searching the internet for how to change the timestamp (which is essentially GMT, but not technically) to a different timezone, but I have gotten anywhere.  But obviously the logging has figured it out somehow.

Best answer by BenPerry

As Jess has mentioned, a custom log4j logger can be used to accomplish the desired output.  I have this working, and would like to share my steps to get there.  As it turns out, it is pretty lengthy.  But I hope that someone finds it useful.  There are also probably people that are already familiar with this, and using their own log4j logging.  So I welcome corrections & comments if I've published anything wrong or misleading.

The way I see it, there are 2 scenarios that could be in play here.

  1. The logging is going to be executed from some Execute Expression robot in a workflow template, or maybe some custom JSP page that is placed on the server.  In these cases, there is no java package and class.
  2. The logging is going to be executed from an actual compiled java class, such as ext.company.SomeClass.

I will cover both scenarios.

Scenario 1

I have a custom JSP page that I put onto the server into codebase/netmarkets/jsp/Custom/mypage.jsp.  Every time someone loads that JSP page, I want to log an event to some external file.  I don't want it simply logged in the MethodServer.  In the example below, it looks at user IP address and tries to update the user's Vault preference.  For the logging, we're only concerned with lines 7 and 16 and 19 in the JSP code below.

<%@ page import="org.apache.log4j.Logger" %>


<%@ page import="wt.org.WTUser" %>


<%@ page import="wt.preference.PreferenceHelper" %>


<%@ page import="wt.session.SessionHelper" %>


<%


// Instantiate some variables


Logger LOGGER = Logger.getLogger("ext.company.customJspLogger");


WTUser user = (WTUser)SessionHelper.manager.getPrincipal();


String username = user.getName();


String ipAddress = request.getRemoteAddr();


String vaultPreferenceOld = (String)PreferenceHelper.service.getValue(user, "/wt/content/contentCacheSite", "WINDCHILL");


String vaultPreferenceNew = "master";


if (ipAddress.equals("192.168.242.32")) {


    vaultPreferenceNew = "Value_of_the_Preference_setting__aka_master_or_Replica1";


    PreferenceHelper.service.setValue("/wt/content/contentCacheSite", vaultPreferenceNew, user);


    LOGGER.info(username + " " + ipAddress + " " + vaultPreferenceOld + " " + vaultPreferenceNew);


} else {


    vaultPreferenceNew = "IP_NOT_RECOGNIZED_PREFERENCE_NOT_SET";


    LOGGER.info(username + " " + ipAddress + " " + vaultPreferenceOld + " " + vaultPreferenceNew);


}


//String redirectURL = "../../../servlet/WindchillGW";


//response.sendRedirect(redirectURL);


%>


Hello, thank you for testing!  Have a nice day.

The corresponding update that needs to be made to codebase/WEB-INF/log4jMethodServer.properties is listed below.  Note "ext.enerpac.customJspLogger" in line 2 below, which matches the getLogger() callout in line 7 of the JSP code above.  Also, after updating and saving the log4jMethodServer.properties file, be sure to wait for up to 3 minutes for the settings to take effect.  I've noticed in the MS, a line printed such as wt.log4j.jmx.LoggerRepositoryMonitor  - log4j configuration read from file:<WT_HOME>/codebase/WEB-INF/log4jMethodServer.properties, and then I know that the new configuration has been read, and ready to use.

# Define customJspLogger appender


log4j.logger.ext.company.customJspLogger=INFO, customJspLogger


log4j.additivity.customJspLogger=false


log4j.appender.customJspLogger=wt.log4j.jmx.DailyRollingFileAppender


log4j.appender.customJspLogger.File=/home/ptc/testing1.log


log4j.appender.customJspLogger.DatePattern='.'yyyy-MM-dd


log4j.appender.customJspLogger.layout=org.apache.log4j.PatternLayout


log4j.appender.customJspLogger.layout.ConversionPattern=%d{ISO8601} %-5p [%t] %c - %m%n

Then, after trying to load the page http://<server>/Windchill/netmarkets/jsp/Custom/mypage.jsp, I get the following line in the external file /home/ptc/testing1.log:

2015-09-02 04:32:38,173 INFO [ajp-bio-8010-exec-1] ext.company.customJspLogger - ben.perry 192.168.242.32 master Replica1

So to summarize, all I really did, besides the import statement, was:

  1. Instantiate the logger on JSP page, Logger LOGGER = Logger.getLogger("ext.enerpac.customJspLogger"); making sure to use the right callout for getLogger() function.
  2. Actually log information by calling LOGGER.info("whatever info message you want printed");
  3. Add the properties of the custom logger to codebase/WEB-INF/log4jMethodServer.properties making sure to wait some moment until the new config is loaded before testing it.

Notes to keep in mind here:

  • The string "ext.company.customJspLogger" that is called out in getLogger() on the JSP page must match here also: log4j.logger.ext.company.customJspLogger=INFO, customJspLogger.
  • The string "customJspLogger" at the end of this line can be anything, but must match on the following lines in the properties file, such as log4j.additivity.customJspLogger=false.  I just happened to drop "ext.company" off, but you can call it anything, I believe.
  • Make sure to wait and allow the new config from log4jMethodServer.properties to load before testing.
  • log4j.appender.<logname>.File= specifies where the external file is going to be stored.  As Jess has pointed out, if you're worried about multiple MS trying to write to the file at the same time, you can include a variable in the filename so that there are actually multiple different testing1.log files - all with unique names - and each MS will write to its respective file.
  • log4j.appender.<logname>.layout.ConversionPatter= specifies the layout of the text that is printed into the log file.  %d{ISO8601} is actually where I'm getting my correct timestamp, which is what I originally opened this discussion for.

Scenario 2

Another scenario is that you have an actual java file that is compiled, and part of a package.  For example, you have the file <WT_HOME>/src/ext/package/CustomClass.java, and it is compiled into <WT_HOME>/codebase/ext/package/CustomClass.class.  If you want to enable this type of logging in that java code, then the steps are very similar.  The only real difference is that when instantiating LOGGER in the code, the getLogger() method should not be passed a string.  Instead, pass it something like this: Logger LOGGER = Logger.getLogger(CustomClass.class);  That will get the string of the fully qualified class name and pass it.  The value in this case would be "ext.package.CustomClass".  And therefore, when setting up the logger properties in log4jMethodServer.properties file, then the first line would become log4j.logger.ext.package.CustomClass=INFO, someNameHere.

Logger LOGGER = Logger.getLogger(CustomClass.class);



# Define customJspLogger appender  


log4j.logger.ext.package.CustomClass=INFO, someNameHere


log4j.additivity.someNameHere=false  


log4j.appender.someNameHere=wt.log4j.jmx.DailyRollingFileAppender  


log4j.appender.someNameHere.File=/home/ptc/testing2.log  


log4j.appender.someNameHere.DatePattern='.'yyyy-MM-dd  


log4j.appender.someNameHere.layout=org.apache.log4j.PatternLayout  


log4j.appender.someNameHere.layout.ConversionPattern=%d{ISO8601} %-5p [%t] %c - %m%n

20 replies

B
BineshKumar12-Explorer
2-Explorer
August 27, 2015

Hi Ben,

We have faced some issues related to object created timestamp through data loader  and what we followed is https://support.ptc.com/appserver/cs/view/solution.jsp?n=CS150627 

and https://support.ptc.com/appserver/cs/view/solution.jsp?n=CS44062

Thanks

Binesh Kumar

Barry Wehmiller

B
BhushanNehe16-Pearl
16-Pearl
August 27, 2015

Hi Ben,

You can also use the following instead to get the date/time in required timezone.

Code:

   java.text.SimpleDateFormat gmtDateFormat = new java.text.SimpleDateFormat("yyyy-MM-dd HH:mm:ss");




  gmtDateFormat.setTimeZone(java.util.TimeZone.getTimeZone("GMT"));


  //Current Date Time in GMT


  System.out.println("Current Date and Time in GMT time zone: " + gmtDateFormat.format(new java.util.Date()));






  gmtDateFormat.setTimeZone(java.util.TimeZone.getTimeZone("IST"));


  //Current Date Time in IST


  System.out.println("Current Date and Time in IST time zone: " + gmtDateFormat.format(new java.util.Date()));


Results:

Current Date and Time in GMT time zone: 2015-08-27 14:49:24

Current Date and Time in IST time zone: 2015-08-27 20:19:24

Regards,

Bhushan

BenPerry
BenPerry15-MoonstoneAuthor
15-Moonstone
August 27, 2015

Thank you for the answers.  But maybe there is something much lighter and succinct that is used by MS since it is executed for every single line printed to the MS?

J
jessh12-Amethyst
12-Amethyst
August 27, 2015

Windchill method servers have historically run in GMT (though I believe that's changing in a near-term future release...) as it made use of some of the older JDBC APIs that use the JVM's default TimeZone as the time zone when reading/writing Timestamps to the database (where databases normally store timestamps without time zone information, requiring you to specify the time zone when reading or writing).

Timestamps in Windchill's own logs should be written with respect to the actual server time zone, not GMT (barring bugs, of course).

The way to get the actual server time zone rather than GMT is WTContext.getContext().getTimeZone().  One could, at least in newer releases, use WTContext.getDefaultTimeZone() -- except that it is not denoted as being a supported API, though I can see no reason whatsoever for this.

BenPerry
BenPerry15-MoonstoneAuthor
15-Moonstone
August 27, 2015

So Jess Holle‌,

Instead of this:

    try(java.io.PrintWriter output = new java.io.PrintWriter(new java.io.BufferedWriter(new java.io.FileWriter("/home/ptc/QuickLinks.log", true)))) {


        output.println(new java.sql.Timestamp(System.currentTimeMillis()) + "\t" + currentUser.getName());


    } catch (java.io.IOException e2) {


        e2.printStackTrace();


    }

What do you suggest to write the timestamp to my file "/home/ptc/QuickLinks.log" in the timezone of the server, instead of GMT?

Sorry if it is simple question - I'm still somewhat novice at java coding.

J
jessh12-Amethyst
12-Amethyst
August 28, 2015

First off, for logging, I'd suggest just using log4j and either writing into the normal method server log file or adjusting log4jMethodServer.properties to route your loggers' output to a separate log file.

More broadly, I was answering how to get the "real" server time zone (rather than GMT) from within the method server.  There are lots of usages for this information.  [By the way, by WTContext I was referring to wt.util.WTContext.]

If, however, you just need to render a time to the current time zone, you could use wt.jmx.core.MBeanUtilities.renderAsTimestampPlusTimeZone(java.util.Date).  If you don't like that format, then use your own, e.g.:

dateFormat = new SimpleDateFormat( "yyyy-MM-dd HH:mm:ss.SSS" )

dateFormat.setTimeZone(WTContext.getContext().getTimeZone());

dateFormat.format(date);

    Terms & ConditionsAccessibility statement