logging of netty messages #100

yschimke · 2016-06-22T18:08:49Z

Log bytes via the standard LoggingHandler added to the pipeline.
Log Frame.toString via something that looks like LoggingHandler.

[nioEventLoopGroup-2-1] DEBUG frameBytes - [id: 0x7fbbae18] REGISTERED
[nioEventLoopGroup-2-1] DEBUG frameBytes - [id: 0x7fbbae18] CONNECT: localhost/127.0.0.1:9898
[nioEventLoopGroup-2-1] DEBUG frameBytes - [id: 0x7fbbae18, L:/127.0.0.1:60946 - R:localhost/127.0.0.1:9898] ACTIVE
[main] DEBUG frames - [id: 0x7fbbae18, L:/127.0.0.1:60946 - R:localhost/127.0.0.1:9898] WRITE: Frame[0] => Stream ID: 0 Type: SETUP Payload: 
[main] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.bytebuf.checkAccessible: true
[main] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxCapacity: 262144
[nioEventLoopGroup-2-1] DEBUG frameBytes - [id: 0x7fbbae18, L:/127.0.0.1:60946 - R:localhost/127.0.0.1:9898] WRITE: 36B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 00 24 00 01 00 20 00 00 00 00 00 00 00 00 |...$... ........|
|00000010| 00 00 03 e8 00 00 00 00 05 55 54 46 2d 38 05 55 |.........UTF-8.U|
|00000020| 54 46 2d 38                                     |TF-8            |
+--------+-------------------------------------------------+----------------+
[nioEventLoopGroup-2-1] DEBUG frameBytes - [id: 0x7fbbae18, L:/127.0.0.1:60946 - R:localhost/127.0.0.1:9898] FLUSH
[main] DEBUG frames - [id: 0x7fbbae18, L:/127.0.0.1:60946 - R:localhost/127.0.0.1:9898] WRITE: Frame[0] => Stream ID: 2 Type: REQUEST_RESPONSE Payload: data: "hello"
[nioEventLoopGroup-2-1] DEBUG frameBytes - [id: 0x7fbbae18, L:/127.0.0.1:60946 - R:localhost/127.0.0.1:9898] WRITE: 17B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 00 11 00 04 00 00 00 00 00 02 68 65 6c 6c |............hell|
|00000010| 6f                                              |o               |
+--------+-------------------------------------------------+----------------+
[nioEventLoopGroup-2-1] DEBUG frameBytes - [id: 0x7fbbae18, L:/127.0.0.1:60946 - R:localhost/127.0.0.1:9898] FLUSH
[nioEventLoopGroup-2-1] DEBUG frameBytes - [id: 0x7fbbae18, L:/127.0.0.1:60946 ! R:localhost/127.0.0.1:9898] INACTIVE
[nioEventLoopGroup-2-1] DEBUG frameBytes - [id: 0x7fbbae18, L:/127.0.0.1:60946 ! R:localhost/127.0.0.1:9898] UNREGISTERED
[Thread-0] DEBUG frames - [id: 0x7fbbae18, L:/127.0.0.1:60946 ! R:localhost/127.0.0.1:9898] WRITE: Frame[0] => Stream ID: 0 Type: KEEPALIVE Payload:

yschimke · 2016-06-22T18:10:32Z

Questions:

We seem to use sfl4j, correct?
when used with Netty, I've adopted netty logging conventions. Any concerns?
should I add to websocket as well?
should I log onError as well. n.b. this won't be error frames, but protocol/io exceptions.

NiteshKant · 2016-06-22T18:54:36Z

@yschimke If you add the LoggingHandler as the first handler pipeline.addFirst() it will print the frame bytes read and written, which will have all information sent/received on the wire. Won't that suffice?

BTW, I would be sending a PR today to at least move TCP to RxNetty, which has wire logging in built, in the way I describe above.

yschimke · 2016-06-22T18:57:37Z

@NiteshKant the netty pipeline doesn't currently see the Frame instances, so could you log those in the same format as RxNetty?

