9.0.x: Connection errors to healthy origin

[mtorluemke]

From docs:

20210328.17h19m28s CONNECT:[0] could not connect [CONNECTION_ERROR] to 192.168.3.1 for 'http://192.168.3.1:2000/' connect_result=5 src_port=0
20210328.17h19m37s CONNECT:[0] could not connect [CONNECTION_ERROR] to 192.168.3.1 for 'http://192.168.3.1:2000' connect_result=5 src_port=0
20210328.17h19m39s CONNECT:[0] could not connect [CONNECTION_ERROR] to 192.168.3.1 for 'http://192.168.3.1:2000/' connect_result=5 src_port=0
20210328.17h20m28s CONNECT:[0] could not connect [CONNECTION_ERROR] to 192.168.3.1 for 'http://192.168.3.1:2000/' connect_result=5 src_port=0

But, connectivity is fine:

root@origin1 # telnet 192.168.3.1 2000
Trying 192.168.3.1...
Connected to 192.168.3.1.
Escape character is '^]'.
^CConnection closed by foreign host.
root@origin1 #

Error is from:

trafficserver/proxy/http/HttpTransact.cc

Line 3849 in 660bd3b

//////////////////////////////////////////

...which hasn't changed in a few years.

So, one theory is that connectivity had an interruption, and did not recover when the connectivity is restored.

[shinrich]

@djcarlin has been tracking down similar issues for us since before Christmas. We have been running with the changes in PR #7580 to help track down the issue.

[djcarlin]

Do you see log entries in error.log with "(setting last failure time)" ? We were triggering "dead/down" origin behavior inappropriately sometimes, which would prevent subsequent connections from working for a time.

In our case, I noticed squid.log entries with "ERR_CONNECT_FAIL 502" when a POST was happening, and Content-Length sent by client request differed from %<cqql> log field - "Client request header and content length combined, in bytes." In our case, Content-Length was tens of megabytes and cqql was only hundreds of bytes. This was marking origin down and breaking other valid requests.

[djcarlin]

If you think you're bumping against dead/down origin behavior, see #7290 and #7283 - I think the conditions on when an origin is marked dead/down need to be reviewed.

[mtorluemke]

If you think you're bumping against dead/down origin behavior, see #7290 and #7283 - I think the conditions on when an origin is marked dead/down need to be reviewed.

I thought "down server" was always when ATS got a TCP RST, and "dead server" was always when connection attempts (TCP connection + HTTP headers in <9.x, TCP connection in >=9.x) failed.

[mtorluemke]

setting last failure time

Yes, see some of those errors in error.log: 20210328.14h19m39s CONNECT Error: EIO: Input/output error [5] connecting to 192.168.3.1:2000 for 'http://192.168.3.1:2000/' (setting last failure time)

[shinrich]

Within the code there is no separate tracking of an origin connection failing due to receiving a TCP RST as opposed to any other failure. More discussion on what currently makes a server dead in issue #7290. I hope to have a PR up to address the options discussed early next week. Testing internally right now. Hopefully those changes will help fix and/or debug the origin connection problems we are seeing with ASF 9.1 in the docs environment.

[bryancall]

@mtorluemke is this still an issue?

[bryancall]

If this is still an issue please reopen.