Hi all,
I am trying to create the following scenario with Nginx-Perl-1.2.9.7 –
1. Create an nginx perl handler to generate response to clients requests
2. Do some stuff in the perl handler once a client request is received
3. Call the nginx-timer within the perl-handler
4. Send a reply to the client from the timer callback.

Below are the nginx.conf file, the PerlHandler code and the nginx debug log.
As far as I can tell, I can see the following problems –
1. Nginx finalize the request once the perl-handler returns.
To my understanding, finalizing the request should be postponed to the timer (due to main_count_inc)
2. The client receives no reply.
3. I get the following error in the debug file - “perl: attempt to use destroyed request” once the timer callback is fired, see end of nginx log file.

Appreciate any help.

Configuration file:
#user nobody;
worker_processes 1;
events {
worker_connections 1024;
}
error_log /usr/local/nginx-perl/logs/debug debug;

http {
perl_modules /home/ubuntu/perl_handlers;
perl_require PerlHandler.pm;
server {
listen 80 ;
location / {
perl_handler PerlHandler::perl_handler_handle;
}
}
}

PerlHandler.pm
package PerlHandler;
use Nginx;

sub perl_handler_handle {
my ($r) = @_;
$r->main_count_inc;
$r->log_error("0", "start perl handler");
ngx_timer 10, 0, sub {
ngx_log_notice 0, "in timer";
$r->send_http_header('text/html');
$r->print("OK\n");
$r->send_special(NGX_HTTP_LAST);
$r->finalize_request(NGX_OK);
};
return NGX_DONE;
}


Nginx-Perl log:
2014/05/02 16:57:16 [debug] 3799#0: *1 http process request header line
2014/05/02 16:57:16 [debug] 3799#0: *1 http header: "User-Agent: Wget/1.13.4 (linux-gnu)"
2014/05/02 16:57:16 [debug] 3799#0: *1 http header: "Accept: */*"
2014/05/02 16:57:16 [debug] 3799#0: *1 http header: "Host: 172.31.42.127"
2014/05/02 16:57:16 [debug] 3799#0: *1 http header: "Connection: Keep-Alive"
2014/05/02 16:57:16 [debug] 3799#0: *1 http header done
2014/05/02 16:57:16 [debug] 3799#0: *1 event timer del: 3: 1399049896673
2014/05/02 16:57:16 [debug] 3799#0: *1 rewrite phase: 0
2014/05/02 16:57:16 [debug] 3799#0: *1 test location: "/"
2014/05/02 16:57:16 [debug] 3799#0: *1 using configuration "/"
2014/05/02 16:57:16 [debug] 3799#0: *1 http cl:-1 max:1048576
2014/05/02 16:57:16 [debug] 3799#0: *1 rewrite phase: 2
2014/05/02 16:57:16 [debug] 3799#0: *1 post rewrite phase: 3
2014/05/02 16:57:16 [debug] 3799#0: *1 generic phase: 4
2014/05/02 16:57:16 [debug] 3799#0: *1 generic phase: 5
2014/05/02 16:57:16 [debug] 3799#0: *1 access phase: 6
2014/05/02 16:57:16 [debug] 3799#0: *1 add cleanup: 0000000000C4A230
2014/05/02 16:57:16 [debug] 3799#0: *1 access phase: 7
2014/05/02 16:57:16 [debug] 3799#0: *1 access phase: 8
2014/05/02 16:57:16 [debug] 3799#0: *1 post access phase: 9
2014/05/02 16:57:16 [debug] 3799#0: *1 perl handler
2014/05/02 16:57:16 [error] 3799#0: *1 perl: start perl handler, client: 172.31.7.101, server: , request: "GET /test HTTP/1.1", host: "172.31.42.127"
2014/05/02 16:57:16 [debug] 3799#0: event timer add: 0: 10000:1399049846673
2014/05/02 16:57:16 [debug] 3799#0: *1 call_sv: -4
2014/05/02 16:57:16 [debug] 3799#0: *1 perl handler done: -4
2014/05/02 16:57:16 [debug] 3799#0: *1 http finalize request: -4, "/test?" a:1, c:2
2014/05/02 16:57:16 [debug] 3799#0: *1 http request count:2 blk:0
2014/05/02 16:57:16 [debug] 3799#0: *1 http finalize request: -4, "/test?" a:1, c:1
2014/05/02 16:57:16 [debug] 3799#0: *1 set http keepalive handler
2014/05/02 16:57:16 [debug] 3799#0: *1 http close request
2014/05/02 16:57:16 [debug] 3799#0: *1 http log handler
2014/05/02 16:57:16 [debug] 3799#0: *1 run cleanup: 0000000000C4A230
2014/05/02 16:57:16 [debug] 3799#0: *1 free: 0000000000C49810, unused: 1341
2014/05/02 16:57:16 [debug] 3799#0: *1 event timer add: 3: 75000:1399049911673
2014/05/02 16:57:16 [debug] 3799#0: *1 free: 0000000000C7D4D0
2014/05/02 16:57:16 [debug] 3799#0: *1 free: 0000000000C7D9C0
2014/05/02 16:57:16 [debug] 3799#0: *1 hc free: 0000000000000000 0
2014/05/02 16:57:16 [debug] 3799#0: *1 hc busy: 0000000000000000 0
2014/05/02 16:57:16 [debug] 3799#0: *1 tcp_nodelay
2014/05/02 16:57:16 [debug] 3799#0: *1 reusable connection: 1
2014/05/02 16:57:16 [debug] 3799#0: *1 post event 0000000000CF8940
2014/05/02 16:57:16 [debug] 3799#0: timer delta: 0
2014/05/02 16:57:16 [debug] 3799#0: posted events 0000000000CF8940
2014/05/02 16:57:16 [debug] 3799#0: posted event 0000000000CF8940
2014/05/02 16:57:16 [debug] 3799#0: *1 delete posted event 0000000000CF8940
2014/05/02 16:57:16 [debug] 3799#0: *1 http keepalive handler
2014/05/02 16:57:16 [debug] 3799#0: *1 malloc: 0000000000C7D4D0:1024
2014/05/02 16:57:16 [debug] 3799#0: *1 recv: fd:3 -1 of 1024
2014/05/02 16:57:16 [debug] 3799#0: *1 recv() not ready (11: Resource temporarily unavailable)
2014/05/02 16:57:16 [debug] 3799#0: *1 free: 0000000000C7D4D0
2014/05/02 16:57:16 [debug] 3799#0: posted event 0000000000000000
2014/05/02 16:57:16 [debug] 3799#0: worker cycle
2014/05/02 16:57:16 [debug] 3799#0: epoll timer: 10000
2014/05/02 16:57:26 [debug] 3799#0: timer delta: 10012
2014/05/02 16:57:26 [debug] 3799#0: event timer del: 0: 1399049846673
2014/05/02 16:57:26 [notice] 3799#0: perl: in timer
2014/05/02 16:57:26 [error] 3799#0: perl: attempt to use destroyed request
2014/05/02 16:57:26 [error] 3799#0: perl: attempt to use destroyed request
2014/05/02 16:57:26 [error] 3799#0: perl: attempt to use destroyed request
2014/05/02 16:57:26 [error] 3799#0: perl: attempt to use destroyed request
2014/05/02 16:57:26 [debug] 3799#0: posted events 0000000000000000
2014/05/02 16:57:26 [debug] 3799#0: worker cycle
2014/05/02 16:57:26 [debug] 3799#0: epoll timer: 64988