I can make the change after you finish yours if you want, just let me know.

yschimke · 2016-06-22T18:59:40Z

@NiteshKant I put it where I did so it logs the bytes for each individual frame rather than before the length based decoding.

NiteshKant · 2016-06-23T01:50:57Z

@yschimke after PR #101 is merged, enabling logs for both client and server, here is the output:

server 22 Jun 2016 18:46:27,711 ERROR [rxnetty-nio-eventloop-1-3] (Slf4JLogger.java:161) - [id: 0x14e6c4d6, L:/192.168.0.12:55190 - R:/192.168.0.12:55191] REGISTERED
client 22 Jun 2016 18:46:27,711 ERROR [rxnetty-nio-eventloop-1-2] (Slf4JLogger.java:161) - [id: 0xa20f21a4, L:/192.168.0.12:55191 - R:/0:0:0:0:0:0:0:0:55190] USER_EVENT: io.reactivex.netty.channel.ChannelSubscriberEvent@6c830976
client 22 Jun 2016 18:46:27,713 ERROR [rxnetty-nio-eventloop-1-2] (Slf4JLogger.java:161) - [id: 0xa20f21a4, L:/192.168.0.12:55191 - R:/0:0:0:0:0:0:0:0:55190] REGISTERED
client 22 Jun 2016 18:46:27,713 ERROR [rxnetty-nio-eventloop-1-2] (Slf4JLogger.java:161) - [id: 0xa20f21a4, L:/192.168.0.12:55191 - R:/0:0:0:0:0:0:0:0:55190] ACTIVE
server 22 Jun 2016 18:46:27,769 ERROR [rxnetty-nio-eventloop-1-3] (Slf4JLogger.java:161) - [id: 0x14e6c4d6, L:/192.168.0.12:55190 - R:/192.168.0.12:55191] USER_EVENT: io.reactivex.netty.channel.ConnectionInputSubscriberEvent@54ad895b
server 22 Jun 2016 18:46:27,771 ERROR [rxnetty-nio-eventloop-1-3] (Slf4JLogger.java:161) - [id: 0x14e6c4d6, L:/192.168.0.12:55190 - R:/192.168.0.12:55191] USER_EVENT: ReadProducer{requested=128}
server 22 Jun 2016 18:46:27,773 ERROR [rxnetty-nio-eventloop-1-3] (Slf4JLogger.java:161) - [id: 0x14e6c4d6, L:/192.168.0.12:55190 - R:/192.168.0.12:55191] ACTIVE
client 22 Jun 2016 18:46:27,787 ERROR [rxnetty-nio-eventloop-1-2] (Slf4JLogger.java:161) - [id: 0xa20f21a4, L:/192.168.0.12:55191 - R:/0:0:0:0:0:0:0:0:55190] WRITE: 36B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 00 24 00 01 00 00 00 00 00 00 00 00 00 00 |...$............|
|00000010| 00 00 03 e8 00 00 00 00 05 55 54 46 2d 38 05 55 |.........UTF-8.U|
|00000020| 54 46 2d 38                                     |TF-8            |
+--------+-------------------------------------------------+----------------+
client 22 Jun 2016 18:46:27,789 ERROR [rxnetty-nio-eventloop-1-2] (Slf4JLogger.java:161) - [id: 0xa20f21a4, L:/192.168.0.12:55191 - R:/0:0:0:0:0:0:0:0:55190] FLUSH
client 22 Jun 2016 18:46:27,796 ERROR [rxnetty-nio-eventloop-1-2] (Slf4JLogger.java:161) - [id: 0xa20f21a4, L:/192.168.0.12:55191 - R:/0:0:0:0:0:0:0:0:55190] FLUSH
client 22 Jun 2016 18:46:27,803 ERROR [rxnetty-nio-eventloop-1-2] (Slf4JLogger.java:161) - [id: 0xa20f21a4, L:/192.168.0.12:55191 - R:/0:0:0:0:0:0:0:0:55190] USER_EVENT: io.reactivex.netty.channel.ConnectionInputSubscriberEvent@76a257dd
client 22 Jun 2016 18:46:27,803 ERROR [rxnetty-nio-eventloop-1-2] (Slf4JLogger.java:161) - [id: 0xa20f21a4, L:/192.168.0.12:55191 - R:/0:0:0:0:0:0:0:0:55190] USER_EVENT: ReadProducer{requested=128}
server 22 Jun 2016 18:46:27,804 ERROR [rxnetty-nio-eventloop-1-3] (Slf4JLogger.java:161) - [id: 0x14e6c4d6, L:/192.168.0.12:55190 - R:/192.168.0.12:55191] RECEIVED: 36B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 00 24 00 01 00 00 00 00 00 00 00 00 00 00 |...$............|
|00000010| 00 00 03 e8 00 00 00 00 05 55 54 46 2d 38 05 55 |.........UTF-8.U|
|00000020| 54 46 2d 38                                     |TF-8            |
+--------+-------------------------------------------------+----------------+
io.reactivesocket.client.LoadBalancer 22 Jun 2016 18:46:27,808  INFO [rxnetty-nio-eventloop-1-2] (LoadBalancer.java:526) - Adding new WeightedSocket WeightedSocket@1858003368 [median:0.0 quantile-low:0.0 quantile-high:0.0 inter-arrival:1000.0 duration/pending:0.0 availability: 1.0]->ReactiveSocketProxy(FailureAwareReactiveSocket(1.0) ~> DrainingSocket(closed=false)->ReactiveSocketProxy(duplexConnection=[[id: 0xa20f21a4, L:/192.168.0.12:55191 - R:/0:0:0:0:0:0:0:0:55190]])) connected to /0:0:0:0:0:0:0:0:55190
server 22 Jun 2016 18:46:27,809 ERROR [rxnetty-nio-eventloop-1-3] (Slf4JLogger.java:161) - [id: 0x14e6c4d6, L:/192.168.0.12:55190 - R:/192.168.0.12:55191] USER_EVENT: ReadProducer{requested=128}
io.reactivesocket.client.LoadBalancer 22 Jun 2016 18:46:28,687  INFO [main] (LoadBalancer.java:169) - Current pending=0.0, new target=1, previous target=3
client 22 Jun 2016 18:46:28,695 ERROR [rxnetty-nio-eventloop-1-2] (Slf4JLogger.java:161) - [id: 0xa20f21a4, L:/192.168.0.12:55191 - R:/0:0:0:0:0:0:0:0:55190] WRITE: 25B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 00 19 00 04 40 00 00 00 00 02 00 00 00 08 |......@.........|
|00000010| 4d 45 54 41 48 65 6c 6c 6f                      |METAHello       |
+--------+-------------------------------------------------+----------------+
client 22 Jun 2016 18:46:28,695 ERROR [rxnetty-nio-eventloop-1-2] (Slf4JLogger.java:161) - [id: 0xa20f21a4, L:/192.168.0.12:55191 - R:/0:0:0:0:0:0:0:0:55190] FLUSH
client 22 Jun 2016 18:46:28,695 ERROR [rxnetty-nio-eventloop-1-2] (Slf4JLogger.java:161) - [id: 0xa20f21a4, L:/192.168.0.12:55191 - R:/0:0:0:0:0:0:0:0:55190] FLUSH
server 22 Jun 2016 18:46:28,696 ERROR [rxnetty-nio-eventloop-1-3] (Slf4JLogger.java:161) - [id: 0x14e6c4d6, L:/192.168.0.12:55190 - R:/192.168.0.12:55191] RECEIVED: 25B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 00 19 00 04 40 00 00 00 00 02 00 00 00 08 |......@.........|
|00000010| 4d 45 54 41 48 65 6c 6c 6f                      |METAHello       |
+--------+-------------------------------------------------+----------------+
server 22 Jun 2016 18:46:28,700 ERROR [rxnetty-nio-eventloop-1-3] (Slf4JLogger.java:161) - [id: 0x14e6c4d6, L:/192.168.0.12:55190 - R:/192.168.0.12:55191] WRITE: 25B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 00 19 00 0b 50 00 00 00 00 02 00 00 00 08 |......P.........|
|00000010| 4d 45 54 41 48 65 6c 6c 6f                      |METAHello       |
+--------+-------------------------------------------------+----------------+
server 22 Jun 2016 18:46:28,700 ERROR [rxnetty-nio-eventloop-1-3] (Slf4JLogger.java:161) - [id: 0x14e6c4d6, L:/192.168.0.12:55190 - R:/192.168.0.12:55191] FLUSH
server 22 Jun 2016 18:46:28,700 ERROR [rxnetty-nio-eventloop-1-3] (Slf4JLogger.java:161) - [id: 0x14e6c4d6, L:/192.168.0.12:55190 - R:/192.168.0.12:55191] FLUSH
client 22 Jun 2016 18:46:28,700 ERROR [rxnetty-nio-eventloop-1-2] (Slf4JLogger.java:161) - [id: 0xa20f21a4, L:/192.168.0.12:55191 - R:/0:0:0:0:0:0:0:0:55190] RECEIVED: 25B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 00 19 00 0b 50 00 00 00 00 02 00 00 00 08 |......P.........|
|00000010| 4d 45 54 41 48 65 6c 6c 6f                      |METAHello       |
+--------+-------------------------------------------------+----------------+

