Timestamps in MethodServer Log Files

[BenPerry]

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.

[BineshKumar1]

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

[BhushanNehe]

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]

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?

[jessh]

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]

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.

[jessh]

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);

[BenPerry]

The intention here is that there are some events that I want logged to some separate file, and not in the MS or BMS.  But the current drawback is that it is not using the same timezone as the MS and BMS.

I have replaced

new java.sql.Timestamp(System.currentTimeMillis())

with this:

wt.jmx.core.MBeanUtilities.renderAsTimestampPlusTimeZone(new java.util.Date())

So my full code to print the timestamp (with server time zone applied) and username to the separate log file is 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(wt.jmx.core.MBeanUtilities.renderAsTimestampPlusTimeZone(new java.util.Date()) + "\t" + currentUser.getName());
    } catch (java.io.IOException e2) {
        e2.printStackTrace();
    }

The resultant timestamp is

2015-08-27 20:53:44.601 -0500

as opposed to

2015-08-27 20:53:44,601 (the formatting printed in the MS/BMS log)

But at least it is in the same timezone as the messages in the MS and BMS logs.

[jessh]

If you don't want the time zone in your output then use:

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

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

String formattedDate = dateFormat.format(date);

renderAsTimestampPlusTimeZone() includes the time zone so that there is no question or confusion about which time zone is being referenced.

But again if your purpose is logging, then just use log4j and let it do the timestamping of the log lines, allow you to control log verbosity on the fly, etc.  Then you only have to worry about formatting dates if you want to log additional timestamps to the log line beyond the time for log line/event itself.  While there still is println() based logging in Windchill, there has been an ongoing effort to eradicate it and replace it all with log4j calls.  There are loads of advantages to this over directly doing your own file or console output when it comes to logging.

[BenPerry]

Jess,

I'll give you an example, and then perhaps you can let me know of a better way of handling it.

I have created a custom jsp page in $WT_HOME/codebase/netmarkets/jsp/Custom/.  I have also added a link to that JSP page in the "Quick Links" drop down menu of Windchill.  But I would like to know when and how often users are actually hitting that JSP page (clicking that link in the "Quick Links" drop down menu).  Therefore, in the coding for the JSP page, I write the event (date/username for example) to a separate log file (/home/ptc/QuickLinks.log, for example).

The advantage of this is that I will always be able to see that file in that location.  Also, if I print it to the MS instead, it will be lost after 15 days as Windchill archives the log files.  In addition, the printed line will be in many different actual log files.  They are not all contained in one file.

The disadvantage of this, of course, is my difficulty with the timestamp that I am discussing here.

So do you have a suggestion on how improve my capture this click event in 1 easy-to-read file that is not automatically deleted or archived?

[jessh]

Configure a log4j file appender to a directory other than WT_HOME/logs and assign it to your logger in place of the existing appenders.

This is purely a matter of log4j configuration -- apart from your logging call of "logger.info(...)" or whatever.

[jessh]

Or, if you really don't like the policy for cleaning up old logs in general, than change it.  Removal after 15 days (or 31 days in newer versions with compression at 15 days) is merely the default behavior.  Just be careful that you don't fill up your disk with log files over time if you disable the cleanup.

[BenPerry]

Jess,

I'm not familiar with that.  Is there some documentation or example?  It sounds interesting (and simpler than what I was doing).

Do I just need to add some lines to log4jMethodServer.properties?  And then in the code, instead of calling out.println(...), call logger.info(...)?

[jessh]

As my math teacher in middle school used to say, "monkey see monkey do", i.e. look the log4j 1.2.x documentation, then look at log4jMethodServer.properties, and copy and adapt from examples there.  And, yes, this would result in new lines in log4jMethodServer.properties.

In any recent version of Windchill (e.g. 10.0 and higher), you can also use this approach to log to a database table of your own creation via PTC's AsyncJDBCAppender.  Again, it's a matter of monkey-see-monkey-do -- with the added wrinkle of needing to look at the database schema for the existing target tables and mimicking that as well.

[BenPerry]

Jess Holle,

I'm still struggling.  Can you provide an example?

I have added the following lines to the bottom of the log4jMethodServer.properties file in codebase/WEB-INF/ (it was copy/paste from a different similar group above, but with "File=" updated, and the name updated to quickLinksClickLog)

