Project

General

Profile

[Solved] How can I get my plugin's subrequest callback to be called only once all data has been placed in the chunkqueue?

Added by slogan621 over 2 years ago

Been banging my head on the wall for a while with the following issue.

We have a plugin (used to send to lighttpd multipart content) that is getting called repeatedly in its subrequest handler callback while con->file_finished 0 and con->stream_response_body 0 (and con->stream_request_body 0 if that matters). I am using 1.4.45. The same plugin in a somewhat older lighttpd (not sure of the version, but at least a year prior to the release of 1.4.45) will only get called once in its subrequest hander. The content is not chunked. Is there some other thing that I need to be aware of to cause it to behave like before, only one call to me once the file has been completely written and all the data resides in chuinkqueue list?

To handle this at the moment, I have this at the top of the handler:

  if (!con->file_finished) {
    return HANDLER_GO_ON;
  }

eventually I will see file_finished 1 but the con->request_content_queue->first member is NULL which the plugin in expecting. A number of tmp files are written to hold the chunkqueue data, maybe the call into the subrequest handler is for the last of these but I'd need to run some experiments to be sure. I need to run some experiments but it could be that in the older lighttpd there is only one file being written to tmp.

Anyway, I did read a posting https://redmine.lighttpd.net/projects/lighttpd/repository/revisions/695c8f4e070b290d98b2ea253a76897c7b86a0d6 that described the various values for stream-response-body and stream-request-body and it seems like I want 0, I wan't all the data buffered and don't want to be called until it is ready.

I'm hoping to not have to recode the plugin, figuring its a config issue maybe, but after reading what docs I can, lots of debug logging, looking at code in connections.c and connections-glue.c, looking at other plugins, still not quite sure how to tackle this.

Here's a snippet of some of the logs for the last couple calls to our subrequest handler and all the state changes in connections that I logged along with various flags found in the con object:

2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.57) connection_set_state con 269458232 state read stream_request_body 0 chunked false
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.54) connection_set_state con 269458232 state req-end bytes read 589 keep_alive is 1
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.55) connection_set_state con 269458232 state req-end file_finished 0 file_started 0
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.56) connection_set_state con 269458232 state req-end stream_response_body 0 chunked false
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.57) connection_set_state con 269458232 state req-end stream_request_body 0 chunked false
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.54) connection_set_state con 269458232 state handle-req bytes read 589 keep_alive is 1
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.55) connection_set_state con 269458232 state handle-req file_finished 0 file_started 0
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.56) connection_set_state con 269458232 state handle-req stream_response_body 0 chunked false
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.57) connection_set_state con 269458232 state handle-req stream_request_body 0 chunked false
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/mod_multipart.c.1258) mod_multipart_handle_subrequest file is done
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/mod_multipart.c.1263) mod_multipart_handle_subrequest ours
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.54) connection_set_state con 269458232 state resp-start bytes read 589 keep_alive is 1
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.55) connection_set_state con 269458232 state resp-start file_finished 1 file_started 1
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.56) connection_set_state con 269458232 state resp-start stream_response_body 0 chunked false
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.57) connection_set_state con 269458232 state resp-start stream_request_body 0 chunked false
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.54) connection_set_state con 269458232 state write bytes read 589 keep_alive is 1
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.55) connection_set_state con 269458232 state write file_finished 1 file_started 1
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.56) connection_set_state con 269458232 state write stream_response_body 0 chunked false
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.57) connection_set_state con 269458232 state write stream_request_body 0 chunked false
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.54) connection_set_state con 269458232 state resp-end bytes read 589 keep_alive is 1
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.55) connection_set_state con 269458232 state resp-end file_finished 1 file_started 1
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.56) connection_set_state con 269458232 state resp-end stream_response_body 0 chunked false
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.57) connection_set_state con 269458232 state resp-end stream_request_body 0 chunked false
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.54) connection_set_state con 269458232 state req-start bytes read 0 keep_alive is 1
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.55) connection_set_state con 269458232 state req-start file_finished 0 file_started 0
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.56) connection_set_state con 269458232 state req-start stream_response_body 0 chunked false
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.57) connection_set_state con 269458232 state req-start stream_request_body 0 chunked false
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.54) connection_set_state con 269458232 state read bytes read 0 keep_alive is 1
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.55) connection_set_state con 269458232 state read file_finished 0 file_started 0
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.56) connection_set_state con 269458232 state read stream_response_body 0 chunked false
2017-11-25 13:42:06: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.57) connection_set_state con 269458232 state read stream_request_body 0 chunked false
2017-11-25 13:42:07: (../../../../vendor/webserver/lighttpd/src/mod_multipart.c.1258) mod_multipart_handle_subrequest file is done
2017-11-25 13:42:07: (../../../../vendor/webserver/lighttpd/src/mod_multipart.c.1263) mod_multipart_handle_subrequest ours
2017-11-25 13:42:07: (../../../../vendor/webserver/lighttpd/src/mod_multipart.c.1268) mod_multipart_handle_subrequest POST
2017-11-25 13:42:07: (../../../../vendor/webserver/lighttpd/src/mod_multipart.c.1273) mod_multipart_handle_subrequest got headers
Connection closed by foreign host.vendor/webserver/lighttpd/src/mod_multipart.c.1300) mod_multipart_handle_subrequest calling check_file_data
Press Enter key to continue.../../vendor/webserver/lighttpd/src/mod_multipart.c.729) check_file_data content_length 24793798 first NULL? yes
2017-11-25 13:42:07: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.54) connection_set_state con 269425592 state resp-start bytes read 24794589 keep_alive is 1
2017-11-25 13:42:07: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.55) connection_set_state con 269425592 state resp-start file_finished 1 file_started 1
2017-11-25 13:42:07: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.56) connection_set_state con 269425592 state resp-start stream_response_body 0 chunked false
2017-11-25 13:42:07: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.57) connection_set_state con 269425592 state resp-start stream_request_body 0 chunked false
2017-11-25 13:42:07: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.54) connection_set_state con 269425592 state write bytes read 24794589 keep_alive is 1
2017-11-25 13:42:07: (../../../../vendor/webserver/lighttpd/src/connections-glue.c.55) connection_set_state con 269425592 state write file_finished 1 file_started 1

