Linux dev environment: Mycroft won't speak

Hi,

When 18.02 came out, I updated my dev environment (arch linux). That went well. I had to re-register my environment with home.mycroft.ai again, but whatever. It was talking to me, I could load skills, etc. In the last couple weeks I’ve been working on my own skill, and somewhere along there (possibly in the last few days), it stopped speaking or making any noise. I am always in the debug view (start-mycroft.sh debug), so I can see it responding, but I don’t hear anything. I don’t see anything pop up in pavucontrol either (no audio stream), so it’s not getting to my sound card. Given the error messages I see at the beginning, it looks like it can’t find the card:

ALSA lib pcm_dsnoop.c:638:(snd_pcm_dsnoop_open) unable to open slave
ALSA lib pcm_dmix.c:1099:(snd_pcm_dmix_open) unable to open slave  
ALSA lib pcm.c:2501:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.rear
ALSA lib pcm.c:2501:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.center_lfe
ALSA lib pcm.c:2501:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.side
ALSA lib pcm_dmix.c:1099:(snd_pcm_dmix_open) unable to open slave
connect(2) call to /dev/shm/jack-1000/default/jack_0 failed (err=No such file or directory)
attempt to connect to server failed
20:23:12.717 - mycroft.client.speech.listener:create_wake_word_recognizer:239 - INFO - creating wake word engine
20:23:12.718 - mycroft.client.speech.hotword_factory:create_hotword:268 - INFO - creating hey mycroft
20:23:12.753 - mycroft.client.speech.listener:create_wakeup_recognizer:257 - INFO - creating stand up word engine
20:23:12.754 - mycroft.client.speech.hotword_factory:create_hotword:268 - INFO - creating wake up

FWIW, I don’t think the mic is working either, but I don’t care about that right now. I’m just typing commands to it.

What’s weird is that this worked not long ago (last couple weeks). I have updated the system since then (it’s arch), and I always do a git pull before I start working on my skill in the evening, but switching my mycroft-core repo from the dev branch to the master one (which I think is more stable) doesn’t change anything.

When I started debugging it tonight, I went to mycroft-core/mimic and did a ./mimic -t “hello world” and got alsa errors, similar to the above. In particular, this one:

    ALSA lib pcm_dmix.c:1099:(snd_pcm_dmix_open) unable to open slave

I had to install pulseaudio-alsa, and then the mimic command would work. It’s odd that I didn’t need to do this/have this package installed a week ago (or whenever). It’s like mycroft was using pulse properly before, and now is falling back to alsa and failing. I also used dev_setup.sh to recheckout and rebuild mimic. It worked fine after the recompile as well.

start-mycroft.sh audiotest records nothing, but it does successfully play it back. When I put another wave file that is actual sound in the expected file’s location, and I hack up the python file so it doesn’t record over it, it plays the file as expected, no issues

This makes me think mycroft should work fine, but no go.

Other things that use pulse and/or alsa work fine, FWIW. It’s not just my skill that has no sound… it’s any skill or fallback. In fact, I removed my skill completely and it still had issues, so it’s not like my skill is somehow messing up the sound card access.

I haven’t destroyed my dev environment and built it completely new, but I think that may be my next step, unless anyone has any ideas…?

Thanks!

Eric! Hey!

First of all, big thanks for doing such great troubleshooting. Our reference distro is Ubuntu 16.04 LTS, and we’ve had a few people try to install on Arch Linux, but have had issues with resolving deps. alsa and pulseaudio issues are our most frequently reported issues across all distros. Being Arch Linux, we’ll need to dig a bit deeper.

Are you able to post your logs for us to have a closer look?

They’re in /mycroft-core/scripts/logs

I can confirm the outage that we had over the last couple of days affecting STT commands and device pairing is now resolve - happy to post the Incident Report.

Also happy to catch up for lunch and see if I can resolve it face to face.

G-town represent :wink:

Best, Kathy

Hey Kathy!

So I came home and started it up tonight and it started working. AFAIK, I made no real changes between last night and tonight. The laptop was asleep, but I actually full rebooted it last night, so I don’t think I changed anything by putting the laptop to sleep/waking it up.

I have no idea… but it’s good for now. Thanks!

I have no idea why it would start working after a reboot if it didn’t work before. Perhaps there was a process holding alsa or pulseaudio? Sorry I know nothing about Arch I’m afraid.

Offer still stands, very happy to come show off the Mark 1 or a Picroft.

Best, K.

I’ve got a Mark 1! Easier to do dev on my laptop though :wink:

Oddly Mycroft is speaking to me now (using paplay), but when I trigger my AudioService play, it’s deciding to take over my chromecast and play the content (mp3 stream) there. I wonder if last night the AudioService was going with local (as the config specifies it should, in fact, the config doesn’t even list chormecast as a backend), and maybe locking it for normal mycroft voice stuff? I am just guessing, and haven’t dug into this at all yet. Going to do some looking now.

