Connection times out when using Homa, but not TCP

[chwebb02]

When running test_server and test_client, as well as my own client code, a timeout occurs when using Homa channels, but not when using TCP. This is being done on Linux 6.1.38 and gRPC 1.57.0, with gRPC and grpc_homa compiled for debugging.

[johnousterhout]

Can invoke the shell command "export GRPC_VERBOSITY=INFO" on both client and server machines, then run this experiment again and respond here with the output produced on each machine?

There is something different between your environment and mine that is causing grpc_homa to misbehave, but I haven't yet been able to put my finger on it.

[chwebb02]

The output after following the above step is as follows:
(I terminated the program since it was seemingly duplicate output just with a different Homa request ID)

chwebb02@vm0:~/grpc_homa$ ./test_client 
I0813 14:27:36.525249184   28751 ev_epoll1_linux.cc:123]               grpc epoll fd: 3
I0813 14:27:36.527579114   28751 ev_epoll1_linux.cc:360]               grpc epoll fd: 5
I0813 14:27:36.530102002   28751 homa_client.cc:299]                   HomaClient::perform_op invoked with start_connectivity_watch
I0813 14:27:36.530258233   28751 homa_stream.cc:221]                   Outgoing metadata: key :authority, value vm0:4000
I0813 14:27:36.530286116   28751 homa_stream.cc:221]                   Outgoing metadata: key :path, value /test.Test/Sum
I0813 14:27:36.530299194   28751 homa_stream.cc:221]                   Outgoing metadata: key WaitForReady, value false
I0813 14:27:36.530309339   28751 homa_stream.cc:221]                   Outgoing metadata: key md1, value md1_value
I0813 14:27:36.530346049   28751 homa_stream.cc:90]                    Sent Homa request to 10.10.1.1:4000, stream id 1, sequence 1 with homaId 166, 98 initial metadata bytes, 4 payload bytes, 0 trailing metadata bytes
E0813 14:27:36.634835389   28751 homa_incoming.cc:179]                 Error in recvmsg (homaId 166): Connection timed out
I0813 14:27:36.634913811   28751 homa_stream.cc:587]                   Recording error for stream id 1: UNKNOWN: Connection timed out [type.googleapis.com/grpc.status.str.syscall='recvmsg'] [type.googleapis.com/grpc.status.str.os_error='Connection timed out'] [type.googleapis.com/grpc.status.int.errno='110'] [type.googleapis.com/grpc.status.time.created_time='2024-08-13T19:27:36.634875209+00:00'] [type.googleapis.com/grpc.status.int.file_line='181'] [type.googleapis.com/grpc.status.str.file='homa_incoming.cc']
I0813 14:27:36.635016980   28751 homa_stream.cc:587]                   Recording error for stream id 1: UNKNOWN: Connection timed out [type.googleapis.com/grpc.status.str.syscall='recvmsg'] [type.googleapis.com/grpc.status.str.os_error='Connection timed out'] [type.googleapis.com/grpc.status.int.errno='110'] [type.googleapis.com/grpc.status.time.created_time='2024-08-13T19:27:36.634875209+00:00'] [type.googleapis.com/grpc.status.int.file_line='181'] [type.googleapis.com/grpc.status.str.file='homa_incoming.cc']
I0813 14:27:36.636853242   28751 homa_stream.cc:587]                   Recording error for stream id 1: UNKNOWN: Connection timed out [type.googleapis.com/grpc.status.str.syscall='recvmsg'] [type.googleapis.com/grpc.status.str.os_error='Connection timed out'] [type.googleapis.com/grpc.status.int.errno='110'] [type.googleapis.com/grpc.status.time.created_time='2024-08-13T19:27:36.634875209+00:00'] [type.googleapis.com/grpc.status.int.file_line='181'] [type.googleapis.com/grpc.status.str.file='homa_incoming.cc']
Sum RPC failed: UNKNOWN (Connection timed out)
I0813 14:27:36.637238527   28751 homa_stream.cc:221]                   Outgoing metadata: key :authority, value vm0:4000
I0813 14:27:36.637263000   28751 homa_stream.cc:221]                   Outgoing metadata: key :path, value /test.Test/Sum
I0813 14:27:36.637274785   28751 homa_stream.cc:221]                   Outgoing metadata: key WaitForReady, value false
I0813 14:27:36.637283426   28751 homa_stream.cc:221]                   Outgoing metadata: key md1, value md1_value
I0813 14:27:36.637332637   28751 homa_stream.cc:90]                    Sent Homa request to 10.10.1.1:4000, stream id 2, sequence 1 with homaId 168, 98 initial metadata bytes, 4 payload bytes, 0 trailing metadata bytes
E0813 14:27:36.741947598   28751 homa_incoming.cc:179]                 Error in recvmsg (homaId 168): Connection timed out
I0813 14:27:36.742071446   28751 homa_stream.cc:587]                   Recording error for stream id 2: UNKNOWN: Connection timed out [type.googleapis.com/grpc.status.str.syscall='recvmsg'] [type.googleapis.com/grpc.status.str.os_error='Connection timed out'] [type.googleapis.com/grpc.status.int.errno='110'] [type.googleapis.com/grpc.status.time.created_time='2024-08-13T19:27:36.742007671+00:00'] [type.googleapis.com/grpc.status.int.file_line='181'] [type.googleapis.com/grpc.status.str.file='homa_incoming.cc']
I0813 14:27:36.742239594   28751 homa_stream.cc:587]                   Recording error for stream id 2: UNKNOWN: Connection timed out [type.googleapis.com/grpc.status.str.syscall='recvmsg'] [type.googleapis.com/grpc.status.str.os_error='Connection timed out'] [type.googleapis.com/grpc.status.int.errno='110'] [type.googleapis.com/grpc.status.time.created_time='2024-08-13T19:27:36.742007671+00:00'] [type.googleapis.com/grpc.status.int.file_line='181'] [type.googleapis.com/grpc.status.str.file='homa_incoming.cc']
I0813 14:27:36.742607138   28751 homa_stream.cc:587]                   Recording error for stream id 2: UNKNOWN: Connection timed out [type.googleapis.com/grpc.status.str.syscall='recvmsg'] [type.googleapis.com/grpc.status.str.os_error='Connection timed out'] [type.googleapis.com/grpc.status.int.errno='110'] [type.googleapis.com/grpc.status.time.created_time='2024-08-13T19:27:36.742007671+00:00'] [type.googleapis.com/grpc.status.int.file_line='181'] [type.googleapis.com/grpc.status.str.file='homa_incoming.cc']

