LDEV-6290 refactor scope logging levels

core/src/main/java/lucee/runtime/type/scope/ScopeContext.java

@@ -123,6 +123,10 @@ public void error(Throwable t) {
 		error(getLog(), t);
 	}
 
+	public static void trace(Log log, String msg) {
+		if (LogUtil.doesTrace(log)) log.log(Log.LEVEL_TRACE, "scope-context", msg + "; " + ExceptionUtil.getTagContextLine(null));
+	}
+
 	public static void debug(Log log, String msg) {
 		if (LogUtil.doesDebug(log)) log.log(Log.LEVEL_DEBUG, "scope-context", msg + "; " + ExceptionUtil.getTagContextLine(null));
 	}
@@ -288,8 +292,7 @@ else if ("cookie".equals(storage)) {
 			}
 		}
 		else {
-			getLog().log(Log.LEVEL_INFO, "scope-context",
-					"use existing " + (isSession ? "session" : "client") + " scope for " + appContext.getName() + "/" + pc.getCFID() + " from storage " + storage);
+			trace(getLog(), "Use existing " + (isSession ? "session" : "client") + " scope for [" + appContext.getName() + "/" + pc.getCFID() + "] from storage " + storage);
 		}
 		scope.touchBeforeRequest(pc);
 		return scope;
@@ -514,7 +517,7 @@ public boolean remove(int type, String appName, String cfid) {
 		Map<String, Map<String, Scope>> contexts = type == Scope.SCOPE_CLIENT ? cfClientContexts : cfSessionContexts;
 		Map<String, Scope> context = getSubMap(contexts, appName);
 		Object res = context.remove(cfid);
-		getLog().log(Log.LEVEL_INFO, "scope-context", "remove " + VariableInterpreter.scopeInt2String(type) + " scope " + appName + "/" + cfid + " from memory");
+		debug(getLog(), "Remove " + VariableInterpreter.scopeInt2String(type) + " scope [" + appName + "/" + cfid + "] from memory");
 
 		return res != null;
 	}
