[Libwebsockets] output.c: lws_issue_raw handle_truncated_send instead of assert(0)

Derald Woods woods.technical at gmail.com
Tue Apr 14 21:37:46 CEST 2015


On Fri, Apr 10, 2015 at 6:45 PM, Andy Green <andy at warmcat.com> wrote:

>
>
> On 11 April 2015 00:21:34 GMT+08:00, Derald Woods <
> woods.technical at gmail.com> wrote:
> >Hello Andy,
> >
> >The following patch allows code, that I am working with, to survive
> >browser
> >refreshes while streaming larger chunks of data (~500k). SSL is enabled
> >on
> >the connections. I have not observed any side-effects or bad behavior.
> >The
> >'partial send' actually completes. The application is 'best-effort'
> >delivery on the network. I am continuing my verifications, but this
> >appears
> >to do the right thing for my use-case.
> >
> >Your thoughts? Corrections? Warnings?
>
> Something else is wrong if you end up there... basically while you have a
> truncated send pending, there should be no way to send something new.
>
> The code in the service loop enforces that; it won't call back as
> writeable while a truncated send is pending.  And you should only be
> sending something new (ending up at lws_issue_raw) in the writeable
> callback.
>
> You are illegally sending something new outside of the writeable
> callback?  Or the library itself has a problem with its enforcement (I
> would have expected to get more complaints about hitting the assert...)
>
>
Here is the callback snippet:

        case LWS_CALLBACK_SERVER_WRITEABLE:
            pss->total = 0;
            do {
                n = libwebsocket_write(wsi, data, length, LWS_WRITE_BINARY);
                if (n < 0) {
                    return -1;
                }
                pss->total += n;
                if (lws_partial_buffered(wsi) || lws_send_pipe_choked(wsi))
{
                    sprintf(msg, "lws writing (%d)", n);
                    LOG(msg);
                    libwebsocket_callback_on_writable(context, wsi);
                    break;
                }
            } while (pss->total < length);
            break;


I get a consistent stream of data, that appears to run fine until a refresh
and/or move to another page. Here is a shortened log:


[1429033993:2218] INFO: lws_calllback_as_writeable: 0xa9e3a458
(user=0xa9e39128)
[1429033993:2230] INFO: ***** a9e3a458 new partial sent 0 from 460810 total
"2015-04-14 12:53:13","protocol/my","lws writing
(460800)","protocol/my.cpp:my_callback():112"
[1429033993:2634] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033993:3037] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033993:3433] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033993:3434] INFO: lws_calllback_as_writeable: 0xa9e14028
(user=0xa9e39340)
[1429033993:3435] INFO: lws_calllback_as_writeable: 0xa9e1c948
(user=0xa9e27b10)
[1429033993:3833] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033993:4233] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033993:4633] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033993:5032] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033993:5431] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033993:5434] INFO: lws_calllback_as_writeable: 0xa9e14028
(user=0xa9e39340)
[1429033993:5435] INFO: lws_calllback_as_writeable: 0xa9e1c948
(user=0xa9e27b10)
[1429033993:5831] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033993:6231] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033993:6631] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033993:7032] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033993:7432] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033993:7434] INFO: lws_calllback_as_writeable: 0xa9e14028
(user=0xa9e39340)
[1429033993:7435] INFO: lws_calllback_as_writeable: 0xa9e1c948
(user=0xa9e27b10)
[1429033993:7832] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033993:8231] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033993:8632] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033993:9032] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033993:9432] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033993:9434] INFO: lws_calllback_as_writeable: 0xa9e14028
(user=0xa9e39340)
[1429033993:9436] INFO: lws_calllback_as_writeable: 0xa9e1c948
(user=0xa9e27b10)
[1429033993:9832] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:0231] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:0631] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:1032] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:1432] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:1434] INFO: lws_calllback_as_writeable: 0xa9e14028
(user=0xa9e39340)
[1429033994:1435] INFO: lws_calllback_as_writeable: 0xa9e1c948
(user=0xa9e27b10)
[1429033994:1832] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:2230] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:2632] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:3028] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:3426] INFO: ***** a9e3a458 partial send moved on by 460810 (vs
460810)
[1429033994:3428] INFO: ***** a9e3a458 partial send completed
[1429033994:3429] INFO: lws_calllback_as_writeable: 0xa9e3a458
(user=0xa9e39128)
[1429033994:3440] INFO: ***** a9e3a458 new partial sent 0 from 460810 total
"2015-04-14 12:53:14","protocol/my","lws writing
(460800)","protocol/my.cpp:my_callback():112"
[1429033994:3453] INFO: lws_calllback_as_writeable: 0xa9e14028
(user=0xa9e39340)
[1429033994:3456] INFO: lws_calllback_as_writeable: 0xa9e1c948
(user=0xa9e27b10)
[1429033994:3842] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:4246] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:4644] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:5043] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:5442] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:5453] INFO: lws_calllback_as_writeable: 0xa9e14028
(user=0xa9e39340)
[1429033994:5455] INFO: lws_calllback_as_writeable: 0xa9e1c948
(user=0xa9e27b10)
[1429033994:5842] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:6241] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:6642] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:7042] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:7442] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:7453] INFO: lws_calllback_as_writeable: 0xa9e14028
(user=0xa9e39340)
[1429033994:7455] INFO: lws_calllback_as_writeable: 0xa9e1c948
(user=0xa9e27b10)
[1429033994:7841] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:8241] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:8642] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:9042] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:9442] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033994:9453] INFO: lws_calllback_as_writeable: 0xa9e14028
(user=0xa9e39340)
[1429033994:9456] INFO: lws_calllback_as_writeable: 0xa9e1c948
(user=0xa9e27b10)
[1429033994:9841] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033995:0241] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033995:0642] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033995:1042] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033995:1441] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033995:1453] INFO: lws_calllback_as_writeable: 0xa9e14028
(user=0xa9e39340)
[1429033995:1455] INFO: lws_calllback_as_writeable: 0xa9e1c948
(user=0xa9e27b10)
[1429033995:1841] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033995:2241] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033995:2641] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033995:3042] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033995:3441] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033995:3454] INFO: lws_calllback_as_writeable: 0xa9e14028
(user=0xa9e39340)
[1429033995:3456] INFO: lws_calllback_as_writeable: 0xa9e1c948
(user=0xa9e27b10)
[1429033995:3841] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033995:4237] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033995:4636] INFO: ***** a9e3a458 partial send moved on by 460810 (vs
460810)
[1429033995:4637] INFO: ***** a9e3a458 partial send completed
[1429033995:4637] INFO: lws_calllback_as_writeable: 0xa9e3a458
(user=0xa9e39128)
[1429033995:4650] INFO: ***** a9e3a458 new partial sent 0 from 460810 total
"2015-04-14 12:53:15","protocol/my","lws writing
(460800)","protocol/my.cpp:my_callback():112"
[1429033995:5046] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033995:5154] DEBUG: libwebsocket_read: read_ok
[1429033995:5163] INFO: ***** a9e3a458 partial send moved on by 0 (vs
460810)
[1429033995:5165] ERR: ****** a9e3a458 Sending new, pending truncated ...
my_app: /src/libwebsockets/lib/output.c:112: lws_issue_raw: Assertion `0'
failed.

Any additional thoughts? Maybe a different approach?

I just need to send a fixed size block of data. My patch simply allowed the
app to survive. I have not observed any leaks or cpu spikes with the small
patch.



> -Andy
>
>
> >---8<-----------------------------------------------------------------------
> >diff --git a/lib/output.c b/lib/output.c
> >index b914f28..9e07ae5 100644
> >--- a/lib/output.c
> >+++ b/lib/output.c
> >@@ -109,7 +109,8 @@ int lws_issue_raw(struct libwebsocket *wsi,
> >unsigned
> >char *buf, size_t len)
> >                 wsi->truncated_send_len +
> >                 wsi->truncated_send_offset))) {
> >       lwsl_err("****** %x Sending new, pending truncated ...\n", wsi);
> >-        assert(0);
> >+        n = 0;
> >+        goto handle_truncated_send;
> >     }
> >
> >     m = lws_ext_callback_for_each_active(wsi,
>
> >---8<-----------------------------------------------------------------------
>
>


-- 
Derald D. Woods
[Ecclesiastes 12:13] "...: Fear God, and keep his commandments: for this is
the whole duty of man."
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://libwebsockets.org/pipermail/libwebsockets/attachments/20150414/6d66b4e8/attachment-0001.html>


More information about the Libwebsockets mailing list