spd-day displays invalid language error and segfault

[seb128]

Using Ubuntu Kinetic

ii libspeechd2:amd64 0.11.3-1ubuntu1 amd64 Speech Dispatcher: Shared libraries
ii python3-speechd 0.11.3-1ubuntu1 all Python interface to Speech Dispatcher
ii speech-dispatcher 0.11.3-1ubuntu1 amd64 Common interface to speech synthesizers
ii speech-dispatcher-audio-plugins:amd64 0.11.3-1ubuntu1 amd64 Speech Dispatcher: Audio output plugins
ii speech-dispatcher-espeak-ng 0.11.3-1ubuntu1 amd64 Speech Dispatcher: Espeak-ng output module

That's basically 0.11.3-1 with the socket activation change from !763 cherrypicked
http://launchpadlibrarian.net/626414937/speech-dispatcher_0.11.3-1_0.11.3-1ubuntu1.diff.gz

$ spd-say -L
Invalid language fr-FR!
Erreur de segmentation (core dumped)

#0  __strlen_avx2 () at ../sysdeps/x86_64/multiarch/strlen-avx2.S:76
No locals.
#1  0x00007ffff7f92bda in get_param_str (reply=reply@entry=0x0, num=num@entry=1, err=err@entry=0x7fffffffdb3c)
    at /tmp/build/speech-dispatcher-0.11.3/src/api/c/libspeechd.c:2003
        i = <optimized out>
        tptr = 0x7fffffffdc04 ""
        pos = 0x0
        pos_begin = <optimized out>
        pos_end = <optimized out>
        rep = <optimized out>
        __PRETTY_FUNCTION__ = <optimized out>
#2  0x00007ffff7f939a7 in spd_execute_command_with_list_reply (connection=connection@entry=0x555555567980, command=command@entry=0x7ffff7f970c7 "LIST SYNTHESIS_VOICES")
    at /tmp/build/speech-dispatcher-0.11.3/src/api/c/libspeechd.c:1541
        reply = 0x0
        line = <optimized out>
        err = 21845
        max_items = 50
        result = 0x555555567d20
        i = 0
#3  0x00007ffff7f93a6e in spd_list_synthesis_voices (connection=connection@entry=0x555555567980) at /tmp/build/speech-dispatcher-0.11.3/src/api/c/libspeechd.c:1476
        svoices_str = <optimized out>
        svoices = <optimized out>
        i = <optimized out>
        num_items = <optimized out>
        __PRETTY_FUNCTION__ = "spd_list_synthesis_voices"
#4  0x000055555555718b in main (argc=2, argv=0x7fffffffdd68) at ./src/clients/say/say.c:199
        list = <optimized out>
        i = <optimized out>
        conn = 0x555555567980
        spd_priority = <optimized out>
        err = <optimized out>
        error = 0x7ffff7ca06a2 <__GI___libc_malloc+418> "H\205\300\017\204\211"
        msg_arg_required = <optimized out>
        ret = <optimized out>
        option_ret = <optimized out>
        line = <optimized out>

the issue seems random, sometime it returns an empty list and sometime the expected result. The previous revision without the systemd change doesn't seem to hit the problem so it could be a regression (or an existing issue made more easy to hit for $reasons)

Cc @nteodosio

[seb128]

Valgrind log

