search

alexa-pi / AlexaPi

Alexa client for all your devices! # No active development. PRs welcome # consider https://github.com/respeaker/avs instead
MIT License
1.33k stars 396 forks source link

No music playback with sox handler (with approved music support) #264

Open maso27 opened 7 years ago

maso27 commented 7 years ago

I don't think many people have seen this, since I'm kinda "grandfathered" in to music support.

Your OS (including version) where you are running AlexaPi:

Raspbian Jessie Lite 8

Your hardware platform and model you are running on:

Raspberry Pi 3

Python release (python2 --version):

2.7.9

Description of problem:

Using dev branch
When I change handlers from "vlc" to "sox" in config.yaml, everything works fine until I ask Alexa to play any music.
(I was approved for music support before they stopped doing it).

ME: "Play music by Tom Waits"
ALEXA: "Shuffling music by Tom Waits"
--silence--

Alexa will respond to future requests, so she doesn't crash, but just can't play the audio files.

Expected:

ME: "Play music by Tom Waits"
ALEXA: "Shuffling music by Tom Waits"
--music starts playing--

Problem-relevant config.yaml entries:

playback_handler: "sox"

Steps to reproduce:

  1. be approved for music playback support
  2. set playback handler to "sox" instead of "vlc"
  3. ask Alexa to play a song

Traceback (if applicable): This is shown in debug mode, starting with my request to play music

