[Libwebsockets] Logging WS HS

Andy Green andy at warmcat.com
Sun Mar 1 19:27:07 CET 2020



On 3/1/20 5:41 PM, Olivier Langlois wrote:
> On Sun, 2020-02-23 at 17:02 -0500, Olivier Langlois wrote:
>> On Sun, 2020-02-16 at 18:12 +0000, Andy Green wrote:
>>>> You don't need that info when developing a server but when
>>>> developing a
>>>> client to use a service that you don't control, you are
>>>> vulnerable to
>>>> unannounced server changes. One day the HS works. Then it
>>>> doesn't. With
>>>> those logs, a simple glance at the logs would show what has
>>>> changed and
>>>> we aren't talking about multi-MB logs. It is 1-2 hundred extra
>>>> bytes.
>>>> IMHO, this is something that even lightweight systems could
>>>> afford.
>>>>
>>>> Another scenario that would be interesting to have some more help
>>>> from
>>>> lws is when the server returns a HTTP error code during the WS
>>>> HS. ie:
>>>> I get a 503. I suspect that along with it, in the reply body, the
>>>> server provides some useful info such as: 'Service disabled for
>>>> maintenance. Service resuming expected at HH:MM'. Recuperating
>>>> those
>>>> messages is something that I would like lws to help with.
>>>
>>> Feel free to propose a patch, but at that point, it's http body,
>>> unrelated to ws protocol, so this is probably a job about generic
>>> handling of http bodies for 4xx / 5xx... not sure if it already
>>> appears at the cb or the transaction is abandoned.
>>
>> Andy,
>>
>> I think that I have found a way to do it without any modification on
>> the lws side (well almost).
>>
>> I need to test this option to validate that it works but I'm not
>> seeing
>> why it wouldn't. FYI, my server is using chunked encoding.
>>
>> In my callback:
>>
>>       case LWS_CALLBACK_CLIENT_FILTER_PRE_ESTABLISH: {
>>            int code = lws_hdr_http_response(wsi);
>>            if (code == 503) {
>>                char buf[4096];
>>                char *ptr = buf;
>>                int len = sizeof(buf);
>>                lws_http_client_read(wsi, &ptr, &len);
>>            }
>>          }
>>          break;
>>        case LWS_CALLBACK_RECEIVE_CLIENT_HTTP_READ:
>>            INFO2("HTTP 503 reply body:\n%.*s", len, (const char *)in);
>>          break;
>>
> Ok, the service that I am connecting to did enter in maintenance,
> started to send out 503s and this made me realize that my new solution
> didn't work. For ws connections, no callbacks are made. I had to modify
> furhter lws_client_interpret_server_handshake() to achieve what I want.

Right for a happy ws upgrade, there's no http body coming... in fact 
what you receive may be coalesced upgrade headers with the other side's 
first ws frames in one read buffer.

If it's not happy, what you're doing here will be needed to see the body 
of 4xx or 5xx.

> The patch isn't tested when 503s are received but I'm sharing it so
> that you can see what I'm proposing ASAP.
> 
> There is a lot of changed lines but it is not as bad as it seems. In a

That's not necessarily a problem, as you say you're largely moving 
things around.

> nutshell, here are the proposed changes:
> 
> 1. Move down the if (!wsi->do_ws) and change it for a if (wsi->do_ws)
> {} else {} so that content-length related HTTP headers are processed
> for ws connections as well.
> 2. Move down the call to lws_ensure_user_space() in the HTTP only block
> so that it isn't called twice for ws connections.
> 3. The bulk of the other line changes are simply for changing the code
> indentation...

OK.  Wrt to your user code example above, 4xx or 5xx not just 503 should 
get this new treatment, otherwise it looks good AFAICS.  Maybe it can do 
with a new public macro to definitively tell the user code if the status 
is "failed".

-Andy