Invalid language fr-FR!
==188335== Invalid read of size 1
==188335==    at 0x484AD16: strlen (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==188335==    by 0x487EBD9: get_param_str (libspeechd.c:2003)
==188335==    by 0x487F9A6: spd_execute_command_with_list_reply (libspeechd.c:1541)
==188335==    by 0x487FA6D: spd_list_synthesis_voices (libspeechd.c:1477)
==188335==    by 0x10B18A: main (say.c:199)
==188335==  Address 0x0 is not stack'd, malloc'd or (recently) free'd

[seb128]

Could it be that the old way to spawn the service was blocking the client and ensuring that the service was up at the time of the query but that with the socket activation the service might be up after the request had been issued?

[nteodosio]

Thanks for the report and logs, I think your hypothesis is true, following back from "invalid language %s", it must hit

speechd/src/api/c/libspeechd.c

Lines 1601 to 1604 in d628c0e

	ret = spd_execute_command_with_reply(connection, command, &reply);
	if (ret) {
	SPD_DBG("Can't execute command in spd_execute_command");
	}

which can hardly be for any other reason as far as I can tell.

I'll enable debugging to confirm it and see what I can get out of it.

[nteodosio]

I managed to reproduce the problem with

for i in {1..100}; do echo $i; pkill speech-dispatch; spd-say hi || break; done

>> /tmp/libspeechd.log <<
Debugging started
Initializing threads, condition variables and mutexes...
Executing command wo_mutex
Inside execute_command_with_reply
Inside spd_send_data_wo_mutex
Writing to socket
Getting reply in spd_events_handler
Written to socket
>> : |SET SELF CLIENT_NAME "nteodosio:spd-say:main"
|
Waiting for cond_reply_ready in spd_send_data_wo_mutex
Error: Can't read reply, broken socket in get_reply!
ERROR: BROKEN SOCKET
Connection reply is NULL
Signalling reply ready after communication failure
Condition for cond_reply_ready satisfied
Reading the reply in spd_send_data_wo_mutex threaded mode
Error: Can't read reply, broken socket in spd_send_data.
Can't send data wo mutex in spd_execute_command_with_reply
Can't execute command in spd_execute_command_wo_mutex
Inside execute_command_with_reply
Inside spd_send_data_wo_mutex
Can't send data wo mutex in spd_execute_command_with_reply
Can't execute command in spd_execute_command
Text to say is: hi
Setting priority
Executing command wo_mutex
Inside execute_command_with_reply
Inside spd_send_data_wo_mutex
Can't send data wo mutex in spd_execute_command_with_reply
Can't execute command in spd_execute_command_wo_mutex
Returning from spd_say

[nteodosio]

The previous revision without the systemd change doesn't seem to hit the problem

I can reproduce the error with that loop without the systemd change:

$ apt list --installed
libspeechd2/kinetic,now 0.11.3-1 amd64 [installed,automatic]
python3-speechd/kinetic,kinetic,now 0.11.3-1 all [installed,auto-removable]
speech-dispatcher-audio-plugins/kinetic,now 0.11.3-1 amd64 [installed]
speech-dispatcher-espeak-ng/kinetic,now 0.11.3-1 amd64 [installed,automatic]
speech-dispatcher/kinetic,now 0.11.3-1 amd64 [installed]

$ type -a speech-dispatcher
speech-dispatcher is /usr/bin/speech-dispatcher
speech-dispatcher is /bin/speech-dispatcher

[sthibaul]

@nteodosio can you reproduce it with the change proposed in #778 ?

[sthibaul]

Concerning the pkill-based testcase, it is really not surprising that spd-say gets odd results, since the kill is asynchronous and thus the current speechd could be still terminating when spd-say connects to it, only to get a connection to a dying server.

Concerning the original testcase (systemd-service-based start), does it help to add -t 0 to the ExecStart line of ./speech-dispatcher.service.in ?

[sthibaul]

(the management of the timeout with a glib timer seems quite weak, and doesn't protect against a client connecting just exactly when speechd is quitting)

[sthibaul]

I'm not actually sure how daemons are supposed to auto-quit after timeout in the systemd startup case, and solve the race condition between a client connecting and the daemon quitting.

[nteodosio]

does it help to add -t 0 to the ExecStart line of ./speech-dispatcher.service.in ?

Nope ):

I don't think the failure is always the service shutting down while spd-say makes a request, because with socket activation 141 happens on every first attempt for me (i.e. where the service had not been running yet):

[Mon Oct 10 13:33:20 2022 : 559645] speechd: Speech Dispatcher started and waiting for clients ...
[Mon Oct 10 13:33:20 2022 : 560094] speechd: Terminating...
[Mon Oct 10 13:33:20 2022 : 560102] speechd:  Closing open connections...
[Mon Oct 10 13:33:20 2022 : 560427] speechd:  Closing open output modules...
[Mon Oct 10 13:33:20 2022 : 560435] speechd:   Unloading module name=flite
[Mon Oct 10 13:33:20 2022 : 560441] speechd:   Closing module "flite"...
[Mon Oct 10 13:33:20 2022 : 560466] speechd:  Error: Broken pipe to module.
[Mon Oct 10 13:33:20 2022 : 560477] speechd:  Output module terminated abnormally, probably crashed.
[Mon Oct 10 13:33:20 2022 : 560487] speechd:   Unloading module name=espeak-ng
[Mon Oct 10 13:33:20 2022 : 560493] speechd:   Closing module "espeak-ng"...
[Mon Oct 10 13:33:20 2022 : 560520] speechd:  Error: Broken pipe to module.
[Mon Oct 10 13:33:20 2022 : 560529] speechd:  Output module terminated abnormally, probably crashed.
[Mon Oct 10 13:33:20 2022 : 560554] speechd:   Unloading module name=espeak
[Mon Oct 10 13:33:20 2022 : 560560] speechd:   Closing module "espeak"...
[Mon Oct 10 13:33:20 2022 : 560567] speechd:  Error: Broken pipe to module.
[Mon Oct 10 13:33:20 2022 : 560574] speechd:  Output module terminated abnormally, probably crashed.
[Mon Oct 10 13:33:20 2022 : 560600] speechd:   Unloading module name=dummy
[Mon Oct 10 13:33:20 2022 : 560605] speechd:   Closing module "dummy"...
[Mon Oct 10 13:33:20 2022 : 560611] speechd:  Error: Broken pipe to module.
[Mon Oct 10 13:33:20 2022 : 560619] speechd:  Output module terminated abnormally, probably crashed.
[Mon Oct 10 13:33:20 2022 : 560634] speechd:  Closing server connection...
[Mon Oct 10 13:33:20 2022 : 560644] speechd:  Speech Dispatcher terminated correctly

Without socket activation, I only manage to reproduce the issue reported by seb128 with the pkill loop, which seems to suggest the service was shutting down indeed (I hadn't realized the race condition). Without pkill, i.e. for i in {1..1000}; do echo $i; spd-say "$i" || break; done, runs absolutely fine.

[nteodosio]

With this patch I can determine that client_process_incoming only runs once if the service was activated via Systemd socket:

[Mon Oct 10 15:34:41 2022 : 277420] speechd:  client_process_incoming
[Mon Oct 10 15:34:41 2022 : 277509] speechd:     38:DATA:|SET SELF CLIENT_NAME "nteodosio:spd-say:main"
| (47)
[Mon Oct 10 15:34:41 2022 : 277544] speechd:     Command caught: "set"
[Mon Oct 10 15:34:41 2022 : 277568] speechd:    Updating client specific settings "nteodosio:spd-say:main" against emacs:*
[Mon Oct 10 15:34:41 2022 : 277663] speechd:     38:REPLY:|208 OK CLIENT NAME SET
|
[Mon Oct 10 15:34:41 2022 : 277682] speechd: Terminating...

Whereas without Systemd socket activation (systemctl stop --user speech-dispatcher.socket):

[Mon Oct 10 15:35:32 2022 : 276426] speechd:  client_process_incoming
[Mon Oct 10 15:35:32 2022 : 276491] speechd:     38:DATA:|SET SELF CLIENT_NAME "nteodosio:spd-say:main"
| (47)
[Mon Oct 10 15:35:32 2022 : 276499] speechd:     Command caught: "set"
[Mon Oct 10 15:35:32 2022 : 276508] speechd:    Updating client specific settings "nteodosio:spd-say:main" against emacs:*
[Mon Oct 10 15:35:32 2022 : 276603] speechd:     38:REPLY:|208 OK CLIENT NAME SET
|
[Mon Oct 10 15:35:32 2022 : 276774] speechd:  read 25 from fd 38

[Mon Oct 10 15:35:32 2022 : 276781] speechd:  client_process_incoming
[Mon Oct 10 15:35:32 2022 : 276811] speechd:     38:DATA:|SET SELF LANGUAGE en-US
| (25)
[Mon Oct 10 15:35:32 2022 : 276817] speechd:     Command caught: "set"
[Mon Oct 10 15:35:32 2022 : 276822] speechd:     38:REPLY:|201 OK LANGUAGE SET
|
[Mon Oct 10 15:35:32 2022 : 277007] speechd:  read 24 from fd 38

[Mon Oct 10 15:35:32 2022 : 277014] speechd:  client_process_incoming
[Mon Oct 10 15:35:32 2022 : 277041] speechd:     38:DATA:|SET SELF PRIORITY TEXT
| (24)
[Mon Oct 10 15:35:32 2022 : 277045] speechd:     Command caught: "set"
[Mon Oct 10 15:35:32 2022 : 277069] speechd:     38:REPLY:|202 OK PRIORITY SET
|
[Mon Oct 10 15:35:32 2022 : 277204] speechd:  read 7 from fd 38

[Mon Oct 10 15:35:32 2022 : 277214] speechd:  client_process_incoming
[Mon Oct 10 15:35:32 2022 : 277228] speechd:     38:DATA:|speak
| (7)
[Mon Oct 10 15:35:32 2022 : 277233] speechd:     Command caught: "speak"
[Mon Oct 10 15:35:32 2022 : 277256] speechd:    Switching to data mode...
[Mon Oct 10 15:35:32 2022 : 277260] speechd:     38:REPLY:|230 OK RECEIVING DATA
|
[Mon Oct 10 15:35:32 2022 : 277388] speechd:  read 7 from fd 38

[Mon Oct 10 15:35:32 2022 : 277394] speechd:  client_process_incoming
[Mon Oct 10 15:35:32 2022 : 277405] speechd:     38:DATA:|hi
| (4)
[Mon Oct 10 15:35:32 2022 : 277410] speechd:     Buffer: |hi
| 4 bytes:
[Mon Oct 10 15:35:32 2022 : 277422] speechd:  read 3 from fd 38

[Mon Oct 10 15:35:32 2022 : 277426] speechd:  client_process_incoming
[Mon Oct 10 15:35:32 2022 : 277433] speechd:     38:DATA:|.
| (3)
[Mon Oct 10 15:35:32 2022 : 277436] speechd:     Buffer: |.
| 3 bytes:
[Mon Oct 10 15:35:32 2022 : 277440] speechd:     Finishing data

So I believe we have two independent issues here: One that Seb128 reported, and this one of incomplete data transfer via Systemd socket.

[nteodosio]

I've produced these Libspeechd output too for the different cases.

• Local socket (usual path without Systemd): libspeechd.log.local-socket.txt
• Systemd socket, fails to produce sound and exits with 141: libspeechd.log.systemd.141.txt
• Systemd socket, fails to produce sound and exits with 1 and "invalid language" message on stderr:libspeechd.log.systemd.invalid-language-en-us.txt

What's curious here is that if you compare the first two, you see there are only missing chunks, as in the previous comment.

I still didn't managed to track down the reason for the Systemd socket breaking.