Malformed eventsource messages when delived during nchan_subrequest

[shtinkov]

#Hello, Iam trying to test eventousrce with nchan. Server is Debian/stretch with nginx-1.13.3 and nchan from master branch (27.11.2017 with latest more delayed-ipc fixing). Here is my nchan configuration:

location /test/publish {
    nchan_channel_id $arg_channel;
    nchan_message_timeout 20s;
    nchan_publisher;
}
location /test/subscribe {
    nchan_channel_id $arg_channel;
    nchan_subscriber eventsource;
    nchan_subscriber_first_message newest;
    nchan_subscribe_request /test/post_msg;
 }
 location = /test/post_msg {
    internal;
    proxy_pass $scheme://$server_addr:$server_port/test/publish?channel=$arg_park/0/0;
    proxy_cache off;
    proxy_method POST;
    proxy_set_header Accept text/json;
    proxy_set_header Content-Type text/json;
    proxy_set_body "{\"device_id\":$arg_device, \"purpose\":$arg_purpose, \"qtype\":\"$arg_qtype\", \"value\":\"$arg_value\",\"channel\":\"$arg_channel\"}";
 }

Testing is done in a following way In my first terminal i start:

curl --request GET -H "Accept: text/event-stream" "https://inovent.bg/test/subscribe?channel=1/0/0&park=1&device=0&purpose=3&qtype=subscription" which produces: ": hi"

on my second terminal i invoke the same: curl --request GET -H "Accept: text/event-stream" "https://inovent.bg/test/subscribe?channel=1/0/0&park=1&device=0&purpose=3&qtype=subscription"

then on first terminal appears: 1511853461:0id: {"device_id":0, "purpose":3, "qtype":"subscription", "value":"","channel":"1/0/0"}data:

You can see that message is malformed

You can check the situation also online because server is up and running

[slact]

Confirmed, looking into it.

[slact]

that was a weird one. fixed in 43a51bb0ebcf251e2c7b2ddbaa08f0b0880fb3a7

[shtinkov]

Thank you very much for the patch! I tested, and it works perfectly!

[nkuehn]

Hi @shtinkov can you recommend the most hassle-free way to test this on debian?
I also have issues with subrequests calling nchan publish paths and currently use the latest debian 1.13.8-1 nginx, but that does not have this patch included yet ( https://anonscm.debian.org/cgit/pkg-nginx/nginx.git/tree/debian/modules/nchan/changelog.txt ). Would like to avoid switching to an own build since there's other hard-to-build modules included.

@slact FYI I'm calling nchan from a 'content_by_lua_block' module using the lua ngx.location.capture() call to be able to modify the response header from 201/202 to 200 (the calling side is a message queue that needs 200 as response for success). In my case the request "just hangs" and does not return at all.

[shtinkov]

Hi, I use debian stretch, and the only solution for me is my own build. Even in backports nchan version is 1.0.8.

[nkuehn]

Thanks! Just saw that nchan has a test / internal build that includes openresty, I'll try to run that to get a binary for my needs: https://github.com/slact/nchan/blob/master/dev/rebuild.sh#L108

[neben]

This is still happening on nchan version 1.1.15, probably connected to nchan_subscribe_request handler posting back to the original pubsub location. The corrupted frame looks like this:

foo:subscribed

1528406275:[0],0id: 

nginx/nchan config:

	location = /pubsub {
		nchan_pubsub;
		nchan_subscriber_channel_id $arg_sub;
		nchan_publisher_channel_id $arg_pub;
		nchan_channel_id_split_delimiter ",";
		nchan_message_buffer_length 1;
		nchan_message_timeout 1w;
		nchan_max_channel_id_length 4096;
		nchan_channel_group "self";
		nchan_subscribe_request /pubsub/sub;
		nchan_unsubscribe_request /pubsub/unsub;
	}

	location = /pubsub/sub {
		internal;
		keepalive_timeout 0;
		content_by_lua_block {
			ngx.eof()
			local id = ngx.var.nchan_channel_id or 'empty'
			local http = require "resty.http"
			local httpc = http.new()
			httpc:set_timeout(500)
			httpc:connect("127.0.0.1", 8080)
			local res, err = httpc:request({
				path = "/pubsub?pub=sub,all," .. id,
				headers = {
					["Host"] = "[hidden]",
				},
				method = "POST",
				body = id .. ':subscribed'
			})
		}
	}

nginx version:

# nginx -V
nginx version: nginx/1.13.12
built with OpenSSL 1.1.0h  27 Mar 2018
TLS SNI support enabled
configure arguments: --with-cc-opt='-g -O2 -fdebug-prefix-map=/nginx-1.13.12=. -fstack-protector-strong -Wformat -Werror=format-security -fPIC -Wdate-time -D_FORTIFY_SOURCE=2' --with-ld-opt='-Wl,-z,relro -Wl,-z,now -fPIC' --prefix=/usr/share/nginx --conf-path=/etc/nginx/nginx.conf --http-log-path=/var/log/nginx/access.log --error-log-path=/var/log/nginx/error.log --lock-path=/var/lock/nginx.lock --pid-path=/run/nginx.pid --modules-path=/usr/lib/nginx/modules --http-client-body-temp-path=/var/lib/nginx/body --http-fastcgi-temp-path=/var/lib/nginx/fastcgi --http-proxy-temp-path=/var/lib/nginx/proxy --http-scgi-temp-path=/var/lib/nginx/scgi --http-uwsgi-temp-path=/var/lib/nginx/uwsgi --with-debug --with-pcre-jit --with-http_ssl_module --with-http_stub_status_module --with-http_realip_module --with-http_auth_request_module --with-http_v2_module --with-http_dav_module --with-http_slice_module --with-threads --with-http_gzip_static_module --without-http_browser_module --without-http_geo_module --without-http_limit_req_module --without-http_limit_conn_module --without-http_memcached_module --without-http_referer_module --without-http_split_clients_module --without-http_userid_module --add-dynamic-module=/nginx-1.13.12/debian/modules/http-echo

nchan stats:

total published messages: 1015
stored messages: 43
shared memory used: 40K
shared memory limit: 131072K
channels: 65
subscribers: 12
redis pending commands: 0
redis connected servers: 0
total interprocess alerts received: 298130
interprocess alerts in transit: 0
interprocess queued alerts: 0
total interprocess send delay: 0
total interprocess receive delay: 0
nchan version: 1.1.15