Logs are prefixed for client/server for respective logs.

It looks like now it has all the information required.

yschimke · 2016-06-23T02:34:31Z

Any objection if I add back logging for Frame instances?

WRITE: Frame[0] => Stream ID: 0 Type: SETUP Payload: 
WRITE: Frame[0] => Stream ID: 2 Type: REQUEST_RESPONSE Payload: data: "hello"

NiteshKant · 2016-06-23T05:55:15Z

I am fine with adding them, you can add them in ReactiveSocketFrameCodec. However, I do not see if that will give more information than what wire logging is giving (I pasted the new output in my comment above). Am I missing something?

yschimke · 2016-06-23T16:05:23Z

Ease of debugging. I can put these at debug level. I'll submit a PR, thanks.

yschimke added 2 commits June 22, 2016 11:03

logging of netty messages

6f51205

clean imports

c045ec1

yschimke closed this Jun 22, 2016

yschimke deleted the logging branch May 6, 2017 06:58

ilayaperumalg pushed a commit to ilayaperumalg/rsocket-java that referenced this pull request Dec 26, 2017

Update README.md (rsocket#100)

1bb9fb1

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

logging of netty messages #100

logging of netty messages #100

Uh oh!

yschimke commented Jun 22, 2016

Uh oh!

yschimke commented Jun 22, 2016 •

edited

Loading

Uh oh!

NiteshKant commented Jun 22, 2016

Uh oh!

yschimke commented Jun 22, 2016

Uh oh!

yschimke commented Jun 22, 2016

Uh oh!

NiteshKant commented Jun 23, 2016

Uh oh!

yschimke commented Jun 23, 2016

Uh oh!

NiteshKant commented Jun 23, 2016

Uh oh!

yschimke commented Jun 23, 2016

Uh oh!

Uh oh!

logging of netty messages #100

logging of netty messages #100

Uh oh!

Conversation

yschimke commented Jun 22, 2016

Uh oh!

yschimke commented Jun 22, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

NiteshKant commented Jun 22, 2016

Uh oh!

yschimke commented Jun 22, 2016

Uh oh!

yschimke commented Jun 22, 2016

Uh oh!

NiteshKant commented Jun 23, 2016

Uh oh!

yschimke commented Jun 23, 2016

Uh oh!

NiteshKant commented Jun 23, 2016

Uh oh!

yschimke commented Jun 23, 2016

Uh oh!

Uh oh!

yschimke commented Jun 22, 2016 •

edited

Loading