Request logger and Thread info

src/main/java/org/genesys2/server/mvc/admin/ThreadInfoController.java

+/*
+ * Copyright 2019 Global Crop Diversity Trust
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.genesys2.server.mvc.admin;
+
+import java.io.IOException;
+import java.io.PrintWriter;
+import java.lang.management.ManagementFactory;
+import java.lang.management.ThreadMXBean;
+import java.util.ArrayList;
+import java.util.Arrays;
+import java.util.Date;
+import java.util.Hashtable;
+import java.util.List;
+import java.util.Map;
+
+import javax.servlet.http.HttpServletResponse;
+
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+import org.springframework.http.MediaType;
+import org.springframework.security.access.prepost.PreAuthorize;
+import org.springframework.stereotype.Controller;
+import org.springframework.web.bind.annotation.PostMapping;
+import org.springframework.web.bind.annotation.RequestMapping;
+
+/**
+ * The Class ThreadInfoController.
+ */
+@Controller
+@RequestMapping("/admin")
+@PreAuthorize("hasRole('ADMINISTRATOR')")
+public class ThreadInfoController {
+
+	public static final Logger LOG = LoggerFactory.getLogger(ThreadInfoController.class);
+
+	@PostMapping(value = "/action", params = "action=threaddump", produces = { MediaType.TEXT_PLAIN_VALUE })
+	public void threadDump(HttpServletResponse response) throws IOException {
+		response.setContentType(MediaType.TEXT_PLAIN_VALUE);
+		LOG.warn("Dumping thread info");
+		PrintWriter writer = response.getWriter();
+		writer.println("Thread dump:\t" + new Date());
+		writer.println("Hostname:\t" + java.net.InetAddress.getLocalHost().getHostName());
+
+		writer.println("CPUs:\t" + Runtime.getRuntime().availableProcessors());
+		writer.println("Free memory:\t" + Runtime.getRuntime().freeMemory());
+		writer.println("Max memory:\t" + Runtime.getRuntime().maxMemory());
+		writer.println("Total memory:\t" + Runtime.getRuntime().totalMemory());
+		writer.println();
+
+		Map<Thread, StackTraceElement[]> threadSet = Thread.getAllStackTraces();
+
+		ArrayList<Thread> sortedThreads = new ArrayList<>(threadSet.keySet());
+		sortedThreads.sort((t1, t2) -> t1.getName().compareTo(t2.getName()));
+
+		writer.println("\n\n*** Thread list ***\n");
+
+		for (Thread t : sortedThreads) {
+			writer.println(t.getName());
+		}
+		writer.println();
+		writer.flush();
+
+		writer.println("\n\n*** Threads ***\n");
+		writer.println("ID\tState\tName\tGroup");
+		for (Thread t : sortedThreads) {
+			writer.print(t.getId());
+			writer.print("\t");
+			writer.print(t.getState());
+			writer.print("\t");
+			writer.print(t.getName());
+			writer.print("\t");
+			ThreadGroup threadGroup = t.getThreadGroup();
+			writer.print(threadGroup == null ? "N/A" : threadGroup.getName());
+			writer.println();
+
+			StackTraceElement[] ste = threadSet.get(t);
+			Arrays.stream(ste).forEach((st) -> {
+				writer.print(t.getId());
+				writer.print("\t");
+				writer.print(st.getClassName());
+				writer.print(":");
+				writer.print(st.getMethodName());
+				writer.print("\t");
+				writer.print(st.getFileName());
+				writer.print("\t");
+				writer.println();
+			});
+
+			writer.println();
+			writer.flush();
+		}
+		
+
+		ThreadMXBean tmxb = ManagementFactory.getThreadMXBean();
+		if (tmxb != null && tmxb.isThreadCpuTimeSupported()) {
+			writer.println("\n\n*** CPU Usage ***\n");
+			writer.println("ID\tCPU%\tCPU[ms]\tUser[ms]\tState\tName\tGroup");
+			Map<Long, ThreadCpuUsage> cpuUsage = findCpuUsage(tmxb, sortedThreads);
+			
+			sortedThreads.sort((t1, t2) -> (int)(cpuUsage.get(t2.getId()).cpuTime - cpuUsage.get(t1.getId()).cpuTime));
+			for (Thread t : sortedThreads) {
+				writer.print(t.getId());
+				writer.print("\t");
+				ThreadCpuUsage cpu = cpuUsage.get(t.getId());
+				writer.printf("%.4f", cpu.utilization * 100);
+				writer.print("\t");
+				writer.printf("%.2f", cpu.cpuTime / 1000f);
+				writer.print("\t");
+				writer.printf("%.2f", cpu.userTime / 1000f);
+				writer.printf("\t");
+
+				writer.print(t.getState());
+				writer.print("\t");
+				writer.print(t.getName());
+				writer.print("\t");
+				ThreadGroup threadGroup = t.getThreadGroup();
+				writer.print(threadGroup == null ? "N/A" : threadGroup.getName());
+
+				writer.println();
+				writer.flush();
+			}
+		}
+		writer.flush();
+	}
+
+	/**
+	 * @param tmxb
+	 * @param threads2
+	 * @return
+	 */
+	private Map<Long, ThreadCpuUsage> findCpuUsage(ThreadMXBean tmxb, List<? extends Thread> threads) {
+		Map<Long, ThreadCpuUsage> cpu = new Hashtable<Long, ThreadCpuUsage>();
+		for (int i = 0; i < threads.size(); i++) {
+			Thread thread = threads.get(i);
+			long threadId = thread.getId();
+			ThreadCpuUsage cpuUsage = new ThreadCpuUsage();
+			cpuUsage.cpuTime1 = tmxb.getThreadCpuTime(threadId);
+			cpuUsage.userTime1 = tmxb.getThreadUserTime(threadId);
+			cpuUsage.time1 = System.currentTimeMillis();
+			cpu.put(threadId, cpuUsage);
+		}
+		try {
+			Thread.sleep(2000);
+		} catch (InterruptedException e) {
+			LOG.warn("Interrupted from sleep: " + e.getMessage());
+		}
+
+		for (int i = 0; i < threads.size(); i++) {
+			Thread thread = threads.get(i);
+			long threadId = thread.getId();
+			ThreadCpuUsage cpuUsage = cpu.get(threadId);
+			cpuUsage.cpuTime2 = tmxb.getThreadCpuTime(threadId);
+			cpuUsage.userTime2 = tmxb.getThreadUserTime(threadId);
+			cpuUsage.time2 = System.currentTimeMillis();
+
+			cpuUsage.cpuTime = cpuUsage.cpuTime2 - cpuUsage.cpuTime1;
+			cpuUsage.userTime = cpuUsage.userTime2 - cpuUsage.userTime1;
+			cpuUsage.time = cpuUsage.time2 - cpuUsage.time1;
+
+//			if (cpuUsage.cpuTime > 0) {
+//				cpuUsage.threadInfo = tmxb.getThreadInfo(threadId, 50);
+//			}
+
+			cpuUsage.utilization = (cpuUsage.cpuTime) / ((cpuUsage.time) * 1000000F);
+		}
+
+		return cpu;
+	}
+
+	private class ThreadCpuUsage {
+//		public ThreadInfo threadInfo;
+		public long userTime1, userTime2, userTime;
+		public long cpuTime1, cpuTime2, cpuTime;
+		public long time1, time2, time;
+		public double utilization;
+	}
+}

