package org.infinispan.server.hotrod.logging;
import java.time.LocalDateTime;
import java.time.temporal.ChronoUnit;
import org.infinispan.commons.logging.LogFactory;
import org.infinispan.commons.util.Util;
import org.infinispan.server.hotrod.CacheDecodeContext;
import org.infinispan.server.hotrod.HotRodOperation;
import io.netty.buffer.ByteBuf;
import io.netty.buffer.ByteBufHolder;
import io.netty.channel.ChannelDuplexHandler;
import io.netty.channel.ChannelHandlerContext;
import io.netty.channel.ChannelPromise;
/**
* Logging handler for hotrod to log what requests have come into the server
*
* @author wburns
* @since 9.0
*/
public class HotRodAccessLoggingHandler extends ChannelDuplexHandler {
private static final Log log = LogFactory.getLog(HotRodAccessLoggingHandler.class, Log.class);
LocalDateTime startTime;
private int bytesRead = 0;
@Override
public void channelRead(ChannelHandlerContext ctx, Object msg) throws Exception {
if (startTime == null) {
startTime = LocalDateTime.now();
}
bytesRead += getByteSize(msg);
// Make sure we don't have a decode context between requests
ctx.channel().attr(LoggingContextHandler.DECODE_CONTEXT_KEY).remove();
super.channelRead(ctx, msg);
}
@Override
public void write(ChannelHandlerContext ctx, Object msg, ChannelPromise promise) throws Exception {
if (startTime != null) {
// We need the information from the context now, because we could clear the context soon after the write completes
CacheDecodeContext cacheDecodeContext = ctx.channel().attr(LoggingContextHandler.DECODE_CONTEXT_KEY).get();
HotRodOperation op;
String cacheName;
String status;
String exception = ctx.channel().attr(LoggingContextHandler.EXCEPTION_MESSAGE_KEY).get();
byte[] key;
// This is only null if an exception was thrown before we could decode a proper message
if (cacheDecodeContext != null && exception == null) {
// Method
op = cacheDecodeContext.getHeader().getOp();
key = cacheDecodeContext.getKey();
// Cache name
cacheName = cacheDecodeContext.getHeader().getCacheName();
status = "OK";
} else {
op = ctx.channel().attr(LoggingContextHandler.OPERATION_KEY).get();
key = null;
cacheName = ctx.channel().attr(LoggingContextHandler.CACHE_NAME_KEY).get();
status = exception;
}
// IP
String remoteAddress = ctx.channel().remoteAddress().toString();
// Date of first byte read
LocalDateTime startTime = this.startTime;
this.startTime = null;
// Request Length
int bytesRead = this.bytesRead;
this.bytesRead = 0;
// Response Length - We rely on the fact that our encoder encodes the entire response in 1 write method
int bytesWritten = getByteSize(msg);
super.write(ctx, msg, promise.addListener(f -> {
// Duration
long ms;
if (startTime == null) {
ms = -1;
} else {
ms = ChronoUnit.MILLIS.between(startTime, LocalDateTime.now());
}
log.tracef("%s [%s] \"%s %s\" \"%s\" %s %d %d %d ms", remoteAddress,
checkForNull(startTime), checkForNull(op), checkForNull(cacheName),
status, checkForNull(key), bytesRead, bytesWritten, ms);
}));
} else {
super.write(ctx, msg, promise);
}
}
String checkForNull(Object obj) {
if (obj == null || obj instanceof String && ((String) obj).isEmpty()) {
return "-";
} else if (obj instanceof byte[]) {
return Util.printArray((byte[]) obj);
} else {
return obj.toString();
}
}
int getByteSize(Object msg) {
if (msg instanceof ByteBuf) {
return ((ByteBuf) msg).readableBytes();
} else if (msg instanceof ByteBufHolder) {
return ((ByteBufHolder) msg).content().readableBytes();
} else {
return -1;
}
}
}