# Define quickLinksClickLog appender
log4j.appender.quickLinksClickLog=wt.log4j.jmx.DailyRollingFileAppender
log4j.appender.quickLinksClickLog.File=/home/ptc/testing.log
log4j.appender.quickLinksClickLog.DatePattern='.'yyyy-MM-dd
log4j.appender.quickLinksClickLog.layout=org.apache.log4j.PatternLayout
log4j.appender.quickLinksClickLog.layout.ConversionPattern=%d{ISO8601} %-5p [%t] %c - %m%n

Then, in some test class, I have pasted this code:

package ext;
public class testClass {
    static org.apache.log4j.Logger log = org.apache.log4j.Logger.getLogger("quickLinksClickLog");
    public static void main(String args[]) {
    System.out.println("hello world");
    log.info("testing it out");
  }
}

And then finally from a Windchill shell I have executed the command windchill ext.testClass.  I'm able to see "hello world" output to the terminal window.  But I don't see any file called testing.log on the Unix computer in the /home/ptc/ directory.  And no message is printed to the method server.

Note that I've been trying to follow the examples set for there: log4j - Quick Guide

[jessh]

You defined an appender, but did not map any logger(s) to it.  Also you almost certainly want a hierarchical sort of logger name.

So you end up with something like:

log4j.logger.myco.xxxLogger=INFO, quickLinksClickLog

log4j.additivity.myco.xxxLogger=false

where myco.xxxLogger would be you logger name (modify as appropriate, but hopefully you get the idea) and the second line ensures that your logging goes *only* to your file.

All that said, whether you use println or log4j you need to be very careful if you're trying to share 1 output file across multiple method servers.  That's generally not a good idea due to contention/conflict between processes, etc.  That's one reason method server logs are named after their process id and start time -- so they're always unique to the given method server process.

[BenPerry]

Jess,

Your answers are still quite ambiguous.  Here is my latest code, but still no /home/ptc/testing.log file exists.

# Define QuickLinksLogger appender
log4j.logger.ext.enerpac.QuickLinksLogger=INFO, QuickLinksLogger
log4j.additivity.ext.enerpac.QuickLinksLogger=false
log4j.appender.QuickLinksLogger=wt.log4j.jmx.DailyRollingFileAppender
log4j.appender.QuickLinksLogger.File=/home/ptc/testing.log
log4j.appender.QuickLinksLogger.DatePattern='.'yyyy-MM-dd
log4j.appender.QuickLinksLogger.layout=org.apache.log4j.PatternLayout
log4j.appender.QuickLinksLogger.layout.ConversionPattern=%d{ISO8601} %-5p [%t] %c - %m%n

package ext;
public class testClass {
    static org.apache.log4j.Logger log = org.apache.log4j.Logger.getLogger("QuickLinksLogger");
    public static void main(String args[]) {
    System.out.println("hello world");
    log.info("testing it out");
  }
}

[jessh]

Sorry, I don't have time to write the code for you.  I will point out that what you pass to getLogger() must be the name of a logger, not the name of an appender.  Thus you want to pass ext.enerpac.QuickLinksLogger in your example above.

But also don't forgot about the issue of trying to share one "testing.log" file from multiple method servers.  That's really not going to work.

[BenPerry]

Jess,

I understand you don't have time to write the code for me.  But that is not what I'm after.  In this discussion, you have offered an alternative method for logging, so I assume you have type of example and experience with it.  That is all I'm asking for.  I have written the code myself from the example on the other website, but no matter what I try it is not working.

I would have given up a while ago if it wasn't for my commitment to these forums.  I believe that if I can get it working it will be really useful for a lot of admins in this forum.  That is the only reason I am trying to continue to make this work rather than giving up and using the other solution I've already implemented.

To address your latest comments...1) I have changed varaible passed to getLogger() to the "ext.enerpac.QuickLinksLogger" string.  But it still doesn't work.  2) I haven't thought about the multiple MS environment yet.  But it should not cause it to not work at all, right?  Currently I'm testing in a test site that is running, but nobody is using it.  Nobody is even logged in since I'm running this java command from the command line.

[BenPerry]

After quite a bit of tinkering, I think I have this figured out now.  But I'm tired!  I'll try to post a procedure as a follow-up tomorrow or else ASAP.

But now that it is working, I am not sure about the comment regarding multiple MS and 1 log file.  The log event is so infrequent, and the data is written to the file so quickly I don't think there will ever be a conflict if 2 MS were handling the action.  But if a person was worried about it, then they could use the log4j property for filename to include the MS process ID or something.  Then it would be 2 unique files being updated.  But at least they're also still outside of the normal log files, so the message(es) won't be co-mingled with every other message.

[BenPerry · Accepted solution]

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