You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@hc.apache.org by ol...@apache.org on 2021/01/03 14:28:54 UTC
[httpcomponents-client] 01/02: Improved I/O session logging
This is an automated email from the ASF dual-hosted git repository.
olegk pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/httpcomponents-client.git
commit a0b4dbb34bce311e894663227d0fae93e33b73f4
Author: Oleg Kalnichevski <ol...@apache.org>
AuthorDate: Sat Dec 19 12:12:15 2020 +0100
Improved I/O session logging
---
.../client5/http/impl/async/LoggingIOSession.java | 165 +++++++++++++++------
1 file changed, 120 insertions(+), 45 deletions(-)
diff --git a/httpclient5/src/main/java/org/apache/hc/client5/http/impl/async/LoggingIOSession.java b/httpclient5/src/main/java/org/apache/hc/client5/http/impl/async/LoggingIOSession.java
index 44bddbd..ea84aa6 100644
--- a/httpclient5/src/main/java/org/apache/hc/client5/http/impl/async/LoggingIOSession.java
+++ b/httpclient5/src/main/java/org/apache/hc/client5/http/impl/async/LoggingIOSession.java
@@ -34,27 +34,26 @@ import java.nio.channels.ByteChannel;
import java.nio.channels.SelectionKey;
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.reactor.Command;
import org.apache.hc.core5.reactor.IOEventHandler;
import org.apache.hc.core5.reactor.IOSession;
+import org.apache.hc.core5.util.Args;
import org.apache.hc.core5.util.Timeout;
import org.slf4j.Logger;
class LoggingIOSession implements IOSession {
private final Logger log;
- private final Wire wireLog;
- private final String id;
+ private final Logger wireLog;
private final IOSession session;
public LoggingIOSession(final IOSession session, final Logger log, final Logger wireLog) {
super();
this.session = session;
- this.id = session.getId();
this.log = log;
- this.wireLog = new Wire(wireLog, this.id);
+ this.wireLog = wireLog;
}
@Override
@@ -64,45 +63,45 @@ class LoggingIOSession implements IOSession {
@Override
public Lock getLock() {
- return this.session.getLock();
+ return session.getLock();
}
@Override
public boolean hasCommands() {
- return this.session.hasCommands();
+ return session.hasCommands();
}
@Override
public Command poll() {
- return this.session.poll();
+ return session.poll();
}
@Override
public void enqueue(final Command command, final Command.Priority priority) {
- this.session.enqueue(command, priority);
+ session.enqueue(command, priority);
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
public ByteChannel channel() {
- return this.session.channel();
+ return session.channel();
}
@Override
public SocketAddress getLocalAddress() {
- return this.session.getLocalAddress();
+ return session.getLocalAddress();
}
@Override
public SocketAddress getRemoteAddress() {
- return this.session.getRemoteAddress();
+ return session.getRemoteAddress();
}
@Override
public int getEventMask() {
- return this.session.getEventMask();
+ return session.getEventMask();
}
private static String formatOps(final int ops) {
@@ -126,25 +125,25 @@ class LoggingIOSession implements IOSession {
@Override
public void setEventMask(final int ops) {
- this.session.setEventMask(ops);
+ session.setEventMask(ops);
if (log.isDebugEnabled()) {
- log.debug("{} {}: Event mask set {}", this.id, this.session, formatOps(ops));
+ log.debug("{} Event mask set {}", session, formatOps(ops));
}
}
@Override
public void setEvent(final int op) {
- this.session.setEvent(op);
+ session.setEvent(op);
if (log.isDebugEnabled()) {
- log.debug("{} {}: Event set {}", this.id, this.session, formatOps(op));
+ log.debug("{} Event set {}", session, formatOps(op));
}
}
@Override
public void clearEvent(final int op) {
- this.session.clearEvent(op);
+ session.clearEvent(op);
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
public void close() {
if (log.isDebugEnabled()) {
- log.debug("{} {}: Close", this.id, this.session);
+ log.debug("{} Close", session);
}
- this.session.close();
+ session.close();
}
@Override
public Status getStatus() {
- return this.session.getStatus();
+ return session.getStatus();
}
@Override
public void close(final CloseMode closeMode) {
if (log.isDebugEnabled()) {
- log.debug("{} {}: Close {}", this.id, this.session, closeMode);
+ log.debug("{} Close {}", session, closeMode);
}
- this.session.close(closeMode);
+ session.close(closeMode);
}
@Override
public Timeout getSocketTimeout() {
- return this.session.getSocketTimeout();
+ return session.getSocketTimeout();
}
@Override
public void setSocketTimeout(final Timeout timeout) {
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
public long getLastReadTime() {
- return this.session.getLastReadTime();
+ return session.getLastReadTime();
}
@Override
public long getLastWriteTime() {
- return this.session.getLastWriteTime();
+ return session.getLastWriteTime();
}
@Override
public void updateReadTime() {
- this.session.updateReadTime();
+ session.updateReadTime();
}
@Override
public void updateWriteTime() {
- this.session.updateWriteTime();
+ session.updateWriteTime();
}
@Override
public long getLastEventTime() {
- return this.session.getLastEventTime();
+ return session.getLastEventTime();
}
@Override
public IOEventHandler getHandler() {
- return this.session.getHandler();
+ return session.getHandler();
}
@Override
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
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()) {
- 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 int p = b.position();
b.limit(p);
b.position(p - bytesRead);
- this.wireLog.input(b);
+ logData(b, "<< ");
}
return bytesRead;
}
-
@Override
public int write(final ByteBuffer src) throws IOException {
- final int byteWritten = session.channel().write(src);
+ final int byteWritten = session.write(src);
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 int p = b.position();
b.limit(p);
b.position(p - byteWritten);
- this.wireLog.output(b);
+ logData(b, ">> ");
}
return byteWritten;
}
@Override
public String toString() {
- return this.id + " " + this.session;
+ return session.toString();
}
}