logging improvements

server/src/main/java/password/pwm/PwmApplication.java

@@ -385,7 +385,7 @@ public class PwmApplication
             pwmScheduler.scheduleDailyZuluZeroStartJob( new DailySummaryJob( this ), executorService, TimeDuration.ZERO );
         }
 
-        LOGGER.trace( () -> "completed post init tasks in " + TimeDuration.fromCurrent( startTime ).asCompactString() );
+        LOGGER.trace( () -> "completed post init tasks", () -> TimeDuration.fromCurrent( startTime ) );
     }
 
     private static void outputKeystore( final PwmApplication pwmApplication ) throws Exception

server/src/main/java/password/pwm/config/profile/LdapProfile.java

@@ -39,6 +39,7 @@ import password.pwm.util.java.StringUtil;
 import password.pwm.util.java.TimeDuration;
 import password.pwm.util.logging.PwmLogger;
 
+import java.time.Instant;
 import java.util.ArrayList;
 import java.util.Collections;
 import java.util.LinkedHashMap;
@@ -134,6 +135,8 @@ public class LdapProfile extends AbstractProfile implements Profile
     )
             throws PwmUnrecoverableException
     {
+        final Instant startTime = Instant.now();
+
         {
             final boolean doCanonicalDnResolve = Boolean.parseBoolean( pwmApplication.getConfig().readAppProperty( AppProperty.LDAP_RESOLVE_CANONICAL_DN ) );
             if ( !doCanonicalDnResolve )
@@ -172,7 +175,8 @@ public class LdapProfile extends AbstractProfile implements Profile
 
                 {
                     final String finalCanonical = canonicalValue;
-                    LOGGER.trace( () -> "read and cached canonical ldap DN value for input '" + dnValue + "' as '" + finalCanonical + "'" );
+                    LOGGER.trace( () -> "read and cached canonical ldap DN value for input '" + dnValue + "' as '" + finalCanonical + "'",
+                            () -> TimeDuration.fromCurrent( startTime ) );
                 }
             }
             catch ( final ChaiUnavailableException | ChaiOperationException e )

server/src/main/java/password/pwm/config/stored/ConfigurationReader.java

@@ -177,8 +177,7 @@ public class ConfigurationReader
         }
 
         final String fileSize = StringUtil.formatDiskSize( configFile.length() );
-        final TimeDuration timeDuration = TimeDuration.fromCurrent( startTime );
-        LOGGER.debug( () -> "configuration reading/parsing of " + fileSize + " complete in " + timeDuration.asLongString() );
+        LOGGER.debug( () -> "configuration reading/parsing of " + fileSize + " complete", () -> TimeDuration.fromCurrent( startTime ) );
 
 
         final Optional<String> configIsEditable = storedConfiguration.readConfigProperty( ConfigurationProperty.CONFIG_IS_EDITABLE );
@@ -306,7 +305,7 @@ public class ConfigurationReader
             StoredConfigurationFactory.output( storedConfiguration, fileOutputStream );
         }
 
-        LOGGER.info( () -> "saved configuration in " + TimeDuration.compactFromCurrent( saveFileStartTime ) );
+        LOGGER.info( () -> "saved configuration", () -> TimeDuration.fromCurrent( saveFileStartTime ) );
         if ( pwmApplication != null )
         {
             final String actualChecksum = storedConfiguration.valueHash();

server/src/main/java/password/pwm/config/stored/StoredConfigurationUtil.java

@@ -174,7 +174,7 @@ public abstract class StoredConfigurationUtil
                 .collect( Collectors.toList() );
 
 
-        LOGGER.trace( () -> "StoredConfiguration validator completed in " + TimeDuration.compactFromCurrent( startTime ) );
+        LOGGER.trace( () -> "StoredConfiguration validator completed", () -> TimeDuration.fromCurrent( startTime ) );
         return Collections.unmodifiableList( errorStrings );
     }
 
@@ -452,7 +452,7 @@ public abstract class StoredConfigurationUtil
                         }
                 ).collect( Collectors.toSet() );
 
-        LOGGER.trace( () -> "generated changeLog items via compare in " + TimeDuration.compactFromCurrent( startTime ) );
+        LOGGER.trace( () -> "generated changeLog items via compare", () -> TimeDuration.fromCurrent( startTime ) );
 
         return Collections.unmodifiableSet( deltaReferences );
     }

server/src/main/java/password/pwm/health/HealthMonitor.java

@@ -180,7 +180,7 @@ public class HealthMonitor implements PwmService
             LOGGER.trace( () ->  "begin force immediate check" );
             final Future future = pwmApplication.getPwmScheduler().scheduleJob( new ImmediateJob(), executorService, TimeDuration.ZERO );
             settings.getMaximumForceCheckWait().pause( future::isDone );
-            LOGGER.trace( () ->  "exit force immediate check, done=" + future.isDone() + ", " + TimeDuration.compactFromCurrent( startTime ) );
+            LOGGER.trace( () ->  "exit force immediate check, done=" + future.isDone(), () -> TimeDuration.fromCurrent( startTime ) );
         }
 
         pwmApplication.getPwmScheduler().scheduleJob( new UpdateJob(), executorService, settings.getNominalCheckInterval() );
@@ -231,7 +231,7 @@ public class HealthMonitor implements PwmService
         }
 
         final Instant startTime = Instant.now();
-        LOGGER.trace( () -> "beginning health check execution (" + counter + ")" );
+        LOGGER.trace( () -> "beginning health check execution #" + counter  );
         final List<HealthRecord> tempResults = new ArrayList<>();
         for ( final HealthChecker loopChecker : HEALTH_CHECKERS )
         {
@@ -271,7 +271,7 @@ public class HealthMonitor implements PwmService
         }
 
         healthData = new HealthData( Collections.unmodifiableSet( new TreeSet<>( tempResults ) ), Instant.now() );
-        LOGGER.trace( () -> "completed health check execution (" + counter + ") in " + TimeDuration.compactFromCurrent( startTime ) );
+        LOGGER.trace( () -> "completed health check execution #" + counter, () -> TimeDuration.fromCurrent( startTime ) );
     }
 
     public ServiceInfoBean serviceInfo( )
