[bug] Issue with UWSC_OP_TEXT scrambling data

Question

[bug] Issue with UWSC_OP_TEXT scrambling data

curz46 opened this issue 5 years ago · 4 comments

Description

When using libuwsc I noticed that the JSON strings I was getting back were often scrambled and this caused the parser to fail. So I wrote a program to reproduce this problem in a way that was clear. The program establishes a connection with the websocket server provided by https://www.websocket.org/echo.html (wss://echo.websocket.org). This server sends a text reply whenever it receives a message containing the text of the message. My program will send a message with a predefined sample text every three seconds. This can be used to test if libuwsc is mutating the data that is being received.

Output of program

Short-mode output

Using the latest upstream (8bad3e1), the output of short mode is like this most of the time:

=====================================================
Sent: "This is a sample string." # This is what is sent to the WS url
OK: content==test: "This is a sample string." # This is what is received in response, it should be the same
=====================================================
Sent: "This is a sample string."
OK: content==test: "This is a sample string."
=====================================================
Sent: "This is a sample string."
OK: content==test: "This is a sample string."
=====================================================
Sent: "This is a sample string."
OK: content==test: "This is a sample string."
=====================================================

This indicates that libuwsc is doing its job. However, sometimes this will happen:

Sent: "This is a sample string."
ERR: content!=test: "This is a sample string.□libuwsc"
=====================================================

The string "libuwsc" is appended to the returned result. This is the most common error. If left running for long enough, this can occur:

Sent: "This is a sample string."
ERR: content!=test: "This is a sample string.otocol Handshake"
=====================================================
Sent: "This is a sample string."
ERR: content!=test: "This is a sample string.ndshake"
=====================================================
Sent: "This is a sample string."
ERR: content!=test: "This is a sample string.de"
=====================================================
Sent: "This is a sample string."
ERR: content!=test: "This is a sample string. 00:26:47 GMT"
=====================================================
Sent: "This is a sample string."
ERR: content!=test: "This is a sample string.□libuwsc"
=====================================================
Sent: "This is a sample string."
ERR: content!=test: "This is a sample string.k2c="
=====================================================
Sent: "This is a sample string."
ERR: content!=test: "This is a sample string.way"
=====================================================

I'm not sure where these appended strings are coming from. Maybe additional data in the received payload? Immediately after this:

Sent: "This is a sample string."
ERR: content!=test: "This is a sample string.
□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□libuwsc□↑This is a sample string.□↑This is a sample string.□↑This is a sample string.□↑This i"
=====================================================

Long-mode output

My test has two modes because it is much easier to reproduce with a larger amount of text. Proper functioning looks like:

Sent: "10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100
"
OK: content==test: "10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100
"
=====================================================

In a brief amount of iterations:

Sent: "10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100
"
ERR: content!=test: "10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100
□libuwsc4 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100
□~10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100
□~10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100
□libuwsc□~10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100
□~10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100
□~10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100
□libuwsc□~10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100
□~10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100
□~10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100
□~10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100
□libuwsc□~10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100
□~10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100
□~10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100
□~10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 9"
=====================================================

Given this we can see that for whatever reason the text is being duplicated, often separated with garbage characters and the string "libuwsc". A repetition always starts with the beginning of the string but is sometimes truncated at the end.

To reproduce

Clone curz46/libuwsc-test and follow the instructions in the README.md. Run the program using ./bin/test and select a mode. Leave the program running until error is observed.

Questions

How could this be occurring?
Which parts of the source are related to the receiving and passing of text to onmessage?
Which parts of the source could be responsible?

Thanks, Dylan

Answer 1 · 2019-11-20T01:08:51.000Z

I would assume that "libuwsc" string is coming from here. Is it possible that pings sent and messages received are somehow being merged?

Answer 2 · 2019-11-21T18:43:37.000Z

Following up on the suspicion that ping data is being mixed with the read buffer, I commented out the logic that causes pings.

static inline void uwsc_ping(struct uwsc_client *cl)
{
    //const char *msg = "libuwsc";
    printf("Refused to ping\n");
    //cl->send(cl, msg, strlen(msg), UWSC_OP_PING);
}

Any instances of "libuwsc" were removed from the test program's logs. The problem remains, though, that after a certain number of iterations the sample text becomes duplicated many times with garbage text in between. So it is not solely the ping function (I suspected it was concurrent read/write) responsible for this bug.

edit: Is it possible that this bug occurs because the test program curz46/libuwsc-test and the application I experienced it in initially both spawn threads using pthread? Is the library thread-safe?

Answer 3 · 2019-12-07T20:44:56.000Z

I investigated this further and the problem was much smaller than I previously thought. For whatever reason, a NULL terminator is not included in the data parameter of onmessage when the mode is UWSC_OP_TEXT.

The reason why this wasn't immediately evident is because (I assume) the buffers are initialized to zero. The extra data after length acts as a NULL terminator. I noticed the problem consistently occurs when buffer_check_persistent_size calls buffer_resize (when buffer_length() > persistent) and since the data in the buffer isn't reset (no need to), that accidental NULL terminator is no longer present and the test fails.

I can make the test pass after any number of buffer_resizes if I add...

data[length] = '\0';

...before I handle the data. I doubt the consistency of this solution, though, since if you receive N packets each with payload size 4096 / N (where N divides 4096, the value of persistent size) then data[length] will eventually cause a segmentation fault.

I'm not really sure if it should be the server's responsibility to append a NULL terminator to the resultant string, or libuwsc's responsibility. However, I first experienced this issue when using the Discord API, so the issue is irrelevant to the fact that libuwsc sends the text that is received.

Answer 4 · 2019-12-08T17:24:58.000Z

Possible solution to add some NULL-terminator insurance logic at uwsc.c L153. Right now UWSC_OP_TEXT and UWSC_OP_BINARY are handled the same. Solution e.g.:

// ...
size_t length = buffer_length(rb);
if (length < frame->payloadlen)
    return false;

switch (frame->opcode) {
    case UWSC_OP_TEXT: // add handling code here
        uint8_t *data = payload;
        payload       = malloc(length + 1);
        memcpy(payload, data, length);
        payload[length] = '\0';
    case UWSC_OP_BINARY:
        if (cl->onmessage)
            cl->onmessage(cl, payload, frame->payloadlen, frame->opcode == UWSC_OP_BINARY);
        break;
// ...

You could say this will have performance implications because now memcpy is called on every message, but really the user shouldn't receive raw payload, anyway. If they hold onto this pointer and use it again and again they will eventually find the payload is now garbage, since buffer will reuse the same memory addresses when it cycles back around. With this in mind:

// ...
struct uwsc_Frame *Frame = &cl->frame;
uint8_t *data = buffer_data(rb);

size_t length = buffer_length(rb);
if (length < frame->payloadlen)
    return false;

uint8_t payload = malloc(frame->opcode == UWSC_OP_TEXT ? length + 1 : length);
memcpy(payload, data, length);

switch (frame->opcode) {
    case UWSC_OP_TEXT:
        payload[length] = '\0';
    case UWSC_OP_BINARY:
        if (cl->onmessage)
            cl->onmessage(cl, payload, frame->payloadlen, frame->opcode == UWSC_OP_BINARY);
        break;
// ...

Let me know what you think about this. There is a potential problem, in that if the user for whatever reasons decides not to define cl->onmessage, or they forget to free the data when they're done with it the malloc will cause a memory leak. Therefore if cl->onmessage is not defined, the payload shouldn't be copied and documentation should clearly state the user is responsible for freeing the payload if they define cl->onmessage.