lib/utils.c:192: utils_data_to_string: Assertion `str' failed.

[rogerbinns]

I get this every few days, but don't have a reliable way to reproduce:

UxPlay-1.63.2/lib/utils.c:192: utils_data_to_string: Assertion `str' failed.

[fduncanh]

Will look into this.

Does it happen without using -d (debug) mode?

Does it happen just when connecting to a client, or on the middle of streaming?

Thanks for any more description you can give.

I suppose it crashes UxPlay?

Coincidently (?) This function utils_data_to_string just had a little work done to it a day or two ago (to replace sprintf by the safer snprintf because of a compiler warning that sprintf was declared obsolete)

[rogerbinns]

Running with no command line flags. I am playing Apple Music from an iPad. I don't know precisely when the assertion fails but it isn't at connecting a client time. Connection time is usually when I spot the problem because uxplay is not running. I do suspend/resume the system several times a day which may be an influence.

uxplay is compiled myself, running on Ubuntu 22.10. Example output

$ ~/uxplay                                                                                                                                                                                                                                                                                   
UxPlay 1.63: An Open-Source AirPlay mirroring and audio-streaming server.                                                                                                                                                                                                                                                      
using system MAC address a8:5e:45:e2:e9:3c                                                                                                                                                                                                                                                                                     
Initialized server socket(s)                                                                                                                                                                                                                                                                                                   
Accepted IPv4 client on socket 32                                                                                                                                                                                                                                                                                              
Local: 192.168.1.5                                                                                                                                                                                                                                                                                                             
Remote: 192.168.1.136                                                                                                                                                                                                                                                                                                          
Client identified as User-Agent: AirPlay/690.4.1                                                                                                                                                                                                                                                                               
Accepted IPv4 client on socket 36                                                                                                                                                                                                                                                                                              
Local: 192.168.1.5                                                                                                                                                                                                                                                                                                             
Remote: 192.168.1.136                                                                                                                                                                                                                                                                                                          
ct=2 spf=352 usingScreen=0 isMedia=1  audioFormat=0x40000                                                                                                                                                                                                                                                                      
start audio connection, format ALAC 44100/16/2                                                                                                                                                                                                                                                                                 
raop_rtp starting audio                                                                                                                                                                                                                                                                                                        
==============Audio Metadata=============                                                                                                                                                                                                                                                                                      
                                                                                                                                                                                                                                                                                                                               
Album: Empire (Bonus Track Version)                                                                                                                                                                                                                                                                                            
Artist: Super8 & Tab                                                                                                                                                                                                                                                                                                           
Genre: Dance                                                                                                                                                                                                                                                                                                                   
Title: Black Is the New Yellow (feat. Anton Sonin) 

<<<< Many many many audio metadata elided, with the same one output many times >>>>

==============Audio Metadata=============

Album: Tripomatic Fairytales 2001 (Deluxe Edition)
Artist: Jam & Spoon
Genre: Dance
Title: Stella


uxplay: /tmp/x/UxPlay-1.63.2/lib/utils.c:192: utils_data_to_string: Assertion `str' failed.
Aborted

[fduncanh]

Hmm: chars_per_line is always 12, 16 or 20.

If it is called with datalen = 0 maybe that would cause the assertion to fail. (but then len +1 would be 2, which seems OK)

Maybe it should test test for datalen <= 0, and just return a null pointer immediately in that case.

char *utils_data_to_string(const unsigned char *data, int datalen, int chars_per_line) {
    int len = 3*datalen + ((datalen-1)/chars_per_line ) + 1;
    char *str = (char *) calloc(len + 1, sizeof(char));
    assert(str);
    char *p = str;
    int n = sizeof(str);
    for (int i = 0; i < datalen; i++) {
        if (i > 0 && i % chars_per_line == 0) {
            snprintf(p, n, "\n");
            n--;
            p++;
        }
        snprintf(p, n, "%2.2x ", (unsigned int) data[i]);
        n -= 3;
        p += 3;
    }
    snprintf(p, n, "\n");
    n--;
    p++;
    assert(p == &(str[len]));
    assert(len == strlen(str));
    return str;
}

The previous version (which you are probably using) is

char *utils_data_to_string(const unsigned char *data, int datalen, int chars_per_line) {
    int len = 3*datalen + ((datalen-1)/chars_per_line ) + 1;
    char *str = (char *) calloc(len + 1, sizeof(char));
    assert(str);
    char *p = str;
    for (int i = 0; i < datalen; i++) {
        if (i > 0 && i % chars_per_line == 0) {
            sprintf(p,"\n");
            p++;
        }
        sprintf(p,"%2.2x ", (unsigned int) data[i]);
        p += 3;
    }
    sprintf(p,"\n");
    p++;
    assert(p == &(str[len]));
    assert(len == strlen(str));
    return str;
}

[fduncanh]

I'll think about it. Since the assertion kills uxplay. maybe should
test if the assertion will fail, and add some informational output

If you get this regularly, that should produce some clues.

[fduncanh]

this utils_data_to_string is mainly used in -d (debug) mode. But you are not using the -d option.

• AH! It get called sometime even it its output is not used for -d output. Not calling it unless it's needed should stop the problem.

[chasecee]

I'm getting this on both of the v1.63 installs I've tried on a pi3a and pi3b today. Error starts as soon as I try to share screen from device and crashes UxPlay.

[fduncanh]

@chasecee
sorry about that: that one was due to a recent "cosmetic fix" made 3 days ago which was not properly tested.
(made just to satisfy a new macOS compiler "nag" about sprintf being deprecated)

That is now fixed. (But I dont think it is @rogerbinns issue)

[fduncanh]

@rogerbinns

Unnecessary calls to utils_data_string when the -d (debug) option is not used have now been removed, as well as some other unnecessary things, and I think this improves the code for normal operation. Thanks for bringing up this issue.

• Please test latest github code and see if this fixes your issue.

Since I didn't understand why the assertion was triggered, it might be a symptom of some other issue,
but the assertion str in utils_data_to_string won't be triggered unless the -d option is used.

[rogerbinns]

I ran the existing version under gdb and got a backtrace:

uxplay: /tmp/x/UxPlay-1.63.2/lib/utils.c:192: utils_data_to_string: Assertion `str' failed.

