"the stream output chain is empty" while writing a stream filter module

Mon Jan 10 18:28:42 UTC 2022

Hello!

On Mon, Jan 10, 2022 at 10:10:37AM +0000, Max Dymond wrote:

> I'm trying to use NGINX as an SSL "man in the middle" to (a) 
> terminate an SSL stream, (b) parse a binary protocol inside that 
> stream to accept or reject messages, (c) connect over SSL to 
> another target and send all the accepted messages.
> 
> After a bit of investigation I'm trying my hand at a stream 
> filter module, and I'm trying to do a very simple module which:
> - splits incoming messages into individual buffers (the protocol 
> has well-defined packet sizes)
> - creates chain links for each of these messages.
> 
>         // Create a new buffer and chain link.
>         link = ngx_alloc_chain_link(c->pool);
>         if (link == NULL) {
>             return NGX_ERROR;
>         }
> 
>         b = ngx_create_temp_buf(c->pool, frame_length);
>         link->buf = b;
> 
>         // Copy the frame into the buffer.
>         ngx_memcpy(link->buf->start, pos, frame_length);
>         link->buf->last += frame_length;
>         link->buf->tag = cl->buf->tag;
>         link->buf->flush = cl->buf->flush;
> 
> 
> This process seems to work but I'm getting an error message when 
> I pass my chain to the next filter:
> 
> 	return ngx_stream_next_filter(s, out, from_upstream);
> 
> gives 
> 
> 	the stream output chain is empty while proxying and sending to upstream, client: 172.20.0.5, server: 0.0.0.0:9043, upstream: "172.20.0.2:9042", bytes from/to client:9/61, bytes from/to upstream:61/9
> 
> I've got diagnostics which verify the (single) chainlink I'm 
> passing to the next filter:
> 
> 	2022/01/10 09:26:14 [info] 24#24: *3 MD: OUT chainlink ....3FB0: buf: ....ADE0 pos:....3FC0 last:....3FC9 file_pos:0 file_last:0 start:....3FC0 end:....3FC9 tag:000055D260A4A880 file:0000000000000000 temporary:1 memory:0 mmap:0 recycled:0 in_file:0 flush:1 last_buf:0 last_in_chain:0 temp_file:0
> 
> (I'm copying the tag and the flush bit from the original chain 
> in the hopes of it doing something, but no dice).

Note that copying tags is generally wrong.  Tags are used to 
identify buffers owned by a module, and wrong tag may result in 
incorrect behaviour if a module will try to modify/reuse such 
buffer.  I don't think this can be a problem in your particular 
case, yet it's something to avoid.

> When I turn debug mode on logs are a little confusing as well; 
> for the incoming chain:
> 
> 	2022/01/10 10:03:30 [info] 24#24: *5 MD: IN chainlink ....7C00: buf: ....7C10 pos:....91E0 last:....91E9 file_pos:0 file_last:0 start:0000000000000000 end:0000000000000000 tag:000055928B63E880 file:0000000000000000 temporary:1 memory:0 mmap:0 recycled:0 in_file:0 flush:1 last_buf:0 last_in_chain:0 temp_file:0
> 	<my processing>
> 	2022/01/10 10:03:30 [info] 24#24: *5 MD: OUT chainlink ....7C60: buf: ....EA70 pos:....7C70 last:....7C79 file_pos:0 file_last:0 start:.....7C70 end:.....7C79 tag:000055928B63E880 file:0000000000000000 temporary:1 memory:0 mmap:0 recycled:0 in_file:0 flush:1 last_buf:0 last_in_chain:0 temp_file:0
> 	2022/01/10 10:03:30 [debug] 24#24: *5 write new buf t:1 f:0 00007FFB71B57C70, pos 00007FFB71B57C70, size: 9 file: 0, size: 0
> 	2022/01/10 10:03:30 [debug] 24#24: *5 stream write filter: l:0 f:1 s:9
> 	2022/01/10 10:03:30 [debug] 24#24: *5 writev: 9 of 9
> 	2022/01/10 10:03:30 [debug] 24#24: *5 stream write filter 0000000000000000
> 	2022/01/10 10:03:30 [debug] 24#24: *5 event timer: 4, old: 515169565, new: 515169565

Writing of your buffer is done here.  Following lines correspond 
to the next chunk of data:

> 	2022/01/10 10:03:30 [debug] 24#24: *5 recv: eof:0, avail:-1
> 	2022/01/10 10:03:30 [debug] 24#24: *5 recv: fd:12 61 of 16384
> 	2022/01/10 10:03:30 [debug] 24#24: *5 write new buf t:1 f:0 0000000000000000, pos 00007FFB70AADC10, size: 61 file: 0, size: 0
> 	2022/01/10 10:03:30 [debug] 24#24: *5 stream write filter: l:0 f:1 s:61
> 	2022/01/10 10:03:30 [debug] 24#24: *5 SSL to write: 61
> 	2022/01/10 10:03:30 [debug] 24#24: *5 SSL_write: 61
> 	2022/01/10 10:03:30 [debug] 24#24: *5 stream write filter 0000000000000000
> 	2022/01/10 10:03:30 [debug] 24#24: *5 event timer: 4, old: 515169565, new: 515169665

(As far as I understand, this is a chunk of data in the opposite 
direction: note it uses SSL_write() instead of writev().)

And here is another call of the stream write filter, which results 
in the error:

> 	2022/01/10 10:03:30 [debug] 24#24: *5 stream write filter: l:0 f:0 s:0
> 	2022/01/10 10:03:30 [alert] 24#24: *5 the stream output chain is empty	

Given no read operations before the call, most likely it's called 
again by nginx because you haven't correctly marked original 
buffers as sent.

> Am I missing some step somewhere that's causing this to fail? 
> Does anyone have an example of a simple stream filter module 
> which repackages buffers?

Some example of a stream filter module can be found in njs code, 
see here:

http://hg.nginx.org/njs/file/9b112a44e540/nginx/ngx_stream_js_module.c#l585

Note the "ctx->buf->pos = ctx->buf->last;" line, which marks the 
original buffer as fully sent:

http://hg.nginx.org/njs/file/9b112a44e540/nginx/ngx_stream_js_module.c#l648

Hope this helps.

-- 
Maxim Dounin
http://mdounin.ru/