WRITE_COMPLETE event in http server open causes traffic server to abort

[vmamidi]

Stack trace :
ink_abort(char const*, ...)
HttpSM::state_http_server_open(int, void*)
HttpSM::main_handler(int, void*)
write_to_net_io(NetHandler*, UnixNetVConnection*, EThread*)
NetHandler::mainNetEvent(int, Event*)
EThread::execute()

and corresponding error messages:
traffic_server[33593]: {0x2aaab6d0c700} ERROR: [HttpSM::state_http_server_open] Unknown event: 103
traffic_server[33593]: FATAL: HttpSM.cc:1798: failed assertion 0

We are seeing this in 7.0.0

[scw00]

Print history in HttpSM

[vmamidi]

i dont have any more information

[scw00]

:(.....sad!!

[bryancall]

@vmamidi What version is this for?

[vmamidi]

we are seeing this on 7.0.0

[bryancall]

@vmamidi Can you post a better backtrace with line numbers in the code? bt full would be great!

[vmamidi]

@scw00 I was able to get the history. Here is the history for ATS on 7.1.x branch.
[0] =
fileline = 0x55a3621f7912
*0x55a3621f7912 = string(0x55a3621f7912, [HttpSM.cc:630])
event = 100
reentrancy = 2
[1] =
fileline = 0x55a3621f7d6d
*0x55a3621f7d6d = string(0x55a3621f7d6d, [HttpSM.cc:1339])
event = 60000
reentrancy = 3
[2] =
fileline = 0x55a3621f7d98
*0x55a3621f7d98 = string(0x55a3621f7d98, [HttpSM.cc:1379])
event = 60000
reentrancy = 3
[3] =
fileline = 0x55a3621f7d6d
*0x55a3621f7d6d = string(0x55a3621f7d6d, [HttpSM.cc:1339])
event = 60000
reentrancy = 4
[4] =
fileline = 0x55a3621f7d98
*0x55a3621f7d98 = string(0x55a3621f7d98, [HttpSM.cc:1379])
event = 60000
reentrancy = 4
[5] =
fileline = 0x55a3621f7d6d
*0x55a3621f7d6d = string(0x55a3621f7d6d, [HttpSM.cc:1339])
event = 60000
reentrancy = 5
[6] =
fileline = 0x55a3621f7d98
*0x55a3621f7d98 = string(0x55a3621f7d98, [HttpSM.cc:1379])
event = 60000
reentrancy = 5
[7] =
fileline = 0x55a3621f7d6d
*0x55a3621f7d6d = string(0x55a3621f7d6d, [HttpSM.cc:1339])
event = 60000
reentrancy = 6
[8] =
fileline = 0x55a3621f7d98
*0x55a3621f7d98 = string(0x55a3621f7d98, [HttpSM.cc:1379])
event = 60000
reentrancy = 6
[9] =
fileline = 0x55a3621f7d6d
*0x55a3621f7d6d = string(0x55a3621f7d6d, [HttpSM.cc:1339])
event = 60000
reentrancy = 7
[10] =
fileline = 0x55a3621f7d98
*0x55a3621f7d98 = string(0x55a3621f7d98, [HttpSM.cc:1379])
event = 60000
reentrancy = 7
[11] =
fileline = 0x55a3621fa4bc
*0x55a3621fa4bc = string(0x55a3621fa4bc, [HttpSM.cc:7373])
event = 65535
reentrancy = 7
[12] =
fileline = 0x55a3621f2ebd
*0x55a3621f2ebd = string(0x55a3621f2ebd, [HttpCacheSM.cc:118])
event = 1103
reentrancy = -1
[13] =
fileline = 0x55a3621f84d6
*0x55a3621f84d6 = string(0x55a3621f84d6, [HttpSM.cc:2577])
event = 1103
reentrancy = 8
[14] =
fileline = 0x55a3621f7d6d
*0x55a3621f7d6d = string(0x55a3621f7d6d, [HttpSM.cc:1339])
event = 60000
reentrancy = 9
[15] =
fileline = 0x55a3621f7d98
*0x55a3621f7d98 = string(0x55a3621f7d98, [HttpSM.cc:1379])
event = 60000
reentrancy = 9
[16] =
fileline = 0x55a3621f7d6d
*0x55a3621f7d6d = string(0x55a3621f7d6d, [HttpSM.cc:1339])
event = 60000
reentrancy = 10
[17] =
fileline = 0x55a3621f7d98
*0x55a3621f7d98 = string(0x55a3621f7d98, [HttpSM.cc:1379])
event = 60000
reentrancy = 10
[18] =
fileline = 0x55a3621fa49e
*0x55a3621fa49e = string(0x55a3621fa49e, [HttpSM.cc:7359])
event = 65535
reentrancy = 10
[19] =
fileline = 0x55a3621fa4e9
*0x55a3621fa4e9 = string(0x55a3621fa4e9, [HttpSM.cc:7488])
event = 65535
reentrancy = 10
[20] =
fileline = 0x55a3621f2f73
*0x55a3621f2f73 = string(0x55a3621f2f73, [HttpCacheSM.cc:177])
event = 1108
reentrancy = -1
[21] =
fileline = 0x55a3621f8429
*0x55a3621f8429 = string(0x55a3621f8429, [HttpSM.cc:2458])
event = 1108
reentrancy = 11
[22] =
fileline = 0x55a3621fa4da
*0x55a3621fa4da = string(0x55a3621fa4da, [HttpSM.cc:7386])
event = 65535
reentrancy = 11
[23] =
fileline = 0x55a3621f9263
*0x55a3621f9263 = string(0x55a3621f9263, [HttpSM.cc:4578])
event = 0
reentrancy = 7
[24] =
fileline = 0x55a3621f8055
*0x55a3621f8055 = string(0x55a3621f8055, [HttpSM.cc:1980])
event = 103
reentrancy = 1
[25] =
fileline = 0x55a3621f7fd2
*0x55a3621f7fd2 = string(0x55a3621f7fd2, [HttpSM.cc:1810])
event = 104
reentrancy = 1
[26] =
fileline = 0x55a3621f96cc
*0x55a3621f96cc = string(0x55a3621f96cc, [HttpSM.cc:5485])
event = 104
reentrancy = 1
[27] =
fileline = 0x55a3621fa4da
*0x55a3621fa4da = string(0x55a3621fa4da, [HttpSM.cc:7386])
event = 65535
reentrancy = 1
[28] =
fileline = 0x55a3621f8055
*0x55a3621f8055 = string(0x55a3621f8055, [HttpSM.cc:1980])
event = 103
reentrancy = 1
[29] =
fileline = 0x55a3621f7fd2
*0x55a3621f7fd2 = string(0x55a3621f7fd2, [HttpSM.cc:1810])
event = 104
reentrancy = 1
[30] =
fileline = 0x55a3621f96cc
*0x55a3621f96cc = string(0x55a3621f96cc, [HttpSM.cc:5485])
event = 104
reentrancy = 1
[31] =
fileline = 0x55a3621fa49e
*0x55a3621fa49e = string(0x55a3621fa49e, [HttpSM.cc:7359])
event = 65535
reentrancy = 1
[32] =
fileline = 0x55a3621f7fd2
*0x55a3621f7fd2 = string(0x55a3621f7fd2, [HttpSM.cc:1810])
event = 3
reentrancy = 1
[33] =
fileline = 0x55a3621f96cc
*0x55a3621f96cc = string(0x55a3621f96cc, [HttpSM.cc:5485])
event = 3
reentrancy = 1
[34] =
fileline = 0x55a3621fa4da
*0x55a3621fa4da = string(0x55a3621fa4da, [HttpSM.cc:7386])
event = 65535
reentrancy = 1
[35] =
fileline = 0x55a3621f7ef5
*0x55a3621f7ef5 = string(0x55a3621f7ef5, [HttpSM.cc:1716])
event = 200
reentrancy = 2
[36] =
fileline = 0x55a3621f8055
*0x55a3621f8055 = string(0x55a3621f8055, [HttpSM.cc:1980])
event = 103
reentrancy = 1
[37] =
fileline = 0x55a3621f7ef5
*0x55a3621f7ef5 = string(0x55a3621f7ef5, [HttpSM.cc:1716])
event = 500
reentrancy = 1

[scw00]

great!

[scw00]

Ok I got it.

The reason is that the HttpSM::state_send_server_request_header may receive the ERROR event when read side down. Then ats retry another server without cleaning the write side.

It may reference to #1629 and #1559 .

[scw00]

@oknet

[vmamidi]

looks like HttpSM is receiving VC_EVENT_ERROR and also WRITE_COMPLETE event after EOS.

[oknet]

ATS do a hostdb lookup to retry the next ip by round robin.

[31] =
fileline = 0x55a3621fa49e
*0x55a3621fa49e = string(0x55a3621fa49e, [HttpSM.cc:7359])
event = 65535
reentrancy = 1

The hostdb callback at [37]

[37] =
fileline = 0x55a3621f7ef5
*0x55a3621f7ef5 = string(0x55a3621f7ef5, [HttpSM.cc:1716])
event = 500
reentrancy = 1

I don't know the reason why [32] shows in the history, it should blocked by pending_action.

Also, I noticed :

traffic_server[33593]: {0x2aaab6d0c700} ERROR: [HttpSM::state_http_server_open] Unknown event: 103

The event is changed from 500 to 103. What is that means ?
May be one callback to HttpSM without get the mutex lock first ? HostDB bug ?

[oknet]

@scw00 I think we should cleanup server_entry at HttpSM.cc:7359, just do the same thing at HttpSM.cc:7386.