Thread 49 "uxplay" received signal SIGABRT, Aborted.
[Switching to Thread 0x7fff067f46c0 (LWP 144801)]
__pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
Download failed: Invalid argument.  Continuing without source file ./nptl/./nptl/pthread_kill.c.                                                               
44      ./nptl/pthread_kill.c: No such file or directory.
(gdb) bt
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
#1  __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
#2  __GI___pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3  0x00007ffff6e3c406 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4  0x00007ffff6e2287c in __GI_abort () at ./stdlib/abort.c:79
#5  0x00007ffff6e2279b in __assert_fail_base
    (fmt=0x7ffff6fb9f68 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x55555558e369 "str", file=file@entry=0x55555558e3c0 "/tmp/x/UxPlay-1.63.2/lib/utils.c", line=line@entry=192, function=function@entry=0x55555558e450 <__PRETTY_FUNCTION__.3> "utils_data_to_string") at ./assert/assert.c:92
#6  0x00007ffff6e33b86 in __assert_fail
    (assertion=0x55555558e369 "str", file=0x55555558e3c0 "/tmp/x/UxPlay-1.63.2/lib/utils.c", line=192, function=0x55555558e450 <__PRETTY_FUNCTION__.3> "utils_data_to_string") at ./assert/assert.c:101
#7  0x000055555556e0ab in utils_data_to_string ()
#8  0x0000555555568d47 in raop_ntp_thread ()
#9  0x00007ffff6e8f18a in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:444
#10 0x00007ffff6f1dbd0 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

There are no symbols or locals as far as gdb is concerned for frames 7 and 8.

[fduncanh]

Good, I see the problem was in raop_ntp_thread....

As I said, I "fixed" it so utils_data_to_string is never called without the -d option, but I could not see what could cause it to fail to allocate memory for str in the first place, so I have probably just address a symptom not a cause in the latest .
github code.

The code you are running is
(from raop_ntp.c)

int send_len = sendto(raop_ntp->tsock, (char *)request, sizeof(request), 0,
                              (struct sockaddr *) &raop_ntp->remote_saddr, raop_ntp->remote_saddr_len);
  char *str = utils_data_to_string(request, send_len, 16);
...
       response_len = recvfrom(raop_ntp->tsock, (char *)response, sizeof(response), 0,
                                    (struct sockaddr *) &raop_ntp->remote_saddr, &raop_ntp->remote_saddr_len);
            if (response_len < 0) {
...
            } else {
                 char *str = utils_data_to_string(response, response_len, 16);       

where request and response are 16 bytes of timing data sent to and received from the client.
utils_data_to_string puts them into a printable form for debug purposes in -d mode.

HMMM `` datalen'' could be a negative return value from sendto( ), it it failed .. this is probably the issue.

char *utils_data_to_string(const unsigned char *data, int datalen, int chars_per_line) {
    int len = 3*datalen + ((datalen-1)/chars_per_line ) + 1;
    char *str = (char *) calloc(len + 1, sizeof(char));
    assert(str);

[fduncanh]

OK its easy to see now: just move the call to utils_to_string to AFTER the testto see if sendlen is < 0

  int send_len = sendto(raop_ntp->tsock, (char *)request, sizeof(request), 0,
                              (struct sockaddr *) &raop_ntp->remote_saddr, raop_ntp->remote_saddr_len);
        char *str = utils_data_to_string(request, send_len, 16);
        logger_log(raop_ntp->logger, LOGGER_DEBUG, "\nraop_ntp send time type_t=%d send_len = %d, now = %8.6f\n%s",
                   request[1] &~0x80, send_len, (double) send_time / SECOND_IN_NSECS, str);
        free(str);
        if (send_len < 0) {
            logger_log(raop_ntp->logger, LOGGER_ERR, "raop_ntp error sending request");
        } else {
            // Read response
            response_len = recvfrom(raop_ntp->tsock, (char *)response, sizeof(response), 0,
                                    (struct sockaddr

[rogerbinns]

I've not had any problems since doing a build earlier as requested. The assertion failure has in the past been correlated with clients coming and going, and with the system being suspended and resumed. I've done light amounts of those and the assertion failure has not repeated.

Note that with suspend resume it is quite possible to have timeouts and similar in those routines reading and writing the network, and hours could pass in what is normally instant.

[fduncanh]

Thanks
that improved code made the error only possible in -d mode.

• with your debug trace, that actual code error (in my additions to the code) is now fixed!
• (the code should have been robust to suspend/resume, and is now)