@@ -305,7 +305,7 @@ public class HealthMonitor implements PwmService
             {
                 final Instant startTime = Instant.now();
                 doHealthChecks();
-                LOGGER.trace( () -> "completed health check dredge " + TimeDuration.compactFromCurrent( startTime ) );
+                LOGGER.trace( () -> "completed health check dredge ", () -> TimeDuration.fromCurrent( startTime ) );
             }
             catch ( final Throwable e )
             {

server/src/main/java/password/pwm/http/ContextManager.java

@@ -557,7 +557,7 @@ public class ContextManager implements Serializable
 
                 {
                     final TimeDuration timeDuration = TimeDuration.fromCurrent( startTime );
-                    LOGGER.info( SESSION_LABEL, () -> "application restart completed (" + timeDuration.asCompactString() + ")" );
+                    LOGGER.info( SESSION_LABEL, () -> "application restart completed", () -> timeDuration );
                 }
             }
             finally

server/src/main/java/password/pwm/http/PwmRequest.java

@@ -47,6 +47,7 @@ import password.pwm.ldap.UserInfo;
 import password.pwm.util.Validator;
 import password.pwm.util.java.LazySupplier;
 import password.pwm.util.java.StringUtil;
+import password.pwm.util.java.TimeDuration;
 import password.pwm.util.logging.PwmLogLevel;
 import password.pwm.util.logging.PwmLogger;
 import password.pwm.util.secure.PwmSecurityKey;
@@ -59,6 +60,7 @@ import java.io.ByteArrayOutputStream;
 import java.io.IOException;
 import java.io.InputStream;
 import java.io.Serializable;
+import java.time.Instant;
 import java.util.ArrayList;
 import java.util.Collections;
 import java.util.HashSet;
@@ -82,6 +84,7 @@ public class PwmRequest extends PwmHttpRequestWrapper
     private final transient Supplier<SessionLabel> sessionLabelLazySupplier = new LazySupplier<>( this::makeSessionLabel );
 
     private final Set<PwmRequestFlag> flags = new HashSet<>();
+    private final Instant requestStartTime = Instant.now();
 
     public static PwmRequest forRequest(
             final HttpServletRequest request,
@@ -385,13 +388,13 @@ public class PwmRequest extends PwmHttpRequestWrapper
         return pwmURL;
     }
 
-    public void debugHttpRequestToLog( final String extraText )
+    public void debugHttpRequestToLog( final String extraText, final Supplier<TimeDuration> timeDuration )
             throws PwmUnrecoverableException
     {
         if ( LOGGER.isEnabled( PwmLogLevel.TRACE ) )
         {
             final String debugTxt = debugHttpRequestToString( extraText, false );
-            LOGGER.trace( this.getLabel(), () -> debugTxt );
+            LOGGER.trace( this.getLabel(), () -> debugTxt, timeDuration );
         }
     }
 
@@ -592,4 +595,9 @@ public class PwmRequest extends PwmHttpRequestWrapper
     {
         return pwmRequestID.toString();
     }
+
+    public Instant getRequestStartTime()
+    {
+        return requestStartTime;
+    }
 }

server/src/main/java/password/pwm/http/filter/SessionFilter.java

@@ -95,7 +95,7 @@ public class SessionFilter extends AbstractPwmFilter
 
         if ( !pwmURL.isResourceURL() )
         {
-            pwmRequest.debugHttpRequestToLog( "" );
+            pwmRequest.debugHttpRequestToLog( "", null );
         }
 
         if ( !pwmURL.isRestService() && !pwmURL.isResourceURL() )
@@ -136,7 +136,7 @@ public class SessionFilter extends AbstractPwmFilter
         }
 
         final TimeDuration requestExecuteTime = TimeDuration.fromCurrent( startTime );
-        pwmRequest.debugHttpRequestToLog( "completed requestID=" + requestID + " in " + requestExecuteTime.asCompactString() );
+        pwmRequest.debugHttpRequestToLog( "completed requestID=" + requestID, () -> requestExecuteTime );
         pwmRequest.getPwmApplication().getStatisticsManager().updateAverageValue( AvgStatistic.AVG_REQUEST_PROCESS_TIME, requestExecuteTime.asMillis() );
         pwmRequest.getPwmSession().getSessionStateBean().getRequestCount().incrementAndGet();
         pwmRequest.getPwmSession().getSessionStateBean().getAvgRequestDuration().update( requestExecuteTime.asMillis() );

server/src/main/java/password/pwm/http/servlet/accountinfo/AccountInformationBean.java

@@ -97,7 +97,7 @@ public class AccountInformationBean implements Serializable
         ) );
         builder.passwordRules( makePasswordRules( pwmRequest ) );
 
-        LOGGER.trace( pwmRequest, () -> "generated account information bean in " + TimeDuration.compactFromCurrent( startTime ) );
+        LOGGER.trace( pwmRequest, () -> "generated account information bean in ", () -> TimeDuration.fromCurrent( startTime ) );
         return builder.build();
     }
 

server/src/main/java/password/pwm/http/servlet/admin/AppDashboardData.java

@@ -167,7 +167,7 @@ public class AppDashboardData implements Serializable
         builder.sessionCount( pwmApplication.getSessionTrackService().sessionCount() );
         builder.requestsInProgress( pwmApplication.getInprogressRequests().get() );
 
-        LOGGER.trace( () -> "AppDashboardData bean created in " + TimeDuration.compactFromCurrent( startTime ) );
+        LOGGER.trace( () -> "AppDashboardData bean created in ", () -> TimeDuration.fromCurrent( startTime ) );
         return builder.build();
     }
 

server/src/main/java/password/pwm/http/servlet/configeditor/ConfigEditorServletUtils.java

@@ -150,7 +150,7 @@ public class ConfigEditorServletUtils
                     pwmRequest.getLocale()
             );
 
