On Fri, 29 Jun 2018 at 11:19, Milan Petruželka <petruze...@fg.cz> wrote:
> I've added more debug into h2s_close to see not only h2s state and flags > but also h2c state and flags. My only way to reproduce the bug is to let > Haproxy run until some of its FD falls into CLOSE_WAIT. After I catch some, > I'll report back. > I just caught new CLOSE_WAIT. ... continuation of longer h2 connection ... 20180629.1347 mpeh2 fd25 h2c_stream_new - id00000117 st00 fl00000000 streams:0 -> 1 20180629.1347 000267eb:frntend.accept(0006)=0019 from [some_ip:52750] ALPN=h2 20180629.1347 mpeh2 fd25 h2c_stream_new - id00000119 st00 fl00000000 streams:1 -> 2 20180629.1347 000267ec:frntend.accept(0006)=0019 from [some_ip:52750] ALPN=h2 20180629.1347 mpeh2 fd25 h2c_stream_new - id0000011b st00 fl00000000 streams:2 -> 3 20180629.1347 000267ed:frntend.accept(0006)=0019 from [some_ip:52750] ALPN=h2 20180629.1347 mpeh2 fd25 h2c_stream_new - id0000011d st00 fl00000000 streams:3 -> 4 20180629.1347 000267ee:frntend.accept(0006)=0019 from [some_ip:52750] ALPN=h2 20180629.1347 mpeh2 fd25 h2c_stream_new - id0000011f st00 fl00000000 streams:4 -> 5 20180629.1347 000267ef:frntend.accept(0006)=0019 from [some_ip:52750] ALPN=h2 20180629.1347 mpeh2 fd25 h2c_stream_new - id00000121 st00 fl00000000 streams:5 -> 6 20180629.1347 000267f0:frntend.accept(0006)=0019 from [some_ip:52750] ALPN=h2 20180629.1347 mpeh2 fd25 h2c_stream_new - id00000123 st00 fl00000000 streams:6 -> 7 20180629.1347 000267f1:frntend.accept(0006)=0019 from [some_ip:52750] ALPN=h2 20180629.1347 mpeh2 fd25 h2c_stream_new - id00000125 st00 fl00000000 streams:7 -> 8 20180629.1347 000267f2:frntend.accept(0006)=0019 from [some_ip:52750] ALPN=h2 20180629.1347 mpeh2 fd25 h2c_stream_new - id00000127 st00 fl00000000 streams:8 -> 9 20180629.1347 000267f3:frntend.accept(0006)=0019 from [some_ip:52750] ALPN=h2 OK, we have some new h2 streams 20180629.1347 000267eb:frntend.clireq[0019:ffffffff]: GET /some/uri HTTP/1.1 20180629.1347 000267ec:frntend.clireq[0019:ffffffff]: GET /some/uri HTTP/1.1 20180629.1347 000267ed:frntend.clireq[0019:ffffffff]: GET /some/uri HTTP/1.1 20180629.1347 000267ee:frntend.clireq[0019:ffffffff]: GET /some/uri HTTP/1.1 20180629.1347 000267ef:frntend.clireq[0019:ffffffff]: GET /some/uri HTTP/1.1 20180629.1347 000267f0:frntend.clireq[0019:ffffffff]: GET /some/uri HTTP/1.1 20180629.1347 000267f1:frntend.clireq[0019:ffffffff]: GET /some/uri HTTP/1.1 20180629.1347 000267f2:frntend.clireq[0019:ffffffff]: GET /some/uri HTTP/1.1 20180629.1347 000267f3:frntend.clireq[0019:ffffffff]: GET /some/uri HTTP/1.1 20180629.1347 000267eb:backend.srvrep[0019:0010]: HTTP/1.1 200 OK 20180629.1347 000267ef:backend.srvrep[0019:001b]: HTTP/1.1 200 OK 20180629.1347 000267f1:backend.srvrep[0019:001d]: HTTP/1.1 200 OK 20180629.1347 000267f3:backend.srvrep[0019:001f]: HTTP/1.1 200 OK 20180629.1347 000267f2:backend.srvrep[0019:adfd]: HTTP/1.1 200 OK 20180629.1347 000267f2:backend.srvcls[0019:adfd] 20180629.1347 mpeh2 fd25 h2s_close/h2c - id00000125 h2c_st02 h2c_fl00000000 streams:9 20180629.1347 mpeh2 fd25 h2s_close/real - id00000125 st04 fl00003001 streams:9 -> 8 20180629.1347 000267ee:backend.srvrep[0019:adfd]: HTTP/1.1 200 OK 20180629.1347 000267ee:backend.srvcls[0019:adfd] 20180629.1347 000267f0:backend.srvrep[0019:adfd]: HTTP/1.1 200 OK 20180629.1347 000267f0:backend.srvcls[0019:adfd] 20180629.1347 000267f4:frntend.clicls[0019:ffffffff] 20180629.1347 000267f4:frntend.closed[0019:ffffffff] 20180629.1347 mpeh2 fd25 h2s_destroy - id00000125 st07 fl00003003 streams:8 20180629.1347 mpeh2 fd25 h2s_close/h2c - id00000125 h2c_st02 h2c_fl00000000 streams:8 20180629.1347 mpeh2 fd25 h2s_close/dumy - id00000125 st07 fl00003003 streams:8 -> 8 20180629.1347 mpeh2 fd25 h2s_close/h2c - id0000011d h2c_st02 h2c_fl00000000 streams:8 20180629.1347 mpeh2 fd25 h2s_close/real - id0000011d st04 fl00003001 streams:8 -> 7 20180629.1347 mpeh2 fd25 h2s_close/h2c - id00000121 h2c_st02 h2c_fl00000000 streams:7 20180629.1347 mpeh2 fd25 h2s_close/real - id00000121 st04 fl00003001 streams:7 -> 6 20180629.1347 000267ed:backend.srvrep[0019:0017]: HTTP/1.1 200 OK 20180629.1347 000267ec:backend.srvrep[0019:adfd]: HTTP/1.1 200 OK 20180629.1347 000267ec:backend.srvcls[0019:adfd] 20180629.1347 000267f5:frntend.clicls[0019:ffffffff] 20180629.1347 000267f5:frntend.closed[0019:ffffffff] 20180629.1347 mpeh2 fd25 h2s_destroy - id0000011d st07 fl00003003 streams:6 20180629.1347 mpeh2 fd25 h2s_close/h2c - id0000011d h2c_st02 h2c_fl00000002 streams:6 20180629.1347 mpeh2 fd25 h2s_close/dumy - id0000011d st07 fl00003003 streams:6 -> 6 20180629.1347 000267f6:frntend.clicls[0019:ffffffff] 20180629.1347 000267f6:frntend.closed[0019:ffffffff] 20180629.1347 mpeh2 fd25 h2s_destroy - id00000121 st07 fl00003003 streams:6 20180629.1347 mpeh2 fd25 h2s_close/h2c - id00000121 h2c_st02 h2c_fl00000002 streams:6 20180629.1347 mpeh2 fd25 h2s_close/dumy - id00000121 st07 fl00003003 streams:6 -> 6 20180629.1347 mpeh2 fd25 h2c_stream_new - id00000129 st00 fl00000000 streams:6 -> 7 20180629.1347 000267f7:frntend.accept(0006)=0019 from [some_ip:52750] ALPN=h2 20180629.1347 mpeh2 fd25 h2c_stream_new - id0000012b st00 fl00000000 streams:7 -> 8 20180629.1347 000267f8:frntend.accept(0006)=0019 from [some_ip:52750] ALPN=h2 20180629.1347 000267f7:frntend.clireq[0019:ffffffff]: GET /some/uri HTTP/1.1 20180629.1347 000267f8:frntend.clireq[0019:ffffffff]: POST /some/uri HTTP/1.1 20180629.1347 000267f7:backend.srvrep[0019:000f]: HTTP/1.1 200 OK 20180629.1347 000267f7:backend.srvcls[0019:adfd] 20180629.1347 000267f8:backend.srvrep[0019:0015]: HTTP/1.1 200 OK 20180629.1347 000267f8:backend.srvcls[0019:adfd] 20180629.1347 mpeh2 fd25 h2s_close/h2c - id00000119 h2c_st04 h2c_fl00000000 streams:8 20180629.1347 mpeh2 fd25 h2s_close/real - id00000119 st04 fl00003001 streams:8 -> 7 20180629.1347 mpeh2 fd25 h2s_close/h2c - id00000129 h2c_st04 h2c_fl00000000 streams:7 20180629.1347 mpeh2 fd25 h2s_close/real - id00000129 st04 fl00003001 streams:7 -> 6 20180629.1347 mpeh2 fd25 h2s_close/h2c - id0000012b h2c_st04 h2c_fl00000000 streams:6 20180629.1347 mpeh2 fd25 h2s_close/real - id0000012b st04 fl00003101 streams:6 -> 5 20180629.1347 mpeh2 fd25 h2s_close/h2c - id00000117 h2c_st04 h2c_fl00000000 streams:5 20180629.1347 mpeh2 fd25 h2s_close/real - id00000117 st04 fl00003001 streams:5 -> 4 20180629.1347 000267fc:frntend.clicls[0019:ffffffff] 20180629.1347 000267fc:frntend.closed[0019:ffffffff] 20180629.1347 mpeh2 fd25 h2s_destroy - id00000119 st07 fl00003003 streams:4 20180629.1347 mpeh2 fd25 h2s_close/h2c - id00000119 h2c_st04 h2c_fl00000002 streams:4 20180629.1347 mpeh2 fd25 h2s_close/dumy - id00000119 st07 fl00003003 streams:4 -> 4 20180629.1347 000267fd:frntend.clicls[0019:ffffffff] 20180629.1347 000267fd:frntend.closed[0019:ffffffff] 20180629.1347 mpeh2 fd25 h2s_destroy - id00000129 st07 fl00003003 streams:4 20180629.1347 mpeh2 fd25 h2s_close/h2c - id00000129 h2c_st04 h2c_fl00000002 streams:4 20180629.1347 mpeh2 fd25 h2s_close/dumy - id00000129 st07 fl00003003 streams:4 -> 4 20180629.1347 000267fe:frntend.clicls[0019:ffffffff] 20180629.1347 000267fe:frntend.closed[0019:ffffffff] 20180629.1347 mpeh2 fd25 h2s_destroy - id00000117 st07 fl00003003 streams:4 20180629.1347 mpeh2 fd25 h2s_close/h2c - id00000117 h2c_st04 h2c_fl00000002 streams:4 20180629.1347 mpeh2 fd25 h2s_close/dumy - id00000117 st07 fl00003003 streams:4 -> 4 Everything OK until now. 20180629.1347 mpeh2 fd25 h2c_error - st04 fl00000002 err05 Just hit h2c_error - H2_ERR_STREAM_CLOSED 20180629.1347 000267ed:backend.srvcls[0019:adfd] 20180629.1347 000267ed:backend.clicls[0019:adfd] 20180629.1347 000267ed:backend.closed[0019:adfd] 20180629.1347 000267ef:backend.srvcls[0019:adfd] 20180629.1347 000267ef:backend.clicls[0019:adfd] 20180629.1347 000267ef:backend.closed[0019:adfd] 20180629.1347 000267f1:backend.srvcls[0019:adfd] 20180629.1347 000267f1:backend.clicls[0019:adfd] 20180629.1347 000267f1:backend.closed[0019:adfd] 20180629.1347 000267f3:backend.srvcls[0019:adfd] 20180629.1347 000267f3:backend.clicls[0019:adfd] 20180629.1347 000267f3:backend.closed[0019:adfd] 20180629.1347 000267f8:backend.clicls[0019:adfd] 20180629.1347 000267f8:backend.closed[0019:adfd] 20180629.1347 mpeh2 fd25 h2s_destroy - id0000012b st07 fl00003103 streams:4 Let's destroy remaining streams 20180629.1347 mpeh2 fd25 h2s_close/h2c - id0000012b h2c_st07 h2c_fl00000100 streams:4 h2c is in H2_CS_ERROR2 20180629.1347 mpeh2 fd25 h2s_close/dumy - id0000012b st07 fl00003103 streams:4 -> 4 h2s already in H2_SS_CLOSED state And that is all, no more logs for file descriptor 25.
