/*
This file is part of Cyclos (www.cyclos.org).
A project of the Social Trade Organisation (www.socialtrade.org).
Cyclos is free software; you can redistribute it and/or modify
it under the terms of the GNU General Public License as published by
the Free Software Foundation; either version 2 of the License, or
(at your option) any later version.
Cyclos is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
GNU General Public License for more details.
You should have received a copy of the GNU General Public License
along with Cyclos; if not, write to the Free Software
Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA
*/
package nl.strohalm.cyclos.utils.logging;
import static nl.strohalm.cyclos.utils.logging.LogFormatter.SEPARATOR;
import java.beans.PropertyDescriptor;
import java.math.BigDecimal;
import java.math.MathContext;
import java.util.Calendar;
import java.util.Map;
import java.util.logging.ConsoleHandler;
import java.util.logging.FileHandler;
import java.util.logging.Handler;
import java.util.logging.Level;
import java.util.logging.Logger;
import nl.strohalm.cyclos.entities.access.Channel;
import nl.strohalm.cyclos.entities.access.User;
import nl.strohalm.cyclos.entities.accounts.fees.account.AccountFee;
import nl.strohalm.cyclos.entities.accounts.fees.account.AccountFee.PaymentDirection;
import nl.strohalm.cyclos.entities.accounts.fees.account.AccountFeeLog;
import nl.strohalm.cyclos.entities.accounts.pos.Pos;
import nl.strohalm.cyclos.entities.accounts.transactions.Invoice;
import nl.strohalm.cyclos.entities.accounts.transactions.Transfer;
import nl.strohalm.cyclos.entities.accounts.transactions.TransferType;
import nl.strohalm.cyclos.entities.members.Element;
import nl.strohalm.cyclos.entities.members.Member;
import nl.strohalm.cyclos.entities.services.ServiceClient;
import nl.strohalm.cyclos.entities.settings.LocalSettings;
import nl.strohalm.cyclos.entities.settings.LogSettings;
import nl.strohalm.cyclos.entities.settings.LogSettings.AccountFeeLevel;
import nl.strohalm.cyclos.entities.settings.LogSettings.ScheduledTaskLevel;
import nl.strohalm.cyclos.entities.settings.LogSettings.TraceLevel;
import nl.strohalm.cyclos.entities.settings.LogSettings.TransactionLevel;
import nl.strohalm.cyclos.entities.settings.LogSettings.WebServiceLevel;
import nl.strohalm.cyclos.entities.settings.events.LogSettingsChangeListener;
import nl.strohalm.cyclos.entities.settings.events.LogSettingsEvent;
import nl.strohalm.cyclos.services.settings.SettingsServiceLocal;
import nl.strohalm.cyclos.utils.FileUnits;
import nl.strohalm.cyclos.utils.FormatObject;
import nl.strohalm.cyclos.utils.access.LoggedUser;
import nl.strohalm.cyclos.utils.conversion.UnitsConverter;
import org.apache.commons.lang.ArrayUtils;
import org.apache.commons.lang.StringUtils;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.springframework.beans.BeanWrapper;
import org.springframework.beans.BeanWrapperImpl;
/**
* This class contains methods for logging actions
* @author luis
*/
public class LoggingHandlerImpl implements LoggingHandler, LogSettingsChangeListener {
private static class WebServiceLogPrepareResult {
private final Level logLevel;
private final boolean logParameters;
public WebServiceLogPrepareResult(final Level logLevel, final boolean logParameters) {
this.logLevel = logLevel;
this.logParameters = logParameters;
}
}
private static final Log LOG = LogFactory.getLog(LoggingHandlerImpl.class);
private Logger traceLogger;
private boolean traceWritesOnly;
private Logger webServiceLogger;
private Logger transactionLogger;
private Logger accountFeeLogger;
private Logger scheduledTaskLogger;
private Logger restLogger;
private LogFormatter logFormatter;
private SettingsServiceLocal settingsService;
@Override
public boolean isRestParametersLogEnabled() {
final Level detailed = WebServiceLevel.DETAILED.getLevel();
return getRestLogger().isLoggable(detailed);
}
/**
* Log a tax error
*/
@Override
public void logAccountFeeError(final AccountFeeLog feeLog, final Throwable error) {
final Logger logger = getAccountFeeLogger();
final Level level = AccountFeeLevel.ERRORS.getLevel();
if (logger.isLoggable(level)) {
try {
logger.log(level, "Error on " + feeLog.getAccountFee().getName(), error);
} catch (final Exception e) {
System.out.println("Error generating log on " + settingsService.getLogSettings().getAccountFeeFile());
}
}
}
@Override
public void logAccountFeeFinished(final AccountFeeLog feeLog) {
final Logger logger = getAccountFeeLogger();
final Level level = AccountFeeLevel.STATUS.getLevel();
if (logger.isLoggable(level)) {
try {
logger.log(level, feeLog.getAccountFee().getName() + ": charging has finished");
} catch (final Exception e) {
System.out.println("Error generating log on " + settingsService.getLogSettings().getAccountFeeFile());
}
}
}
/**
* Log an account fee transfer
*/
@Override
public void logAccountFeeInvoice(final Invoice invoice) {
final Logger logger = getAccountFeeLogger();
final Level level = AccountFeeLevel.DETAILED.getLevel();
if (logger.isLoggable(level)) {
final UnitsConverter unitsConverter = settingsService.getLocalSettings().getUnitsConverter(invoice.getTransferType().getFrom().getCurrency().getPattern());
final String message = "Sent invoice of %s from %s";
final Object[] params = { unitsConverter.toString(invoice.getAmount()), invoice.getToMember().getUsername() };
try {
logger.log(level, String.format(message, params));
} catch (final Exception e) {
System.out.println("Error generating log on " + settingsService.getLogSettings().getAccountFeeFile());
}
}
}
/**
* Log an account fee transfer
*/
@Override
public void logAccountFeePayment(final Transfer transfer) {
final Logger logger = getAccountFeeLogger();
final Level level = AccountFeeLevel.DETAILED.getLevel();
if (logger.isLoggable(level)) {
final AccountFeeLog feeLog = transfer.getAccountFeeLog();
final AccountFee fee = feeLog.getAccountFee();
final UnitsConverter unitsConverter = settingsService.getLocalSettings().getUnitsConverter(transfer.getFrom().getType().getCurrency().getPattern());
String message;
Object[] params;
if (fee.getPaymentDirection() == PaymentDirection.TO_SYSTEM) {
message = "Charged %s from %s";
params = new Object[] { unitsConverter.toString(transfer.getAmount()), transfer.getFrom().getOwnerName() };
} else {
message = "Paid %s to %s";
params = new Object[] { unitsConverter.toString(transfer.getAmount()), transfer.getTo().getOwnerName() };
}
try {
logger.log(level, String.format(message, params));
} catch (final Exception e) {
System.out.println("Error generating log on " + settingsService.getLogSettings().getAccountFeeFile());
}
}
}
@Override
public void logAccountFeeStarted(final AccountFeeLog feeLog) {
final Logger logger = getAccountFeeLogger();
final Level level = AccountFeeLevel.STATUS.getLevel();
if (logger.isLoggable(level)) {
try {
logger.log(level, feeLog.getAccountFee().getName() + ": charging has started");
} catch (final Exception e) {
System.out.println("Error generating log on " + settingsService.getLogSettings().getAccountFeeFile());
}
}
}
@Override
public void logScheduledTaskError(final String taskName, final Calendar hour, final Exception error) {
final Logger logger = getScheduledTaskLogger();
final Level level = ScheduledTaskLevel.ERRORS.getLevel();
if (logger.isLoggable(level)) {
try {
logger.log(level, "Exception on scheduled task: " + taskName + " for hour " + FormatObject.formatObject(hour), error);
} catch (final Exception e) {
System.out.println("Error generating log on " + settingsService.getLogSettings().getScheduledTaskFile());
}
}
}
@Override
public void logScheduledTaskTrace(final String taskName, final Calendar hour, final long timeTaken) {
final Logger logger = getScheduledTaskLogger();
final Level level = ScheduledTaskLevel.DETAILED.getLevel();
if (logger.isLoggable(level)) {
final MathContext mathContext = settingsService.getLocalSettings().getMathContext();
final String formattedTime = settingsService.getLocalSettings().getNumberConverter().toString(new BigDecimal(timeTaken).divide(new BigDecimal(1000), mathContext));
try {
logger.log(level, String.format("Scheduled task '%s' for hour %s ran on %s seconds", taskName, FormatObject.formatObject(hour), formattedTime));
} catch (final Exception e) {
System.out.println("Error generating log on " + settingsService.getLogSettings().getScheduledTaskFile());
}
}
}
@Override
public void logSchedulingTrace(final Calendar hour, final long timeTaken) {
final Logger logger = getScheduledTaskLogger();
final Level level = ScheduledTaskLevel.INFO.getLevel();
if (logger.isLoggable(level)) {
final MathContext mathContext = settingsService.getLocalSettings().getMathContext();
final String formattedTime = settingsService.getLocalSettings().getNumberConverter().toString(new BigDecimal(timeTaken).divide(new BigDecimal(1000), mathContext));
try {
logger.log(level, String.format("Scheduled tasks for hour %s ran on %s seconds", FormatObject.formatObject(hour), formattedTime));
} catch (final Exception e) {
System.out.println("Error generating log on " + settingsService.getLogSettings().getScheduledTaskFile());
}
}
}
/**
* Log a successful transfer
*/
@Override
public void logTransfer(final Transfer transfer) {
final Logger logger = getTransactionLogger();
final Level detailed = TransactionLevel.DETAILED.getLevel();
final Level normal = TransactionLevel.NORMAL.getLevel();
final boolean detailedLoggable = logger.isLoggable(detailed);
final boolean normalLoggable = logger.isLoggable(normal);
final boolean willLog = detailedLoggable || normalLoggable;
// Generate log if, at least, normal level is enabled
if (willLog) {
// transfer = fetchService.fetch(transfer, RelationshipHelper.nested(Payment.Relationships.FROM, Account.Relationships.TYPE,
// AccountType.Relationships.CURRENCY), Payment.Relationships.TO);
Level level;
final LocalSettings localSettings = settingsService.getLocalSettings();
final UnitsConverter unitsConverter = localSettings.getUnitsConverter(transfer.getFrom().getType().getCurrency().getPattern());
String message;
Object[] args;
// Get the specific level arguments
String loggedUser = LoggedUser.hasUser() ? LoggedUser.user().getUsername() : "<no logged user>";
if (detailedLoggable) {
final TransferType type = transfer.getType();
level = detailed;
message = "logged user: %s, id: %s, date: %s, type: %s (%s), amount: %s, from: %s, to: %s, by: %s, tx#: %s, description: %s";
final Element by = transfer.getBy();
args = new Object[] { loggedUser, transfer.getId(), localSettings.getDateTimeConverter().toString(transfer.getDate()), type.getId(), type.getName(), unitsConverter.toString(transfer.getAmount()), transfer.getFrom().getOwnerName(), transfer.getTo().getOwnerName(), by == null ? "<null>" : by.getUsername(), StringUtils.defaultIfEmpty(transfer.getTransactionNumber(), "<null>"), StringUtils.replace(transfer.getDescription(), "\n", "\\n") };
} else {
level = normal;
message = "logged user: %s, id: %s, amount: %s, from: %s, to: %s";
args = new Object[] { loggedUser, transfer.getId(), unitsConverter.toString(transfer.getAmount()), transfer.getFrom().getOwnerName(), transfer.getTo().getOwnerName() };
}
try {
logger.log(level, String.format(message, args));
} catch (final Exception e) {
System.out.println("Error generating log on " + settingsService.getLogSettings().getTransactionFile());
}
}
}
@Override
public synchronized void onLogSettingsUpdate(final LogSettingsEvent event) {
// Invalidate the loggers, forcing them to be recreated on the next time
close(traceLogger);
traceLogger = null;
close(webServiceLogger);
webServiceLogger = null;
close(transactionLogger);
transactionLogger = null;
close(accountFeeLogger);
accountFeeLogger = null;
close(scheduledTaskLogger);
scheduledTaskLogger = null;
}
public void setLogFormatter(final LogFormatter logFormatter) {
this.logFormatter = logFormatter;
}
public void setSettingsServiceLocal(final SettingsServiceLocal service) {
settingsService = service;
service.addListener(this);
}
@Override
public void trace(final TraceLogDTO params) {
final Logger logger = getTraceLogger();
boolean isError = params.getError() != null;
final Level detailed = TraceLevel.DETAILED.getLevel();
final boolean detailedLoggable = logger.isLoggable(detailed);
boolean logParameters = detailedLoggable;
Level logLevel;
if (isError) {
final Level error = TraceLevel.ERRORS.getLevel();
final boolean errorLoggable = logger.isLoggable(error);
logLevel = errorLoggable ? error : null;
} else {
if (traceWritesOnly && !params.isHasDatabaseWrites()) {
return;
}
final Level normal = TraceLevel.SIMPLE.getLevel();
final boolean normalLoggable = logger.isLoggable(normal);
logLevel = detailedLoggable ? detailed : normalLoggable ? normal : null;
}
if (logLevel != null) {
final String message = buildActionString(params, logParameters);
try {
logger.log(logLevel, message, params.getError());
} catch (final Exception e) {
System.out.println("Error generating log on " + settingsService.getLogSettings().getTraceFile());
}
}
}
/**
* Logs an user login
*/
@Override
public void traceLogin(final TraceLogDTO params) {
params.setRequestMethod("LOGIN");
traceLoginLogout(params);
}
/**
* Logs an user logout
*/
@Override
public void traceLogout(final TraceLogDTO params) {
params.setRequestMethod("LOGOUT");
traceLoginLogout(params);
}
@Override
public void traceRest(final RestLogDTO params) {
Logger logger = getRestLogger();
boolean isError = params.getError() != null;
WebServiceLogPrepareResult result = prepareWebService(logger, isError);
if (result.logLevel != null) {
final String message = buildRestString(params, result.logParameters);
try {
logger.log(result.logLevel, message, params.getError());
} catch (final Exception e) {
System.out.println("Error generating log on " + settingsService.getLogSettings().getWebServiceFile());
}
}
}
@Override
public void traceWebService(final WebServiceLogDTO params) {
final Logger logger = getWebServiceLogger();
boolean isError = params.getError() != null || StringUtils.isNotEmpty(params.getErrorMessage());
WebServiceLogPrepareResult result = prepareWebService(logger, isError);
if (result.logLevel != null) {
final String message = buildWebServiceString(params, result.logParameters);
try {
logger.log(result.logLevel, message, params.getError());
} catch (final Exception e) {
System.out.println("Error generating log on " + settingsService.getLogSettings().getWebServiceFile());
}
}
}
/**
* Appends all property values on the given {@link StringBuilder}
*/
private void appendPropertyValues(final StringBuilder sb, final Object bean) {
if (bean == null) {
sb.append("<null>");
return;
} else if (bean instanceof String) {
sb.append(bean);
return;
}
BeanWrapper bw = new BeanWrapperImpl(bean);
boolean first = true;
for (PropertyDescriptor desc : bw.getPropertyDescriptors()) {
if (desc.getWriteMethod() == null) {
// Only log readable and writable properties
continue;
}
if (first) {
first = false;
} else {
sb.append(", ");
}
String name = desc.getName();
sb.append(name).append('=');
Object value = bw.getPropertyValue(name);
appendValue(sb, FormatObject.maskIfNeeded(name, value));
}
}
/**
* Appends a value to the given {@link StringBuilder}
*/
private void appendValue(final StringBuilder sb, final String value) {
if (value == null) {
return;
}
for (int i = 0; i < value.length(); i++) {
char c = value.charAt(i);
switch (c) {
case '\t':
sb.append("\\t");
continue;
case '\r':
sb.append("\\r");
continue;
case '\n':
sb.append("\\n");
continue;
default:
sb.append(c);
}
}
}
/**
* Builds an action string, appending parameters if detailed logging is enabled
*/
private String buildActionString(final TraceLogDTO params, final boolean logParameters) {
final String remoteAddress = params.getRemoteAddress();
final User user = params.getUser();
final String requestMethod = params.getRequestMethod();
final String sessionId = params.getSessionId();
final String path = params.getPath();
final Map<String, String[]> parameters = params.getParameters();
final StringBuilder sb = new StringBuilder();
appendValue(sb, remoteAddress);
sb.append(SEPARATOR);
appendValue(sb, sessionId);
sb.append(SEPARATOR);
sb.append(user == null ? "<unknown user>" : user.getUsername()).append(SEPARATOR);
sb.append(StringUtils.rightPad(requestMethod == null ? "" : requestMethod, 6, ' ')).append(SEPARATOR);
if (path != null) {
sb.append(path);
if (logParameters) {
// Append the arguments
sb.append(SEPARATOR);
boolean first = true;
for (Map.Entry<String, String[]> entry : parameters.entrySet()) {
String name = entry.getKey();
if (first) {
first = false;
} else {
sb.append(", ");
}
String[] value = entry.getValue();
if (ArrayUtils.isEmpty(value)) {
// Nothing to log
continue;
}
sb.append(name).append('=');
if (FormatObject.shouldMask(name)) {
sb.append(FormatObject.MASKED_VALUE);
} else {
if (value.length == 1) {
appendValue(sb, value[0]);
} else {
sb.append('[');
for (int i = 0; i < value.length; i++) {
if (i > 0) {
sb.append(',');
}
appendValue(sb, value[i]);
}
sb.append(']');
}
}
}
}
}
return sb.toString();
}
private String buildRestString(final RestLogDTO params, final boolean logParameters) {
final StringBuilder sb = new StringBuilder();
appendValue(sb, params.getRemoteAddress());
sb.append(SEPARATOR);
appendValue(sb, params.getMember() == null ? "" : params.getMember().getUsername());
sb.append(SEPARATOR);
appendValue(sb, params.getMethod() == null ? "" : params.getMethod());
sb.append(SEPARATOR);
appendValue(sb, params.getUri() == null ? "" : params.getUri());
if (logParameters) {
sb.append(SEPARATOR);
appendPropertyValues(sb, params.getQueryString() == null ? "" : params.getQueryString());
sb.append(SEPARATOR);
appendPropertyValues(sb, params.getRequestBody() == null ? "" : params.getRequestBody());
}
return sb.toString();
}
private String buildWebServiceString(final WebServiceLogDTO params, final boolean logParameters) {
final String remoteAddress = params.getRemoteAddress();
Pos pos = params.getPos();
ServiceClient serviceClient = params.getServiceClient();
String message = params.getMessage();
String serviceName = params.getServiceName();
String methodName = params.getMethodName();
String errorMessage = params.getErrorMessage();
Object parameter = params.getParameter();
final StringBuilder sb = new StringBuilder();
appendValue(sb, remoteAddress);
sb.append(SEPARATOR);
String clientDescription = "";
Member member = null;
String channel = null;
if (pos != null) {
clientDescription = "POS<" + pos.getPosId() + ">";
try {
member = pos.getMemberPos().getMember();
} catch (NullPointerException e) {
// Ignore
}
channel = Channel.POS;
} else if (serviceClient != null) {
clientDescription = "CLIENT<" + serviceClient.getName() + ">";
member = serviceClient.getMember();
try {
channel = serviceClient.getChannel().getInternalName();
} catch (NullPointerException e) {
// Ignore
}
}
sb.append(channel == null ? "" : channel).append(SEPARATOR);
sb.append(clientDescription).append(SEPARATOR);
sb.append(member == null ? "" : member.getUsername()).append(SEPARATOR);
sb.append(message != null ? message : errorMessage != null ? errorMessage : "").append(SEPARATOR);
if (serviceName != null && methodName != null) {
sb.append(serviceName).append('.').append(methodName);
if (logParameters) {
// Append the parameter
sb.append(SEPARATOR);
appendPropertyValues(sb, parameter);
}
}
return sb.toString();
}
/**
* Closes all handlers for the given logger
* @param logger
*/
private void close(final Logger logger) {
if (logger == null) {
return;
}
for (final Handler handler : logger.getHandlers()) {
try {
handler.close();
} catch (final Exception e) {
LOG.warn("Error while closing log handler - Ignoring", e);
}
}
}
private Logger getAccountFeeLogger() {
if (accountFeeLogger == null) {
final LogSettings logSettings = settingsService.getLogSettings();
accountFeeLogger = init(logSettings.getAccountFeeLevel().getLevel(), logSettings.getAccountFeeFile());
}
return accountFeeLogger;
}
private Logger getRestLogger() {
if (restLogger == null) {
final LogSettings logSettings = settingsService.getLogSettings();
restLogger = init(logSettings.getRestLevel().getLevel(), logSettings.getRestFile());
}
return restLogger;
}
private Logger getScheduledTaskLogger() {
if (scheduledTaskLogger == null) {
final LogSettings logSettings = settingsService.getLogSettings();
scheduledTaskLogger = init(logSettings.getScheduledTaskLevel().getLevel(), logSettings.getScheduledTaskFile());
}
return scheduledTaskLogger;
}
private Logger getTraceLogger() {
if (traceLogger == null) {
final LogSettings logSettings = settingsService.getLogSettings();
traceLogger = init(logSettings.getTraceLevel().getLevel(), logSettings.getTraceFile());
traceWritesOnly = logSettings.isTraceWritesOnly();
}
return traceLogger;
}
private Logger getTransactionLogger() {
if (transactionLogger == null) {
final LogSettings logSettings = settingsService.getLogSettings();
transactionLogger = init(logSettings.getTransactionLevel().getLevel(), logSettings.getTransactionFile());
}
return transactionLogger;
}
private Logger getWebServiceLogger() {
if (webServiceLogger == null) {
final LogSettings logSettings = settingsService.getLogSettings();
webServiceLogger = init(logSettings.getWebServiceLevel().getLevel(), logSettings.getWebServiceFile());
}
return webServiceLogger;
}
/**
* Creates a new logger
*/
private Logger init(final Level level, final String file) {
final LogSettings logSettings = settingsService.getLogSettings();
final Logger logger = Logger.getAnonymousLogger();
logger.setLevel(level);
logger.setUseParentHandlers(false);
try {
final FileUnits units = logSettings.getMaxLengthPerFileUnits();
final FileHandler fileHandler = new FileHandler(file, units.calculate(logSettings.getMaxLengthPerFile()), logSettings.getMaxFilesPerLog(), true);
fileHandler.setFormatter(logFormatter);
fileHandler.setEncoding(settingsService.getLocalSettings().getCharset());
logger.addHandler(fileHandler);
} catch (final Exception e) {
final ConsoleHandler consoleHandler = new ConsoleHandler();
consoleHandler.setFormatter(logFormatter);
try {
consoleHandler.setEncoding(settingsService.getLocalSettings().getCharset());
} catch (final Exception e1) {
// Just ignore
}
logger.addHandler(consoleHandler);
logger.log(Level.WARNING, "Unable to create logger for file " + file);
}
return logger;
}
private WebServiceLogPrepareResult prepareWebService(final Logger logger, final boolean isError) {
Level logLevel;
final Level detailed = WebServiceLevel.DETAILED.getLevel();
final boolean detailedLoggable = logger.isLoggable(detailed);
boolean logParameters = detailedLoggable;
if (isError) {
final Level error = WebServiceLevel.ERRORS.getLevel();
final boolean errorLoggable = logger.isLoggable(error);
logLevel = errorLoggable ? error : null;
} else {
final Level normal = WebServiceLevel.SIMPLE.getLevel();
final boolean normalLoggable = logger.isLoggable(normal);
logLevel = detailedLoggable ? detailed : normalLoggable ? normal : null;
}
return new WebServiceLogPrepareResult(logLevel, logParameters);
}
private void traceLoginLogout(final TraceLogDTO params) {
final Logger logger = getTraceLogger();
final Level level = TraceLevel.SIMPLE.getLevel();
if (logger.isLoggable(level)) {
try {
logger.log(level, buildActionString(params, false));
} catch (final Exception e) {
System.out.println("Error generating log on " + settingsService.getLogSettings().getTraceFile());
}
}
}
}