From 5146f6d65d62eda5db67273e17f3de61af5e67b1 Mon Sep 17 00:00:00 2001 From: Imteyaz Ahmed Khan <30792765+khanimteyaz@users.noreply.github.com> Date: Sat, 2 Feb 2019 08:01:09 +0530 Subject: [PATCH] Acesslog dateformat enhancemnet (#3274) * #3026 Access log related changed * Reviwe comment incorporated given by @satansk and removed unuded method * Incorporated @beiwei30 review comment, incorporated common-lang3 time package modified version * Added rat entry for common lang3 FastDateFormat related java files * switch back to jdk's dateformatter --- .../dubbo/rpc/filter/AccessLogFilter.java | 221 +++++++-------- .../dubbo/rpc/support/AccessLogData.java | 266 ++++++++++++++++++ 2 files changed, 372 insertions(+), 115 deletions(-) create mode 100644 dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/support/AccessLogData.java diff --git a/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/AccessLogFilter.java b/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/AccessLogFilter.java index 2690dbf11b0..dd95d3fd10e 100644 --- a/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/AccessLogFilter.java +++ b/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/AccessLogFilter.java @@ -20,7 +20,6 @@ import org.apache.dubbo.common.extension.Activate; import org.apache.dubbo.common.logger.Logger; import org.apache.dubbo.common.logger.LoggerFactory; -import org.apache.dubbo.common.utils.ArrayUtils; import org.apache.dubbo.common.utils.ConcurrentHashSet; import org.apache.dubbo.common.utils.ConfigUtils; import org.apache.dubbo.common.utils.NamedThreadFactory; @@ -30,21 +29,20 @@ import org.apache.dubbo.rpc.Result; import org.apache.dubbo.rpc.RpcContext; import org.apache.dubbo.rpc.RpcException; - -import com.alibaba.fastjson.JSON; +import org.apache.dubbo.rpc.support.AccessLogData; import java.io.File; import java.io.FileWriter; +import java.io.IOException; +import java.text.DateFormat; import java.text.SimpleDateFormat; import java.util.Date; import java.util.Iterator; import java.util.Map; import java.util.Set; import java.util.concurrent.ConcurrentHashMap; -import java.util.concurrent.ConcurrentMap; import java.util.concurrent.Executors; import java.util.concurrent.ScheduledExecutorService; -import java.util.concurrent.ScheduledFuture; import java.util.concurrent.TimeUnit; /** @@ -68,88 +66,42 @@ public class AccessLogFilter implements Filter { private static final String ACCESS_LOG_KEY = "dubbo.accesslog"; - private static final String FILE_DATE_FORMAT = "yyyyMMdd"; - - private static final String MESSAGE_DATE_FORMAT = "yyyy-MM-dd HH:mm:ss"; - private static final int LOG_MAX_BUFFER = 5000; private static final long LOG_OUTPUT_INTERVAL = 5000; - private final ConcurrentMap> logQueue = new ConcurrentHashMap>(); + private static final String FILE_DATE_FORMAT = "yyyyMMdd"; - private final ScheduledExecutorService logScheduled = Executors.newScheduledThreadPool(2, new NamedThreadFactory("Dubbo-Access-Log", true)); + // It's safe to declare it as singleton since it runs on single thread only + private static final DateFormat FILE_NAME_FORMATTER = new SimpleDateFormat(FILE_DATE_FORMAT); - private volatile ScheduledFuture logFuture = null; + private static final Map> logEntries = new ConcurrentHashMap>(); - private void init() { - if (logFuture == null) { - synchronized (logScheduled) { - if (logFuture == null) { - logFuture = logScheduled.scheduleWithFixedDelay(new LogTask(), LOG_OUTPUT_INTERVAL, LOG_OUTPUT_INTERVAL, TimeUnit.MILLISECONDS); - } - } - } - } + private static final ScheduledExecutorService logScheduled = Executors.newSingleThreadScheduledExecutor(new NamedThreadFactory("Dubbo-Access-Log", true)); - private void log(String accesslog, String logmessage) { - init(); - Set logSet = logQueue.get(accesslog); - if (logSet == null) { - logQueue.putIfAbsent(accesslog, new ConcurrentHashSet()); - logSet = logQueue.get(accesslog); - } - if (logSet.size() < LOG_MAX_BUFFER) { - logSet.add(logmessage); - } + /** + * Default constructor initialize demon thread for writing into access log file with names with access log key + * defined in url accesslog + */ + public AccessLogFilter() { + logScheduled.scheduleWithFixedDelay(this::writeLogToFile, LOG_OUTPUT_INTERVAL, LOG_OUTPUT_INTERVAL, TimeUnit.MILLISECONDS); } + /** + * This method logs the access log for service method invocation call. + * + * @param invoker service + * @param inv Invocation service method. + * @return Result from service method. + * @throws RpcException + */ @Override public Result invoke(Invoker invoker, Invocation inv) throws RpcException { try { - String accesslog = invoker.getUrl().getParameter(Constants.ACCESS_LOG_KEY); - if (ConfigUtils.isNotEmpty(accesslog)) { - RpcContext context = RpcContext.getContext(); - String serviceName = invoker.getInterface().getName(); - String version = invoker.getUrl().getParameter(Constants.VERSION_KEY); - String group = invoker.getUrl().getParameter(Constants.GROUP_KEY); - StringBuilder sn = new StringBuilder(); - sn.append("[").append(new SimpleDateFormat(MESSAGE_DATE_FORMAT).format(new Date())).append("] ").append(context.getRemoteHost()).append(":").append(context.getRemotePort()) - .append(" -> ").append(context.getLocalHost()).append(":").append(context.getLocalPort()) - .append(" - "); - if (null != group && group.length() > 0) { - sn.append(group).append("/"); - } - sn.append(serviceName); - if (null != version && version.length() > 0) { - sn.append(":").append(version); - } - sn.append(" "); - sn.append(inv.getMethodName()); - sn.append("("); - Class[] types = inv.getParameterTypes(); - if (types != null && types.length > 0) { - boolean first = true; - for (Class type : types) { - if (first) { - first = false; - } else { - sn.append(","); - } - sn.append(type.getName()); - } - } - sn.append(") "); - Object[] args = inv.getArguments(); - if (ArrayUtils.isNotEmpty(args)) { - sn.append(JSON.toJSONString(args)); - } - String msg = sn.toString(); - if (ConfigUtils.isDefault(accesslog)) { - LoggerFactory.getLogger(ACCESS_LOG_KEY + "." + invoker.getInterface().getName()).info(msg); - } else { - log(accesslog, msg); - } + String accessLogKey = invoker.getUrl().getParameter(Constants.ACCESS_LOG_KEY); + if (ConfigUtils.isNotEmpty(accessLogKey)) { + AccessLogData logData = buildAccessLogData(invoker, inv); + log(accessLogKey, logData); } } catch (Throwable t) { logger.warn("Exception in AcessLogFilter of service(" + invoker + " -> " + inv + ")", t); @@ -157,52 +109,91 @@ public Result invoke(Invoker invoker, Invocation inv) throws RpcException { return invoker.invoke(inv); } - private class LogTask implements Runnable { - @Override - public void run() { - try { - if (logQueue != null && logQueue.size() > 0) { - for (Map.Entry> entry : logQueue.entrySet()) { - try { - String accesslog = entry.getKey(); - Set logSet = entry.getValue(); - File file = new File(accesslog); - File dir = file.getParentFile(); - if (null != dir && !dir.exists()) { - dir.mkdirs(); - } - if (logger.isDebugEnabled()) { - logger.debug("Append log to " + accesslog); - } - if (file.exists()) { - String now = new SimpleDateFormat(FILE_DATE_FORMAT).format(new Date()); - String last = new SimpleDateFormat(FILE_DATE_FORMAT).format(new Date(file.lastModified())); - if (!now.equals(last)) { - File archive = new File(file.getAbsolutePath() + "." + last); - file.renameTo(archive); - } - } - FileWriter writer = new FileWriter(file, true); - try { - for (Iterator iterator = logSet.iterator(); - iterator.hasNext(); - iterator.remove()) { - writer.write(iterator.next()); - writer.write("\r\n"); - } - writer.flush(); - } finally { - writer.close(); - } - } catch (Exception e) { - logger.error(e.getMessage(), e); + private void log(String accessLog, AccessLogData accessLogData) { + Set logSet = logEntries.computeIfAbsent(accessLog, k -> new ConcurrentHashSet<>()); + + if (logSet.size() < LOG_MAX_BUFFER) { + logSet.add(accessLogData); + } else { + //TODO we needs use force writing to file so that buffer gets clear and new log can be written. + logger.warn("AccessLog buffer is full skipping buffer "); + } + } + + private void writeLogToFile() { + if (!logEntries.isEmpty()) { + for (Map.Entry> entry : logEntries.entrySet()) { + try { + String accessLog = entry.getKey(); + Set logSet = entry.getValue(); + if (ConfigUtils.isDefault(accessLog)) { + processWithServiceLogger(logSet); + } else { + File file = new File(accessLog); + createIfLogDirAbsent(file); + if (logger.isDebugEnabled()) { + logger.debug("Append log to " + accessLog); } + renameFile(file); + processWithAccessKeyLogger(logSet, file); } + + } catch (Exception e) { + logger.error(e.getMessage(), e); } - } catch (Exception e) { - logger.error(e.getMessage(), e); } } } + private void processWithAccessKeyLogger(Set logSet, File file) throws IOException { + try (FileWriter writer = new FileWriter(file, true)) { + for (Iterator iterator = logSet.iterator(); + iterator.hasNext(); + iterator.remove()) { + writer.write(iterator.next().getLogMessage()); + writer.write("\r\n"); + } + writer.flush(); + } + } + + private AccessLogData buildAccessLogData(Invoker invoker, Invocation inv) { + RpcContext context = RpcContext.getContext(); + AccessLogData logData = AccessLogData.newLogData(); + logData.setServiceName(invoker.getInterface().getName()); + logData.setMethodName(inv.getMethodName()); + logData.setVersion(invoker.getUrl().getParameter(Constants.VERSION_KEY)); + logData.setGroup(invoker.getUrl().getParameter(Constants.GROUP_KEY)); + logData.setInvocationTime(new Date()); + logData.setTypes(inv.getParameterTypes()); + logData.setArguments(inv.getArguments()); + return logData; + } + + private void processWithServiceLogger(Set logSet) { + for (Iterator iterator = logSet.iterator(); + iterator.hasNext(); + iterator.remove()) { + AccessLogData logData = iterator.next(); + LoggerFactory.getLogger(ACCESS_LOG_KEY + "." + logData.getServiceName()).info(logData.getLogMessage()); + } + } + + private void createIfLogDirAbsent(File file) { + File dir = file.getParentFile(); + if (null != dir && !dir.exists()) { + dir.mkdirs(); + } + } + + private void renameFile(File file) { + if (file.exists()) { + String now = FILE_NAME_FORMATTER.format(new Date()); + String last = FILE_NAME_FORMATTER.format(new Date(file.lastModified())); + if (!now.equals(last)) { + File archive = new File(file.getAbsolutePath() + "." + last); + file.renameTo(archive); + } + } + } } diff --git a/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/support/AccessLogData.java b/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/support/AccessLogData.java new file mode 100644 index 00000000000..b7d10961470 --- /dev/null +++ b/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/support/AccessLogData.java @@ -0,0 +1,266 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You 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.apache.dubbo.rpc.support; + +import org.apache.dubbo.common.utils.StringUtils; +import org.apache.dubbo.rpc.RpcContext; + +import com.alibaba.fastjson.JSON; + +import java.text.DateFormat; +import java.text.SimpleDateFormat; +import java.util.Arrays; +import java.util.Date; +import java.util.HashMap; +import java.util.Map; + +/** + * AccessLogData is a container for log event data. In internally uses map and store each filed of log as value. It + * does not generate any dynamic value e.g. time stamp, local jmv machine host address etc. It does not allow any null + * or empty key. + * + * Note: since its date formatter is a singleton, make sure to run it in single thread only. + */ +public final class AccessLogData { + + private static final String MESSAGE_DATE_FORMAT = "yyyy-MM-dd HH:mm:ss"; + private static final DateFormat MESSAGE_DATE_FORMATTER = new SimpleDateFormat(MESSAGE_DATE_FORMAT); + + private static final String VERSION = "version"; + private static final String GROUP = "group"; + private static final String SERVICE = "service"; + private static final String METHOD_NAME = "method-name"; + private static final String INVOCATION_TIME = "invocation-time"; + private static final String TYPES = "types"; + private static final String ARGUMENTS = "arguments"; + private static final String REMOTE_HOST = "remote-host"; + private static final String REMOTE_PORT = "remote-port"; + private static final String LOCAL_HOST = "localhost"; + private static final String LOCAL_PORT = "local-port"; + + /** + * This is used to store log data in key val format. + */ + private Map data; + + /** + * Default constructor. + */ + private AccessLogData() { + RpcContext context = RpcContext.getContext(); + data = new HashMap<>(); + setLocalHost(context.getLocalHost()); + setLocalPort(context.getLocalPort()); + setRemoteHost(context.getRemoteHost()); + setRemotePort(context.getRemotePort()); + } + + /** + * Get new instance of log data. + * + * @return instance of AccessLogData + */ + public static AccessLogData newLogData() { + return new AccessLogData(); + } + + + /** + * Add version information. + * + * @param version + */ + public void setVersion(String version) { + set(VERSION, version); + } + + /** + * Add service name. + * + * @param serviceName + */ + public void setServiceName(String serviceName) { + set(SERVICE, serviceName); + } + + /** + * Add group name + * + * @param group + */ + public void setGroup(String group) { + set(GROUP, group); + } + + /** + * Set the invocation date. As an argument it accept date string. + * + * @param invocationTime + */ + public void setInvocationTime(Date invocationTime) { + set(INVOCATION_TIME, invocationTime); + } + + /** + * Set caller remote host + * + * @param remoteHost + */ + private void setRemoteHost(String remoteHost) { + set(REMOTE_HOST, remoteHost); + } + + /** + * Set caller remote port. + * + * @param remotePort + */ + private void setRemotePort(Integer remotePort) { + set(REMOTE_PORT, remotePort); + } + + /** + * Set local host + * + * @param localHost + */ + private void setLocalHost(String localHost) { + set(LOCAL_HOST, localHost); + } + + /** + * Set local port of exported service + * + * @param localPort + */ + private void setLocalPort(Integer localPort) { + set(LOCAL_PORT, localPort); + } + + /** + * Set target method name. + * + * @param methodName + */ + public void setMethodName(String methodName) { + set(METHOD_NAME, methodName); + } + + /** + * Set invocation's method's input parameter's types + * + * @param types + */ + public void setTypes(Class[] types) { + set(TYPES, types != null ? Arrays.copyOf(types, types.length) : null); + } + + /** + * Sets invocation arguments + * + * @param arguments + */ + public void setArguments(Object[] arguments) { + set(ARGUMENTS, arguments != null ? Arrays.copyOf(arguments, arguments.length) : null); + } + + /** + * Return gthe service of access log entry + * + * @return + */ + public String getServiceName() { + return get(SERVICE).toString(); + } + + + public String getLogMessage() { + StringBuilder sn = new StringBuilder(); + + sn.append("[") + .append(MESSAGE_DATE_FORMATTER.format(getInvocationTime())) + .append("] ") + .append(get(REMOTE_HOST)) + .append(":") + .append(get(REMOTE_PORT)) + .append(" -> ") + .append(get(LOCAL_HOST)) + .append(":") + .append(get(LOCAL_PORT)) + .append(" - "); + + String group = get(GROUP) != null ? get(GROUP).toString() : ""; + if (StringUtils.isNotEmpty(group.toString())) { + sn.append(group).append("/"); + } + + sn.append(get(SERVICE)); + + String version = get(VERSION) != null ? get(VERSION).toString() : ""; + if (StringUtils.isNotEmpty(version.toString())) { + sn.append(":").append(version); + } + + sn.append(" "); + sn.append(get(METHOD_NAME)); + + sn.append("("); + Class[] types = get(TYPES) != null ? (Class[]) get(TYPES) : new Class[0]; + boolean first = true; + for (Class type : types) { + if (first) { + first = false; + } else { + sn.append(","); + } + sn.append(type.getName()); + } + sn.append(") "); + + + Object[] args = get(ARGUMENTS) != null ? (Object[]) get(ARGUMENTS) : null; + if (args != null && args.length > 0) { + sn.append(JSON.toJSONString(args)); + } + + return sn.toString(); + } + + private Date getInvocationTime() { + return (Date)get(INVOCATION_TIME); + } + /** + * Return value of key + * + * @param key + * @return + */ + private Object get(String key) { + return data.get(key); + } + + /** + * Add log key along with his value. + * + * @param key Any not null or non empty string + * @param value Any object including null. + */ + private void set(String key, Object value) { + data.put(key, value); + } + +}