haskell-distributed / haskell-distributed/distributed-process

Closing the socket on the probing timeout may not take the desirable effect

Open
#427 0 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

network-transport-tcp
Dominant language
Haskell
Stars
751
Forks
99
Avg merge
45m
Merged PRs (30d)
2

Description

Closing the socket on probing timeout (code) may not take any effect on the thread handling the incoming messages (as it is supposed) and, as result, the connection gets stuck in an endless loop of trying to be established without any success:

ssu1: May 08 16:04:27 ssu1 p[8909]: Network.Socket.ByteString.sendMany: total=407552 sent=325800
ssu1: May 08 16:04:28 ssu1 p[8909]: Network.Socket.ByteString.sendMany: total=506136 sent=76374
ssu1: May 08 16:04:28 ssu1 p[8909]: Network.Socket.ByteString.sendMany: total=506072 sent=65036
ssu1: May 08 16:04:28 ssu1 p[8909]: runScheduledAction: exception=ProcessLinkException pid://172.28.128.18:9070:0:544484 DiedNormal remote=172.28.128.14:9070:0 stack=["Network.Transport.TCP.runScheduledAction (src/Network/Transport/TCP.hs:(1950,1)-(1981,38))","Network.Transport.TCP.withScheduledAction.\\ (src/Network/Transport/TCP.hs:1989:34-71)","Network.Transport.TCP.withScheduledAction (src/Network/Transport/TCP.hs:(1987,1)-(1990,94))","Network.Transport.TCP.apiSend (src/Network/Transport/TCP.hs:(820,1)-(850,49))","Network.Transport.TCP.apiConnect (src/Network/Transport/TCP.hs:(766,1)-(780,11))"]
ssu1: May 08 16:04:28 ssu1 p[8909]: Network.Socket.ByteString.sendMany: total=441036 sent=325800
ssu1: May 08 16:04:28 ssu1 p[8909]: Network.Socket.ByteString.sendMany: total=63244 sent=41662
ssu1: May 08 16:04:29 ssu1 p[8909]: Network.Socket.ByteString.sendMany: total=63308 sent=52878
ssu1: May 08 16:04:29 ssu1 p[8909]: runScheduledAction: exception=ProcessLinkException pid://172.28.128.18:9070:0:544701 DiedNormal remote=172.28.128.14:9070:0 stack=["Network.Transport.TCP.runScheduledAction (src/Network/Transport/TCP.hs:(1950,1)-(1981,38))","Network.Transport.TCP.withScheduledAction.\\ (src/Network/Transport/TCP.hs:1989:34-71)","Network.Transport.TCP.withScheduledAction (src/Network/Transport/TCP.hs:(1987,1)-(1990,94))","Network.Transport.TCP.apiSend (src/Network/Transport/TCP.hs:(820,1)-(850,49))","Network.Transport.TCP.apiConnect (src/Network/Transport/TCP.hs:(766,1)-(780,11))"]
ssu1: May 08 16:04:29 ssu1 p[8909]: Network.Socket.ByteString.sendMany: total=63387 sent=1494
ssu1: May 08 16:04:29 ssu1 p[8909]: runScheduledAction: exception=ProcessLinkException pid://172.28.128.18:9070:0:544732 DiedNormal remote=172.28.128.14:9070:0 stack=["Network.Transport.TCP.runScheduledAction (src/Network/Transport/TCP.hs:(1950,1)-(1981,38))","Network.Transport.TCP.withScheduledAction.\\ (src/Network/Transport/TCP.hs:1989:34-71)","Network.Transport.TCP.withScheduledAction (src/Network/Transport/TCP.hs:(1987,1)-(1990,94))","Network.Transport.TCP.apiSend (src/Network/Transport/TCP.hs:(820,1)-(850,49))","Network.Transport.TCP.apiConnect (src/Network/Transport/TCP.hs:(766,1)-(780,11))"]
ssu1: May 08 16:04:29 ssu1 p[8909]: Network.Socket.ByteString.sendMany: total=63384 sent=24181
ssu1: May 08 16:04:29 ssu1 p[8909]: runScheduledAction: exception=ProcessLinkException pid://172.28.128.18:9070:0:544983 DiedNormal remote=172.28.128.14:9070:0 stack=["Network.Transport.TCP.runScheduledAction (src/Network/Transport/TCP.hs:(1950,1)-(1981,38))","Network.Transport.TCP.withScheduledAction.\\ (src/Network/Transport/TCP.hs:1989:34-71)","Network.Transport.TCP.withScheduledAction (src/Network/Transport/TCP.hs:(1987,1)-(1990,94))","Network.Transport.TCP.apiSend (src/Network/Transport/TCP.hs:(820,1)-(850,49))","Network.Transport.TCP.apiConnect (src/Network/Transport/TCP.hs:(766,1)-(780,11))"]
ssu1: May 08 16:04:29 ssu1 p[8909]: handleIncomingMessages.prematureExit: err=Network.Socket.recvBuf: resource vanished (Connection reset by peer) st=RemoteEndPointValid
ssu1: May 08 16:04:29 ssu1 p[8909]: resetIfBroken: remoteEP failed
ssu1: May 08 16:04:29 ssu1 p[8909]: removeRemoteEndPoint: 172.28.128.14:9070:0
ssu1: May 08 16:04:29 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu1: May 08 16:04:29 ssu1 p[8909]: findRemoteEndPoint: (addr, new?, id)=(172.28.128.14:9070:0,True,35)
ssu1: May 08 16:04:29 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu1: May 08 16:04:29 ssu1 p[8909]: socketToEndPoint: AddrInfo {addrFlags = [AI_ADDRCONFIG,AI_V4MAPPED], addrFamily = AF_INET, addrSocketType = Stream, addrProtocol = 6, addrAddress = 172.28.128.14:9070, addrCanonName = Nothing}
ssu1: May 08 16:04:29 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu4: May 08 16:04:29 ssu4 p[8904]: findRemoteEndPoint: (addr, new?, id)=(172.28.128.18:9070:0,False,16)
ssu4: May 08 16:04:29 ssu4 p[8904]: handleConnectionRequest.go: ConnectionRequestCrossed: 172.28.128.18:53624
----------------------   send ProbeSocket 👇which should timeout after 2 seconds (transportConnectTimeout) if there is no reply (and there was not)
ssu4: May 08 16:04:29 ssu4 p[8904]: ProbeSocket: 172.28.128.18:9070:0
ssu1: May 08 16:04:30 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu4: May 08 16:04:31 ssu4 p[8904]: findRemoteEndPoint: (addr, new?, id)=(172.28.128.18:9070:0,False,16)
ssu4: May 08 16:04:31 ssu4 p[8904]: handleConnectionRequest.go: ConnectionRequestCrossed: 172.28.128.18:53626
ssu1: May 08 16:04:31 ssu1 p[8909]: createConnectionTo.go: remove crossed RemoteEndPoint 172.28.128.14:9070:0
ssu1: May 08 16:04:31 ssu1 p[8909]: removeRemoteEndPoint: 172.28.128.14:9070:0
ssu1: May 08 16:04:31 ssu1 p[8909]: findRemoteEndPoint: (addr, new?, id)=(172.28.128.14:9070:0,True,36)
ssu1: May 08 16:04:31 ssu1 p[8909]: socketToEndPoint: AddrInfo {addrFlags = [AI_ADDRCONFIG,AI_V4MAPPED], addrFamily = AF_INET, addrSocketType = Stream, addrProtocol = 6, addrAddress = 172.28.128.14:9070, addrCanonName = Nothing}
ssu1: May 08 16:04:31 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu1: May 08 16:04:31 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu4: May 08 16:04:32 ssu4 p[8904]: findRemoteEndPoint: (addr, new?, id)=(172.28.128.18:9070:0,False,16)
ssu4: May 08 16:04:32 ssu4 p[8904]: handleConnectionRequest.go: ConnectionRequestCrossed: 172.28.128.18:53628
ssu1: May 08 16:04:32 ssu1 p[8909]: createConnectionTo.go: remove crossed RemoteEndPoint 172.28.128.14:9070:0
ssu1: May 08 16:04:32 ssu1 p[8909]: removeRemoteEndPoint: 172.28.128.14:9070:0
ssu1: May 08 16:04:32 ssu1 p[8909]: findRemoteEndPoint: (addr, new?, id)=(172.28.128.14:9070:0,True,37)
ssu1: May 08 16:04:32 ssu1 p[8909]: socketToEndPoint: AddrInfo {addrFlags = [AI_ADDRCONFIG,AI_V4MAPPED], addrFamily = AF_INET, addrSocketType = Stream, addrProtocol = 6, addrAddress = 172.28.128.14:9070, addrCanonName = Nothing}
ssu1: May 08 16:04:32 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu4: May 08 16:04:33 ssu4 p[8904]: findRemoteEndPoint: (addr, new?, id)=(172.28.128.18:9070:0,False,16)
ssu4: May 08 16:04:33 ssu4 p[8904]: handleConnectionRequest.go: ConnectionRequestCrossed: 172.28.128.18:53630
ssu1: May 08 16:04:33 ssu1 p[8909]: createConnectionTo.go: remove crossed RemoteEndPoint 172.28.128.14:9070:0
ssu1: May 08 16:04:33 ssu1 p[8909]: removeRemoteEndPoint: 172.28.128.14:9070:0
ssu1: May 08 16:04:33 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu1: May 08 16:04:33 ssu1 p[8909]: findRemoteEndPoint: (addr, new?, id)=(172.28.128.14:9070:0,True,38)
ssu1: May 08 16:04:33 ssu1 p[8909]: socketToEndPoint: AddrInfo {addrFlags = [AI_ADDRCONFIG,AI_V4MAPPED], addrFamily = AF_INET, addrSocketType = Stream, addrProtocol = 6, addrAddress = 172.28.128.14:9070, addrCanonName = Nothing}
ssu1: May 08 16:04:33 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu1: May 08 16:04:34 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu4: May 08 16:04:35 ssu4 p[8904]: findRemoteEndPoint: (addr, new?, id)=(172.28.128.18:9070:0,False,16)
ssu4: May 08 16:04:35 ssu4 p[8904]: handleConnectionRequest.go: ConnectionRequestCrossed: 172.28.128.18:53632
ssu1: May 08 16:04:35 ssu1 p[8909]: createConnectionTo.go: remove crossed RemoteEndPoint 172.28.128.14:9070:0
ssu1: May 08 16:04:35 ssu1 p[8909]: removeRemoteEndPoint: 172.28.128.14:9070:0
ssu1: May 08 16:04:35 ssu1 p[8909]: findRemoteEndPoint: (addr, new?, id)=(172.28.128.14:9070:0,True,39)
ssu1: May 08 16:04:35 ssu1 p[8909]: socketToEndPoint: AddrInfo {addrFlags = [AI_ADDRCONFIG,AI_V4MAPPED], addrFamily = AF_INET, addrSocketType = Stream, addrProtocol = 6, addrAddress = 172.28.128.14:9070, addrCanonName = Nothing}
ssu1: May 08 16:04:35 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu1: May 08 16:04:35 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu4: May 08 16:04:36 ssu4 p[8904]: findRemoteEndPoint: (addr, new?, id)=(172.28.128.18:9070:0,False,16)
ssu4: May 08 16:04:36 ssu4 p[8904]: handleConnectionRequest.go: ConnectionRequestCrossed: 172.28.128.18:53634
ssu1: May 08 16:04:36 ssu1 p[8909]: createConnectionTo.go: remove crossed RemoteEndPoint 172.28.128.14:9070:0
ssu1: May 08 16:04:36 ssu1 p[8909]: removeRemoteEndPoint: 172.28.128.14:9070:0
ssu1: May 08 16:04:36 ssu1 p[8909]: findRemoteEndPoint: (addr, new?, id)=(172.28.128.14:9070:0,True,40)
ssu1: May 08 16:04:36 ssu1 p[8909]: socketToEndPoint: AddrInfo {addrFlags = [AI_ADDRCONFIG,AI_V4MAPPED], addrFamily = AF_INET, addrSocketType = Stream, addrProtocol = 6, addrAddress = 172.28.128.14:9070, addrCanonName = Nothing}
ssu1: May 08 16:04:36 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu4: May 08 16:04:37 ssu4 p[8904]: findRemoteEndPoint: (addr, new?, id)=(172.28.128.18:9070:0,False,16)
ssu4: May 08 16:04:37 ssu4 p[8904]: handleConnectionRequest.go: ConnectionRequestCrossed: 172.28.128.18:53636
ssu1: May 08 16:04:37 ssu1 p[8909]: createConnectionTo.go: remove crossed RemoteEndPoint 172.28.128.14:9070:0
ssu1: May 08 16:04:37 ssu1 p[8909]: removeRemoteEndPoint: 172.28.128.14:9070:0
ssu1: May 08 16:04:37 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu1: May 08 16:04:37 ssu1 p[8909]: findRemoteEndPoint: (addr, new?, id)=(172.28.128.14:9070:0,True,41)
ssu1: May 08 16:04:37 ssu1 p[8909]: socketToEndPoint: AddrInfo {addrFlags = [AI_ADDRCONFIG,AI_V4MAPPED], addrFamily = AF_INET, addrSocketType = Stream, addrProtocol = 6, addrAddress = 172.28.128.14:9070, addrCanonName = Nothing}
ssu1: May 08 16:04:37 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu1: May 08 16:04:37 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu1: May 08 16:04:37 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu1: May 08 16:04:37 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu1: May 08 16:04:37 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu1: May 08 16:04:37 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu1: May 08 16:04:38 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu4: May 08 16:04:39 ssu4 p[8904]: findRemoteEndPoint: (addr, new?, id)=(172.28.128.18:9070:0,False,16)
ssu4: May 08 16:04:39 ssu4 p[8904]: handleConnectionRequest.go: ConnectionRequestCrossed: 172.28.128.18:53638
ssu1: May 08 16:04:39 ssu1 p[8909]: createConnectionTo.go: remove crossed RemoteEndPoint 172.28.128.14:9070:0
ssu1: May 08 16:04:39 ssu1 p[8909]: removeRemoteEndPoint: 172.28.128.14:9070:0
ssu1: May 08 16:04:39 ssu1 p[8909]: findRemoteEndPoint: (addr, new?, id)=(172.28.128.14:9070:0,True,42)
ssu1: May 08 16:04:39 ssu1 p[8909]: socketToEndPoint: AddrInfo {addrFlags = [AI_ADDRCONFIG,AI_V4MAPPED], addrFamily = AF_INET, addrSocketType = Stream, addrProtocol = 6, addrAddress = 172.28.128.14:9070, addrCanonName = Nothing}
ssu1: May 08 16:04:39 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu1: May 08 16:04:39 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu1: May 08 16:04:39 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu1: May 08 16:04:39 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu4: May 08 16:04:40 ssu4 p[8904]: findRemoteEndPoint: (addr, new?, id)=(172.28.128.18:9070:0,False,16)
ssu4: May 08 16:04:40 ssu4 p[8904]: handleConnectionRequest.go: ConnectionRequestCrossed: 172.28.128.18:53640
ssu1: May 08 16:04:40 ssu1 p[8909]: createConnectionTo.go: remove crossed RemoteEndPoint 172.28.128.14:9070:0
ssu1: May 08 16:04:40 ssu1 p[8909]: removeRemoteEndPoint: 172.28.128.14:9070:0
ssu1: May 08 16:04:40 ssu1 p[8909]: findRemoteEndPoint: (addr, new?, id)=(172.28.128.14:9070:0,True,43)
ssu1: May 08 16:04:40 ssu1 p[8909]: socketToEndPoint: AddrInfo {addrFlags = [AI_ADDRCONFIG,AI_V4MAPPED], addrFamily = AF_INET, addrSocketType = Stream, addrProtocol = 6, addrAddress = 172.28.128.14:9070, addrCanonName = Nothing}
ssu1: May 08 16:04:40 ssu1 p[8909]: createConnectionTo.go: ourAddr=172.28.128.18:9070:0 theirAddr=172.28.128.14:9070:0
ssu4: May 08 16:04:41 ssu4 p[8904]: findRemoteEndPoint: (addr, new?, id)=(172.28.128.18:9070:0,False,16)
ssu4: May 08 16:04:41 ssu4 p[8904]: handleConnectionRequest.go: ConnectionRequestCrossed: 172.28.128.18:53642
...

Originally posted by @andriytk in https://github.com/haskell-distributed/network-transport-tcp/issues/74#issuecomment-490576689

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start in src/Network/Transport/TCP.hs at the probing-timeout code around line 1121, then trace handleIncomingMessages, createConnectionTo, and ProbeSocket using the reported logs. Reproduce a missing probe reply and inspect whether closing the socket reaches the incoming-message thread. Done means the timed-out connection does not remain in an endless reconnection loop.

Written by the indexing model from the issue text.

Assessment

Tech stack
haskell
Domain
distributed-systems, networking
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.