Skip to content
This repository has been archived by the owner on Jun 28, 2024. It is now read-only.

ffmpeg on openbsd #116

Closed
azlux opened this issue Mar 29, 2020 · 44 comments
Closed

ffmpeg on openbsd #116

azlux opened this issue Mar 29, 2020 · 44 comments
Labels

Comments

@azlux
Copy link
Owner

azlux commented Mar 29, 2020

No sound on openbsd with the bot. Look like an issue related to the ffmpeg command.

Summary:

First test : ffmpeg -y -v warning -nostdin -i http://jazz-wr04.ice.infomaniak.ch/jazz-wr04-128.mp3 -ac 1 -f s16le -ar 48000 -

  • openbsd v4.2.2 debug file:
    • no sound.
    • If we replace the final '-' by 'output.mp3' , we observe the file don't have sound
  • Debian v4.1.4 debug file:
    • good

Second test : ffmpeg -y -v warning -nostdin -i http://jazz-wr04.ice.infomaniak.ch/jazz-wr04-128.mp3 -ac 1 -ar 48000 -

  • openbsd v4.2.2 debug file:
    • good
  • Debian v4.1.4 debug file :
    • Error : Unable to find a suitable output format for 'pipe:'
@azlux azlux added the bug label Mar 29, 2020
@azlux
Copy link
Owner Author

azlux commented Mar 29, 2020

Can you try placing the -f at different places ? :
ffmpeg -y -v warning -nostdin -i http://jazz-wr04.ice.infomaniak.ch/jazz-wr04-128.mp3 -f s16le -ac 1 -ar 48000 -
or
ffmpeg -y -v warning -nostdin -i http://jazz-wr04.ice.infomaniak.ch/jazz-wr04-128.mp3 -ac 1 -ar 48000 -f s16le -

@comete-geek
Copy link

Sorry, this doesn't change anything. Same result.

@comete-geek
Copy link

I have sound when I redirect the pipe to the audio device like this:
ffmpeg -y -v warning -nostdin -i http://jazz-wr04.ice.infomaniak.ch/jazz-wr04-128.mp3 -ac 1 -f s16le -ar 48000 - | aucat -i -

@azlux
Copy link
Owner Author

azlux commented Mar 29, 2020

Wait that the exact same command the bot use :
ffmpeg -v warning -nostdin -i <uri> -ac 1 -f s16le -ar 48000 -