-            LOGGER.debug( () -> "config health check done in " + TimeDuration.compactFromCurrent( startTime ) );
+            LOGGER.debug( () -> "config health check done in ", () -> TimeDuration.fromCurrent( startTime ) );
 
             return HealthData.builder()
                     .overall( "CONFIG" )

server/src/main/java/password/pwm/http/servlet/configmanager/DebugItemGenerator.java

@@ -190,9 +190,9 @@ public class DebugItemGenerator
         }
 
         {
-            final String msg = "completed in " + TimeDuration.compactFromCurrent( startTime );
+            final String msg = "completed";
             debugGeneratorLogFile.appendLine( msg );
-            LOGGER.trace( sessionLabel, () -> msg );
+            LOGGER.trace( sessionLabel, () -> msg, () ->  TimeDuration.fromCurrent( startTime ) );
         }
 
         try
@@ -574,7 +574,7 @@ public class DebugItemGenerator
             final Function<PwmLogEvent, String> logEventFormatter = PwmLogEvent::toLogString;
 
             outputLogs( debugItemInput.getPwmApplication(), outputStream, logEventFormatter );
-            LOGGER.trace( () ->  "debug log output completed in " + TimeDuration.compactFromCurrent( startTime ) );
+            LOGGER.trace( () ->  "debug log output completed in ", () -> TimeDuration.fromCurrent( startTime ) );
         }
     }
 
@@ -593,7 +593,7 @@ public class DebugItemGenerator
             final Function<PwmLogEvent, String> logEventFormatter = pwmLogEvent -> JsonUtil.serialize( pwmLogEvent );
 
             outputLogs( debugItemInput.getPwmApplication(), outputStream, logEventFormatter );
-            LOGGER.trace( () ->  "debug json output completed in " + TimeDuration.compactFromCurrent( startTime ) );
+            LOGGER.trace( () ->  "debug json output completed in ", () -> TimeDuration.fromCurrent( startTime ) );
         }
     }
 

server/src/main/java/password/pwm/http/servlet/newuser/NewUserServlet.java

@@ -239,7 +239,7 @@ public class NewUserServlet extends ControlledPwmServlet
         {
             final Instant startTime = Instant.now();
             newUserProfile.getNewUserPasswordPolicy( pwmApplication, pwmSession.getSessionStateBean().getLocale() );
-            LOGGER.trace( () -> "read new user password policy in " + TimeDuration.compactFromCurrent( startTime ) );
+            LOGGER.trace( () -> "read new user password policy in ", () -> TimeDuration.fromCurrent( startTime ) );
         }
 
         if ( !newUserBean.isFormPassed() )
@@ -461,7 +461,7 @@ public class NewUserServlet extends ControlledPwmServlet
             passwordCheckInfo = new PasswordUtility.PasswordCheckInfo( null, true, 0, PasswordUtility.PasswordCheckInfo.MatchStatus.MATCH, 0 );
         }
 
-        LOGGER.trace( () -> "competed form validation in " + TimeDuration.compactFromCurrent( startTime ) );
+        LOGGER.trace( () -> "competed form validation in ", () -> TimeDuration.fromCurrent( startTime ) );
         return passwordCheckInfo;
     }
 

server/src/main/java/password/pwm/http/servlet/peoplesearch/PeopleSearchDataReader.java

@@ -630,7 +630,7 @@ class PeopleSearchDataReader
         }
         finally
         {
-            LOGGER.trace( pwmRequest, () -> "completed checkIfUserViewable for " + userIdentity.toDisplayString() + " in " + TimeDuration.compactFromCurrent( startTime ) );
+            LOGGER.trace( pwmRequest, () -> "completed checkIfUserViewable for " + userIdentity.toDisplayString() + " in ", () -> TimeDuration.fromCurrent( startTime ) );
         }
     }
 

server/src/main/java/password/pwm/http/servlet/resource/ResourceFileServlet.java

@@ -34,6 +34,7 @@ import password.pwm.svc.stats.Statistic;
 import password.pwm.svc.stats.StatisticsManager;
 import password.pwm.util.java.JavaHelper;
 import password.pwm.util.java.MovingAverage;
+import password.pwm.util.java.TimeDuration;
 import password.pwm.util.logging.PwmLogger;
 
 import javax.servlet.ServletException;
