Skip to content

Commit

Permalink
srm: Add an access log
Browse files Browse the repository at this point in the history
Adds an access log to the SRM. The access log writes a line to
/var/log/dcache/access-DOMAIN.log for each SRM access. The log
is rotated once a day and kept for 30 days. Log level and age
can be adjusted through the new properties dcache.log.level.access
and dcache.log.access.max-history. Currently only the SRM supports
this log file, but it is invisioned that other doors could
produce similar logs. Note that an access log file is generated
for every domain, but only domains with an srm service will write
anything to the file. The log format follows the NetLogger format.
Currently, only SRM v2 requests are logged.  IMPORTANT: To allow
dcache to generate the log file the /var/log/dcache directory will
be changed to dcache upon upgrade.

We have regularly found ourselves in the position of not knowing
whether some particular problem is to be attributed to the client
or the server. An access log which for each SRM request shows
some basic information would help alot in such situations.

I tried to keep the format generic enough that we could implement
similar functionality for other doors. Therefore I chose the
NetLogger format. The Common Logging Format used by web servers
does not apply to the kind of informatio I want to log.

The fields to be logged are a tradeoff between logging something
that is useful, but without logging too much or to log something
that can readily be extracted from the SRM database. Hence I
log client IP, DN, session, request method, request token if
available, surl if request token is not available, the return
status and the user-agent. More detailed information about
requests can often be found by looking up the request using the
request token.

Note that I had a change of heart regarding overship of the log
directory. I have always insisted on the directory to not be
writable by the dcache user, but concluded it is just too much
trouble for the default setup. A site that wants the extra
protection against log tampering can still customize their
setup. Our new default is no different from how other services
are setup by default on various distros. As a consequence of
that change I have also moved the events log to the log directory.
The events log too uses a rolling appender, but with a history
of 0 days (so it should delete log files after one day).

I adjusted the name of the events logger such that it too is
placed under the org.dcache hierarchy. Finally I adjusted the
timestamp to include the timezone (per NetLogger recomendations).

A few SRM status codes have been reclassified to not be errors.

The srmLs implementation has been altered to return a request
token no matter what. This is useful no matter whether the request
is processed synchronously or asynchronously as it bind the request
to the request identifier used in the database. I also remove
a useless status string for the ls implementation that I found
while looking at the access log output.

Target: trunk
Request: 2.7
Require-notes: yes
Require-book: yes
Acked-by: Paul Millar <paul.millar@desy.de>
Patch: http://rb.dcache.org/r/6226/
  • Loading branch information
gbehrmann committed Nov 11, 2013
1 parent 1142ec3 commit cc106ce
Show file tree
Hide file tree
Showing 9 changed files with 495 additions and 196 deletions.
113 changes: 57 additions & 56 deletions modules/cells/src/main/java/dmg/cells/nucleus/EventLogger.java
Expand Up @@ -3,6 +3,8 @@
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import org.dcache.util.NetLoggerBuilder;