Edit: Looks like it may be because the local backend doesn’t handle MP3 streams so it goes to something non-local that does, and that’s my Chromecast.

1 Like

If you’ve got a Mark 1 and want a giggle, check this out, it was a Sill I built just to learn the Skill structure.

1 Like

Nice :wink:

OK I have hit a stopping point. This seems to set the default backend to mpg123, which can’t handle streams, of course. What’s odd though, is that it doesn’t seem to prefer vlc as something that can handle https streams (I am assuming vlc has reported it can handle https URIs) when I try to play one. It picks one of my chromecasts instead (and which chromecast that gets picked is random).

Finding default of mpg123:

19:33:21.369 - __main__:main:470 - INFO - Staring Audio Services
19:33:21.373 - mycroft.messagebus.client.ws:on_open:58 - INFO - Connected 
19:33:21.374 - __main__:load_services:106 - INFO - Loading services
19:33:21.375 - __main__:get_services:67 - INFO - Loading services from /home/ejstacey/mycroft-core/mycroft/audio/services/
19:33:21.377 - __main__:load_services:112 - INFO - Loading chromecast
19:33:29.982 - requests.packages.urllib3.connectionpool - DEBUG - Starting new HTTP connection (1): 192.168.1.196
19:33:30.087 - requests.packages.urllib3.connectionpool - DEBUG - http://192.168.1.196:8008 "GET /ssdp/device-desc.xml HTTP/1.1" 200 1067
19:33:30.136 - requests.packages.urllib3.connectionpool - DEBUG - Starting new HTTP connection (1): 192.168.1.197
19:33:30.195 - requests.packages.urllib3.connectionpool - DEBUG - http://192.168.1.197:8008 "GET /ssdp/device-desc.xml HTTP/1.1" 200 1062
19:33:30.263 - chromecast__init__:autodetect:150 - INFO - MIBOX3 found.
19:33:30.264 - chromecast__init__:autodetect:150 - INFO - Lounge Room found.
19:33:30.265 - __main__:load_services:112 - INFO - Loading mopidy
19:33:30.268 - __main__:load_services:112 - INFO - Loading mpg123
19:33:30.270 - __main__:load_services:112 - INFO - Loading vlc
19:33:30.411 - __main__:load_services_callback:174 - INFO - [<chromecast__init__.ChromecastService object at 0x7f62f80ec450>, <chromecast__init__.ChromecastService object at 0x7f62f80ec490>, <mpg123__init__.Mpg123Service object at 0x7f62f8092210>, <vlc__init__.VlcService object at 0x7f62f809db90>]
19:33:30.412 - __main__:load_services_callback:181 - INFO - Finding default backend...
19:33:30.413 - __main__:load_services_callback:183 - INFO - checking mibox3
19:33:30.414 - __main__:load_services_callback:183 - INFO - checking lounge room
19:33:30.415 - __main__:load_services_callback:183 - INFO - checking local
19:33:30.416 - __main__:load_services_callback:186 - INFO - Found local
19:33:30.416 - __main__:load_services_callback:191 - INFO - Default:<mpg123__init__.Mpg123Service object at 0x7f62f8092210>

Then here it is selecting chromecast:

