Apache
/
httpcomponents-client
mirror of https://github.com/apache/httpcomponents-client.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Improved I/O session logging

This commit is contained in:
Oleg Kalnichevski 2020-12-19 12:12:15 +01:00
parent d4308d0462
commit a0b4dbb34b
1 changed files with 120 additions and 45 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

165
httpclient5/src/main/java/org/apache/hc/client5/http/impl/async/LoggingIOSession.java
View File

@ -34,27 +34,26 @@ import java.nio.channels.ByteChannel;
import java.nio.channels.SelectionKey; import java.nio.channels.SelectionKey;
import java.util.concurrent.locks.Lock; import java.util.concurrent.locks.Lock;
import org.apache.hc.client5.http.impl.Wire; import org.apache.hc.core5.http.Chars;
import org.apache.hc.core5.io.CloseMode; import org.apache.hc.core5.io.CloseMode;
import org.apache.hc.core5.reactor.Command; import org.apache.hc.core5.reactor.Command;
import org.apache.hc.core5.reactor.IOEventHandler; import org.apache.hc.core5.reactor.IOEventHandler;
import org.apache.hc.core5.reactor.IOSession; import org.apache.hc.core5.reactor.IOSession;
import org.apache.hc.core5.util.Args;
import org.apache.hc.core5.util.Timeout; import org.apache.hc.core5.util.Timeout;
import org.slf4j.Logger; import org.slf4j.Logger;
class LoggingIOSession implements IOSession { class LoggingIOSession implements IOSession {
private final Logger log; private final Logger log;
private final Wire wireLog; private final Logger wireLog;
private final String id;
private final IOSession session; private final IOSession session;
public LoggingIOSession(final IOSession session, final Logger log, final Logger wireLog) { public LoggingIOSession(final IOSession session, final Logger log, final Logger wireLog) {
super(); super();
this.session = session; this.session = session;
this.id = session.getId();
this.log = log; this.log = log;
this.wireLog = new Wire(wireLog, this.id); this.wireLog = wireLog;
} }
@Override @Override
@ -64,45 +63,45 @@ class LoggingIOSession implements IOSession {
@Override @Override
public Lock getLock() { public Lock getLock() {
return this.session.getLock(); return session.getLock();
} }
@Override @Override
public boolean hasCommands() { public boolean hasCommands() {
return this.session.hasCommands(); return session.hasCommands();
} }
@Override @Override
public Command poll() { public Command poll() {
return this.session.poll(); return session.poll();
} }
@Override @Override
public void enqueue(final Command command, final Command.Priority priority) { public void enqueue(final Command command, final Command.Priority priority) {
this.session.enqueue(command, priority); session.enqueue(command, priority);
if (log.isDebugEnabled()) { if (log.isDebugEnabled()) {
log.debug("{} Enqueued {} with priority {}", this.session, command.getClass().getSimpleName(), priority); log.debug("{} Enqueued {} with priority {}", session, command.getClass().getSimpleName(), priority);
} }
} }
@Override @Override
public ByteChannel channel() { public ByteChannel channel() {
return this.session.channel(); return session.channel();
} }
@Override @Override
public SocketAddress getLocalAddress() { public SocketAddress getLocalAddress() {
return this.session.getLocalAddress(); return session.getLocalAddress();
} }
@Override @Override
public SocketAddress getRemoteAddress() { public SocketAddress getRemoteAddress() {
return this.session.getRemoteAddress(); return session.getRemoteAddress();
} }
@Override @Override
public int getEventMask() { public int getEventMask() {
return this.session.getEventMask(); return session.getEventMask();
} }
private static String formatOps(final int ops) { private static String formatOps(final int ops) {
@ -126,25 +125,25 @@ class LoggingIOSession implements IOSession {
@Override @Override
public void setEventMask(final int ops) { public void setEventMask(final int ops) {
this.session.setEventMask(ops); session.setEventMask(ops);
if (log.isDebugEnabled()) { if (log.isDebugEnabled()) {
log.debug("{} {}: Event mask set {}", this.id, this.session, formatOps(ops)); log.debug("{} Event mask set {}", session, formatOps(ops));
} }
} }
@Override @Override
public void setEvent(final int op) { public void setEvent(final int op) {
this.session.setEvent(op); session.setEvent(op);
if (log.isDebugEnabled()) { if (log.isDebugEnabled()) {
log.debug("{} {}: Event set {}", this.id, this.session, formatOps(op)); log.debug("{} Event set {}", session, formatOps(op));
} }
} }
@Override @Override
public void clearEvent(final int op) { public void clearEvent(final int op) {
this.session.clearEvent(op); session.clearEvent(op);
if (log.isDebugEnabled()) { if (log.isDebugEnabled()) {
log.debug("{} {}: Event cleared {}", this.id, this.session, formatOps(op)); log.debug("{} Event cleared {}", session, formatOps(op));
} }
} }
@ -156,108 +155,184 @@ class LoggingIOSession implements IOSession {
@Override @Override
public void close() { public void close() {
if (log.isDebugEnabled()) { if (log.isDebugEnabled()) {
log.debug("{} {}: Close", this.id, this.session); log.debug("{} Close", session);
} }
this.session.close(); session.close();
} }
@Override @Override
public Status getStatus() { public Status getStatus() {
return this.session.getStatus(); return session.getStatus();
} }
@Override @Override
public void close(final CloseMode closeMode) { public void close(final CloseMode closeMode) {
if (log.isDebugEnabled()) { if (log.isDebugEnabled()) {
log.debug("{} {}: Close {}", this.id, this.session, closeMode); log.debug("{} Close {}", session, closeMode);
} }
this.session.close(closeMode); session.close(closeMode);
} }
@Override @Override
public Timeout getSocketTimeout() { public Timeout getSocketTimeout() {
return this.session.getSocketTimeout(); return session.getSocketTimeout();
} }
@Override @Override
public void setSocketTimeout(final Timeout timeout) { public void setSocketTimeout(final Timeout timeout) {
if (log.isDebugEnabled()) { if (log.isDebugEnabled()) {
log.debug("{} {}: Set timeout {}", this.id, this.session, timeout); log.debug("{} Set timeout {}", session, timeout);
} }
this.session.setSocketTimeout(timeout); session.setSocketTimeout(timeout);
} }
@Override @Override
public long getLastReadTime() { public long getLastReadTime() {
return this.session.getLastReadTime(); return session.getLastReadTime();
} }
@Override @Override
public long getLastWriteTime() { public long getLastWriteTime() {
return this.session.getLastWriteTime(); return session.getLastWriteTime();
} }
@Override @Override
public void updateReadTime() { public void updateReadTime() {
this.session.updateReadTime(); session.updateReadTime();
} }
@Override @Override
public void updateWriteTime() { public void updateWriteTime() {
this.session.updateWriteTime(); session.updateWriteTime();
} }
@Override @Override
public long getLastEventTime() { public long getLastEventTime() {
return this.session.getLastEventTime(); return session.getLastEventTime();
} }
@Override @Override
public IOEventHandler getHandler() { public IOEventHandler getHandler() {
return this.session.getHandler(); return session.getHandler();
} }
@Override @Override
public void upgrade(final IOEventHandler handler) { public void upgrade(final IOEventHandler handler) {
this.session.upgrade(handler); Args.notNull(handler, "Protocol handler");
if (log.isDebugEnabled()) {
log.debug("{} protocol upgrade {}", session, handler.getClass());
}
session.upgrade(new IOEventHandler() {
@Override
public void connected(final IOSession protocolSession) throws IOException {
handler.connected(protocolSession);
}
@Override
public void inputReady(final IOSession protocolSession, final ByteBuffer src) throws IOException {
if (src != null && wireLog.isDebugEnabled()) {
final ByteBuffer b = src.duplicate();
logData(b, "<< ");
}
handler.inputReady(protocolSession, src);
}
@Override
public void outputReady(final IOSession protocolSession) throws IOException {
handler.outputReady(protocolSession);
}
@Override
public void timeout(final IOSession protocolSession, final Timeout timeout) throws IOException {
handler.timeout(protocolSession, timeout);
}
@Override
public void exception(final IOSession protocolSession, final Exception cause) {
handler.exception(protocolSession, cause);
}
@Override
public void disconnected(final IOSession protocolSession) {
handler.disconnected(protocolSession);
}
});
}
private void logData(final ByteBuffer data, final String prefix) throws IOException {
final byte[] line = new byte[16];
final StringBuilder buf = new StringBuilder();
while (data.hasRemaining()) {
buf.setLength(0);
buf.append(session).append(" ").append(prefix);
final int chunk = Math.min(data.remaining(), line.length);
data.get(line, 0, chunk);
for (int i = 0; i < chunk; i++) {
final char ch = (char) line[i];
if (ch > Chars.SP && ch <= Chars.DEL) {
buf.append(ch);
} else if (Character.isWhitespace(ch)) {
buf.append(' ');
} else {
buf.append('.');
}
}
for (int i = chunk; i < 17; i++) {
buf.append(' ');
}
for (int i = 0; i < chunk; i++) {
buf.append(' ');
final int b = line[i] & 0xff;
final String s = Integer.toHexString(b);
if (s.length() == 1) {
buf.append("0");
}
buf.append(s);
}
wireLog.debug(buf.toString());
}
} }
@Override @Override
public int read(final ByteBuffer dst) throws IOException { public int read(final ByteBuffer dst) throws IOException {
final int bytesRead = this.session.channel().read(dst); final int bytesRead = session.read(dst);
if (log.isDebugEnabled()) { if (log.isDebugEnabled()) {
log.debug("{} {}: {} bytes read", this.id, this.session, bytesRead); log.debug("{} {} bytes read", session, bytesRead);
} }
if (bytesRead > 0 && this.wireLog.isEnabled()) { if (bytesRead > 0 && wireLog.isDebugEnabled()) {
final ByteBuffer b = dst.duplicate(); final ByteBuffer b = dst.duplicate();
final int p = b.position(); final int p = b.position();
b.limit(p); b.limit(p);
b.position(p - bytesRead); b.position(p - bytesRead);
this.wireLog.input(b); logData(b, "<< ");
} }
return bytesRead; return bytesRead;
} }
@Override @Override
public int write(final ByteBuffer src) throws IOException { public int write(final ByteBuffer src) throws IOException {
final int byteWritten = session.channel().write(src); final int byteWritten = session.write(src);
if (log.isDebugEnabled()) { if (log.isDebugEnabled()) {
log.debug("{} {}: {} bytes written", this.id, this.session, byteWritten); log.debug("{} {} bytes written", session, byteWritten);
} }
if (byteWritten > 0 && this.wireLog.isEnabled()) { if (byteWritten > 0 && wireLog.isDebugEnabled()) {
final ByteBuffer b = src.duplicate(); final ByteBuffer b = src.duplicate();
final int p = b.position(); final int p = b.position();
b.limit(p); b.limit(p);
b.position(p - byteWritten); b.position(p - byteWritten);
this.wireLog.output(b); logData(b, ">> ");
} }
return byteWritten; return byteWritten;
} }
@Override @Override
public String toString() { public String toString() {
return this.id + " " + this.session; return session.toString();
} }
} }