@@ -155,7 +156,7 @@ public class ResourceFileServlet extends HttpServlet implements PwmServlet
             pwmRequest.getPwmResponse().getHttpServletResponse().sendError( HttpServletResponse.SC_INTERNAL_SERVER_ERROR, e.getMessage() );
             try
             {
-                pwmRequest.debugHttpRequestToLog( "returning HTTP 500 status" );
+                pwmRequest.debugHttpRequestToLog( "returning HTTP 500 status", null );
             }
             catch ( final PwmUnrecoverableException e2 )
             {
@@ -169,7 +170,7 @@ public class ResourceFileServlet extends HttpServlet implements PwmServlet
             pwmRequest.getPwmResponse().getHttpServletResponse().sendError( HttpServletResponse.SC_NOT_FOUND );
             try
             {
-                pwmRequest.debugHttpRequestToLog( "returning HTTP 404 status" );
+                pwmRequest.debugHttpRequestToLog( "returning HTTP 404 status", null );
             }
             catch ( final PwmUnrecoverableException e )
             {
@@ -209,7 +210,7 @@ public class ResourceFileServlet extends HttpServlet implements PwmServlet
                 debugText = makeDebugText( fromCache, acceptsGzip, true );
             }
 
-            pwmRequest.debugHttpRequestToLog( debugText );
+            pwmRequest.debugHttpRequestToLog( debugText, () -> TimeDuration.fromCurrent( pwmRequest.getRequestStartTime() ) );
 
             final MovingAverage cacheHitRatio = resourceService.getCacheHitRatio();
             StatisticsManager.incrementStat( pwmApplication, Statistic.HTTP_RESOURCE_REQUESTS );
@@ -372,7 +373,7 @@ public class ResourceFileServlet extends HttpServlet implements PwmServlet
             response.setStatus( HttpServletResponse.SC_NOT_MODIFIED );
             try
             {
-                pwmRequest.debugHttpRequestToLog( "returning HTTP 304 status" );
+                pwmRequest.debugHttpRequestToLog( "returning HTTP 304 status", null );
             }
             catch ( final PwmUnrecoverableException e2 )
             {

server/src/main/java/password/pwm/http/servlet/resource/ResourceServletService.java

@@ -182,7 +182,7 @@ public class ResourceServletService implements PwmService
 
         final Instant startTime = Instant.now();
         final String nonce = checksumAllResources( pwmApplication );
-        LOGGER.debug( () -> "completed generation of nonce '" + nonce + "' in " + TimeDuration.fromCurrent( startTime ).asCompactString() );
+        LOGGER.debug( () -> "completed generation of nonce '" + nonce + "'", () ->  TimeDuration.fromCurrent( startTime ) );
 
         final String noncePrefix = pwmApplication.getConfig().readAppProperty( AppProperty.HTTP_RESOURCES_NONCE_PATH_PREFIX );
         return "/" + noncePrefix + nonce;

server/src/main/java/password/pwm/ldap/search/UserSearchEngine.java

@@ -765,7 +765,7 @@ public class UserSearchEngine implements PwmService
     void log( final PwmLogLevel level, final SessionLabel sessionLabel, final int searchID, final int jobID, final String message )
     {
         final String idMsg = logIdString( searchID, jobID );
-        LOGGER.log( level, sessionLabel, idMsg + " " + message );
+        LOGGER.log( level, sessionLabel, () -> idMsg + " " + message );
     }
 
     private static String logIdString( final int searchID, final int jobID )

server/src/main/java/password/pwm/svc/PwmServiceManager.java

@@ -157,7 +157,7 @@ public class PwmServiceManager
         }
         initialized = false;
 
-        LOGGER.trace( () -> "closed all services in " + TimeDuration.compactFromCurrent( startTime ) );
+        LOGGER.trace( () -> "closed all services in ", () -> TimeDuration.fromCurrent( startTime ) );
     }
 
     private void shutDownService( final Class<? extends PwmService> serviceClass )

server/src/main/java/password/pwm/svc/event/AuditService.java

@@ -93,6 +93,8 @@ public class AuditService implements PwmService
         this.status = STATUS.OPENING;
         this.pwmApplication = pwmApplication;
 
+        final Instant startTime = Instant.now();
+
         settings = new AuditSettings( pwmApplication.getConfig() );
 
         if ( pwmApplication.getApplicationMode() == null || pwmApplication.getApplicationMode() == PwmApplicationMode.READ_ONLY )
@@ -119,7 +121,7 @@ public class AuditService implements PwmService
             catch ( final Exception e )
             {
                 final ErrorInformation errorInformation = new ErrorInformation( PwmError.ERROR_SYSLOG_WRITE_ERROR, "startup error: " + e.getMessage() );
-                LOGGER.error( () -> errorInformation.toDebugStr() );
+                LOGGER.error( errorInformation::toDebugStr );
             }
         }
         {
@@ -163,7 +165,7 @@ public class AuditService implements PwmService
                     status = STATUS.CLOSED;
                     return;
             }
-            LOGGER.info( () -> debugMsg );
+            LOGGER.debug( () -> debugMsg, () -> TimeDuration.fromCurrent( startTime ) );
             serviceInfo = new ServiceInfoBean( Collections.singletonList( storageMethodUsed ) );
         }
         {

server/src/main/java/password/pwm/svc/report/ReportService.java

@@ -416,7 +416,7 @@ public class ReportService implements PwmService
                 transactionCalculator.recordLastTransactionDuration( TimeDuration.fromCurrent( loopStart ) );
             }
             LOGGER.trace( SessionLabel.REPORTING_SESSION_LABEL,
-                    () -> "completed transfer of ldap search results to work queue in " + TimeDuration.compactFromCurrent( startTime ) );
+                    () -> "completed transfer of ldap search results to work queue in ", () -> TimeDuration.fromCurrent( startTime ) );
         }
     }
 

server/src/main/java/password/pwm/svc/sessiontrack/UserAgentUtils.java

@@ -62,7 +62,7 @@ public class UserAgentUtils
     {
         final Instant startTime = Instant.now();
         CACHED_PARSER.get();
-        LOGGER.trace( () -> "loaded useragent parser in " + TimeDuration.compactFromCurrent( startTime ) );
+        LOGGER.trace( () -> "loaded useragent parser", () -> TimeDuration.fromCurrent( startTime ) );
     }
 
     public static void checkIfPreIE11( final PwmRequest pwmRequest ) throws PwmUnrecoverableException

server/src/main/java/password/pwm/svc/telemetry/FtpTelemetrySender.java

@@ -170,7 +170,7 @@ public class FtpTelemetrySender implements TelemetrySender
                 throw new PwmUnrecoverableException( new ErrorInformation( PwmError.ERROR_TELEMETRY_SEND_ERROR, msg ) );
             }
 
-            LOGGER.trace( SessionLabel.TELEMETRY_SESSION_LABEL, () -> "completed transfer of " + fileBytes.length + " in " + TimeDuration.compactFromCurrent( startTime ) );
+            LOGGER.trace( SessionLabel.TELEMETRY_SESSION_LABEL, () -> "completed transfer of " + fileBytes.length + " in ", () -> TimeDuration.fromCurrent( startTime ) );
         }
         catch ( final IOException e )
         {

server/src/main/java/password/pwm/svc/token/DataStoreTokenMachine.java

@@ -103,8 +103,7 @@ public class DataStoreTokenMachine implements TokenMachine
         }
         {
             final long finalSize = size();
-            LOGGER.trace( () -> "completed record purge cycle in " + TimeDuration.compactFromCurrent( startTime )
-                    + "; database size = " + finalSize );
+            LOGGER.trace( () -> "completed record purge cycle; database size = " + finalSize, () -> TimeDuration.fromCurrent( startTime ) );
         }
     }
 

server/src/main/java/password/pwm/svc/wordlist/SharedHistoryManager.java

