Reading logs: has my data been sent across the wire?

[tippe...@googlemail.com]

I am trying to configure Envoy to act as a TCP proxy, where downstream connections are made to Envoy using TCP encrypted by TLS. Upstream connections are unencrypted TCP. The connections are long-lived.

At the client downstream end, I am occasionally not seeing all data sent by Envoy.  I get some of it, but the data only eventually fully arrives when further data is sent from upstream.  I am trying to work out whether there is a problem in my client code that is reading and decrypting the TLS data received from Envoy (all of the data has been sent, I'm just not reading it properly), or whether there is a problem with the way I have configured Envoy (and genuinely not all of the data has been sent).

I want to make sure I am interpreting the logs correctly, can someone please confirm my interpretation?

[2020-05-05 20:05:00.961][40][trace][connection] [source/common/network/connection_impl.cc:466] [C329] socket event: 3

[2020-05-05 20:05:00.961][40][trace][connection] [source/common/network/connection_impl.cc:554] [C329] write ready

[2020-05-05 20:05:00.961][40][trace][connection] [source/common/network/connection_impl.cc:504] [C329] read ready

[2020-05-05 20:05:00.961][40][trace][connection] [source/common/network/raw_buffer_socket.cc:24] [C329] read returns: 16384

[2020-05-05 20:05:00.961][40][trace][connection] [source/common/network/raw_buffer_socket.cc:24] [C329] read returns: 227

[2020-05-05 20:05:00.961][40][trace][connection] [source/common/network/raw_buffer_socket.cc:38] [C329] read error: Resource temporarily unavailable

[2020-05-05 20:05:00.961][40][trace][filter] [source/common/tcp_proxy/tcp_proxy.cc:531] [C328] upstream connection received 16611 bytes, end_stream=false

[2020-05-05 20:05:00.961][40][trace][connection] [source/common/network/connection_impl.cc:402] [C328] writing 16611 bytes, end_stream false

[2020-05-05 20:05:00.961][40][trace][connection] [source/common/network/connection_impl.cc:466] [C328] socket event: 2

[2020-05-05 20:05:00.961][40][trace][connection] [source/common/network/connection_impl.cc:554] [C328] write ready

[2020-05-05 20:05:00.961][40][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:259] [C328] ssl write returns: 16384

[2020-05-05 20:05:00.961][40][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:259] [C328] ssl write returns: 227

[2020-05-05 20:05:00.961][40][trace][connection] [source/common/network/connection_impl.cc:466] [C329] socket event: 3

[2020-05-05 20:05:00.961][40][trace][connection] [source/common/network/connection_impl.cc:554] [C329] write ready

[2020-05-05 20:05:00.961][40][trace][connection] [source/common/network/connection_impl.cc:504] [C329] read ready

[2020-05-05 20:05:00.961][40][trace][connection] [source/common/network/raw_buffer_socket.cc:24] [C329] read returns: 186

[2020-05-05 20:05:00.961][40][trace][connection] [source/common/network/raw_buffer_socket.cc:38] [C329] read error: Resource temporarily unavailable

[2020-05-05 20:05:00.961][40][trace][filter] [source/common/tcp_proxy/tcp_proxy.cc:531] [C328] upstream connection received 186 bytes, end_stream=false

[2020-05-05 20:05:00.961][40][trace][connection] [source/common/network/connection_impl.cc:402] [C328] writing 186 bytes, end_stream false

[2020-05-05 20:05:00.961][40][trace][connection] [source/common/network/connection_impl.cc:466] [C328] socket event: 2

[2020-05-05 20:05:00.961][40][trace][connection] [source/common/network/connection_impl.cc:554] [C328] write ready

[2020-05-05 20:05:00.961][40][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:259] [C328] ssl write returns: 186

[2020-05-05 20:05:02.799][1][debug][main] [source/server/server.cc:174] flushing stats

[2020-05-05 20:05:07.797][1][debug][main] [source/server/server.cc:174] flushing stats

[2020-05-05 20:05:11.639][40][trace][connection] [source/common/network/connection_impl.cc:466] [C329] socket event: 3

[2020-05-05 20:05:11.639][40][trace][connection] [source/common/network/connection_impl.cc:554] [C329] write ready

[2020-05-05 20:05:11.639][40][trace][connection] [source/common/network/connection_impl.cc:504] [C329] read ready

C329 is the connection from proxy to my upstream server, using unencrypted TCP.

My server writes 16611 bytes (I know this because I have checked my server logs) and sends it to Envoy. C329 appears to receive this in 2 chunks (16384 & 227 bytes), in pink.

C328 is my connection between my client and Envoy, using TLS-encrypted TCP.

My questions:

Q1. Does the first pair of writes by C328 highlighted in yellow mean that the data is definitively on the wire?

Q2. There is a significant delay between another write by C328 (186 bytes) and the socket event: 3, highlighted in green. Is this delay significant? Does the transition from socket event 2 to socket event 3 mean anything in terms of what is sent over the wire? What causes the transition?

Thank you very much, hope someone can help,

John

[Matt Klein]

Q1. Does the first pair of writes by C328 highlighted in yellow mean that the data is definitively on the wire?

It means it has been written into the kernel socket buffer, but there is no guarantee that it has been written to the wire.

 Q2. There is a significant delay between another write by C328 (186 bytes) and the socket event: 3, highlighted in green. Is this delay significant? Does the transition from socket event 2 to socket event 3 mean anything in terms of what is sent over the wire? What causes the transition?

It's hard to know what this means without seeing more logs. It could be that there is more data to read, a connection close, or something else. 

--
You received this message because you are subscribed to the Google Groups "envoy-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to envoy-users...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/envoy-users/31e20c2d-f16e-48dd-b2f7-586d089792ac%40googlegroups.com.