[Libwebsockets] Logging WS HS

Olivier Langlois olivier at olivierlanglois.net
Sat Mar 7 18:01:54 CET 2020


On Sun, 2020-03-01 at 18:27 +0000, Andy Green wrote:
> 
> 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".

You are correct that I should check for other codes as well. It is just
that AFAIK, the only error code that the used service can return is
503. I'm taking a small shortcut just to make a quick proof of concept
prototype.

I guess that if we were to add the new public macro, this is what I
would use in my code.

So today, the used service did enter into a maintenance mode and this
did allowed me to test my proposed patch.

1. It works like a charm! Here is the trace log:

[2020-03-07  11:05:16] INFO WSBASE/callback
LWS_CALLBACK_ESTABLISHED_CLIENT_HTTP: 0
[2020-03-07  11:05:16] INFO WSCONT/log_emit_function 0:
lws_http_client_read: rlen 178

[2020-03-07  11:05:16] INFO WSCONT/log_emit_function 0: chunk 172

[2020-03-07  11:05:16] INFO WSBASE/callback HTTP 503 reply body:
<html>
<head><title>503 Service Temporarily Unavailable</title></head>
<body bgcolor="white">
<center><h1>503 Service Temporarily Unavailable</h1></center>
</body>
</html>

[2020-03-07  11:05:16] WARN WSCONT/log_emit_function 0:
lws_client_handshake: got bad HTTP response '503'

[2020-03-07  11:05:16] EROR WSBASE/connection_error
CLIENT_CONNECTION_ERROR: HS: ws upgrade response not 101
[2020-03-07  11:05:16] INFO WS/getReconnTO Retrying in 256 seconds
[2020-03-07  11:05:16] INFO WSBASE/callback
LWS_CALLBACK_CLOSED_CLIENT_HTTP
[2020-03-07  11:05:16] INFO WSBASE/callback LWS_CALLBACK_WSI_DESTROY

2. Is the only thing missing to integrate the patch is the macro()?

How about:

/**
 * lws_http_client_http_error() - determine if the response code
indicates an error
 *
 * \param code: the response code to test
 *
 * Returns 0 if the code indicates an error or nonzero
 *
 */
#define lws_http_client_http_error(code) (!(code >= 400))

?

Greetings,

> 
> -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
> > 
-------------- next part --------------
A non-text attachment was scrubbed...
Name: 0001-Process-HTTP-headers-related-to-content-length-for-w.patch
Type: text/x-patch
Size: 7231 bytes
Desc: not available
URL: <https://libwebsockets.org/pipermail/libwebsockets/attachments/20200307/8533f95e/attachment.bin>


More information about the Libwebsockets mailing list