2017-06-17 17:57:57 DEBUG: Setting up recording
2017-06-17 17:57:57 DEBUG: Start recording
2017-06-17 17:57:57 DEBUG: Starting new HTTPS connection (1): access-alexa-na.amazon.com
2017-06-17 17:57:57 DEBUG: Start sending speech to Alexa Voice Service
2017-06-17 17:58:01 DEBUG: End recording
2017-06-17 17:58:01 DEBUG: Finished sending speech to Alexa Voice Service
2017-06-17 17:58:03 DEBUG: Processing Request Response...
2017-06-17 17:58:03 DEBUG: JSON String Returned: {
  "messageBody": {
    "directives": [
      {
        "namespace": "Speaker",
        "name": "SetMute",
        "payload": {
          "mute": false
        }
      },
      {
        "namespace": "SpeechSynthesizer",
        "name": "speak",
        "payload": {
          "contentIdentifier": "amzn1.as-ct.v1.Domain:Application:Music#ACRI#DeviceTTSRendererV4_1f018ae9-2fac-4c22-8e4b-0efd599df104",
          "audioContent": "cid:DeviceTTSRendererV4_1f018ae9-2fac-4c22-8e4b-0efd599df104_174777882"
        }
      },
      {
        "namespace": "Speaker",
        "name": "SetMute",
        "payload": {
          "mute": false
        }
      },
      {
        "namespace": "AudioPlayer",
        "name": "play",
        "payload": {
          "playBehavior": "REPLACE_PREVIOUS",
          "audioItem": {
            "streams": [
              {
                "progressReport": {
                  "progressReportDelayInMilliseconds": 1000,
                  "progressReportIntervalInMilliseconds": 0
                },
                "streamUrl": "https://d29r7idq0wxsiz.cloudfront.net/DigitalMusicDeliveryService/HPS.m3u8?m=m&dmid=283067961&c=cf&f=ts&t=10&bl=256k&s=true&e1=1497725100000&e2=1497726000000&v=V2&h=61ca1d145c6ac3ed0f5e1033b7632693fcfe6d45ca8f59e65c0e35d4a9cf3592",
                "offsetInMilliseconds": 0,
                "expiryTime": "2017-06-17T17:59:02+0000",
                "streamId": "amzn1.as-ct.v1.Dee-Domain-Music#ACRI#url#ACRI#35a05996-6dd5-4d3f-a60e-d976fef8a78b:1",
                "progressReportRequired": true
              }
            ],
            "audioItemId": "amzn1.as-ct.v1.Dee-Domain-Music#ACRI#url#ACRI#35a05996-6dd5-4d3f-a60e-d976fef8a78b:1"
          },
          "navigationToken": "amzn1.as-ct.v1.Dee-Domain-Music#ACRI#url#ACRI#35a05996-6dd5-4d3f-a60e-d976fef8a78b:1"
        }
      }
    ]
  },
  "messageHeader": {}
}
2017-06-17 17:58:03 DEBUG: Stopping audio play
2017-06-17 17:58:03 DEBUG: Stopped play. [Errno 3] No such process
2017-06-17 17:58:03 DEBUG: Playing audio: file:///tmp/AlexaPi-runtime-wBidqC/DeviceTTSRendererV4_1f018ae9-2fac-4c22-8e4b-0efd599df104_174777882.mp3
2017-06-17 17:58:03 DEBUG: Started play. sox -q /tmp/AlexaPi-runtime-wBidqC/DeviceTTSRendererV4_1f018ae9-2fac-4c22-8e4b-0efd599df104_174777882.mp3 -t alsa plughw:CARD=ALSA,DEV=0 vol -3 dB pad 0 0
2017-06-17 17:58:05 DEBUG: Finished play.
2017-06-17 17:58:05 DEBUG: Playing audio: https://d29r7idq0wxsiz.cloudfront.net/DigitalMusicDeliveryService/HPS.m3u8?m=m&dmid=283067961&c=cf&f=ts&t=10&bl=256k&s=true&e1=1497725100000&e2=1497726000000&v=V2&h=61ca1d145c6ac3ed0f5e1033b7632693fcfe6d45ca8f59e65c0e35d4a9cf3592
2017-06-17 17:58:05 DEBUG: Started play. sox -q https://d29r7idq0wxsiz.cloudfront.net/DigitalMusicDeliveryService/HPS.m3u8?m=m&dmid=283067961&c=cf&f=ts&t=10&bl=256k&s=true&e1=1497725100000&e2=1497726000000&v=V2&h=61ca1d145c6ac3ed0f5e1033b7632693fcfe6d45ca8f59e65c0e35d4a9cf3592 -t alsa plughw:CARD=ALSA,DEV=0 vol 0 dB pad 0 0
2017-06-17 17:58:05 DEBUG: Sending Playback Progress Report Request...
2017-06-17 17:58:05 DEBUG: Starting new HTTPS connection (1): access-alexa-na.amazon.com
2017-06-17 17:58:05 DEBUG: Error attempting play. sox FAIL formats: no handler for file extension `m3u8?m=m&dmid=283067961&c=cf&f=ts&t=10&bl=256k&s=true&e1=1497725100000&e2=1497726000000&v=V2&h=61ca1d145c6ac3ed0f5e1033b7632693fcfe6d45ca8f59e65c0e35d4a9cf3592'

2017-06-17 17:58:06 DEBUG: https://access-alexa-na.amazon.com:443 "POST /v1/avs/audioplayer/playbackStarted HTTP/1.1" 204 0
2017-06-17 17:58:06 DEBUG: Playback Progress Report was Successful

Additional info:

Everything has been working well with the vlc handler.
I just tried the sox handler out and ran into this.
maso27 commented 7 years ago

Same command with vlc enabled: OUTPUT WHEN NOT BROKEN

2017-06-17 18:18:28 DEBUG: Setting up recording
2017-06-17 18:18:28 DEBUG: Start recording
2017-06-17 18:18:28 DEBUG: Starting new HTTPS connection (1): access-alexa-na.amazon.com
2017-06-17 18:18:28 DEBUG: Start sending speech to Alexa Voice Service
2017-06-17 18:18:31 DEBUG: End recording
2017-06-17 18:18:31 DEBUG: Finished sending speech to Alexa Voice Service
2017-06-17 18:18:33 DEBUG: Processing Request Response...
2017-06-17 18:18:33 DEBUG: JSON String Returned: {
  "messageBody": {
    "directives": [
      {
        "namespace": "Speaker",
        "name": "SetMute",
        "payload": {
          "mute": false
        }
      },
      {
        "namespace": "SpeechSynthesizer",
        "name": "speak",
        "payload": {
          "contentIdentifier": "amzn1.as-ct.v1.Domain:Application:Music#ACRI#DeviceTTSRendererV4_1eeccbd8-5b06-49bc-9b57-c4e5513b0f77",
          "audioContent": "cid:DeviceTTSRendererV4_1eeccbd8-5b06-49bc-9b57-c4e5513b0f77_1056585638"
        }
      },
      {
        "namespace": "Speaker",
        "name": "SetMute",
        "payload": {
          "mute": false
        }
      },
      {
        "namespace": "AudioPlayer",
        "name": "play",
        "payload": {
          "playBehavior": "REPLACE_PREVIOUS",
          "audioItem": {
            "streams": [
              {
                "progressReport": {
                  "progressReportDelayInMilliseconds": 1000,
                  "progressReportIntervalInMilliseconds": 0
                },
                "streamUrl": "https://d29r7idq0wxsiz.cloudfront.net/DigitalMusicDeliveryService/HPS.m3u8?m=m&dmid=206829241&c=cf&f=ts&t=10&bl=256k&s=true&e1=1497726900000&e2=1497727800000&v=V2&h=d8bf595743ba779305f1da525dc0145ab9ebc6b02f46891ee7b67e362d0dafb8",
                "offsetInMilliseconds": 0,
                "expiryTime": "2017-06-17T18:19:32+0000",
                "streamId": "amzn1.as-ct.v1.Dee-Domain-Music#ACRI#url#ACRI#f62b2ec0-fec0-40e6-aa3d-98b51a1a1e08:1",
                "progressReportRequired": true
              }
            ],
            "audioItemId": "amzn1.as-ct.v1.Dee-Domain-Music#ACRI#url#ACRI#f62b2ec0-fec0-40e6-aa3d-98b51a1a1e08:1"
          },
          "navigationToken": "amzn1.as-ct.v1.Dee-Domain-Music#ACRI#url#ACRI#f62b2ec0-fec0-40e6-aa3d-98b51a1a1e08:1"
        }
      }
    ]
  },
  "messageHeader": {}
}
2017-06-17 18:18:33 DEBUG: Stopping audio play
2017-06-17 18:18:33 DEBUG: Playing audio: file:///tmp/AlexaPi-runtime-o5fAph/DeviceTTSRendererV4_1eeccbd8-5b06-49bc-9b57-c4e5513b0f77_1056585638.mp3
2017-06-17 18:18:33 DEBUG: Player State: State.Opening
2017-06-17 18:18:33 DEBUG: Player State: State.Playing
2017-06-17 18:18:33 DEBUG: Started play.
2017-06-17 18:18:35 DEBUG: Player State: State.Ended
2017-06-17 18:18:35 DEBUG: Finished play.
2017-06-17 18:18:35 DEBUG: Playing audio: https://d29r7idq0wxsiz.cloudfront.net/DigitalMusicDeliveryService/HPS.m3u8?m=m&dmid=206829241&c=cf&f=ts&t=10&bl=256k&s=true&e1=1497726900000&e2=1497727800000&v=V2&h=d8bf595743ba779305f1da525dc0145ab9ebc6b02f46891ee7b67e362d0dafb8
2017-06-17 18:18:35 DEBUG: Player State: State.Opening
[7371ed90] httplive stream: HTTP Live Streaming (d29r7idq0wxsiz.cloudfront.net/DigitalMusicDeliveryService/HPS.m3u8?m=m&dmid=206829241&c=cf&f=ts&t=10&bl=256k&s=true&e1=1497726900000&e2=1497727800000&v=V2&h=d8bf595743ba779305f1da525dc0145ab9ebc6b02f46891ee7b67e362d0dafb8)
[737210c0] ts demux: MPEG-4 descriptor not found for pid 0x100 type 0xf
2017-06-17 18:18:37 DEBUG: Player State: State.Playing
2017-06-17 18:18:37 DEBUG: Started play.
2017-06-17 18:18:37 DEBUG: Sending Playback Progress Report Request...
[73728720] packetizer_mpeg4audio packetizer: AAC channels: 2 samplerate: 44100
2017-06-17 18:18:37 DEBUG: Starting new HTTPS connection (1): access-alexa-na.amazon.com
INFO: cmn_live.c(88): Update from < 31.25 -0.65 -8.43  1.84  1.72  5.58 -0.67  0.25  4.57  0.19  1.86  1.13 -0.79 >
INFO: cmn_live.c(105): Update to   < 30.26 -1.85 -8.68  1.57  1.45  4.92 -0.68  1.01  4.59  0.53  1.66  1.66 -0.63 >
2017-06-17 18:18:38 DEBUG: https://access-alexa-na.amazon.com:443 "POST /v1/avs/audioplayer/playbackStarted HTTP/1.1" 204 0
2017-06-17 18:18:38 DEBUG: Playback Progress Report was Successful
ViennaMike commented 7 years ago

There's a similar problem with some other requests when using Sox, e.g., "Alexa, tell me a story." The response comes back to an mp3 file WITH and expiration parameter at the end of the URL, e.g.,

2017-09-15 14:00:34 DEBUG: Playing audio: https://dvi8md6049w6b.cloudfront.net/nina_v1_645641cfbc78aa785058__Stories_en_us_nina_new_spring_on_mars_128kb.mp3?Expires=1505527234&Signature=iNaqIPYSNF5D3gnOJcbTs3QW2y8g7DK25e2YhOK9Tv5CgLEIqjyE9x3A9UDC4x7oxypxF6vxXEzuu5d5B07dzVY6C9ZUuga4EjbENpS8EdkCN4baDPnAb8VdULj1pZm-iPM3qBE8GP9cfe5QRpCUkuSlD7Ny05WwEBnn0lYFL0zyeMosWTX3k7TmwgI1NHxo60yRWGouZlqXcWqqqDYjDuLJ15rz-hPJgjYqh4v70judQPxkmQwuQNXyrDKqHENLQ5Qi~1YuHojcSiznyDk~TAlthsqp5z6tX4QieU1pA2jPM-6TUe30dnspwqDTp-hsB2f96yNU~igoPjCV5JCa9w__&Key-Pair-Id=APKAJMAIYIGWWT37OIHA 2017-09-15 14:00:34 DEBUG: Started play. sox -q https://dvi8md6049w6b.cloudfront.net/nina_v1_645641cfbc78aa785058__Stories_en_us_nina_new_spring_on_mars_128kb.mp3?Expires=1505527234&Signature=iNaqIPYSNF5D3gnOJcbTs3QW2y8g7DK25e2YhOK9Tv5CgLEIqjyE9x3A9UDC4x7oxypxF6vxXEzuu5d5B07dzVY6C9ZUuga4EjbENpS8EdkCN4baDPnAb8VdULj1pZm-iPM3qBE8GP9cfe5QRpCUkuSlD7Ny05WwEBnn0lYFL0zyeMosWTX3k7TmwgI1NHxo60yRWGouZlqXcWqqqDYjDuLJ15rz-hPJgjYqh4v70judQPxkmQwuQNXyrDKqHENLQ5Qi~1YuHojcSiznyDk~TAlthsqp5z6tX4QieU1pA2jPM-6TUe30dnspwqDTp-hsB2f96yNU~igoPjCV5JCa9w__&Key-Pair-Id=APKAJMAIYIGWWT37OIHA -t alsa default vol 4 dB pitch -700 reverb 15 bass 15 tempo -s 0.9 pad 0 0 2017-09-15 14:00:34 DEBUG: Error attempting play. sox FAIL formats: no handler for file extensionmp3?Expires=1505527234&Signature=iNaqIPYSNF5D3gnOJcbTs3QW2y8g7DK25e2YhOK9Tv5CgLEIqjyE9x3A9UDC4x7oxypxF6vxXEzuu5d5B07dzVY6C9ZUuga4EjbENpS8EdkCN4baDPnAb8VdULj1pZm-iPM3qBE8GP9cfe5QRpCUkuSlD7Ny05WwEBnn0lYFL0zyeMosWTX3k7TmwgI1NHxo60yRWGouZlqXcWqqqDYjDuLJ15rz-hPJgjYqh4v70judQPxkmQwuQNXyrDKqHENLQ5Qi~1YuHojcSiznyDk~TAlthsqp5z6tX4QieU1pA2jPM-6TUe30dnspwqDTp-hsB2f96yNU~igoPjCV5JCa9w__&Key-Pair-Id=APKAJMAIYIGWWT37OIHA' ` I'm reporting this here, because I think it's the same problem. If I understand what's happening, VLC plays back the stream from Amazon, which works. With Sox, the response stream name is used as a file name, which causes the problem, because the "?" and other data after the file type causes problems.

