[Libwebsockets] Logging WS HS

Olivier Langlois olivier at olivierlanglois.net
Sun Feb 16 18:01:31 CET 2020


This was my first message to the list. Andy, you did reply to it back
then. I had few things to say about what you said but I had more
important things to do then. Today is the day.

On Sun, 2019-12-01 at 18:11 +0000, Andy Green wrote:
> 
> On 12/1/19 9:50 AM, Olivier Langlois wrote:
> > Guys,
> > 
> > First of all, your lib is great. Upon compiling my first client
> > based
> > from minimal-ws-client-echo, I have been able to make my ws-client
> > work
> > on first try!
> 
> Glad it's useful.
> 
> > As a side goal of using your library, I was looking to get some
> > insight
> > on how the ws protocol works. In that regard, I found the lib
> > opaque.
> 
> It's intended to conceal as much of the workings as consistent with 
> working on lightweight targets.  But of course it's FOSS as you
> found 
> you can just hack whatever you're interested in out of it.
> 
> > Finding the handshake exchange in the log would have helped me a
> > lot.
> > 
> > 1.
> > 
> > It might be feasible to extract the client request and the server
> > reply
> 
> If you want to see what's going on at the wire for educational
> reasons, 
> disable tls and watch it from the side, eg, tcpdump -ilo -s0 -X

Loopback interface is useless when interfacing with 3rd party encrypted
server. I missed the days when you could launch wireshark and learn a
bunch of things from the majority of unencrypted traffic moving around.
Those days are gone...

> 
> Also modern browsers in the "Developer Tools / Network" tab will
> tell 
> you about the headers that went both ways.

I thought that the main appeal of lws was to develop a WS app OUTSIDE a
browser. This kinda beat the initial purpose if it forces you to write
JS WS client on top of the one you develop with lws, no?
> 
> > from the wsi inside the callback when called for the following
> > reasons:
> > 
> > LWS_CALLBACK_CLIENT_APPEND_HANDSHAKE_HEADER
> 
> The reply hasn't been received by this point.
> 
> > LWS_CALLBACK_CLIENT_FILTER_PRE_ESTABLISH
> > 
> > but I couldn't figure out how...
> > 
> > please consider adding something about that in one of the examples.

What I was trying to say here is that those 2 CB points would be the
perfect spots for logging the HS msgs.

LWS_CALLBACK_CLIENT_APPEND_HANDSHAKE_HEADER to log the request
and LWS_CALLBACK_CLIENT_FILTER_PRE_ESTABLISH to log the reply.

I'm fine if lws doesn't want to do it because it stands for the
conceiling design principle but why make it hard to do it for people
interested in those loggings?

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.

LWS_CALLBACK_CLIENT_APPEND_HANDSHAKE_HEADER provides a pointer at the
current reply tail. Why not provide provide a pointer at the start +
current size or provide a mean to easily get that info?

The header API is excellent when you know exactly what you are looking
for in it but there is nothing that would let you easily dump all its
content. It could be used in LWS_CALLBACK_CLIENT_FILTER_PRE_ESTABLISH
for logging purposes.