@@ -550,11 +553,22 @@ private Session getJSessionScope(PageContext pc) throws PageException {
 			jSession = (JSession) session;
 			try {
 				if (jSession.isExpired()) {
-					if (httpSession == null) jSession.touch();
-					else jSession = createNewJSession(pc, httpSession);
-
+					if (httpSession == null) {
+						jSession.touch();
+						debug(getLog(), "JSession expired (no httpSession) — touched for [" + appContext.getName() + "/" + pc.getCFID() + "]");
+					}
+					else {
+						long now = System.currentTimeMillis();
+						long jsessionLastAccessAgo = now - jSession.getLastAccess();
+						long httpLastAccessedAgo = now - httpSession.getLastAccessedTime();
+						info(getLog(), "JSession expired but HttpSession still alive for [" + appContext.getName() + "/" + pc.getCFID() + "]"
+								+ " — replacing data (jsession.lastAccess=" + jsessionLastAccessAgo + "ms ago, httpSession.lastAccessed=" + httpLastAccessedAgo + "ms ago, gap=" + (jsessionLastAccessAgo - httpLastAccessedAgo) + "ms)");
+						jSession = createNewJSession(pc, httpSession);
+					}
+				}
+				else {
+					trace(getLog(), "Use existing JSession for [" + appContext.getName() + "/" + pc.getCFID() + "]");
 				}
-				info(getLog(), "use existing JSession for " + appContext.getName() + "/" + pc.getCFID());
 
 			}
 			catch (ClassCastException cce) {
@@ -577,14 +591,47 @@ private Session getJSessionScope(PageContext pc) throws PageException {
 
 	private JSession createNewJSession(PageContext pc, HttpSession httpSession) {
 		ApplicationContext appContext = pc.getApplicationContext();
-		debug(getLog(), "create new JSession for " + appContext.getName() + "/" + pc.getCFID());
+		Map<String, Scope> context = getSubMap(cfSessionContexts, appContext.getName());
+
+		Object prior = context.get(pc.getCFID());
+		Log log = getLog();
+		if (prior == null) {
+			if (LogUtil.doesDebug(log)) {
+				log.log(Log.LEVEL_DEBUG, "scope-context",
+						"Create new JSession for [" + appContext.getName() + "/" + pc.getCFID() + "]"
+								+ " — no prior cfSessionContexts entry" + diagSuffix(httpSession));
+			}
+		}
+		else if (prior instanceof JSession) {
+			if (LogUtil.doesInfo(log)) {
+				JSession priorJSession = (JSession) prior;
+				long lastAccessAgo = System.currentTimeMillis() - priorJSession.getLastAccess();
+				log.log(Log.LEVEL_INFO, "scope-context",
+						"Create new JSession for [" + appContext.getName() + "/" + pc.getCFID() + "]"
+								+ " — replacing prior JSession (lastAccess=" + lastAccessAgo + "ms ago, expired=" + priorJSession.isExpired() + ")"
+								+ diagSuffix(httpSession));
+			}
+		}
+		else {
+			if (LogUtil.doesWarn(log)) {
+				log.log(Log.LEVEL_WARN, "scope-context",
+						"Create new JSession for [" + appContext.getName() + "/" + pc.getCFID() + "]"
+								+ " — prior entry was non-JSession: " + prior.getClass().getName() + diagSuffix(httpSession));
+			}
+		}
+
 		JSession jSession = new JSession();
 		httpSession.setAttribute(appContext.getName(), jSession);
-		Map<String, Scope> context = getSubMap(cfSessionContexts, appContext.getName());
 		context.put(pc.getCFID(), jSession);
 		return jSession;
 	}
 
+	private static String diagSuffix(HttpSession httpSession) {
+		return " httpSessionId=" + httpSession.getId()
+				+ " httpSessionAge=" + (System.currentTimeMillis() - httpSession.getCreationTime()) + "ms"
+				+ " maxInactiveInterval=" + httpSession.getMaxInactiveInterval() + "s";
+	}
+
 	/**
 	 * return the application Scope for this context (cfid,cftoken,contextname)
 	 *
@@ -650,19 +697,24 @@ public void clearUnused(boolean force) {
 					});
 
 			// store session/client scope and remove from memory
-			storeUnusedStorageScope(factory, Scope.SCOPE_CLIENT);
-			storeUnusedStorageScope(factory, Scope.SCOPE_SESSION);
+			int clientStored = storeUnusedStorageScope(factory, Scope.SCOPE_CLIENT);
+			int sessionStored = storeUnusedStorageScope(factory, Scope.SCOPE_SESSION);
 
 			// remove unused memory based client/session scope (invoke onSessonEnd)
-			clearUnusedMemoryScope(factory, Scope.SCOPE_CLIENT);
-			clearUnusedMemoryScope(factory, Scope.SCOPE_SESSION);
+			int clientEnded = clearUnusedMemoryScope(factory, Scope.SCOPE_CLIENT);
+			int sessionEnded = clearUnusedMemoryScope(factory, Scope.SCOPE_SESSION);
 
 			// session must be executed first, because session creates a reference from client scope
 			session.clean(force);
 			client.clean(force);
 
 			// clean all unused application scopes
 			clearUnusedApplications(factory);
+
+			if (sessionEnded + clientEnded + sessionStored + clientStored > 0) {
+				info(getLog(), "Scope expiry: ended " + sessionEnded + " session(s), " + clientEnded + " client scope(s); moved to backing storage "
+						+ sessionStored + " session(s), " + clientStored + " client scope(s)");
+			}
 		}
 		catch (Exception t) {
 			error(t);
@@ -719,13 +771,14 @@ public void clear() {
 		}
 	}
 
-	private void storeUnusedStorageScope(CFMLFactoryImpl cfmlFactory, int type) {
+	private int storeUnusedStorageScope(CFMLFactoryImpl cfmlFactory, int type) {
 		Map<String, Map<String, Scope>> contexts = type == Scope.SCOPE_CLIENT ? cfClientContexts : cfSessionContexts;
 		long timespan = type == Scope.SCOPE_CLIENT ? CLIENT_MEMORY_TIMESPAN : SESSION_MEMORY_TIMESPAN;
 		String strType = VariableInterpreter.scopeInt2String(type);
 
-		if (contexts.size() == 0) return;
+		if (contexts.size() == 0) return 0;
 		long now = System.currentTimeMillis();
+		int removed = 0;
 		Object[] arrContexts = contexts.keySet().toArray();
 		Object applicationName, cfid, o;
 		Map<String, Scope> fhm;
@@ -743,21 +796,23 @@ private void storeUnusedStorageScope(CFMLFactoryImpl cfmlFactory, int type) {
 					StorageScope scope = (StorageScope) o;
 					if (scope.lastVisit() + timespan < now) {
 						if (!(scope instanceof MemoryScope)) {
-							getLog().log(Log.LEVEL_INFO, "scope-context",
-									"remove " + strType + " scope [" + applicationName + "/" + cfid + "] from memory, it remain in storage [" + scope.getStorage() + "]");
+							debug(getLog(), "Remove " + strType + " scope [" + applicationName + "/" + cfid + "] from memory, it remains in storage [" + scope.getStorage() + "]");
 							fhm.remove(arrClients[y]);
 							count--;
+							removed++;
 						}
 						else if (!((MemoryScope) scope).hasContent()) {
-							getLog().log(Log.LEVEL_INFO, "scope-context", "remove " + strType + " scope [" + applicationName + "/" + cfid + "] from memory, because it is empty.");
+							debug(getLog(), "Remove " + strType + " scope [" + applicationName + "/" + cfid + "] from memory, because it is empty.");
 							fhm.remove(arrClients[y]);
 							count--;
+							removed++;
 						}
 					}
 				}
 				if (count == 0) contexts.remove(arrContexts[i]);
 			}
 		}
+		return removed;
 	}
 
 	/**
@@ -796,9 +851,10 @@ public static boolean hasContent(Map<Key, IKStorageScopeItem> map, int type) {
 	 * @param cfmlFactory
 	 *
 	 */
-	private void clearUnusedMemoryScope(CFMLFactoryImpl cfmlFactory, int type) {
+	private int clearUnusedMemoryScope(CFMLFactoryImpl cfmlFactory, int type) {
 		Map<String, Map<String, Scope>> contexts = type == Scope.SCOPE_CLIENT ? cfClientContexts : cfSessionContexts;
-		if (contexts.size() == 0) return;
+		if (contexts.size() == 0) return 0;
+		int ended = 0;
 		Object[] arrContexts = contexts.keySet().toArray();
 		ApplicationListener listener = cfmlFactory.getConfig().getApplicationListener();
 		Object applicationName, cfid, o;
@@ -840,15 +896,16 @@ private void clearUnusedMemoryScope(CFMLFactoryImpl cfmlFactory, int type) {
 							if (application != null) application.setLastAccess(appLastAccess);
 							fhm.remove(cfids[y]);
 							scope.release(ThreadLocalPageContext.get());
-							getLog().log(Log.LEVEL_INFO, "scope-context",
-									"remove memory based " + VariableInterpreter.scopeInt2String(type) + " scope for [" + applicationName + "/" + cfid + "]");
+							debug(getLog(), "Remove memory based " + VariableInterpreter.scopeInt2String(type) + " scope for [" + applicationName + "/" + cfid + "]");
 							count--;
+							ended++;
 						}
 					}
 				}
 				if (count == 0) contexts.remove(arrContexts[i]);
 			}
 		}
+		return ended;
 	}
 
 	private void clearUnusedApplications(CFMLFactoryImpl jspFactory) {
@@ -905,6 +962,14 @@ public void invalidateUserScope(PageContextImpl pc, boolean migrateSessionData,
 		boolean hasSessionManagement = appContext.isSetSessionManagement();
 		boolean isJ2EESession = pc.getSessionType() == Config.SESSION_TYPE_JEE;
 
+		Log log = getLog();
+		if (LogUtil.doesDebug(log)) {
+			log.log(Log.LEVEL_DEBUG, "scope-context",
+					"Invalidate user scope [" + appContext.getName() + "/" + pc.getCFID() + "]"
+							+ " sessionType=" + (isJ2EESession ? "jee" : "cf")
+							+ " migrate=" + migrateSessionData);
+		}
+
 		// get in memory scopes
 		UserScope oldClient = null;
 		if (hasClientManagement) {

core/src/main/java/lucee/runtime/type/scope/storage/IKHandlerCache.java

@@ -33,17 +33,17 @@ public IKStorageValue loadData(PageContext pc, String appName, String name, Stri
 		synchronized (SystemUtil.createToken("IKHandlerCache", key)) { // sync necessary?
 			Object val = cache.getValue(key, null);
 			if (val instanceof byte[][]) {
-				ScopeContext.info(log,
-						"Load existing byte data from cache [" + name + "] to create " + strType + " scope for " + pc.getApplicationContext().getName() + "/" + pc.getCFID());
+				ScopeContext.trace(log,
+						"Load existing byte data from cache [" + name + "] to create " + strType + " scope for [" + pc.getApplicationContext().getName() + "/" + pc.getCFID() + "]");
 				return new IKStorageValue((byte[][]) val);
 			}
 			else if (val instanceof IKStorageValue) {
-				ScopeContext.info(log,
-						"Load existing data from cache [" + name + "] to create " + strType + " scope for " + pc.getApplicationContext().getName() + "/" + pc.getCFID());
+				ScopeContext.trace(log,
+						"Load existing data from cache [" + name + "] to create " + strType + " scope for [" + pc.getApplicationContext().getName() + "/" + pc.getCFID() + "]");
 				return (IKStorageValue) val;
 			}
 			else {
-				ScopeContext.info(log, "Create new [" + strType + "] scope for [" + pc.getApplicationContext().getName() + "/" + pc.getCFID() + "] in cache [" + name + "]");
+				ScopeContext.debug(log, "Create new [" + strType + "] scope for [" + pc.getApplicationContext().getName() + "/" + pc.getCFID() + "] in cache [" + name + "]");
 			}
 			return null;
 		}
@@ -71,7 +71,7 @@ else if (existingVal != null) {
 					cache.remove(key);
 				}
 			}
-			ScopeContext.info(log, "Store scope for [" + pc.getApplicationContext().getName() + "/" + pc.getCFID() + "] in cache [" + name + "]");
+			ScopeContext.trace(log, "Store scope for [" + pc.getApplicationContext().getName() + "/" + pc.getCFID() + "] in cache [" + name + "]");
 		}
 		catch (Exception e) {
 			ScopeContext.error(log, e);

core/src/main/java/lucee/runtime/type/scope/storage/IKHandlerDatasource.java

@@ -75,7 +75,7 @@ private IKStorageValue loadData(PageContext pc, String appName, String name, Str
 		boolean _isNew = query.getRecordcount() == 0;
 
 		if (_isNew) {
-			ScopeContext.debug(log, "create new " + strType + " scope for " + pc.getApplicationContext().getName() + "/" + pc.getCFID() + " in datasource [" + name + "]");
+			ScopeContext.debug(log, "Create new " + strType + " scope for [" + pc.getApplicationContext().getName() + "/" + pc.getCFID() + "] in datasource [" + name + "]");
 			return null;
 		}
 		String str = Caster.toString(query.getAt(KeyConstants._data, 1));
@@ -94,8 +94,8 @@ private IKStorageValue loadData(PageContext pc, String appName, String name, Str
 
 		try {
 			IKStorageValue data = (IKStorageValue) JavaConverter.deserialize(str);
-			ScopeContext.info(log, "load existing data from [" + name + "." + PREFIX + "_" + strType + "_data] to create " + strType + " scope for "
-					+ pc.getApplicationContext().getName() + "/" + pc.getCFID());
+			ScopeContext.trace(log, "Load existing data from [" + name + "." + PREFIX + "_" + strType + "_data] to create " + strType + " scope for ["
+					+ pc.getApplicationContext().getName() + "/" + pc.getCFID() + "]");
 			return data;
 		}
 		catch (Exception e) {
@@ -147,11 +147,11 @@ public void store(IKStorageScopeSupport storageScope, PageContext pc, String app
 				IKStorageValue sv = new IKStorageValue(
 						IKStorageScopeSupport.prepareToStore(data, existingVal, storageScope.lastModified(), storageScope.lastModifiedAtInit(), log, type));
 				executor.update(ci, pc.getCFID(), appName, dc, storageScope.getType(), sv, storageScope.getTimeSpan(), log);
-				ScopeContext.info(log, "Store scope for [" + pc.getApplicationContext().getName() + "/" + pc.getCFID() + "] in datasource [" + name + "]");
+				ScopeContext.trace(log, "Store scope for [" + pc.getApplicationContext().getName() + "/" + pc.getCFID() + "] in datasource [" + name + "]");
 			}
 			else if (existingVal != null) {
 				executor.delete(ci, pc.getCFID(), appName, dc, storageScope.getType(), log);
-				ScopeContext.info(log, "Remove scope for [" + pc.getApplicationContext().getName() + "/" + pc.getCFID() + "] from datasource [" + name + "]");
+				ScopeContext.debug(log, "Remove scope for [" + pc.getApplicationContext().getName() + "/" + pc.getCFID() + "] from datasource [" + name + "]");
 			}
 		}
 		catch (Exception e) {

core/src/main/java/lucee/runtime/type/scope/storage/StorageScopeCookie.java

@@ -176,15 +176,15 @@ protected static Struct _loadData(PageContext pc, String cookieName, int type, S
 					}
 				}
 
-				ScopeContext.debug(log, "load data from cookie for " + strType + " scope for " + pc.getApplicationContext().getName() + "/" + pc.getCFID());
+				ScopeContext.trace(log, "Load data from cookie for " + strType + " scope for [" + pc.getApplicationContext().getName() + "/" + pc.getCFID() + "]");
 				return sct;
 			}
 			catch (Exception e) {
 
 			}
 		}
 		if (!createIfNeeded) return null;
-		ScopeContext.debug(log, "create new " + strType + " scope for " + pc.getApplicationContext().getName() + "/" + pc.getCFID());
+		ScopeContext.debug(log, "Create new " + strType + " scope for [" + pc.getApplicationContext().getName() + "/" + pc.getCFID() + "]");
 		return new StructImpl(Struct.TYPE_SYNC);
 	}
 

core/src/main/java/lucee/runtime/type/scope/storage/StorageScopeFile.java

@@ -126,15 +126,15 @@ protected static Struct _loadData(PageContext pc, Resource res, Log log) {
 					}
 				}
 				Struct s = (Struct) evaluator.interpret(pc, str);
-				ScopeContext.debug(log, "load existing file storage [" + res + "]");
+				ScopeContext.trace(log, "Load existing file storage [" + res + "]");
 				return s;
 			}
 			catch (Throwable t) {
 				ExceptionUtil.rethrowIfNecessary(t);
 				ScopeContext.error(log, t);
 			}
 		}