@@ -229,10 +229,10 @@ public class SharedHistoryManager implements PwmService
         try
         {
             final long size = localDB.size( WORDS_DB );
-            LOGGER.info( () -> "open with " + size + " words ("
-                    + TimeDuration.compactFromCurrent( startTime ) + ")"
+            LOGGER.debug( () -> "open with " + size + " words"
                     + ", maxAgeMs=" + TimeDuration.of( maxAgeMs, TimeDuration.Unit.MILLISECONDS ).asCompactString()
-                    + ", oldestEntry=" + TimeDuration.fromCurrent( oldestEntry ).asCompactString() );
+                    + ", oldestEntry=" + TimeDuration.fromCurrent( oldestEntry ).asCompactString(),
+                    () -> TimeDuration.fromCurrent( startTime ) );
         }
         catch ( final LocalDBException e )
         {
@@ -426,7 +426,7 @@ public class SharedHistoryManager implements PwmService
                 LOGGER.debug( () -> "completed wordDB reduce operation" + ", removed=" + finalRemove
                         + ", totalRemaining=" + size()
                         + ", oldestEntry=" + TimeDuration.asCompactString( oldestEntry )
-                        + " in " + TimeDuration.compactFromCurrent( startTime ) );
+                        + " in ", () -> TimeDuration.fromCurrent( startTime ) );
             }
         }
     }

server/src/main/java/password/pwm/svc/wordlist/WordlistImporter.java

@@ -319,7 +319,7 @@ class WordlistImporter implements Runnable
         final long wordlistSize = wordlistBucket.size();
 
         getLogger().info( () -> "population complete, added " + wordlistSize
-                + " total words in " + TimeDuration.compactFromCurrent( startTime ) );
+                + " total words in ", () -> TimeDuration.fromCurrent( startTime ) );
 
         completed = true;
         writeCurrentWordlistStatus();

server/src/main/java/password/pwm/util/localdb/LocalDBFactory.java

@@ -97,7 +97,7 @@ public class LocalDBFactory
         }
 
         final StringBuilder debugText = new StringBuilder();
-        debugText.append( "LocalDB open in " ).append( openTime.asCompactString() );
+        debugText.append( "LocalDB open" );
         if ( localDB.getFileLocation() != null )
         {
             debugText.append( ", db size: " ).append( StringUtil.formatDiskSize( FileSystemUtility.getFileDirectorySize( localDB.getFileLocation() ) ) );
@@ -108,7 +108,7 @@ public class LocalDBFactory
                 debugText.append( ", " ).append( StringUtil.formatDiskSize( freeSpace ) ).append( " free" );
             }
         }
-        LOGGER.info( () -> debugText );
+        LOGGER.info( () -> debugText, () -> openTime );
 
         return localDB;
     }

server/src/main/java/password/pwm/util/localdb/WorkQueueProcessor.java

@@ -53,6 +53,7 @@ import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.concurrent.atomic.AtomicInteger;
 import java.util.concurrent.locks.LockSupport;
