Seg fault in http read event handler caused by rouge event call without context

Mon Nov 18 16:03:11 UTC 2019

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 at 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/