-		ScopeContext.debug(log, "create new file storage [" + res + "]");
+		ScopeContext.debug(log, "Create new file storage [" + res + "]");
 		return null;
 	}
 

core/src/main/java/lucee/runtime/type/scope/storage/StorageScopeMemory.java

@@ -42,7 +42,7 @@ public abstract class StorageScopeMemory extends StorageScopeImpl implements Mem
 	 */
 	protected StorageScopeMemory(PageContext pc, String strType, int type, Log log) {
 		super(new StructImpl(Struct.TYPE_SYNC), new DateTimeImpl(), null, -1, 1, strType, type);
-		ScopeContext.debug(log, "create new memory based " + strType + " scope for " + pc.getApplicationContext().getName() + "/" + pc.getCFID());
+		ScopeContext.debug(log, "Create new memory based " + strType + " scope for [" + pc.getApplicationContext().getName() + "/" + pc.getCFID() + "]");
 
 	}
 

core/src/main/java/lucee/runtime/type/scope/storage/db/Ansi92.java

@@ -144,7 +144,7 @@ public Query select(Config config, String cfid, String applicationName, Datasour
 			query = new QueryImpl(pc, dc, sqlSelect, -1, -1, null, scopeName + "_storage");
 		}
 
-		ScopeContext.debug(log, sqlSelect.toString());
+		ScopeContext.trace(log, sqlSelect.toString());
 		return query;
 	}
 