command = ("ffmpeg", '-v', ffmpeg_debug, '-nostdin', '-i',

@comete-geek
Copy link

Yes it's strange. I hear sound but it's really too speedy, not the normal speed and only aucat can read something.
vlc - tells me "Header missing", ffplay - tells "pipe:: Invalid data found when processing input"

@comete-geek
Copy link

I can get a good sound at normal speed with this :
ffmpeg -y -v warning -nostdin -i http://jazz-wr04.ice.infomaniak.ch/jazz-wr04-128.mp3 -ac 1 -f s16le -ar 48000 - | play -t s16 -r 48000 -

play command is part of sox audio tool.

@TerryGeng
Copy link
Collaborator

Did you tried different streams or music files? I suppose that maybe this problem only occurs on some files or streams.

@comete-geek
Copy link

Yes I've tried different streams, youtube links, different web radios. Youtube links don't work either, so this may not be a ffmpeg problem.
Another thing I've noticed, is when the bot join the channel and is playing something, I can hear 1 second of music and then nothing else...
Maybe a cache/buffer problem ?

@TerryGeng
Copy link
Collaborator

Sorry but probably no, we use ffmpeg to handle youtube as well. The bot will invoke youtube-dl to download files first and feeds its path into ffempg to play. We constantly fetch bytes from stdout of ffmpeg and send it to your murmur server.

Can you try a local file? Something like xxxxx.mp3.

And, I'm still confused by your description.
Do you mean

  • no music comes out from the bot, or
  • the timing is wrong but something does come out from the bot, or
  • you have music from the bot playing normally but only for ~one second and then the bot stuck, or
  • the bot didn't get stuck, it just moves to the next song after playing normally for ~one second.

Each of these problems points to different parts that may be wrong.

@comete-geek
Copy link

Hello,
no music from the bot at all in any case. A simple mp3 file produce no sound either.
With version 0.6, occasionally when restarting the bot and when it joined the channel, 1 seconds of music was sometimes played and then nothing.
Now with the last release, I've made multiple tests and no sound in any case.

@TerryGeng
Copy link
Collaborator

Thanks for your reply. Just to be sure, did the bot move to the next song? Or it just got stuck at one song without moving on?

@azlux
Copy link
Owner Author

azlux commented Mar 31, 2020

As you can test different ffmpeg command, you can try to modify them here :
https://github.com/azlux/botamusique/blob/master/mumbleBot.py#L371
and
https://github.com/azlux/botamusique/blob/master/mumbleBot.py#L590

Can you try with removing the -f s16le part ?

@comete-geek
Copy link

@TerryGeng it seems to be stuck.
@azlux yes that's what I tried first, no change when removing the option

@TerryGeng
Copy link
Collaborator

Ok. Now I suppose this is the problem of your ffmpeg build. I suggest you try ffmpeg -formats | grep PCM to see whether your ffmpeg build support raw formats, according to https://trac.ffmpeg.org/wiki/audio%20types .

If you can see s16le from the list, you may try ffmpeg -i your_file.mp3 -c:a pcm_s16le output.wav to see if it can correctly convert a mp3 file into pcm format.

If one of the steps above fails, I think you'd better rebuild your ffmpeg with raw format support.

@comete-geek
Copy link

comete-geek commented Mar 31, 2020

ffmpeg version 4.2.1 Copyright (c) 2000-2019 the FFmpeg developers
  built with OpenBSD clang version 8.0.1 (tags/RELEASE_801/final) (based on LLVM 8.0.1)
  configuration: --enable-shared --arch=amd64 --cc=cc --disable-altivec --disable-debug --disable-indev=jack --disable-indev=oss --disable-mipsdsp --disable-mipsdspr2 --disable-mipsfpu --disable-mmi --disable-msa --disable-outdev=oss --disable-outdev=sdl2 --enable-avresample --enable-fontconfig --enable-frei0r --enable-gpl --enable-libaom --enable-libass --enable-libdav1d --enable-libfreetype --enable-libfribidi --enable-libgsm --enable-libmp3lame --enable-libopus --enable-libspeex --enable-libtheora --enable-libv4l2 --enable-libvorbis --enable-libvpx --enable-libx264 --enable-libx265 --enable-libxml2 --enable-libxvid --enable-nonfree --enable-openssl --extra-cflags='-I/usr/local/include -I/usr/X11R6/include' --extra-libs='-L/usr/local/lib -L/usr/X11R6/lib' --extra-ldsoflags= --mandir=/usr/local/man --optflags='-O2 -pipe -Wno-redundant-decls'
  libavutil      56. 31.100 / 56. 31.100
  libavcodec     58. 54.100 / 58. 54.100
  libavformat    58. 29.100 / 58. 29.100
  libavdevice    58.  8.100 / 58.  8.100
  libavfilter     7. 57.100 /  7. 57.100
  libavresample   4.  0.  0 /  4.  0.  0
  libswscale      5.  5.100 /  5.  5.100
  libswresample   3.  5.100 /  3.  5.100
  libpostproc    55.  5.100 / 55.  5.100
 DE alaw            PCM A-law
 DE f32be           PCM 32-bit floating-point big-endian
 DE f32le           PCM 32-bit floating-point little-endian
 DE f64be           PCM 64-bit floating-point big-endian
 DE f64le           PCM 64-bit floating-point little-endian
 DE mulaw           PCM mu-law
 DE s16be           PCM signed 16-bit big-endian
 DE s16le           PCM signed 16-bit little-endian
 DE s24be           PCM signed 24-bit big-endian
 DE s24le           PCM signed 24-bit little-endian
 DE s32be           PCM signed 32-bit big-endian
 DE s32le           PCM signed 32-bit little-endian
 DE s8              PCM signed 8-bit
 DE u16be           PCM unsigned 16-bit big-endian
 DE u16le           PCM unsigned 16-bit little-endian
 DE u24be           PCM unsigned 24-bit big-endian
 DE u24le           PCM unsigned 24-bit little-endian
 DE u32be           PCM unsigned 32-bit big-endian
 DE u32le           PCM unsigned 32-bit little-endian
 DE u8              PCM unsigned 8-bit
 DE vidc            PCM Archimedes VIDC

@comete-geek
Copy link

Yes it is well converted. I can play the output.wav file

@TerryGeng
Copy link
Collaborator

Can you try ffmpeg -nostdin -i your_file.mp3 -ac 1 -ar 48000 -f s16le -?

Can you see things coming out from the console?

@comete-geek
Copy link

Yes it displays a lot of characters as expected.

@TerryGeng
Copy link
Collaborator

Okay.... maybe ffmpeg is running correctly? Have you tried enable

[debug]
ffmpeg = True

in your configuration.ini file? Maybe the debug log of ffmpeg will provide more clues.

@comete-geek
Copy link

comete-geek commented Mar 31, 2020

Ok this is what I get:

[Mar 31 17:59:52 INFO Thread-3] bot: received command url - <a href="https://www.youtube.com/watch?v=DIh8sz9pTkc">https://www.youtube.com/watch?v=DIh8sz9pTkc</a> by Morgan                                         
[Mar 31 17:59:52 DEBUG Thread-3] library: music found in database: [url] Joanne Shaw Taylor - Diamonds In The Dirt (Live At Glasgow Oran-Mor) (https://www.youtube.com/watch?v=DIh8sz9pTkc)                         
[Mar 31 17:59:52 DEBUG Validating] playlist: start validating...                                                                                                                                                    
[Mar 31 17:59:52 INFO Thread-3] cmd: add to playlist: [url] Joanne Shaw Taylor - Diamonds In The Dirt (Live At Glasgow Oran-Mor) (https://www.youtube.com/watch?v=DIh8sz9pTkc)                                      
[Mar 31 17:59:52 DEBUG Validating] playlist: validating [url] Joanne Shaw Taylor - Diamonds In The Dirt (Live At Glasgow Oran-Mor) (https://www.youtube.com/watch?v=DIh8sz9pTkc)                                    
[Mar 31 17:59:52 DEBUG Validating] playlist: validating finished.                                                                                                                                                   
[Mar 31 17:59:52 INFO MainThread] bot: play music [url] Joanne Shaw Taylor - Diamonds In The Dirt (Live At Glasgow Oran-Mor) (https://www.youtube.com/watch?v=DIh8sz9pTkc)                                          
[Mar 31 17:59:52 DEBUG MainThread] bot: execute ffmpeg command: ffmpeg -v debug -nostdin -i /tmp/94123e5b0845fb7f87281f6888f0f674.mp3 -ac 1 -f s16le -ar 48000 -                                                    
[Mar 31 17:59:52 DEBUG MainThread] bot: Async download next asked                                                                                                                                                   
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: ffmpeg version 4.2.1 Copyright (c) 2000-2019 the FFmpeg developers                                                                                                       
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:   built with OpenBSD clang version 8.0.1 (tags/RELEASE_801/final) (based on LLVM 8.0.1)                                                                                  
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:   configuration: --enable-shared --arch=amd64 --cc=cc --disable-altivec --disable-debug --disable-indev=jack --disable-indev=oss --disable-mipsdsp --disable-mipsdspr2 --
disable-mipsfpu --disable-mmi --disable-msa --disable-outdev=oss --disable-outdev=sdl2 --enable-avresample --enable-fontconfig --enable-frei0r --enable-gpl --enable-libaom --enable-libass --enable-libdav1d --enab
le-libfreetype --enable-libfribidi --enable-libgsm --enable-libmp3lame --enable-libopus --enable-libspeex --enable-libtheora --enable-libv4l2 --enable-libvorbis --enable-libvpx --enable-libx264 --enable-libx265 -
-enable-libxml2 --enable-libxvid --enable-nonfree --enable-openssl --extra-cflags='-I/usr/local/include -I/usr/X11R6/include' --extra-libs='-L/usr/local/lib -L/usr/X11R6/lib' --extra-ldsoflags= --mandir=/usr/loca
l/man --optflags='-O2 -pipe -Wno-redundant-decls'                                                                                                                                                                   
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:   libavutil      56. 31.100 / 56. 31.100                                                                                                                                 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:   libavcodec     58. 54.100 / 58. 54.100                                                                                                                                 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:   libavformat    58. 29.100 / 58. 29.100                                                                                                                                 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:   libavdevice    58.  8.100 / 58.  8.100                                                                                                                                 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:   libavfilter     7. 57.100 /  7. 57.100                                                                                                                                 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:   libavresample   4.  0.  0 /  4.  0.  0                                                                                                                                 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:   libswscale      5.  5.100 /  5.  5.100                                                                                                                                 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:   libswresample   3.  5.100 /  3.  5.100                                                                                                                                 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:   libpostproc    55.  5.100 / 55.  5.100                                                                                                                                 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Splitting the commandline.                                                                                                                                               
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Reading option '-v' ... matched as option 'v' (set logging level) with argument 'debug'.                                                                                 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Reading option '-nostdin' ... matched as option 'stdin' (enable or disable interaction on standard input) with argument 0.                                               
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Reading option '-i' ... matched as input url with argument '/tmp/94123e5b0845fb7f87281f6888f0f674.mp3'.                                                                  
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Reading option '-ac' ... matched as option 'ac' (set number of audio channels) with argument '1'.                                                                        
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Reading option '-f' ... matched as option 'f' (force format) with argument 's16le'.                                                                                      
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Reading option '-ar' ... matched as option 'ar' (set audio sampling rate (in Hz)) with argument '48000'.                                                                 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Reading option '-' ... matched as output url.                                                                                                                            
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Finished splitting the commandline.                                                                                                                                      
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Parsing a group of options: global .                                                                                                                                     
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Applying option v (set logging level) with argument debug.                                                                                                               
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Applying option nostdin (enable or disable interaction on standard input) with argument 0.                                                                               
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Successfully parsed a group of options.                                                                                                                                  
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Parsing a group of options: input url /tmp/94123e5b0845fb7f87281f6888f0f674.mp3.
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Opening an input file: /tmp/94123e5b0845fb7f87281f6888f0f674.mp3.
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [NULL @ 0x1700fcaa6000] Opening '/tmp/94123e5b0845fb7f87281f6888f0f674.mp3' for reading
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [file @ 0x1701a9f66600] Setting default whitelist 'file,crypto' 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [mp3 @ 0x1700fcaa6000] Format mp3 probed with size=8192 and score=51
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: id3v2 ver:4 flags:00 len:895
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [mp3 @ 0x1700fcaa6000] pad 576 894
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [mp3 @ 0x1700fcaa6000] Skipping 0 bytes of junk at 1481.
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [mp3 @ 0x1700fcaa6000] Before avformat_find_stream_info() pos: 1481 bytes read:32768 seeks:0 nb_streams:1
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [mp3 @ 0x1700fcaa6000] demuxer injecting skip 1105 / discard 0
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [mp3float @ 0x17010cc85800] skip 1105 / discard 0 samples due to side data
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [mp3float @ 0x17010cc85800] skip 1105/1152 samples
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [mp3 @ 0x1700fcaa6000] All info found
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [mp3 @ 0x1700fcaa6000] After avformat_find_stream_info() pos: 31177 bytes read:32768 seeks:0 frames:50
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Input #0, mp3, from '/tmp/94123e5b0845fb7f87281f6888f0f674.mp3':
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:   Metadata:
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:     artist          : Joanne Shaw Taylor
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:     title           : Joanne Shaw Taylor - Diamonds In The Dirt (Live At Glasgow Oran-Mor)
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:     date            : 20160511
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:     description     : Joanne Shaw Taylor - Diamonds In The Dirt (Live At Glasgow Oran-Mor)
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : Preorder new album Reckless Heart - http://smarturl.it/JST_RH
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : Follow Joanne Shaw Taylor
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : Facebook - https://www.facebook.com/joanneshawtaylor
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : Instagram - https://www.instagram.com/joanneshawtaylor/
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : Twitter - https://twitter.com/joshawtaylor/
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:     comment         : Joanne Shaw Taylor - Diamonds In The Dirt (Live At Glasgow Oran-Mor)
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : Preorder new album Reckless Heart - http://smarturl.it/JST_RH
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : Follow Joanne Shaw Taylor
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : Facebook - https://www.facebook.com/joanneshawtaylor
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : Instagram - https://www.instagram.com/joanneshawtaylor/
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : Twitter - https://twitter.com/joshawtaylor/
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:     purl            : https://www.youtube.com/watch?v=DIh8sz9pTkc
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:     encoder         : Lavf58.29.100
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:   Duration: 00:08:16.39, start: 0.023021, bitrate: 192 kb/s
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:     Stream #0:0, 50, 1/14112000: Audio: mp3, 48000 Hz, stereo, fltp, 192 kb/s
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:     Metadata:
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:       encoder         : Lavc58.54
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Successfully opened the file.                                                                                                                                            
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Parsing a group of options: output url -.                                                                                                                                
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Applying option ac (set number of audio channels) with argument 1.
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Applying option f (force format) with argument s16le.
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Applying option ar (set audio sampling rate (in Hz)) with argument 48000.
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Successfully parsed a group of options.
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Opening an output file: -.
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [pipe @ 0x170175658000] Setting default whitelist 'crypto'
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Successfully opened the file.
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Stream mapping:
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:   Stream #0:0 -> #0:0 (mp3 (mp3float) -> pcm_s16le (native))
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: cur_dts is invalid st:0 (0) [init:0 i_done:0 finish:0] (this is harmless if it occurs once at the start per stream)
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [mp3float @ 0x17016e120000] skip 1105 / discard 0 samples due to side data
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [mp3float @ 0x17016e120000] skip 1105/1152 samples
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: detected 8 logical cores
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [graph_0_in_0_0 @ 0x1700f7a92400] Setting 'time_base' to value '1/48000'
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [graph_0_in_0_0 @ 0x1700f7a92400] Setting 'sample_rate' to value '48000'
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [graph_0_in_0_0 @ 0x1700f7a92400] Setting 'sample_fmt' to value 'fltp'
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [graph_0_in_0_0 @ 0x1700f7a92400] Setting 'channel_layout' to value '0x3'
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [graph_0_in_0_0 @ 0x1700f7a92400] tb:1/48000 samplefmt:fltp samplerate:48000 chlayout:0x3
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [format_out_0_0 @ 0x1700c5875b00] Setting 'sample_fmts' to value 's16'
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [format_out_0_0 @ 0x1700c5875b00] Setting 'sample_rates' to value '48000'
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [format_out_0_0 @ 0x1700c5875b00] Setting 'channel_layouts' to value '0x4'
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [format_out_0_0 @ 0x1700c5875b00] auto-inserting filter 'auto_resampler_0' between the filter 'Parsed_anull_0' and the filter 'format_out_0_0'
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [AVFilterGraph @ 0x170166bc5900] query_formats: 4 queried, 6 merged, 3 already done, 0 delayed
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [auto_resampler_0 @ 0x1700c5875c00] [SWR @ 0x170129b6d000] Using fltp internally between filters
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [auto_resampler_0 @ 0x1700c5875c00] [SWR @ 0x170129b6d000] Matrix coefficients:
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [auto_resampler_0 @ 0x1700c5875c00] [SWR @ 0x170129b6d000] FC: FL:0.500000 FR:0.500000 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: [auto_resampler_0 @ 0x1700c5875c00] ch:2 chl:stereo fmt:fltp r:48000Hz -> ch:1 chl:mono fmt:s16 r:48000Hz
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg: Output #0, s16le, to 'pipe:':
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:   Metadata:
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:     artist          : Joanne Shaw Taylor
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:     title           : Joanne Shaw Taylor - Diamonds In The Dirt (Live At Glasgow Oran-Mor)
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:     date            : 20160511
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:     description     : Joanne Shaw Taylor - Diamonds In The Dirt (Live At Glasgow Oran-Mor)
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : Preorder new album Reckless Heart - http://smarturl.it/JST_RH
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : Follow Joanne Shaw Taylor
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : Facebook - https://www.facebook.com/joanneshawtaylor
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : Instagram - https://www.instagram.com/joanneshawtaylor/
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : Twitter - https://twitter.com/joshawtaylor/
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:     comment         : Joanne Shaw Taylor - Diamonds In The Dirt (Live At Glasgow Oran-Mor)
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : Preorder new album Reckless Heart - http://smarturl.it/JST_RH
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     :
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : 
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : Follow Joanne Shaw Taylor
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : Facebook - https://www.facebook.com/joanneshawtaylor
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : Instagram - https://www.instagram.com/joanneshawtaylor/
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:                     : Twitter - https://twitter.com/joshawtaylor/
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:     purl            : https://www.youtube.com/watch?v=DIh8sz9pTkc
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:     encoder         : Lavf58.29.100
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:     Stream #0:0, 0, 1/48000: Audio: pcm_s16le, 48000 Hz, mono, s16, 768 kb/s
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:     Metadata:
[Mar 31 17:59:52 DEBUG MainThread] ffmpeg:       encoder         : Lavc58.54.100 pcm_s16le

It's stuck here.

@TerryGeng
Copy link
Collaborator

TerryGeng commented Apr 1, 2020

It looks that something wrong with the pipe. I use Mac(also one of the BSD family) to test and everything works. Currently, I'm not sure what is wrong. Whether ffmpeg failed to write to pipe, or python didn't read from pipe successfully.

But I can't rule out other possibilities since the bot can also get stuck by many other reasons,

botamusique/mumbleBot.py

Lines 409 to 434 in eeaa09b

def loop(self):
raw_music = ""
while not self.exit and self.mumble.is_alive():
while self.thread and self.mumble.sound_output.get_buffer_size() > 0.5 and not self.exit:
# If the buffer isn't empty, I cannot send new music part, so I wait
self._loop_status = 'Wait for buffer %.3f' % self.mumble.sound_output.get_buffer_size()
time.sleep(0.01)
if self.thread:
# I get raw from ffmpeg thread
# move playhead forward
self._loop_status = 'Reading raw'
if self.song_start_at == -1:
self.song_start_at = time.time() - self.playhead
self.playhead = time.time() - self.song_start_at
raw_music = self.thread.stdout.read(480)
self.read_pcm_size += 480
try:
self.last_ffmpeg_err = self.thread_stderr.readline()
if self.last_ffmpeg_err:
self.log.debug("ffmpeg: " + self.last_ffmpeg_err.strip("\n"))
except:
pass

It may get stuck while waiting for buffer (L413), or while fetching contains in the pipe (L426).

To be certain, can you please add print("waiting for buffer") right before L413 and print("reading from pipe") right before L426?

Then, you can know from the log that where is wrong.

@comete-geek
Copy link

Ok this is what I did:

# Main loop of the Bot
    def loop(self):
        raw_music = ""
        while not self.exit and self.mumble.is_alive():
            print("waiting for buffer")

            while self.thread and self.mumble.sound_output.get_buffer_size() > 0.5 and not self.exit:
                # If the buffer isn't empty, I cannot send new music part, so I wait
                self._loop_status = 'Wait for buffer %.3f' % self.mumble.sound_output.get_buffer_size()
                time.sleep(0.01)

            if self.thread:
                # I get raw from ffmpeg thread
                # move playhead forward
                self._loop_status = 'Reading raw'
                if self.song_start_at == -1:
                    self.song_start_at = time.time() - self.playhead
                self.playhead = time.time() - self.song_start_at

                print("reading from pipe")
                raw_music = self.thread.stdout.read(480)
                self.read_pcm_size += 480

                try:
                    self.last_ffmpeg_err = self.thread_stderr.readline()
                    if self.last_ffmpeg_err:
                        self.log.debug("ffmpeg: " + self.last_ffmpeg_err.strip("\n"))
                except:
                    pass

                if raw_music:
                    # Adjust the volume and send it to mumble
                    self.volume_cycle()
                    self.mumble.sound_output.add_sound(
                        audioop.mul(raw_music, 2, self.volume))
                else:
                    time.sleep(0.1)
            else:
                time.sleep(0.1)

Then when I start playing something:

...
waiting for buffer
reading from pipe
waiting for buffer
reading from pipe
waiting for buffer
reading from pipe

@TerryGeng
Copy link
Collaborator

Thanks. So the problem comes from this little pipe huh?

It may also be insightful if you can add print(self.read_pcm_size) before print("reading from pipe") so we know how many bytes we can read before the pipe gets stuck. If this number doesn't change, then I think we should look into some buffer problems.

@comete-geek
Copy link

the last size displayed is 52800

@azlux
Copy link
Owner Author

azlux commented Apr 1, 2020

Another test can help.
Remove the line https://github.com/azlux/botamusique/blob/master/mumbleBot.py#L37
Then run the bot manually, when you Ctrl+C , the trace will show where the bot is hanging.

@comete-geek
Copy link

argh... it doesn't take the CTRL+C...

@azlux
Copy link
Owner Author

azlux commented Apr 1, 2020

What ? It should (I've test it) botamusique and pymumble don't catch KeyboardInterrupt if you have remove the line.
Maybe you need another keyboard press ?

@comete-geek
Copy link

I tried multiple press but same result. I've also tried a : kill -INT process_id (which is the same signal as CTRL+C) without success...

@comete-geek
Copy link

...but if I had the line again, the CTRL+C works...

@azlux
Copy link
Owner Author

azlux commented Apr 1, 2020

that is really strange. So last try is : you keep that line, and you run the bot like that :
venv/bin/python -m trace --trace mumbleBot.py <All parameter you need>
You will have a lot, A LOT, of output. Just wait the bot get connected (can take minutes) and reproduce the bug.
2 cases:

  • Infinite output : We need to read that to check infinite loop
  • output stop : we have some lock into the code or I/O issue.

@comete-geek
Copy link

Ok this a part of the output:

mumble.py(196):             if self.control_socket in rlist:  # something to be read on the control socket                                                                                                          
mumble.py(198):             elif self.control_socket in xlist:  # socket was closed                                                                                                                                 
mumble.py(183):         while self.connected not in (PYMUMBLE_CONN_STATE_NOT_CONNECTED, PYMUMBLE_CONN_STATE_FAILED) and self.parent_thread.is_alive():                                                              
 --- modulename: threading, funcname: is_alive                                                                                                                                                                      
threading.py(1100):         assert self._initialized, "Thread.__init__() not called"                                                                                                                                
threading.py(1101):         if self._is_stopped or not self._started.is_set():                                                                                                                                      
 --- modulename: threading, funcname: is_set                                                                                                                                                                        
threading.py(509):         return self._flag                                                                                                                                                                        
threading.py(1103):         self._wait_for_tstate_lock(False)                                                                                                                                                       
 --- modulename: threading, funcname: _wait_for_tstate_lock                                                                                                                                                         
threading.py(1057):         lock = self._tstate_lock                                                                                                                                                                
threading.py(1058):         if lock is None:  # already determined that the C code is done                                                                                                                          
threading.py(1060):         elif lock.acquire(block, timeout):                                                                                                                                                      
threading.py(1104):         return not self._is_stopped                                                                                                                                                             
mumble.py(184):             if last_ping + PYMUMBLE_PING_DELAY <= time.time():  # when it is time, send the ping                                                                                                    
mumble.py(188):             if self.connected == PYMUMBLE_CONN_STATE_CONNECTED:                                                                                                                                     
mumble.py(189):                 while self.commands.is_cmd():                                                                                                                                                       
 --- modulename: commands, funcname: is_cmd                                                                                                                                                                         
commands.py(33):         if len(self.queue) > 0:                                                                                                                                                                    
commands.py(36):             return False                                                                                                                                                                           
mumble.py(192):                 self.sound_output.send_audio()  # send outgoing audio if available                                                                                                                  
 --- modulename: soundoutput, funcname: send_audio                                                                                                                                                                  
soundoutput.py(50):         if not self.encoder or len(self.pcm) == 0:  # no codec configured or no audio sent                                                                                                      
soundoutput.py(51):             return ()                                                                                                                                                                           
mumble.py(194):             (rlist, wlist, xlist) = select.select([self.control_socket], [], [self.control_socket], self.loop_rate)  # wait for a socket activity                                                   
mumble.py(196):             if self.control_socket in rlist:  # something to be read on the control socket                                                                                                          
mumble.py(198):             elif self.control_socket in xlist:  # socket was closed                                                                                                                                 
mumble.py(183):         while self.connected not in (PYMUMBLE_CONN_STATE_NOT_CONNECTED, PYMUMBLE_CONN_STATE_FAILED) and self.parent_thread.is_alive():                                                              
 --- modulename: threading, funcname: is_alive                                                                                                                                                                      
threading.py(1100):         assert self._initialized, "Thread.__init__() not called"                                                                                                                                
threading.py(1101):         if self._is_stopped or not self._started.is_set():                                                                                                                                      
 --- modulename: threading, funcname: is_set                                                                                                                                                                        
threading.py(509):         return self._flag                                                                                                                                                                        
threading.py(1103):         self._wait_for_tstate_lock(False)                                                                                                                                                       
 --- modulename: threading, funcname: _wait_for_tstate_lock                                                                                                                                                         
threading.py(1057):         lock = self._tstate_lock                                                                                                                                                                
threading.py(1058):         if lock is None:  # already determined that the C code is done                                                                                                                          
threading.py(1060):         elif lock.acquire(block, timeout):                                                                                                                                                      
threading.py(1104):         return not self._is_stopped                                                                                                                                                             
mumble.py(184):             if last_ping + PYMUMBLE_PING_DELAY <= time.time():  # when it is time, send the ping                                                                                                    
mumble.py(188):             if self.connected == PYMUMBLE_CONN_STATE_CONNECTED:                                                                                                                                     
mumble.py(189):                 while self.commands.is_cmd():                                                                                                                                                       
 --- modulename: commands, funcname: is_cmd                                                                                                                                                                         
commands.py(33):         if len(self.queue) > 0:                                                                                                                                                                    
commands.py(36):             return False                                                                                                                                                                           
mumble.py(192):                 self.sound_output.send_audio()  # send outgoing audio if available                                                                                                                  
 --- modulename: soundoutput, funcname: send_audio                                                                                                                                                                  
soundoutput.py(50):         if not self.encoder or len(self.pcm) == 0:  # no codec configured or no audio sent                                                                                                      
soundoutput.py(51):             return ()
mumble.py(194):             (rlist, wlist, xlist) = select.select([self.control_socket], [], [self.control_socket], self.loop_rate)  # wait for a socket activity                                         [890/1903]
mumble.py(196):             if self.control_socket in rlist:  # something to be read on the control socket                                                                                                          
mumble.py(198):             elif self.control_socket in xlist:  # socket was closed                                                                                                                                 
mumble.py(183):         while self.connected not in (PYMUMBLE_CONN_STATE_NOT_CONNECTED, PYMUMBLE_CONN_STATE_FAILED) and self.parent_thread.is_alive():                                                              
 --- modulename: threading, funcname: is_alive                                                                                                                                                                      
threading.py(1100):         assert self._initialized, "Thread.__init__() not called"                                                                                                                                
threading.py(1101):         if self._is_stopped or not self._started.is_set():                                                                                                                                      
 --- modulename: threading, funcname: is_set                                                                                                                                                                        
threading.py(509):         return self._flag                                                                                                                                                                        
threading.py(1103):         self._wait_for_tstate_lock(False)                                                                                                                                                       
 --- modulename: threading, funcname: _wait_for_tstate_lock                                                                                                                                                         
threading.py(1057):         lock = self._tstate_lock                                                                                                                                                                
threading.py(1058):         if lock is None:  # already determined that the C code is done                                                                                                                          
threading.py(1060):         elif lock.acquire(block, timeout):                                                                                                                                                      
threading.py(1104):         return not self._is_stopped                                                                                                                                                             
mumble.py(184):             if last_ping + PYMUMBLE_PING_DELAY <= time.time():  # when it is time, send the ping                                                                                                    
mumble.py(188):             if self.connected == PYMUMBLE_CONN_STATE_CONNECTED:                                                                                                                                     
mumble.py(189):                 while self.commands.is_cmd():                                                                                                                                                       
 --- modulename: commands, funcname: is_cmd                                                                                                                                                                         
commands.py(33):         if len(self.queue) > 0:
commands.py(36):             return False
mumble.py(192):                 self.sound_output.send_audio()  # send outgoing audio if available
 --- modulename: soundoutput, funcname: send_audio
soundoutput.py(50):         if not self.encoder or len(self.pcm) == 0:  # no codec configured or no audio sent
soundoutput.py(51):             return ()
mumble.py(194):             (rlist, wlist, xlist) = select.select([self.control_socket], [], [self.control_socket], self.loop_rate)  # wait for a socket activity
mumble.py(196):             if self.control_socket in rlist:  # something to be read on the control socket 
mumble.py(198):             elif self.control_socket in xlist:  # socket was closed
mumble.py(183):         while self.connected not in (PYMUMBLE_CONN_STATE_NOT_CONNECTED, PYMUMBLE_CONN_STATE_FAILED) and self.parent_thread.is_alive():
 --- modulename: threading, funcname: is_alive
threading.py(1100):         assert self._initialized, "Thread.__init__() not called"
threading.py(1101):         if self._is_stopped or not self._started.is_set():
 --- modulename: threading, funcname: is_set
threading.py(509):         return self._flag
threading.py(1103):         self._wait_for_tstate_lock(False)
 --- modulename: threading, funcname: _wait_for_tstate_lock
threading.py(1057):         lock = self._tstate_lock
threading.py(1058):         if lock is None:  # already determined that the C code is done
threading.py(1060):         elif lock.acquire(block, timeout):
threading.py(1104):         return not self._is_stopped
mumble.py(184):             if last_ping + PYMUMBLE_PING_DELAY <= time.time():  # when it is time, send the ping
mumble.py(188):             if self.connected == PYMUMBLE_CONN_STATE_CONNECTED:
mumble.py(189):                 while self.commands.is_cmd():
 --- modulename: commands, funcname: is_cmd
commands.py(33):         if len(self.queue) > 0:
commands.py(36):             return False
mumble.py(192):                 self.sound_output.send_audio()  # send outgoing audio if available
 --- modulename: soundoutput, funcname: send_audio
soundoutput.py(50):         if not self.encoder or len(self.pcm) == 0:  # no codec configured or no audio sent
soundoutput.py(51):             return ()
mumble.py(194):             (rlist, wlist, xlist) = select.select([self.control_socket], [], [self.control_socket], self.loop_rate)  # wait for a socket activity

@comete-geek
Copy link

oh I forgot to say, it's a loop

@TerryGeng
Copy link
Collaborator

If this loop keeps going on, you would surely hear something. And I didn't see mumbleBot.py in this log. Can you see mumbleBot.py from it?

@TerryGeng
Copy link
Collaborator

I'm sorry that I don't have a device with openbsd installed on it. If you can join IRC channel #mumble at Freenode, I think we can investigate this problem in a more efficient way.

@azlux
Copy link
Owner Author

azlux commented Apr 17, 2020

Can you try to replace these 2 lines
https://github.com/azlux/botamusique/blob/master/mumbleBot.py#L378-L379
by :

flags = os.O_NONBLOCK 
pipe_rd, pipe_wd = os.pipe2(flags) 

This is an alternative pipe on some OS.

@comete-geek
Copy link

It works ! Bravo ! :)
thanks a lot !

@azlux
Copy link
Owner Author

azlux commented Apr 17, 2020

ok, I should add this exception into the code. What's your print(os.name), print(sys.platform)

@comete-geek
Copy link

print(os.name) --> posix
print(sys.platform) --> openbsd6

@TerryGeng
Copy link
Collaborator

I think I'm going to work on this part later. Thank @azlux @comete-geek for the solution!

TerryGeng added a commit that referenced this issue Apr 18, 2020
Thanks @azlux for this solution. Close #116.

Also created an option 'redirect_ffmpeg_log' to enable/disable
reading the log of ffmpeg.
@comete-geek
Copy link

Sorry but this change doesn't work for me. If I start playing something like "!radio jazz" or a file, the bot crashes with this error:
Traceback (most recent call last):
File "mumbleBot.py", line 757, in
var.bot.loop()
File "mumbleBot.py", line 512, in loop
self.launch_music()
File "mumbleBot.py", line 381, in launch_music
pipe_rd, pipe_wd = util.pipe_no_wait() # Let the pipe work in non-blocking mode
TypeError: cannot unpack non-iterable NoneType object

@TerryGeng TerryGeng reopened this Apr 25, 2020
@TerryGeng
Copy link
Collaborator

Can you run

python -c "from sys import platform; print(platform)"

in your terminal, so we can know the platform code of your system? It seems that we have missed this in our code.

@TerryGeng
Copy link
Collaborator

And, I know this kind of (sad) things will happen. So I add a switch in the config file. If you are busy making the bot work, just set

redirect_ffmpeg_log = False

in the [debug] section.

@TerryGeng
Copy link
Collaborator

print(os.name) --> posix
print(sys.platform) --> openbsd6

Oh you have already provided it. This post has become so long and sorry that I have missed this information.

@comete-geek
Copy link

Thanks a lot ! it works now.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Projects
None yet
Development

No branches or pull requests

3 participants