>  From 29943a0df1a55a02e82adaffb8d36a4d4504e2fe Mon Sep 17 00:00:00 2001
> From: Olivier Langlois <olivier at trillion01.com>
> Date: Sun, 1 Mar 2020 12:24:29 -0500
> Subject: [PATCH] Process HTTP headers related to content length for ws
>   connections
> 
> and make 1 callback before continuing to the ws upgrade code.
> This gives one last opportunity to ws protocols to inspect server reply
> before the ws upgrade code discard it. ie: download reply body in case
> of any other response code than 101.
> ---
>   lib/roles/http/client/client-http.c | 175 +++++++++++++++-------------
>   1 file changed, 94 insertions(+), 81 deletions(-)
> 
> diff --git a/lib/roles/http/client/client-http.c
> b/lib/roles/http/client/client-http.c
> index cba95eee..2462bfc1 100644
> --- a/lib/roles/http/client/client-http.c
> +++ b/lib/roles/http/client/client-http.c
> @@ -735,72 +735,113 @@ lws_client_interpret_server_handshake(struct lws
> *wsi)
>   		return 0;
>   	}
>   
> -	if (!wsi->do_ws) {
> +	/* if h1 KA is allowed, enable the queued pipeline guys */
>   
> -		/* if h1 KA is allowed, enable the queued pipeline guys
> */
> +	if (!wsi->client_h2_alpn && !wsi->client_mux_substream) {
> +		/* ie, coming to this for the first time */
> +		if (wsi->http.conn_type == HTTP_CONNECTION_KEEP_ALIVE)
> +			wsi->keepalive_active = 1;
> +		else {
> +			/*
> +			 * Ugh... now the main http connection has seen
> +			 * both sides, we learn the server doesn't
> +			 * support keepalive.
> +			 *
> +			 * That means any guys queued on us are going
> +			 * to have to be restarted from connect2 with
> +			 * their own connections.
> +			 */
>   
> -		if (!wsi->client_h2_alpn && !wsi->client_mux_substream)
> {
> -			/* ie, coming to this for the first time */
> -			if (wsi->http.conn_type ==
> HTTP_CONNECTION_KEEP_ALIVE)
> -				wsi->keepalive_active = 1;
> -			else {
> -				/*
> -				 * Ugh... now the main http connection
> has seen
> -				 * both sides, we learn the server
> doesn't
> -				 * support keepalive.
> -				 *
> -				 * That means any guys queued on us are
> going
> -				 * to have to be restarted from
> connect2 with
> -				 * their own connections.
> -				 */
> -
> -				/*
> -				 * stick around telling any new guys
> they can't
> -				 * pipeline to this server
> -				 */
> -				wsi->keepalive_rejected = 1;
> -
> -				lws_vhost_lock(wsi->vhost);
> -				lws_start_foreach_dll_safe(struct
> lws_dll2 *,
> -							   d, d1,
> -				  wsi->dll2_cli_txn_queue_owner.head) {
> -					struct lws *ww =
> lws_container_of(d,
> -						struct lws,
> -						dll2_cli_txn_queue);
> -
> -					/* remove him from our queue */
> -					lws_dll2_remove(&ww-
>> dll2_cli_txn_queue);
> -					/* give up on pipelining */
> -					ww->client_pipeline = 0;
> -
> -					/* go back to "trying to
> connect" state */
> -					lws_role_transition(ww,
> LWSIFR_CLIENT,
> -							    LRS_UNCONNE
> CTED,
> +			/*
> +			 * stick around telling any new guys they can't
> +			 * pipeline to this server
> +			 */
> +			wsi->keepalive_rejected = 1;
> +
> +			lws_vhost_lock(wsi->vhost);
> +			lws_start_foreach_dll_safe(struct lws_dll2 *,
> +						   d, d1,
> +			  wsi->dll2_cli_txn_queue_owner.head) {
> +				struct lws *ww = lws_container_of(d,
> +					struct lws,
> +					dll2_cli_txn_queue);
> +
> +				/* remove him from our queue */
> +				lws_dll2_remove(&ww-
>> dll2_cli_txn_queue);
> +				/* give up on pipelining */
> +				ww->client_pipeline = 0;
> +
> +				/* go back to "trying to connect" state
> */
> +				lws_role_transition(ww, LWSIFR_CLIENT,
> +						    LRS_UNCONNECTED,
>   #if defined(LWS_ROLE_H1)
> -							    &role_ops_h
> 1);
> +						    &role_ops_h1);
>   #else
>   #if defined (LWS_ROLE_H2)
> -							    &role_ops_h
> 2);
> +						    &role_ops_h2);
>   #else
> -							    &role_ops_r
> aw);
> +						    &role_ops_raw);
>   #endif
>   #endif
> -					ww->user_space = NULL;
> -				} lws_end_foreach_dll_safe(d, d1);
> -				lws_vhost_unlock(wsi->vhost);
> -			}
> +				ww->user_space = NULL;
> +			} lws_end_foreach_dll_safe(d, d1);
> +			lws_vhost_unlock(wsi->vhost);
>   		}
> +	}
>   
>   #ifdef LWS_WITH_HTTP_PROXY
> -		wsi->http.perform_rewrite = 0;
> -		if (lws_hdr_total_length(wsi,
> WSI_TOKEN_HTTP_CONTENT_TYPE)) {
> -			if (!strncmp(lws_hdr_simple_ptr(wsi,
> -						WSI_TOKEN_HTTP_CONTENT_
> TYPE),
> -						"text/html", 9))
> -				wsi->http.perform_rewrite = 0;
> -		}
> +	wsi->http.perform_rewrite = 0;
> +	if (lws_hdr_total_length(wsi, WSI_TOKEN_HTTP_CONTENT_TYPE)) {
> +		if (!strncmp(lws_hdr_simple_ptr(wsi,
> +					WSI_TOKEN_HTTP_CONTENT_TYPE),
> +					"text/html", 9))
> +			wsi->http.perform_rewrite = 0;
> +	}
>   #endif
>   
> +	/* he may choose to send us stuff in chunked transfer-coding */
> +	wsi->chunked = 0;
> +	wsi->chunk_remaining = 0; /* ie, next thing is chunk size */
> +	if (lws_hdr_total_length(wsi,
> +				WSI_TOKEN_HTTP_TRANSFER_ENCODING)) {
> +		wsi->chunked = !strcmp(lws_hdr_simple_ptr(wsi,
> +				       WSI_TOKEN_HTTP_TRANSFER_ENCODING
> ),
> +					"chunked");
> +		/* first thing is hex, after payload there is crlf */
> +		wsi->chunk_parser = ELCP_HEX;
> +	}
> +
> +	wsi->http.content_length_given = 0;
> +	if (lws_hdr_total_length(wsi, WSI_TOKEN_HTTP_CONTENT_LENGTH)) {
> +		wsi->http.rx_content_length =
> +				atoll(lws_hdr_simple_ptr(wsi,
> +					WSI_TOKEN_HTTP_CONTENT_LENGTH))
> ;
> +		lwsl_info("%s: incoming content length %llu\n",
> +			    __func__, (unsigned long long)
> +				    wsi->http.rx_content_length);
> +		wsi->http.rx_content_remain =
> +				wsi->http.rx_content_length;
> +		wsi->http.content_length_given = 1;
> +	} else { /* can't do 1.1 without a content length or chunked */
> +		if (!wsi->chunked)
> +			wsi->http.conn_type = HTTP_CONNECTION_CLOSE;
> +		lwsl_debug("%s: no content length\n", __func__);
> +	}
> +
> +	if (wsi->do_ws) {
> +		/*
> +		 * Give one last opportunity to ws protocols to inspect
> server reply
> +		 * before the ws upgrade code discard it. ie: download
> reply body in case
> +		 * of any other response code than 101.
> +		 */
> +		if (w->protocol->callback(w,
> +					  LWS_CALLBACK_ESTABLISHED_CLIE
> NT_HTTP,
> +					  w->user_space, NULL, 0)) {
> +
> +			cce = "HS: disallowed by client filter";
> +			goto bail2;
> +		}
> +	} else {
>   		/* allocate the per-connection user memory (if any) */
>   		if (lws_ensure_user_space(wsi)) {
>   			lwsl_err("Problem allocating wsi user mem\n");
> @@ -808,34 +849,6 @@ lws_client_interpret_server_handshake(struct lws
> *wsi)
>   			goto bail2;
>   		}
>   
> -		/* he may choose to send us stuff in chunked transfer-
> coding */
> -		wsi->chunked = 0;
> -		wsi->chunk_remaining = 0; /* ie, next thing is chunk
> size */
> -		if (lws_hdr_total_length(wsi,
> -					WSI_TOKEN_HTTP_TRANSFER_ENCODIN
> G)) {
> -			wsi->chunked = !strcmp(lws_hdr_simple_ptr(wsi,
> -					       WSI_TOKEN_HTTP_TRANSFER_
> ENCODING),
> -						"chunked");
> -			/* first thing is hex, after payload there is
> crlf */
> -			wsi->chunk_parser = ELCP_HEX;
> -		}
> -
> -		wsi->http.content_length_given = 0;
> -		if (lws_hdr_total_length(wsi,
> WSI_TOKEN_HTTP_CONTENT_LENGTH)) {
> -			wsi->http.rx_content_length =
> -					atoll(lws_hdr_simple_ptr(wsi,
> -						WSI_TOKEN_HTTP_CONTENT_
> LENGTH));
> -			lwsl_info("%s: incoming content length %llu\n",
> -				    __func__, (unsigned long long)
> -					    wsi-
>> http.rx_content_length);
> -			wsi->http.rx_content_remain =
> -					wsi->http.rx_content_length;
> -			wsi->http.content_length_given = 1;
> -		} else { /* can't do 1.1 without a content length or
> chunked */
> -			if (!wsi->chunked)
> -				wsi->http.conn_type =
> HTTP_CONNECTION_CLOSE;
> -			lwsl_debug("%s: no content length\n",
> __func__);
> -		}
>   
>   		/*
>   		 * we seem to be good to go, give client last chance to
> check
> 


More information about the Libwebsockets mailing list