Here is the plugin init:

int mod_multipart_plugin_init(plugin *p) {
  p->version           = LIGHTTPD_VERSION_ID;
  p->name              = buffer_init_string("multipart");

  p->init              = mod_multipart_init;

  /* Called after URI is URL-decoded */
  p->handle_uri_clean  = mod_multipart_uri_handler;

  /* Called after full sub-request (in our case the full POST) has been received. */
  p->handle_subrequest = mod_multipart_handle_subrequest;

  p->set_defaults      = mod_multipart_set_defaults;
  p->cleanup           = mod_multipart_free;

  p->data              = NULL;

  return 0;
}

Replies (3)

RE: [Solved] How can I get my plugin's subrequest callback to be called only once all data has been placed in the chunkqueue? - Added by gstrauss over 2 years ago

Sorry, it sounds like you need to do some re-coding.

Not all modules handle request body, so instead of reading the request body before running handlers, the handlers are run and the subrequest handler needs to call connection_handle_read_post_state() to read the request body.

Look at mod_cgi_handle_subrequest() in mod_cgi. You should be able to use the first half of the routine verbatim in your module to read the request body before proceeding.

[edit]
As per above, the comment in your code (below) is no longer valid. The subrequest handler gets called and must trigger reading of request body.

  /* Called after full sub-request (in our case the full POST) has been received. */
  p->handle_subrequest = mod_multipart_handle_subrequest;

RE: [Solved] How can I get my plugin's subrequest callback to be called only once all data has been placed in the chunkqueue? - Added by slogan621 over 2 years ago

Awesome, thanks for the quick response - I will take a look at this as soon as I can and see if I can make sense of it.

syd

RE: [Solved] How can I get my plugin's subrequest callback to be called only once all data has been placed in the chunkqueue? - Added by slogan621 over 2 years ago

That seems to have done the trick.

After looking at the mod_cgi plugin, I searched for other uses and found that the webdav plugin was structured a bit more closely to our plugin. Our logic in handling the subrequest callback is, basically:

- make sure the plugin is for us
- check that it is a POST
- check the content type to make sure it it is multipart/form-data
- then (and this is the part taken nearly verbatim from webdav module):

if (con->request.content_length) {{
handler_t r = connection_handle_read_post_state(srv, con);
if (r != HANDLER_GO_ON) return r;
}

- walk the chunkqueue, decoding the content and putting the result in the desired location of the filesystem.

The CGI code had quite a bit more logic going on in the first half of the handler While I still have to do some cleanup and negative testing, on the strength of the positive tested passing now 2 for 2 tries and the webdav code, I'm thinking that it all boiled down to the above few lines.

While I'm here, we got bit in porting to 1.4.45 by changes in the buffer code. We had to reinstate buffer_prepare_copy() which basically provides a raw buffer that is not length 1 and set initially to '\0'; I guess in all other use cases in the lighttpd code base, these buffers are intended for strings but we were basically using them as raw byte buffers in our plugin. When I did the port I didn't pay close attention and switching to the string-based buffer prepare left us with a one-off error that was fixed by pulling back in buffer_prepare_copy and using that instead.

Again, thanks for the help. Consumed quite a bit of my Thanksgiving weekend trying to get to this point, your response to my plea for help really came through and my thanks.

    (1-3/3)