src/main/java/org/genesys2/spring/config/WebInitializer.java

@@ -32,8 +32,10 @@ import org.genesys2.server.servlet.filter.SuppressRequestRejectedExceptionFilter
 import org.sitemesh.builder.SiteMeshFilterBuilder;
 import org.sitemesh.config.ConfigurableSiteMeshFilter;
 import org.sitemesh.webapp.contentfilter.BasicSelector;
+import org.springframework.context.annotation.Bean;
 import org.springframework.web.context.WebApplicationContext;
 import org.springframework.web.filter.CharacterEncodingFilter;
+import org.springframework.web.filter.CommonsRequestLoggingFilter;
 import org.springframework.web.filter.DelegatingFilterProxy;
 import org.springframework.web.servlet.DispatcherServlet;
 import org.springframework.web.servlet.support.AbstractAnnotationConfigDispatcherServletInitializer;
@@ -91,7 +93,23 @@ public class WebInitializer extends AbstractAnnotationConfigDispatcherServletIni
 		servletContext.addListener(new SessionListener());
 	}
 
+
+	@Bean
+	public CommonsRequestLoggingFilter requestLoggingFilter() {
+		CommonsRequestLoggingFilter loggingFilter = new CommonsRequestLoggingFilter();
+		loggingFilter.setIncludeClientInfo(true);
+		loggingFilter.setIncludeQueryString(true);
+		loggingFilter.setIncludePayload(true);
+		loggingFilter.setMaxPayloadLength(100);
+		loggingFilter.setBeforeMessagePrefix("START ");
+		loggingFilter.setAfterMessagePrefix("DONE ");
+		return loggingFilter;
+	}
+
 	private void registerFilters(final ServletContext servletContext) {
+		final FilterRegistration.Dynamic loggingFilter = servletContext.addFilter("requestLoggingFilter", requestLoggingFilter());
+		loggingFilter.addMappingForUrlPatterns(null, false, "/*");
+
 		final FilterRegistration.Dynamic customLogFilter = servletContext.addFilter("suppressRequestRejectedExceptionFilter", SuppressRequestRejectedExceptionFilter.class);
 		customLogFilter.addMappingForUrlPatterns(null, false, "/*");
 

src/main/resources/log4j.properties

@@ -29,6 +29,7 @@ log4j.rootLogger=error, stdout
 log4j.category.org.genesys2=warn
 log4j.category.org.genesys=warn
 log4j.category.org.genesys2.server.api=warn
+log4j.category.org.springframework.web.filter.CommonsRequestLoggingFilter=INFO
 #log4j.category.org.genesys2.server.service.impl.KPIServiceImpl=trace
 log4j.category.org.genesys2.server.service.worker.KpiScheduledExecutor=info
 log4j.category.liquibase=debug

src/main/webapp/WEB-INF/jsp/admin/index.jsp

@@ -9,6 +9,14 @@
 </head>
 <body>
 
+	<h3>Toolkit</h3>
+	<form method="post" action="<c:url value="/admin/action" />">
+		<input type="submit" class="btn btn-default" name="action" value="threaddump" />
+		<!-- CSRF protection -->
+		<input type="hidden" name="${_csrf.parameterName}" value="${_csrf.token}" />
+	</form>
+
+	<h3>Updates</h3>
 	<form method="post" action="<c:url value="/admin/admin-action" />">
 		<input type="submit" class="btn btn-default" name="accenumbnumb" value="ACCENUMB-NUMB" />
 		<!-- CSRF protection -->