Credit to dmclane14, who ID'd the mp3 problem on gitter. I had experienced the problem, but not yet run debug mode to identify what was going on.

ak15199 commented 5 years ago

I noticed this today:

Aug 11 20:59:17 raspberrypi python3[2922]: DEBUG: Playing audio: https://play.podtrac.com/npr-500005/edge1.pod.npr.org/anon.npr-mp3/npr/newscasts/2019/08/11/newscast160802.mp3?awCollectionId=500005&awEpisodeId=750309145&aw_0_1st.playerid=alexa&orgId=1&d=300&p=500005&story=750309145&t=podcast&e=750309145&size=4500000&sc=alexa&utm_campaign=nprnewsnow
Aug 11 20:59:17 raspberrypi python3[2922]: DEBUG: Started play. sox -q https://play.podtrac.com/npr-500005/edge1.pod.npr.org/anon.npr-mp3/npr/newscasts/2019/08/11/newscast160802.mp3?awCollectionId=500005&awEpisodeId=750309145&aw_0_1st.playerid=alexa&orgId=1&d=300&p=500005&story=750309145&t=podcast&e=750309145&size=4500000&sc=alexa&utm_campaign=nprnewsnow -t alsa default vol 0 dB pad 0 0
Aug 11 20:59:17 raspberrypi python3[2922]: DEBUG: indicate_playback True
Aug 11 20:59:18 raspberrypi python3[2922]: DEBUG: Error attempting play. sox FAIL formats: no handler for file extension `playerid=alexa&orgId=1&d=300&p=500005&story=750309145&t=podcast&e=750309145&size=4500000&sc=alexa&utm_campaign=nprnewsnow'

The implication is that sox is parsing the filename (actually a stream beginning https://...) and splitting on the '.' such that anything after the dot is considered too be file extension.

I thought that sox is probably smarter than that, so I modified .../AlexaPi/src/alexapi/playback_handlers/soxhandler.py to set the file type before the filename is processed: sox_cmd = ['sox', '-t', 'mp3', '-q', audio_file]

Turns out this works. But it's not a good enough fix, because not all files are mp3 :( 

Aug 11 21:26:22 raspberrypi python3[3011]: DEBUG: Playing audio: http://custom-hls.iheart.com/WMG4/Thumb_Content/Full_AAC/WMG/Sep14/091614/603497987214/resources/603497896059_00021_256.m4a?nga=20190811212718&track=1121980&player=QTFNakk1SnlrcEsvRVNJMy9rTnc1dz09&env=live&sig=KA27AeGVJtWs_gCsEBMezYM9Othp8O1GdwGOHRXce6s&as=SIMPLE&rnga=20190811212718&host=amazon.appliance.us

So then. How about modifying on_play() to parse out the file extension for media? It's not actually that hard:

             self.playback_padding = str(self.__config['sound']['playback_padding'])

        def _filetype(self, url):
            before = url.split('?', 1)[0]  # Everything before a '?'
            return before.split('.')[-1]   # After the final '.' part

        def on_play(self, item):
                # SoX can't play file URLs
                audio_file = item.url.replace('file://', '')

                sox_cmd = ['sox']

                if item.audio_type == PlaybackAudioType.MEDIA:
                    sox_cmd.extend(['-t', self._filetype(audio_file)])

                sox_cmd.extend(['-q', audio_file])

                if item.audio_type == PlaybackAudioType.SPEECH:
                        sox_cmd.extend(self.parameters_speech)
                        sox_cmd.extend(['vol', str(self.volume_gain), 'dB'])
                else:

The problem with this approach? Not all file formats that services might throw at you are supported by sox, for example the above file wanted to stream `m4a'.

At this point, I moved back to VLC. 🤦‍♂