@@ -170,7 +170,7 @@ private static int _update(Config config, Connection conn, String cfid, String a
 			throws SQLException, PageException {
 		SQLImpl sql = new SQLImpl(strSQL, new SQLItem[] { new SQLItemImpl(createExpires(config, timeSpan), Types.VARCHAR),
 				new SQLItemImpl(serialize(data, ignoreSet), Types.VARCHAR), new SQLItemImpl(cfid, Types.VARCHAR), new SQLItemImpl(applicationName, Types.VARCHAR) });
-		ScopeContext.debug(log, sql.toString());
+		ScopeContext.trace(log, sql.toString());
 
 		return execute(null, conn, sql, tz);
 	}
@@ -193,7 +193,7 @@ public void delete(Config config, String cfid, String applicationName, Datasourc
 		String strSQL = "DELETE FROM " + PREFIX + "_" + strType + "_data WHERE cfid=? AND name=?";
 		SQLImpl sql = new SQLImpl(strSQL, new SQLItem[] { new SQLItemImpl(cfid, Types.VARCHAR), new SQLItemImpl(applicationName, Types.VARCHAR) });
 		execute(null, dc.getConnection(), sql, ThreadLocalPageContext.getTimeZone());
-		ScopeContext.debug(log, sql.toString());
+		ScopeContext.trace(log, sql.toString());
 
 	}
 
@@ -222,7 +222,7 @@ public void clean(Config config, DatasourceConnection dc, int type, StorageScope
 
 			if (listener != null) listener.doEnd(engine, cleaner, name, cfid);
 
-			ScopeContext.info(log, "remove " + strType + "/" + name + "/" + cfid + " from datasource " + dc.getDatasource().getName());
+			ScopeContext.debug(log, "Remove " + strType + " [" + name + "/" + cfid + "] from datasource [" + dc.getDatasource().getName() + "]");
 			engine.remove(type, name, cfid);
 			SQLImpl sql = new SQLImpl("DELETE FROM " + PREFIX + "_" + strType + "_data WHERE cfid=? and name=?",
 					new SQLItem[] { new SQLItemImpl(cfid, Types.VARCHAR), new SQLItemImpl(name, Types.VARCHAR) });