> 
> The oldstyle test app dumps http headers at LWS_CALLBACK_HTTP, the
> ws 
> equivalent is ESTABLISHED.  On ws, after ESTABLISHED, the http
> headers 
> are destroyed since it's no long http at that point.
> 
> > 2. I did add the following logs to fullfill my curiosity:
> > 
> > diff --git a/lib/roles/http/client/client-http.c
> > b/lib/roles/http/client/client-http.c
> > index 15ea1717..4792a4b5 100644
> > --- a/lib/roles/http/client/client-http.c
> > +++ b/lib/roles/http/client/client-http.c
> > @@ -1281,6 +1281,8 @@ lws_generate_client_handshake(struct lws
> > *wsi,
> > char *pkt)
> >                  lws_client_http_body_pending(wsi, 1);
> >          }
> >   
> > +        lwsl_debug("server request:\n'%s'\n", pkt);
> > +
> >          p += lws_snprintf(p, 4, "\x0d\x0a");
> >   
> >          // puts(pkt);
> > diff --git a/lib/roles/http/parsers.c b/lib/roles/http/parsers.c
> > index 985e7d60..f80c9524 100644
> > --- a/lib/roles/http/parsers.c
> > +++ b/lib/roles/http/parsers.c
> > @@ -946,7 +946,7 @@ lws_parse(struct lws *wsi, unsigned char *buf,
> > int
> > *len)
> >          int r, pos;
> >   
> >          assert(wsi->http.ah);
> > -
> > +        lwsl_debug("Server reply: %.*s\n", *len, buf);
> >          do {
> >                  (*len)--;
> >                  c = *buf++;
> > 
> > I believe that other users could be interested in those traces...
> 
> I think it's good to hack it to find stuff out, but there are
> external 
> ways to get this particular info.

My server reply logging hack stopped working as lws is now parsing it 1
byte at a time. Here is the new one (note that it is for those needing
to log the reply. I'm not offering this code to be included in lws. Nor
do I think it has chance to be accepted anyway...):

diff --git a/lib/roles/http/parsers.c b/lib/roles/http/parsers.c
index 94e8490b..9d8bd41a 100644
--- a/lib/roles/http/parsers.c
+++ b/lib/roles/http/parsers.c
@@ -39,6 +39,9 @@ static const unsigned char lextable[] = {
 
 #endif
 
+#define RAW_INPUT_PTR(ah) (&(ah)->data[(ah)->data_length+4])
+#define RAW_INPUT_LEN(ah) (*(unsigned *)&(ah)->data[(ah)-
>data_length])
+
 static struct allocated_headers *
 _lws_create_ah(struct lws_context_per_thread *pt, ah_data_idx_t
data_size)
 {
@@ -47,7 +50,7 @@ _lws_create_ah(struct lws_context_per_thread *pt,
ah_data_idx_t data_size)
        if (!ah)
                return NULL;
 
-       ah->data = lws_malloc(data_size, "ah data");
+       ah->data = lws_malloc(data_size*2, "ah data");
        if (!ah->data) {
                lws_free(ah);
 
@@ -96,6 +99,8 @@ _lws_header_table_reset(struct allocated_headers *ah)
        ah->http_response = 0;
        ah->parser_state = WSI_TOKEN_NAME_PART;
        ah->lextable_pos = 0;
+       RAW_INPUT_PTR(ah)[0] = '\0';
+       RAW_INPUT_LEN(ah) = 0;
 #if defined(LWS_WITH_CUSTOM_HEADERS)
        ah->unk_pos = 0;
        ah->unk_ll_head = 0;
@@ -961,6 +966,10 @@ lws_parse(struct lws *wsi, unsigned char *buf, int
*len)
                (*len)--;
                c = *buf++;
 
+               if (RAW_INPUT_LEN(ah) < ah->data_length) {
+                       RAW_INPUT_PTR(ah)[RAW_INPUT_LEN(ah)++] = c;
+               }
+
                switch (ah->parser_state) {
 #if defined(LWS_WITH_CUSTOM_HEADERS)
                case WSI_TOKEN_UNKNOWN_VALUE_PART:
@@ -1408,7 +1417,7 @@ set_parsing_complete:
        }
        ah->parser_state = WSI_PARSING_COMPLETE;
        wsi->hdr_parsing_completed = 1;
-
+       lwsl_notice("Server reply:\n%.*s", RAW_INPUT_LEN(ah),
RAW_INPUT_PTR(ah));
        return LPR_OK;
 
 forbid:
> 
> > 3. This made me realized that despite that I kept the permessage-
> > deflate settings from the minimal-ws-client-echo code, it wasn't
> > added
> > in the client request (but the contacted server don't support it
> > anyway! FYI, it is (WebSocket-Server: uWebSockets) from server
> > reply).
> > I found out that it was because the arch-linux build wasn't
> > building
> > the lib with -DLWS_WITHOUT_EXTENSIONS=OFF
> > 
> > So, maybe this would help:
> > 
> > diff --git a/lib/roles/ws/ext/extension.c
> > b/lib/roles/ws/ext/extension.c
> > index 576cb140..3d1f852d 100644
> > --- a/lib/roles/ws/ext/extension.c
> > +++ b/lib/roles/ws/ext/extension.c
> > @@ -31,6 +31,10 @@ lws_context_init_extensions(const struct
> > lws_context_creation_info *info,
> >                              struct lws_context *context)
> >   {
> >          lwsl_info(" LWS_MAX_EXTENSIONS_ACTIVE: %u\n",
> > LWS_MAX_EXTENSIONS_ACTIVE);
> > +#if defined(LWS_WITHOUT_EXTENSIONS)
> > +       if (info->extensions)
> > +               lwsl_warn("Non NULL info extensions pointer with
> > lib
> > built with LWS_WITHOUT_EXTENSIONS\n");
> > +#endif
> >   }
> >   
> >   enum lws_ext_option_parser_states {
> 
> That sounds pretty reasonable... at least on master that won't get 
> called if extensions aren't built though.  I moved it to 
> lib/core/context.c in create_context.
> 
> > 4. When I did tried my new traces, I have found out that the 541
> > bytes
> > long server was truncated by the log function. Therefore, I did
> > this:
> > 
> > diff --git a/lib/core/logs.c b/lib/core/logs.c
> > index 3b41783f..d56bd4d1 100644
> > --- a/lib/core/logs.c
> > +++ b/lib/core/logs.c
> > @@ -179,7 +179,7 @@ lwsl_emit_stderr_notimestamp(int level, const
> > char
> > *line)
> >   #if !(defined(LWS_PLAT_OPTEE) && !defined(LWS_WITH_NETWORK))
> >   LWS_VISIBLE void _lws_logv(int filter, const char *format,
> > va_list vl)
> >   {
> > -       static char buf[256];
> > +       static char buf[1024];
> >          int n;
> >   
> >          if (!(log_level & filter))
> > 
> > BTW, I'm still using lws from a single thread and I don't know how
> > well
> > tested lws is with MT scenarios but having a static buf in the log
> > function makes it not thread safe, I believe...
> 
> I guess it's right.  The problem is I don't want to force even small 
> targets to have to make a big stack allocation to print something
> (you 
> may find yourself printing something many function calls down and
> push 
> yourself over the edge) or make a big .data allocation either.
> 
> But, multi threaded service threads are incompatible with trying to
> work 
> on tiny devices.  So I added a patch on master making the choice
> between 
> static or not and a larger buffer or not dependent on LWS_MAX_SMP !=
> 1.
> 
> > I think that by either removing the 'static' attribute to have the
> > buffer on the stack (my favorite option) or using a lock would fix
> > that. but there is probably concerns for embedded platforms that
> > I'm
> > not aware of... therefore, I'll let you do the change if one is
> > needed...
> 
> The worst that can happen is logs from different threads treading on 
> each other.  But the scheme above will fix that.
> 
> I pushed this and the extensions warning one on master.

I haven't seen those last 2 ideas integrated in the master like you
said you did. Do you need me to resubmit those things the way you
suggested they should be packaged to have them integrated?

Greetings,




More information about the Libwebsockets mailing list