+import java.util.function.Supplier;
 
 /**
  * A work item queue manager.   Items submitted to the queue will eventually be worked on by the client side @code {@link ItemProcessor}.
@@ -205,12 +206,13 @@ public final class WorkQueueProcessor<W extends Serializable>
 
     private void sendAndQueueIfNecessary( final ItemWrapper<W> itemWrapper )
     {
+        final Instant processStartTime = Instant.now();
         try
         {
             final ProcessResult processResult = itemProcessor.process( itemWrapper.getWorkItem() );
             if ( processResult == ProcessResult.SUCCESS )
             {
-                logAndStatUpdateForSuccess( itemWrapper );
+                logAndStatUpdateForSuccess( itemWrapper, () -> TimeDuration.fromCurrent( processStartTime ) );
             }
             else if ( processResult == ProcessResult.RETRY || processResult == ProcessResult.NOOP )
             {
@@ -400,6 +402,7 @@ public final class WorkQueueProcessor<W extends Serializable>
 
         void processNextItem( )
         {
+            final Instant processStartTime = Instant.now();
             final String nextStrValue = queue.peekFirst();
             if ( nextStrValue == null )
             {
@@ -455,7 +458,7 @@ public final class WorkQueueProcessor<W extends Serializable>
                         case SUCCESS:
                         {
                             removeQueueTop();
-                            logAndStatUpdateForSuccess( itemWrapper );
+                            logAndStatUpdateForSuccess( itemWrapper, () -> TimeDuration.fromCurrent( processStartTime ) );
                         }
                         break;
 
@@ -575,14 +578,14 @@ public final class WorkQueueProcessor<W extends Serializable>
         private TimeDuration maxShutdownWaitTime = TimeDuration.of( 30, TimeDuration.Unit.SECONDS );
     }
 
-    private void logAndStatUpdateForSuccess( final ItemWrapper<W> itemWrapper )
+    private void logAndStatUpdateForSuccess( final ItemWrapper<W> itemWrapper, final Supplier<TimeDuration> processDuration )
             throws PwmOperationalException
     {
         final TimeDuration lagTime = TimeDuration.fromCurrent( itemWrapper.getDate() );
         avgLagTime.update( lagTime.asMillis() );
         sendRate.markEvents( 1 );
         logger.trace( () -> "successfully processed item=" + makeDebugText( itemWrapper ) + "; lagTime=" + lagTime.asCompactString()
-                + "; " + StringUtil.mapToString( debugInfo() ) );
+                + "; " + StringUtil.mapToString( debugInfo() ), processDuration );
     }
 
     public Map<String, String> debugInfo( )

server/src/main/java/password/pwm/util/logging/LocalDBLogger.java

@@ -140,8 +140,7 @@ public class LocalDBLogger implements PwmService
 
         cleanOnWriteFlag.set( eventQueue.size() >= this.settings.getMaxEvents() );
 
-        final TimeDuration timeDuration = TimeDuration.fromCurrent( startTime );
-        LOGGER.info( () -> "open in " + timeDuration.asCompactString() + ", " + debugStats() );
+        LOGGER.info( () -> "open, " + debugStats(), () -> TimeDuration.fromCurrent( startTime ) );
     }
 
 

server/src/main/java/password/pwm/util/logging/PwmLogger.java

@@ -35,6 +35,7 @@ import password.pwm.svc.event.AuditRecord;
 import password.pwm.svc.event.AuditRecordFactory;
 import password.pwm.util.java.JavaHelper;
 import password.pwm.util.java.JsonUtil;
+import password.pwm.util.java.TimeDuration;
 
 import java.io.IOException;
 import java.time.Instant;
@@ -117,7 +118,12 @@ public class PwmLogger
         return name;
     }
 
-    private void doPwmRequestLogEvent( final PwmLogLevel level, final PwmRequest pwmRequest, final Supplier<CharSequence> message, final Throwable e )
+    private void doPwmRequestLogEvent(
+            final PwmLogLevel level,
+            final PwmRequest pwmRequest,
+            final Supplier<CharSequence> message,
+            final Throwable e,
+            final Supplier<TimeDuration> timeDuration )
     {
         if ( !isEnabled( level ) )
         {
@@ -141,15 +147,26 @@ public class PwmLogger
             }
         }
 
-        doLogEvent( level, sessionLabel, cleanedMessage, e );
+        doLogEvent( level, sessionLabel, cleanedMessage, e, timeDuration );
     }
 
-    private void doLogEvent( final PwmLogLevel level, final SessionLabel sessionLabel, final CharSequence message, final Throwable e )
+    private void doLogEvent(
+            final PwmLogLevel level,
+            final SessionLabel sessionLabel,
+            final Supplier<CharSequence> message,
+            final Throwable e
+            )
     {
-        doLogEvent( level, sessionLabel, () -> message == null ? "" : message, e );
+        doLogEvent( level, sessionLabel, message, e, null );
     }
 
-    private void doLogEvent( final PwmLogLevel level, final SessionLabel sessionLabel, final Supplier<CharSequence> message, final Throwable e )
+    private void doLogEvent(
+            final PwmLogLevel level,
+            final SessionLabel sessionLabel,
+            final Supplier<CharSequence> message,
+            final Throwable e,
+            final Supplier<TimeDuration> timeDuration
+    )
     {
         if ( !isEnabled( level ) )
         {
@@ -158,12 +175,26 @@ public class PwmLogger
 
         final PwmLogLevel effectiveLevel = level == null ? PwmLogLevel.TRACE : level;
         final String topic = log4jLogger.getName();
-        final CharSequence effectiveMessage = message == null ? "" : message.get();
+        final CharSequence effectiveMessage = formatEffectiveMessage( message, timeDuration );
         final PwmLogEvent logEvent = PwmLogEvent.createPwmLogEvent( Instant.now(), topic, effectiveMessage.toString(), sessionLabel,
                 e, effectiveLevel );
         doLogEvent( logEvent );
     }
 
+    private CharSequence formatEffectiveMessage( final Supplier<CharSequence> message, final Supplier<TimeDuration> timeDuration )
+    {
+        final CharSequence output = message == null
+                ? ""
+                : message.get();
+
+        if ( timeDuration != null )
+        {
+            return output + " (" + timeDuration.get().asCompactString() + ")";
+        }
+
+        return output;
+    }
+
     private void doLogEvent( final PwmLogEvent logEvent )
     {
         pushMessageToLog4j( logEvent );
@@ -244,14 +275,9 @@ public class PwmLogger
         }
     }
 
-    private static String convertErrorInformation( final ErrorInformation info )
-    {
-        return info.toDebugStr();
-    }
-
-    public void log( final PwmLogLevel level, final SessionLabel sessionLabel, final CharSequence message )
+    private static Supplier<CharSequence> convertErrorInformation( final ErrorInformation info )
     {
-        doLogEvent( level, sessionLabel, message, null );
+        return info::toDebugStr;
     }
 
     public void log( final PwmLogLevel level, final SessionLabel sessionLabel, final Supplier<CharSequence> message )
@@ -264,9 +290,19 @@ public class PwmLogger
         doLogEvent( PwmLogLevel.TRACE, null, message, null );
     }
 
+    public void trace( final Supplier<CharSequence> message, final Supplier<TimeDuration> timeDuration )
+    {
+        doLogEvent( PwmLogLevel.TRACE, null, message, null, timeDuration );
+    }
+
     public void trace( final PwmRequest pwmRequest, final Supplier<CharSequence> message )
     {
-        doPwmRequestLogEvent( PwmLogLevel.TRACE, pwmRequest, message, null );
+        doPwmRequestLogEvent( PwmLogLevel.TRACE, pwmRequest, message, null, null );
+    }
+
+    public void trace( final PwmRequest pwmRequest, final Supplier<CharSequence> message, final Supplier<TimeDuration> timeDuration )
+    {
+        doPwmRequestLogEvent( PwmLogLevel.TRACE, pwmRequest, message, null, timeDuration );
     }
 
     public void trace( final SessionLabel sessionLabel, final Supplier<CharSequence> message )
@@ -274,6 +310,11 @@ public class PwmLogger
         doLogEvent( PwmLogLevel.TRACE, sessionLabel, message, null );
     }
 
+    public void trace( final SessionLabel sessionLabel, final Supplier<CharSequence> message, final Supplier<TimeDuration> timeDuration )
+    {
+        doLogEvent( PwmLogLevel.TRACE, sessionLabel, message, null, timeDuration );
+    }
+
     public void trace( final Supplier<CharSequence> message, final Throwable exception )
     {
         doLogEvent( PwmLogLevel.TRACE, null, message, exception );
@@ -284,14 +325,19 @@ public class PwmLogger
         doLogEvent( PwmLogLevel.DEBUG, null, message, null );
     }
 
+    public void debug( final Supplier<CharSequence> message, final Supplier<TimeDuration> timeDuration )
+    {
+        doLogEvent( PwmLogLevel.DEBUG, null, message, null, timeDuration );
+    }
+
     public void debug( final PwmRequest pwmRequest, final Supplier<CharSequence> message )
     {
-        doPwmRequestLogEvent( PwmLogLevel.DEBUG, pwmRequest, message, null );
+        doPwmRequestLogEvent( PwmLogLevel.DEBUG, pwmRequest, message, null, null );
     }
 
     public void debug( final PwmRequest pwmRequest, final ErrorInformation errorInformation )
     {
-        doPwmRequestLogEvent( PwmLogLevel.DEBUG, pwmRequest, () -> convertErrorInformation( errorInformation ), null );
+        doPwmRequestLogEvent( PwmLogLevel.DEBUG, pwmRequest, convertErrorInformation( errorInformation ), null, null );
     }
 
     public void debug( final SessionLabel sessionLabel, final Supplier<CharSequence> message )
@@ -299,6 +345,11 @@ public class PwmLogger
         doLogEvent( PwmLogLevel.DEBUG, sessionLabel, message, null );
     }
 
+    public void debug( final SessionLabel sessionLabel, final Supplier<CharSequence> message, final Supplier<TimeDuration> timeDuration )
+    {
+        doLogEvent( PwmLogLevel.DEBUG, sessionLabel, message, null, timeDuration );
+    }
+
     public void debug( final SessionLabel sessionLabel, final ErrorInformation errorInformation )
     {
         doLogEvent( PwmLogLevel.DEBUG, sessionLabel, convertErrorInformation( errorInformation ), null );
@@ -306,7 +357,7 @@ public class PwmLogger
 
     public void debug( final Supplier<CharSequence> message, final Throwable exception )
     {
-        doPwmRequestLogEvent( PwmLogLevel.DEBUG, null, message, exception );
+        doPwmRequestLogEvent( PwmLogLevel.DEBUG, null, message, exception, null );
     }
 
     public void info( final Supplier<CharSequence> message )
@@ -314,14 +365,19 @@ public class PwmLogger
         doLogEvent( PwmLogLevel.INFO, null, message, null );
     }
 
+    public void info( final Supplier<CharSequence> message, final Supplier<TimeDuration> timeDuration )
+    {
+        doLogEvent( PwmLogLevel.INFO, null, message, null, timeDuration );
+    }
+
     public void info( final PwmRequest pwmRequest, final Supplier<CharSequence> message )
     {
-        doPwmRequestLogEvent( PwmLogLevel.INFO, pwmRequest, message, null );
+        doPwmRequestLogEvent( PwmLogLevel.INFO, pwmRequest, message, null, null );
     }
 
     public void info( final PwmRequest pwmRequest, final ErrorInformation errorInformation )
     {
-        doPwmRequestLogEvent( PwmLogLevel.INFO, pwmRequest, () -> convertErrorInformation( errorInformation ), null );
+        doPwmRequestLogEvent( PwmLogLevel.INFO, pwmRequest, convertErrorInformation( errorInformation ), null, null );
     }
 
     public void info( final SessionLabel sessionLabel, final Supplier<CharSequence> message )
@@ -329,6 +385,11 @@ public class PwmLogger
         doLogEvent( PwmLogLevel.INFO, sessionLabel, message, null );
     }
 
+    public void info( final SessionLabel sessionLabel, final Supplier<CharSequence> message, final Supplier<TimeDuration> timeDuration )
+    {
+        doLogEvent( PwmLogLevel.INFO, sessionLabel, message, null, timeDuration );
+    }
+
     public void info( final Supplier<CharSequence> message, final Throwable exception )
     {
         doLogEvent( PwmLogLevel.INFO, null, message, exception );
@@ -341,22 +402,22 @@ public class PwmLogger
 
     public void error( final PwmRequest pwmRequest, final Supplier<CharSequence> message, final Throwable exception )
     {
-        doPwmRequestLogEvent( PwmLogLevel.ERROR, pwmRequest, message, exception );
+        doPwmRequestLogEvent( PwmLogLevel.ERROR, pwmRequest, message, exception, null );
     }
 
     public void error( final PwmRequest pwmRequest, final Supplier<CharSequence> message )
     {
-        doPwmRequestLogEvent( PwmLogLevel.ERROR, pwmRequest, message, null );
+        doPwmRequestLogEvent( PwmLogLevel.ERROR, pwmRequest, message, null, null );
     }
 
     public void error( final PwmRequest pwmRequest, final ErrorInformation errorInformation )
     {
-        doPwmRequestLogEvent( PwmLogLevel.ERROR, pwmRequest, () -> convertErrorInformation( errorInformation ), null );
+        doPwmRequestLogEvent( PwmLogLevel.ERROR, pwmRequest, convertErrorInformation( errorInformation ), null, null );
     }
 
     public void error( final ErrorInformation errorInformation )
     {
-        doPwmRequestLogEvent( PwmLogLevel.ERROR, null, () -> convertErrorInformation( errorInformation ), null );
+        doPwmRequestLogEvent( PwmLogLevel.ERROR, null, convertErrorInformation( errorInformation ), null, null );
     }
 
     public void error( final SessionLabel sessionLabel, final Supplier<CharSequence> message )
@@ -391,12 +452,12 @@ public class PwmLogger
 
     public void warn( final PwmRequest pwmRequest, final Supplier<CharSequence> message )
     {
-        doPwmRequestLogEvent( PwmLogLevel.WARN, pwmRequest, message, null );
+        doPwmRequestLogEvent( PwmLogLevel.WARN, pwmRequest, message, null, null );
     }
 
     public void warn( final PwmRequest pwmRequest, final Supplier<CharSequence> message, final Throwable exception )
     {
-        doPwmRequestLogEvent( PwmLogLevel.WARN, pwmRequest, message, exception );
+        doPwmRequestLogEvent( PwmLogLevel.WARN, pwmRequest, message, exception, null );
     }
 
     public void warn( final SessionLabel sessionLabel, final ErrorInformation errorInformation, final Throwable exception )
@@ -488,7 +549,7 @@ public class PwmLogger
             {
                 final String line = buffer.substring( 0, length );
                 buffer.delete( 0, +length + 1 );
-                doLogEvent( logLevel, sessionLabel, line, null );
+                doLogEvent( logLevel, sessionLabel, () -> line, null );
                 length = buffer.indexOf( "\n" );
             }
         }
@@ -517,18 +578,6 @@ public class PwmLogger
 
     public boolean isEnabled( final PwmLogLevel pwmLogLevel )
     {
-        /*
-        if ( minimumDbLogLevel != null )
-        {
-            final int compareValue = minimumDbLogLevel.compareTo( pwmLogLevel );
-            final boolean dbLogLevelHigher =  compareValue <= 0;
-            System.out.println( " dbLogLevelHigher=" + dbLogLevelHigher
-                    + ", compareValue=" + compareValue
-                    + " pwmLogLevel=" + pwmLogLevel
-                    + ", minDbLevel=" + minimumDbLogLevel );
-        }
-        */
-
         return (
                 log4jLogger != null
                         && log4jLogger.isEnabledFor( pwmLogLevel.getLog4jLevel() )

server/src/main/java/password/pwm/util/operations/CrService.java

@@ -174,9 +174,8 @@ public class CrService implements PwmService
 
                         LOGGER.debug( sessionLabel, () -> "using ldap c/r policy for user " + theUser.getEntryDN() + ": "
                                 + finalReturnSet.toString() );
-                        LOGGER.trace( sessionLabel, () -> "readUserChallengeProfile completed in "
-                                + TimeDuration.fromCurrent( methodStartTime ).asCompactString() + ", result="
-                                + JsonUtil.serialize( challengeProfile ) );
+                        LOGGER.trace( sessionLabel, () -> "readUserChallengeProfile completed, result=" + JsonUtil.serialize( challengeProfile ),
+                                () -> TimeDuration.fromCurrent( methodStartTime ) );
 
                         return challengeProfile;
                     }
