https://bz.apache.org/bugzilla/show_bug.cgi?id=61616

--- Comment #26 from Carsten Wolff <[email protected]> ---
I added this just at the end of the poll() loop:
        ap_log_rerror(APLOG_MARK, APLOG_TRACE2, 0, r,
            "@END: "
            "[%s: POLLIN: %d POLLOUT: %d POLLHUP: %d data_in_filters: %d] "
            "[%s: POLLIN: %d POLLOUT: %d POLLHUP: %d data_in_filters: %d]",
            conns[0].name,
            conns[0].pfd.reqevents & APR_POLLIN && 1,
            conns[0].pfd.reqevents & APR_POLLOUT && 1,
            conns[0].pfd.reqevents & APR_POLLHUP && 1,
            conns[0].c->data_in_output_filters,
            conns[1].name,
            conns[1].pfd.reqevents & APR_POLLIN && 1,
            conns[1].pfd.reqevents & APR_POLLOUT && 1,
            conns[1].pfd.reqevents & APR_POLLHUP && 1,
            conns[1].c->data_in_output_filters
        );


The whole long log looks like this sample:

[Sun Oct 22 21:31:00.885835 2017] [proxy_connect:debug] [pid 26472:tid
140206004721408] mod_proxy_connect.c(452): [client ::1:33400] AH01024: woke
from poll(), i=1
[Sun Oct 22 21:31:00.885891 2017] [proxy_connect:debug] [pid 26472:tid
140206004721408] mod_proxy_connect.c(483): [client ::1:33400] AH01025: client
was readable
[Sun Oct 22 21:31:00.885946 2017] [proxy:trace2] [pid 26472:tid
140206004721408] proxy_util.c(3845): [client ::1:33400]
ap_proxy_transfer_between_connections complete
[Sun Oct 22 21:31:00.885960 2017] [proxy_connect:debug] [pid 26472:tid
140206004721408] mod_proxy_connect.c(517): [client ::1:33400] backend wait
writable
[Sun Oct 22 21:31:00.885978 2017] [proxy_connect:trace2] [pid 26472:tid
140206004721408] mod_proxy_connect.c(569): [client ::1:33400] @END: [client:
POLLIN: 0 POLLOUT: 0 POLLHUP: 0 data_in_filters: 0] [backend: POLLIN: 1
POLLOUT: 1 POLLHUP: 0 data_in_filters: 1]
[Sun Oct 22 21:31:00.885992 2017] [proxy_connect:debug] [pid 26472:tid
140206004721408] mod_proxy_connect.c(452): [client ::1:33400] AH01024: woke
from poll(), i=1
[Sun Oct 22 21:31:00.886002 2017] [proxy_connect:debug] [pid 26472:tid
140206004721408] mod_proxy_connect.c(528): [client ::1:33400] backend was
writable
[Sun Oct 22 21:31:00.886068 2017] [core:trace6] [pid 26472:tid 140206004721408]
core_filters.c(878): [remote ::1:873] writev_nonblocking: 8/8 bytes
[Sun Oct 22 21:31:00.886108 2017] [proxy_connect:trace2] [pid 26472:tid
140206004721408] mod_proxy_connect.c(569): [client ::1:33400] @END: [client:
POLLIN: 1 POLLOUT: 0 POLLHUP: 0 data_in_filters: 0] [backend: POLLIN: 1
POLLOUT: 0 POLLHUP: 0 data_in_filters: 0]
[Sun Oct 22 21:31:00.888170 2017] [proxy_connect:debug] [pid 26472:tid
140206004721408] mod_proxy_connect.c(452): [client ::1:33400] AH01024: woke
from poll(), i=1
[Sun Oct 22 21:31:00.888229 2017] [proxy_connect:debug] [pid 26472:tid
140206004721408] mod_proxy_connect.c(483): [client ::1:33400] AH01025: backend
was readable
[Sun Oct 22 21:31:00.888271 2017] [proxy:trace2] [pid 26472:tid
140206004721408] proxy_util.c(3845): [client ::1:33400]
ap_proxy_transfer_between_connections complete
[Sun Oct 22 21:31:00.888307 2017] [proxy_connect:debug] [pid 26472:tid
140206004721408] mod_proxy_connect.c(517): [client ::1:33400] client wait
writable
[Sun Oct 22 21:31:00.888329 2017] [proxy_connect:trace2] [pid 26472:tid
140206004721408] mod_proxy_connect.c(569): [client ::1:33400] @END: [client:
POLLIN: 1 POLLOUT: 1 POLLHUP: 0 data_in_filters: 1] [backend: POLLIN: 0
POLLOUT: 0 POLLHUP: 0 data_in_filters: 0]
[Sun Oct 22 21:31:00.888344 2017] [proxy_connect:debug] [pid 26472:tid
140206004721408] mod_proxy_connect.c(452): [client ::1:33400] AH01024: woke
from poll(), i=1
[Sun Oct 22 21:31:00.888354 2017] [proxy_connect:debug] [pid 26472:tid
140206004721408] mod_proxy_connect.c(528): [client ::1:33400] client was
writable
[Sun Oct 22 21:31:00.888450 2017] [core:trace6] [pid 26472:tid 140206004721408]
core_filters.c(878): [client ::1:33400] writev_nonblocking: 12/12 bytes
[Sun Oct 22 21:31:00.888492 2017] [proxy_connect:trace2] [pid 26472:tid
140206004721408] mod_proxy_connect.c(569): [client ::1:33400] @END: [client:
POLLIN: 1 POLLOUT: 0 POLLHUP: 0 data_in_filters: 0] [backend: POLLIN: 1
POLLOUT: 0 POLLHUP: 0 data_in_filters: 0]


Two things are peculiar:
- we no longer request APR_POLLHUP events. Is that intentional?
- It seems like when ap_proxy_transfer_between_connections returns,
"data_in_output_filters" is always true on the outgoing connection and we're
always entering the "write wait" path.

-- 
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]

Reply via email to