/**
* Implements cell event logging following the NetLogger format.
*
Expand All @@ -14,27 +16,27 @@
*/
public class EventLogger
{
private final static Logger deliver =
LoggerFactory.getLogger("events.org.dcache.cells.deliver");
private final static Logger send =
LoggerFactory.getLogger("events.org.dcache.cells.send");
private final static Logger queue =
LoggerFactory.getLogger("events.org.dcache.cells.queue");
private static final Logger deliver =
LoggerFactory.getLogger("org.dcache.events.cells.deliver");
private static final Logger send =
LoggerFactory.getLogger("org.dcache.events.cells.send");
private static final Logger queue =
LoggerFactory.getLogger("org.dcache.events.cells.queue");

private final static String DELIVER_BEGIN =
private static final String DELIVER_BEGIN =
"org.dcache.cells.deliver.begin";
private final static String DELIVER_END =
private static final String DELIVER_END =
"org.dcache.cells.deliver.end";
private final static String SEND_BEGIN =
private static final String SEND_BEGIN =
"org.dcache.cells.send.begin";
private final static String SEND_END =
private static final String SEND_END =
"org.dcache.cells.send.end";
private final static String QUEUE_BEGIN =
private static final String QUEUE_BEGIN =
"org.dcache.cells.queue.begin";
private final static String QUEUE_END =
private static final String QUEUE_END =
"org.dcache.cells.queue.end";

static private String getMessage(CellMessage envelope)
private static String getMessage(CellMessage envelope)
{
Object o = envelope.getMessageObject();
if (o == null) {
Expand All @@ -46,34 +48,31 @@ static private String getMessage(CellMessage envelope)
}
}

static private String toString(Object o)
{
return (o == null) ? "" : o.toString();
}

static public void deliverBegin(CellMessage envelope)
public static void deliverBegin(CellMessage envelope)
{
if (deliver.isInfoEnabled()) {
deliver.info(String.format("event=%s uoid=%s lastuoid=%s session=%s message=%s source=%s destination=%s",
DELIVER_BEGIN,
envelope.getUOID(), envelope.getLastUOID(),
toString(envelope.getSession()),
getMessage(envelope),
envelope.getSourcePath(),
envelope.getDestinationPath()));
NetLoggerBuilder log = new NetLoggerBuilder(DELIVER_BEGIN);
log.add("uoid", envelope.getUOID());
log.add("lastuoid", envelope.getLastUOID());
log.add("session", envelope.getSession());
log.add("message", getMessage(envelope));
log.add("source", envelope.getSourcePath())
log.add("destination", envelope.getDestinationPath());
deliver.info(log.toString());
}
}

static public void deliverEnd(Object session, UOID uoid)
public static void deliverEnd(Object session, UOID uoid)
{
if (deliver.isInfoEnabled()) {
deliver.info(String.format("event=%s uoid=%s session=%s",
DELIVER_END,
uoid, toString(session)));
NetLoggerBuilder log = new NetLoggerBuilder(DELIVER_END);
log.add("uoid", uoid);
log.add("session", session);
deliver.info(log.toString());
}
}

static public void sendBegin(CellNucleus nucleus, CellMessage envelope, String mode)
public static void sendBegin(CellNucleus nucleus, CellMessage envelope, String mode)
{
if (send.isInfoEnabled() && !envelope.isStreamMode()) {
/* The envelope does not have a source yet, so we need to
Expand All @@ -84,48 +83,50 @@ static public void sendBegin(CellNucleus nucleus, CellMessage envelope, String m
source = new CellPath();
source.add(nucleus.getThisAddress());
}
send.info(String.format("event=%s uoid=%s lastuoid=%s session=%s mode=%s message=%s source=%s destination=%s",
SEND_BEGIN,
envelope.getUOID(), envelope.getLastUOID(),
toString(envelope.getSession()),
mode,
getMessage(envelope),
source,
envelope.getDestinationPath()));
NetLoggerBuilder log = new NetLoggerBuilder(SEND_BEGIN);
log.add("uoid", envelope.getUOID());
log.add("lastuoid", envelope.getLastUOID());
log.add("session", envelope.getSession());
log.add("mode", mode);
log.add("message", getMessage(envelope));
log.add("source", source);
log.add("destination", envelope.getDestinationPath());
send.info(log.toString());
}
}

static public void sendEnd(CellMessage envelope)
public static void sendEnd(CellMessage envelope)
{
if (send.isInfoEnabled() && !envelope.isStreamMode()) {
send.info(String.format("event=%s uoid=%s session=%s",
SEND_END, envelope.getUOID(),
toString(envelope.getSession())));
NetLoggerBuilder log = new NetLoggerBuilder(SEND_END);
log.add("uoid", envelope.getUOID());
log.add("session", envelope.getSession());
send.info(log.toString());
}
}

static public void queueBegin(CellEvent event)
public static void queueBegin(CellEvent event)
{
if (queue.isInfoEnabled() && event.getClass().equals(MessageEvent.class)) {
CellMessage envelope = ((MessageEvent) event).getMessage();
queue.info(String.format("event=%s uoid=%s lastuoid=%s session=%s source=%s destination=%s",
QUEUE_BEGIN,
envelope.getUOID(), envelope.getLastUOID(),
toString(envelope.getSession()),
envelope.getSourcePath(),
envelope.getDestinationPath()));
NetLoggerBuilder log = new NetLoggerBuilder(QUEUE_BEGIN);
log.add("uoid", envelope.getUOID());
log.add("lastuoid", envelope.getLastUOID());
log.add("session", envelope.getSession());
log.add("source", envelope.getSourcePath());
log.add("destination", envelope.getDestinationPath());
queue.info(log.toString());
}
}

static public void queueEnd(CellEvent event)
public static void queueEnd(CellEvent event)
{
if (queue.isInfoEnabled() && event.getClass().equals(MessageEvent.class)) {
CellMessage envelope = ((MessageEvent) event).getMessage();
queue.info(String.format("event=%s uoid=%s session=%s",
QUEUE_END,
envelope.getUOID(),
toString(envelope.getSession())));
NetLoggerBuilder log = new NetLoggerBuilder(QUEUE_END);
log.add("uoid", envelope.getUOID());
log.add("session", envelope.getSession());
queue.info(log.toString());
}
}

}
123 changes: 123 additions & 0 deletions modules/common/src/main/java/org/dcache/util/NetLoggerBuilder.java
@@ -0,0 +1,123 @@
package org.dcache.util;

import org.slf4j.Logger;

import java.text.SimpleDateFormat;
import java.util.Date;

import static com.google.common.base.Preconditions.checkState;

/**
* Builder implementing the NetLogger format.
*
* The log format was originally documented as a CEDPS best practice recommendation,
* however CEDPS no longer exists. A more current description of the format can
* be found at https://docs.google.com/document/d/1oeW_l_YgQbR-C_7R2cKl6eYBT5N4WSMbvz0AT6hYDvA
*
* The NetLogger project can be found at http://netlogger.lbl.gov
*/
public class NetLoggerBuilder
{
private static final SimpleDateFormat TS_FORMAT = new SimpleDateFormat("yyyy-MM-dd'T'HH:mm:ss.SSSZ");

private final StringBuilder s = new StringBuilder(256);
private boolean omitNullValues;
private Level level;

public enum Level
{
ERROR, WARN, INFO, DEBUG, TRACE
}

private static synchronized String getTimestamp()
{
return TS_FORMAT.format(new Date());
}

public NetLoggerBuilder(String event)
{
s.append("ts=").append(getTimestamp()).append(' ');
s.append("event=").append(event);
}

public NetLoggerBuilder(Level level, String event)
{
this.level = level;
s.append("level=").append(level).append(' ');
s.append("ts=").append(getTimestamp()).append(' ');
s.append("event=").append(event);
}

public NetLoggerBuilder omitNullValues() {
omitNullValues = true;
return this;
}

public NetLoggerBuilder add(String name, Object value) {
if (!omitNullValues || value != null) {
s.append(' ').append(name).append('=');
if (value != null) {
String valueString = value.toString();
if (valueString.indexOf(' ') > -1) {
s.append('"').append(valueString.replace("\"", "\\\"")).append('"');
} else {
s.append(valueString);
}
}
}
return this;
}

public NetLoggerBuilder add(String name, boolean value) {
return add(name, String.valueOf(value));
}

public NetLoggerBuilder add(String name, char value) {
return add(name, String.valueOf(value));
}

public NetLoggerBuilder add(String name, double value) {
return add(name, String.valueOf(value));
}

public NetLoggerBuilder add(String name, float value) {
return add(name, String.valueOf(value));
}

public NetLoggerBuilder add(String name, int value) {
return add(name, String.valueOf(value));
}

public NetLoggerBuilder add(String name, long value) {
return add(name, String.valueOf(value));
}

@Override
public String toString()
{
return s.toString();
}

public void toLogger(Logger logger)
{
checkState(level != null, "Cannot log to logger without a level.");
String line = toString();
switch (level) {
case ERROR:
logger.error(line);
break;
case WARN:
logger.warn(line);
break;
case INFO:
logger.info(line);
break;
case DEBUG:
logger.debug(line);
break;
case TRACE:
logger.trace(line);
break;
}
}
}
Expand Up @@ -231,8 +231,8 @@ public final SrmLsResponse getSrmLsResponse()
response.setDetails(details);
} else {
response.setDetails(null);
response.setRequestToken(getTRequestToken());
}
response.setRequestToken(getTRequestToken());
return response;
}

Expand Down Expand Up @@ -394,7 +394,7 @@ else if (RequestStatusTool.isFailedFileRequestStatus(fileReqRS)) {
logger.error("Illegal State Transition : " +ist.getMessage());
}
}
return new TReturnStatus(TStatusCode.SRM_SUCCESS, "All ls file requests completed");
return new TReturnStatus(TStatusCode.SRM_SUCCESS, null);
}
if (canceled_req == len ) {
return new TReturnStatus(TStatusCode.SRM_ABORTED, "All ls file requests were cancelled");
Expand Down

0 comments on commit cc106ce

Please sign in to comment.