[johnousterhout]

Sorry for another slow response; I've been on vacation without my laptop for the last 2 weeks. Thanks for the log info. However, this appears to be only the client-side log. Could you post the server-side log as well? Thanks.

…

-John-

On Tue, Aug 13, 2024 at 12:30 PM Chase Webb ***@***.***> wrote: The output after following the above step is as follows: (I terminated the program since it was seemingly duplicate output just with a different Homa request ID) ***@***.***:~/grpc_homa$ ./test_client I0813 14:27:36.525249184 28751 ev_epoll1_linux.cc:123] grpc epoll fd: 3 I0813 14:27:36.527579114 28751 ev_epoll1_linux.cc:360] grpc epoll fd: 5 I0813 14:27:36.530102002 28751 homa_client.cc:299] HomaClient::perform_op invoked with start_connectivity_watch I0813 14:27:36.530258233 28751 homa_stream.cc:221] Outgoing metadata: key :authority, value vm0:4000 I0813 14:27:36.530286116 28751 homa_stream.cc:221] Outgoing metadata: key :path, value /test.Test/Sum I0813 14:27:36.530299194 28751 homa_stream.cc:221] Outgoing metadata: key WaitForReady, value false I0813 14:27:36.530309339 28751 homa_stream.cc:221] Outgoing metadata: key md1, value md1_value I0813 14:27:36.530346049 28751 homa_stream.cc:90] Sent Homa request to 10.10.1.1:4000, stream id 1, sequence 1 with homaId 166, 98 initial metadata bytes, 4 payload bytes, 0 trailing metadata bytes E0813 14:27:36.634835389 28751 homa_incoming.cc:179] Error in recvmsg (homaId 166): Connection timed out I0813 14:27:36.634913811 28751 homa_stream.cc:587] Recording error for stream id 1: UNKNOWN: Connection timed out [type.googleapis.com/grpc.status.str.syscall='recvmsg'] [type.googleapis.com/grpc.status.str.os_error='Connection timed out'] [type.googleapis.com/grpc.status.int.errno='110'] [type.googleapis.com/grpc.status.time.created_time='2024-08-13T19:27:36.634875209+00:00'] [type.googleapis.com/grpc.status.int.file_line='181'] [type.googleapis.com/grpc.status.str.file='homa_incoming.cc'] I0813 14:27:36.635016980 28751 homa_stream.cc:587] Recording error for stream id 1: UNKNOWN: Connection timed out [type.googleapis.com/grpc.status.str.syscall='recvmsg'] [type.googleapis.com/grpc.status.str.os_error='Connection timed out'] [type.googleapis.com/grpc.status.int.errno='110'] [type.googleapis.com/grpc.status.time.created_time='2024-08-13T19:27:36.634875209+00:00'] [type.googleapis.com/grpc.status.int.file_line='181'] [type.googleapis.com/grpc.status.str.file='homa_incoming.cc'] I0813 14:27:36.636853242 28751 homa_stream.cc:587] Recording error for stream id 1: UNKNOWN: Connection timed out [type.googleapis.com/grpc.status.str.syscall='recvmsg'] [type.googleapis.com/grpc.status.str.os_error='Connection timed out'] [type.googleapis.com/grpc.status.int.errno='110'] [type.googleapis.com/grpc.status.time.created_time='2024-08-13T19:27:36.634875209+00:00'] [type.googleapis.com/grpc.status.int.file_line='181'] [type.googleapis.com/grpc.status.str.file='homa_incoming.cc'] Sum RPC failed: UNKNOWN (Connection timed out) I0813 14:27:36.637238527 28751 homa_stream.cc:221] Outgoing metadata: key :authority, value vm0:4000 I0813 14:27:36.637263000 28751 homa_stream.cc:221] Outgoing metadata: key :path, value /test.Test/Sum I0813 14:27:36.637274785 28751 homa_stream.cc:221] Outgoing metadata: key WaitForReady, value false I0813 14:27:36.637283426 28751 homa_stream.cc:221] Outgoing metadata: key md1, value md1_value I0813 14:27:36.637332637 28751 homa_stream.cc:90] Sent Homa request to 10.10.1.1:4000, stream id 2, sequence 1 with homaId 168, 98 initial metadata bytes, 4 payload bytes, 0 trailing metadata bytes E0813 14:27:36.741947598 28751 homa_incoming.cc:179] Error in recvmsg (homaId 168): Connection timed out I0813 14:27:36.742071446 28751 homa_stream.cc:587] Recording error for stream id 2: UNKNOWN: Connection timed out [type.googleapis.com/grpc.status.str.syscall='recvmsg'] [type.googleapis.com/grpc.status.str.os_error='Connection timed out'] [type.googleapis.com/grpc.status.int.errno='110'] [type.googleapis.com/grpc.status.time.created_time='2024-08-13T19:27:36.742007671+00:00'] [type.googleapis.com/grpc.status.int.file_line='181'] [type.googleapis.com/grpc.status.str.file='homa_incoming.cc'] I0813 14:27:36.742239594 28751 homa_stream.cc:587] Recording error for stream id 2: UNKNOWN: Connection timed out [type.googleapis.com/grpc.status.str.syscall='recvmsg'] [type.googleapis.com/grpc.status.str.os_error='Connection timed out'] [type.googleapis.com/grpc.status.int.errno='110'] [type.googleapis.com/grpc.status.time.created_time='2024-08-13T19:27:36.742007671+00:00'] [type.googleapis.com/grpc.status.int.file_line='181'] [type.googleapis.com/grpc.status.str.file='homa_incoming.cc'] I0813 14:27:36.742607138 28751 homa_stream.cc:587] Recording error for stream id 2: UNKNOWN: Connection timed out [type.googleapis.com/grpc.status.str.syscall='recvmsg'] [type.googleapis.com/grpc.status.str.os_error='Connection timed out'] [type.googleapis.com/grpc.status.int.errno='110'] [type.googleapis.com/grpc.status.time.created_time='2024-08-13T19:27:36.742007671+00:00'] [type.googleapis.com/grpc.status.int.file_line='181'] [type.googleapis.com/grpc.status.str.file='homa_incoming.cc'] — Reply to this email directly, view it on GitHub <#16 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ACOOUCQ4PU6WIY2I7UJLLZTZRJNE3AVCNFSM6AAAAABLDKJ4ISVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDEOBWHE4DCOBSGM> . You are receiving this because you commented.Message ID: ***@***.***>