19:34:27.184 - mycroft.configuration.config:load_local:128 - DEBUG - Configuration /home/ejstacey/mycroft-core/mycroft/configuration/mycroft.conf loaded
19:34:27.189 - requests.packages.urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): api.mycroft.ai
19:34:28.288 - requests.packages.urllib3.connectionpool - DEBUG - https://api.mycroft.ai:443 "GET /v1/device/X/setting HTTP/1.1" 200 2919
19:34:28.294 - requests.packages.urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): api.mycroft.ai
19:34:29.524 - requests.packages.urllib3.connectionpool - DEBUG - https://api.mycroft.ai:443 "GET /v1/device/X/location HTTP/1.1" 200 900
19:34:29.530 - mycroft.configuration.config:load_local:133 - DEBUG - Configuration '/etc/mycroft/mycroft.conf' not found
19:34:29.531 - mycroft.configuration.config:load_local:133 - DEBUG - Configuration '/home/ejstacey/.mycroft/mycroft.conf' not found
19:34:29.533 - mycroft.configuration.config:load_local:128 - DEBUG - Configuration /home/ejstacey/mycroft-core/mycroft/configuration/mycroft.conf loaded
19:34:29.534 - requests.packages.urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): api.mycroft.ai
19:34:30.739 - requests.packages.urllib3.connectionpool - DEBUG - https://api.mycroft.ai:443 "GET /v1/device/X/setting HTTP/1.1" 200 2919
19:34:30.747 - requests.packages.urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): api.mycroft.ai
19:34:31.939 - requests.packages.urllib3.connectionpool - DEBUG - https://api.mycroft.ai:443 "GET /v1/device/X/location HTTP/1.1" 200 900
19:34:31.945 - mycroft.configuration.config:load_local:133 - DEBUG - Configuration '/etc/mycroft/mycroft.conf' not found
19:34:31.946 - mycroft.configuration.config:load_local:133 - DEBUG - Configuration '/home/ejstacey/.mycroft/mycroft.conf' not found
19:36:11.819 - __main__:echo:468 - DEBUG - {"type": "mycroft.audio.service.play", "data": {"tracks": ["https://afx.joyrex.net:443/subsonic/rest/stream?id=44579&c=mycroft-subsonic&f=mp3&s=X&u=ejstacey&t=X&v=1.16.0"], "utterance": "play something i can never have"}, "context": null}
19:36:11.822 - __main__:_play:404 - INFO - mycroft.audio.service.play
19:36:11.823 - __main__:_play:405 - INFO - [u'https://afx.joyrex.net:443/subsonic/rest/stream?id=44579&c=mycroft-subsonic&f=mp3&s=X&u=ejstacey&t=X&v=1.16.0']
19:36:11.823 - __main__:_play:411 - INFO - mibox3
19:36:11.824 - __main__:_play:411 - INFO - lounge room
19:36:11.825 - __main__:_play:411 - INFO - local
19:36:11.825 - __main__:_play:411 - INFO - vlc
19:36:11.826 - __main__:play:356 - INFO - play
19:36:11.827 - __main__:_stop:265 - INFO - stopping all playing services
19:36:11.828 - __main__:_stop:269 - INFO - Stopped
19:36:11.831 - __main__:play:359 - INFO - uri_type: https
19:36:11.832 - __main__:play:369 - INFO - Searching the services
19:36:11.833 - __main__:play:371 - INFO - <chromecast__init__.ChromecastService object at 0x7f62f80ec450>
19:36:11.833 - chromecast__init__:supported_uris:67 - INFO - Chromecasts found: Chromecast('192.168.1.197', port=8009, device=DeviceStatus(friendly_name=u'MIBOX3', model_name=u'MIBOX3', manufacturer=u'Xiaomi', api_version=(1, 0), uuid=UUID('1944190b-677d-370a-d46e-761fb0262f93'), cast_type='cast'))
19:36:11.834 - __main__:play:373 - INFO - Service <chromecast__init__.ChromecastService object at 0x7f62f80ec450> supports URI https
19:36:11.834 - __main__:play:379 - INFO - Clear list
19:36:11.835 - __main__:play:381 - INFO - Add tracks[u'https://afx.joyrex.net:443/subsonic/rest/stream?id=44579&c=mycroft-subsonic&f=mp3&s=X&u=ejstacey&t=X&v=1.16.0']
19:36:11.836 - __main__:play:383 - INFO - Playing
19:36:11.899 - chromecast__init__:play:95 - DEBUG - track: https://afx.joyrex.net:443/subsonic/rest/stream?id=44579&c=mycroft-subsonic&f=mp3&s=X&u=ejstacey&t=X&v=1.16.0, type: (None, None)

I don’t get it. The config I have is the default:

"Audio": {
    "backends": {
        "local": {
            "type": "mpg123",
            "active": true
        },
        "vlc": {
            "type": "vlc",
            "active": true
        }
    },
    "default-backend": "local"
},

Should I change default-backend to vlc? I thought it’d get picked up before my chromecasts.

Log bundle (I took out API keys/etc) are here: https://afx.joyrex.net/ejstacey-mycroft-logs.tgz

That is me doing ./start-mycroft.sh debug, playing a song (something i can never have), letting it run for a short time, stopping it, closing the debug console, and running ./stop-mycroft.sh

Awesome debugging, thanks.
It’s worth changing the default-backend to vlc just in case to rule it out as a possibility.

I have neither Arch nor a Chromecast here to try and replicate, but let me ask around in Chat (https://chat.mycroft.ai) to see if anyone has seen this before.

I haven’t seen this error, or this combination (arch/chromecast) before so not sure where to start debugging.

Release King @forslund, any suggestions?

(Eric, please meet my colleague Åke, Åke please meet Eric - Eric and I used to work together in Geelong). Eric is a very experienced sysadmin, fluent in multiple distros.

Best, Kathy

Hi Eric, pleased to meet you.

mpg123 can handle streams but not https.

The resolution order of the backends seems to be programmed a bit stupidly (by yours truly), and the order isn’t really stable but will most likely be in alphabetical order.

I have a WIP branch fixing some vlc issues and adding support for pulseaudio ducking. I’ll make sure to add some sort of ordering so local services are tried before remote.

If this is a skill you’re developing yourself you can use the utterance field when calling the audio service to ask it nicely to use vlc for the stream.

        self.audioservice.play(track_list, 'vlc')

Thanks Kathy!

Hi Åke, good to meet you too. Thanks for the help! Using the manual set of ‘vlc’ as the utterance field worked fine. I’ll keep this in place until the local-before-remote stuff pops in, unless someone actually names a chromecast or backend.

1 Like