@@ -319,7 +318,7 @@ public class CrService implements PwmService
                                     new String[]
                                             {
                                                     loopChallenge.getChallengeText(),
-                                            }
+                                                    }
                             );
                             throw new PwmDataValidationException( errorInfo );
                         }
@@ -345,7 +344,7 @@ public class CrService implements PwmService
                                 new String[]
                                         {
                                                 text,
-                                        }
+                                                }
                         );
                         throw new PwmDataValidationException( errorInformation );
                     }

server/src/main/java/password/pwm/util/operations/cr/LdapCrOperator.java

@@ -37,8 +37,11 @@ import password.pwm.config.profile.LdapProfile;
 import password.pwm.error.ErrorInformation;
 import password.pwm.error.PwmError;
 import password.pwm.error.PwmUnrecoverableException;
+import password.pwm.util.java.TimeDuration;
 import password.pwm.util.logging.PwmLogger;
 
+import java.time.Instant;
+
 public class LdapCrOperator implements CrOperator
 {
 
@@ -132,6 +135,7 @@ public class LdapCrOperator implements CrOperator
     public void writeResponses( final UserIdentity userIdentity, final ChaiUser theUser, final String userGuid, final ResponseInfoBean responseInfoBean )
             throws PwmUnrecoverableException
     {
+        final Instant startTime = Instant.now();
         final LdapProfile ldapProfile = userIdentity.getLdapProfile( config );
         final String ldapStorageAttribute = ldapProfile.readSettingAsString( PwmSetting.CHALLENGE_USER_ATTRIBUTE );
         if ( ldapStorageAttribute == null || ldapStorageAttribute.length() < 1 )
@@ -151,7 +155,7 @@ public class LdapCrOperator implements CrOperator
                     responseInfoBean.getCsIdentifier()
             );
             ChaiCrFactory.writeChaiResponseSet( responseSet, theUser );
-            LOGGER.info( () -> "saved responses for user to chai-ldap format" );
+            LOGGER.info( () -> "saved responses for user to chai-ldap format", () -> TimeDuration.fromCurrent( startTime ) );
         }
         catch ( final ChaiException e )
         {

server/src/main/java/password/pwm/util/password/PasswordUtility.java

@@ -956,7 +956,7 @@ public class PasswordUtility
                 throw new IllegalStateException( "unknown policy source defined: " + ppSource.name() );
         }
 
