[Libwebsockets] Logging WS HS

Andy Green andy at warmcat.com
Sun Feb 16 19:12:45 CET 2020



On February 16, 2020 5:01:31 PM GMT, Olivier Langlois <olivier at olivierlanglois.net> wrote:
>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?

Lws supports both client and server equally for ws.  If you want to learn about ws protocol, as you said here, browser network tabs are nice because they show what was inside the tls tunnel cleanly.

>> > 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?

Providing lws for free isn't 'making it hard for people'.

If you turn up log verbosity to, eg, 1151 you'll see the parsing of incoming http headers.

>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.

>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?

Don't want to expose that... again you are extrapolating from your current usecase and not considering if it's http/2, to encoding of the headers is very different.  The lws header apis conceal it for you.

>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.

You can stick an lws_hexdump_debug() in the related h1 / h2 role code if you care about it...

>> 
>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...):

Yeah why do that... just hexdump the incoming pkt before parse if you want to see it.  But for incoming parse you already get massive detail where you can see everything with -d1151, this is redundant.

>...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?

How hard did you look?  They're there in your name since Dec 1 2019, the day of my email reply.

https://libwebsockets.org/git/libwebsockets/commit/lib?id=de8bb9ade7904469ac0f262f2f3e5c3046f240a2
https://libwebsockets.org/git/libwebsockets/commit/lib?id=6a40a3ba437ceb6ab59c6526ea417c2e4342a285

-Andy



More information about the Libwebsockets mailing list