Re: [Libevent-users] Re: libevent http and lost requests

[Mark Ellzey <mthomas@xxxxxxxxxx>]

On Tue, Aug 16, 2011 at 05:59:19PM +0300, about bus wrote:
> I've added debug output to next libevent functions:
> * event_add - add file descriptor to kqueue for monitoring network activity.
> * kq_dispatch - return file descriptor when event appeared on it.
> 
> ### Previous request which used the same file descriptor.
> ### Sending answer back to nginx.
> 2011.08.15 18:58:14 [warn] ===  event_add: event: 0x8022deb48 (fd: 115),
> EV_WRITE  call 0x800796f50
> 2011.08.15 18:58:14 [warn] ===  kq_dispatch: fd: 115 kevent reports filter:
> -2 (EVFILT_WRITE)
> 2011.08.15 18:58:14 [warn] ===  event_active: 0x8022deb48 (fd: 115), res 4,
> callback 0x800796f50
> 2011.08.15 18:58:14 [warn] ===  evhttp_write_cb: fd: 115
> 2011.08.15 18:58:14 [warn] ===  kq_dispatch: fd: 115 kevent reports filter:
> -2 (EVFILT_WRITE)
> 
> ### New request from nginx, it will be failed and reported by nginx as
> timeout error.
> ### Accepting connection and adding file descriptor to kqueue for looking
> READ event.
> 2011.08.15 18:58:15 [warn] ===  evhttp_socket_cb: fd: 115
> 2011.08.15 18:58:15 [warn] ===  evhttp_get_request_connection: fd: 115 new
> request from 127.0.0.1:57661
> 2011.08.15 18:58:15 [warn] ===  event_add: event: 0x8022de768 (fd: 115),
> EV_WRITE  call 0x800796f50
> 2011.08.15 18:58:15 [warn] ===  event_add: event: 0x8022de6e0 (fd: 115),
> EV_READ   call 0x8007971a0
> 
> ### Receiving event from kqueue for our file descriptor after 30 seconds!
> ### Receiving GET query, preparing and sending answer back to nginx.
> 2011.08.15 18:58:45 [warn] ===  kq_dispatch: fd: 115 kevent reports filter:
> -1 (EVFILT_READ)
> 2011.08.15 18:58:45 [warn] ===  event_active: 0x8022de6e0 (fd: 115), res 2,
> callback 0x8007971a0
> 2011.08.15 18:58:45 [warn] ===  evhttp_read_cb: fd: 115 len: 434: data: GET
> /QUERY/XXX/YYY/ <--headers-->
> 2011.08.15 18:58:45 v[3]        http_handler_input: id: 383131
> 2011.08.15 18:58:45 v[3]        http_handler: id: 383131 ip: XX.XX.XX.XX
> remote: 127.0.0.1:57661 uri: /brick/1/2/448/11/65/
> 2011.08.15 18:58:45 [warn] ===  event_add: event: 0x8022de768 (fd: 115),
> EV_WRITE  call 0x800796f50
> 2011.08.15 18:58:45 v[3]        http_handler_output: id: 383131
> 2011.08.15 18:58:45 [warn] ===  kq_dispatch: fd: 115 kevent reports filter:
> -2 (EVFILT_WRITE)
> 2011.08.15 18:58:45 [warn] ===  event_active: 0x8022de768 (fd: 115), res 4,
> callback 0x800796f50
> 2011.08.15 18:58:45 [warn] ===  evhttp_write_cb: fd: 115
> 2011.08.15 18:58:45 [warn] ===  kq_dispatch: fd: 115 kevent reports filter:
> -2 (EVFILT_WRITE)
> 
> ### New request from nginx.
> 2011.08.15 18:58:55 [warn] ===  evhttp_socket_cb: fd: 115
> 2011.08.15 18:58:55 [warn] ===  evhttp_get_request_connection: fd: 115 new
> request from 127.0.0.1:62217
> 
> So, our socket waited EV_READ event in kqueue for 30 seconds, and got it
> only when nginx has closed connection.
> 
> I can reproduce this issue when run my http server on FreeBSD 7.2 and
> FreeBSD 8.1
> Today I've tried to run http server on Debian Lenny 2.6.26 - everything
> working fine.

OK, this makes sense. there have been issues with kqueue being broken on older 
versions of libevent (a while back, with 1.x), try falling back to either poll or
select for now to see if it works. I still need to know what version of
libevent you are using. 
***********************************************************************
To unsubscribe, send an e-mail to majordomo@xxxxxxxxxxxxx with
unsubscribe libevent-users    in the body.