-        LOGGER.trace( pwmSession, () -> "readPasswordPolicyForUser completed in " + TimeDuration.fromCurrent( startTime ).asCompactString() );
+        LOGGER.trace( pwmSession, () -> "readPasswordPolicyForUser completed", () -> TimeDuration.fromCurrent( startTime ) );
         return returnPolicy;
     }
 

server/src/main/java/password/pwm/ws/server/RestServlet.java

@@ -180,7 +180,7 @@ public abstract class RestServlet extends HttpServlet
 
         outputRestResultBean( restResultBean, req, resp );
         final boolean success = restResultBean != null && !restResultBean.isError();
-        LOGGER.trace( sessionLabel, () -> "completed rest invocation in " + TimeDuration.compactFromCurrent( startTime ) + " success=" + success );
+        LOGGER.trace( sessionLabel, () -> "completed rest invocation, success=" + success, () -> TimeDuration.fromCurrent( startTime ) );
     }
 
     private RestResultBean invokeWebService( final RestRequest restRequest ) throws IOException, PwmUnrecoverableException

server/src/main/java/password/pwm/ws/server/rest/RestStatusServer.java

@@ -100,8 +100,8 @@ public class RestStatusServer extends RestServlet
             StatisticsManager.incrementStat( restRequest.getPwmApplication(), Statistic.REST_STATUS );
 
             final RestResultBean restResultBean = RestResultBean.withData( publicUserInfoBean );
-            LOGGER.debug( restRequest.getSessionLabel(), () -> "completed REST status request in "
-                    + TimeDuration.compactFromCurrent( startTime ) + ", result=" + JsonUtil.serialize( restResultBean ) );
+            LOGGER.debug( restRequest.getSessionLabel(), () -> "completed REST status request, result="
+                    + JsonUtil.serialize( restResultBean ), () -> TimeDuration.fromCurrent( startTime ) );
             return restResultBean;
         }
         catch ( final PwmException e )