Hello!

On Mon, Nov 18, 2019 at 02:03:15PM +0000, Dave Brennan wrote:

> For the last few years we have been using the "nginx_upload"
> module to streamline result posting within our environment.
>
> With the introduction of nginx 1.17.5 we saw a large number of
> segment faults, causing us to revert to 1.17.4 on our
> development system.
>
> While isolating the fault we added an increase in debug messages
> to monitor the request and context variables being passed to
> event handlers.
>
> So a good response in 1.17.4 looks like this:-
>
> 2019/11/14 10:24:21 [debug] 12398#12398: *9770 Upload handle pre alloc Request address = 0000563E9FE451F0 Context = 0000000000000000
> 2019/11/14 10:24:21 [debug] 12398#12398: *9770 Upload Handler post alloc Request address = 0000563E9FE451F0 Context = 0000563E9FE81CD8
> 2019/11/14 10:24:21 [debug] 12398#12398: *9770 Upload_eval_path Request address = 0000563E9FE451F0 Context = 0000563E9FE81CD8
> 2019/11/14 10:24:21 [debug] 12398#12398: *9770 Upload eval state path Request address = 0000563E9FE451F0 Context = 0000563E9FE81CD8
> 2019/11/14 10:24:21 [debug] 12398#12398: *9770 Upload client read Request address = 0000563E9FE451F0 Context = 0000563E9FE81CD8
> 2019/11/14 10:24:21 [debug] 12398#12398: *9770 do read upload client Request address = 0000563E9FE451F0 Context = 0000563E9FE81CD8
> 2019/11/14 10:24:21 [debug] 12398#12398: *9770 process request body Request address = 0000563E9FE451F0 Context = 0000563E9FE81CD8
> 2019/11/14 10:24:21 [debug] 12398#12398: *9770 Upload variable Request address = 0000563E9FE451F0 Context = 0000563E9FE81CD8
> 2019/11/14 10:24:21 [debug] 12398#12398: *9770 Upload variable Request address = 0000563E9FE451F0 Context = 0000563E9FE81CD8
> 2019/11/14 10:24:21 [debug] 12398#12398: *9770 Upload variable Request address = 0000563E9FE451F0 Context = 0000563E9FE81CD8
> 2019/11/14 10:24:21 [debug] 12398#12398: *9770 Upload variable Request address = 0000563E9FE451F0 Context = 0000563E9FE81CD8
> 2019/11/14 10:24:21 [debug] 12398#12398: *9770 Upload variable Request address = 0000563E9FE451F0 Context = 0000563E9FE81CD8
> 2019/11/14 10:24:21 [debug] 12398#12398: *9770 Upload variable Request address = 0000563E9FE451F0 Context = 0000563E9FE81CD8
> 2019/11/14 10:24:21 [debug] 12398#12398: *9770 Upload variable Request address = 0000563E9FE451F0 Context = 0000563E9FE81CD8
> 2019/11/14 10:24:21 [debug] 12398#12398: *9770 upload md5 variable Request address = 0000563E9FE451F0 Context = 0000563E9FE81CD8
> 2019/11/14 10:24:21 [debug] 12398#12398: *9770 Upload variable Request address = 0000563E9FE451F0 Context = 0000563E9FE81CD8
> 2019/11/14 10:24:21 [debug] 12398#12398: *9770 Upload File size variable Request address = 0000563E9FE451F0 Context = 0000563E9FE81CD8
> 2019/11/14 10:24:21 [debug] 12398#12398: *9770 Upload Body Handler Request address = 0000563E9FE451F0 Context = 0000563E9FE81CD8
>
> In 1.17.5 the event stream looks like this:-
>
> 2019/11/13 14:21:52 [debug] 28086#28086: *3703 Upload handle pre alloc Request address = 0000558ADDD4F780 Context = 0000000000000000
> 2019/11/13 14:21:52 [debug] 28086#28086: *3703 Upload Handler post alloc Request address = 0000558ADDD4F780 Context = 0000558ADDD49FF8
> 2019/11/13 14:21:52 [debug] 28086#28086: *3703 Upload_eval_path Request address = 0000558ADDD4F780 Context = 0000558ADDD49FF8
> 2019/11/13 14:21:52 [debug] 28086#28086: *3703 Upload eval state path Request address = 0000558ADDD4F780 Context = 0000558ADDD49FF8
> 2019/11/13 14:21:52 [debug] 28086#28086: *3703 Upload client read Request address = 0000558ADDD4F780 Context = 0000558ADDD49FF8
> 2019/11/13 14:21:52 [debug] 28086#28086: *3703 do read upload client Request address = 0000558ADDD4F780 Context = 0000558ADDD49FF8
> 2019/11/13 14:21:52 [debug] 28086#28086: *3703 process request body Request address = 0000558ADDD4F780 Context = 0000558ADDD49FF8
> 2019/11/13 14:21:52 [debug] 28086#28086: *3703 Upload variable Request address = 0000558ADDD4F780 Context = 0000558ADDD49FF8
> 2019/11/13 14:21:52 [debug] 28086#28086: *3703 Upload variable Request address = 0000558ADDD4F780 Context = 0000558ADDD49FF8
> 2019/11/13 14:21:52 [debug] 28086#28086: *3703 Upload variable Request address = 0000558ADDD4F780 Context = 0000558ADDD49FF8
> 2019/11/13 14:21:52 [debug] 28086#28086: *3703 Upload variable Request address = 0000558ADDD4F780 Context = 0000558ADDD49FF8
> 2019/11/13 14:21:52 [debug] 28086#28086: *3703 Upload variable Request address = 0000558ADDD4F780 Context = 0000558ADDD49FF8
> 2019/11/13 14:21:52 [debug] 28086#28086: *3703 Upload variable Request address = 0000558ADDD4F780 Context = 0000558ADDD49FF8
> 2019/11/13 14:21:52 [debug] 28086#28086: *3703 process request body Request address = 0000558ADDD4F780 Context = 0000558ADDD49FF8
> 2019/11/13 14:21:52 [debug] 28086#28086: *3703 Upload variable Request address = 0000558ADDD4F780 Context = 0000558ADDD49FF8
> 2019/11/13 14:21:52 [debug] 28086#28086: *3703 upload md5 variable Request address = 0000558ADDD4F780 Context = 0000558ADDD49FF8
> 2019/11/13 14:21:52 [debug] 28086#28086: *3703 Upload variable Request address = 0000558ADDD4F780 Context = 0000558ADDD49FF8
> 2019/11/13 14:21:52 [debug] 28086#28086: *3703 Upload File size variable Request address = 0000558ADDD4F780 Context = 0000558ADDD49FF8
> 2019/11/13 14:21:52 [debug] 28086#28086: *3703 Upload Body Handler Request address = 0000558ADDD4F780 Context = 0000558ADDD49FF8
>
> 2019/11/13 14:21:52 [debug] 28086#28086: *3703 read upload clent request body Request address = 0000558ADDD4F780 Context = 0000000000000000
> 2019/11/13 14:21:52 [debug] 28086#28086: *3703 do read upload client Request address = 0000558ADDD4F780 Context = 0000000000000000
>
>
> There appears to be an extra call to the request "read event"
> and although the request address has not changed the context
> address returned by:-
>
> ngx_http_upload_ctx_t *u = ngx_http_get_module_ctx(r, ngx_http_upload_module);
>
> Returns NULL, which causes any reference to the context table to cause a segment fault.
>
> While it is possible to work round this by checking for a NULL
> context, the read event appears to be rouge when compared to the
> previous version of nginx, and I can only assume has been
> generated by code changes in 1.17.5.

In 1.17.5, a mechanism to limit amount of data being read in a
single event loop iteration was introduced. See the following
commits:

http://hg.nginx.org/nginx/rev/efd71d49bde0
http://hg.nginx.org/nginx/rev/9d2ad2fb4423

This is not expected to affect any properly written code, but may
change various timings and sizes, revealing existing bugs in the
code. Most importantly, this can affect SSL connections.

Further, looking into the upload module code suggests that it is
based on an old version of the nginx body reading code, and seems
to miss this this fix from 2011
(http://hg.nginx.org/nginx/rev/cf334deeea66):

changeset: 4072:cf334deeea66
user: Maxim Dounin <mdounin@mdounin.ru>
date: Mon Sep 05 12:43:31 2011 +0000
summary: Bugfix: read event was not blocked after reading body.

That is, the upload module fails to disable read event handler
once request body reading is done, and any additional client
activity might trigger a problem. In this particular case an
additional event probably happens due to the limits introduced,
and the code cannot handle it.

I would expect the same problem to also happen with nginx 1.17.4
on real additional client activity. Either way, it looks like a
bug in the upload module.

--
Maxim Dounin
http://mdounin.ru/
_______________________________________________
nginx-devel mailing list
nginx-devel@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-devel