search

azlux / botamusique

Bot to play youtube / soundcloud / radio / local music on Mumble (using pymumble).
MIT License
313 stars 79 forks source link

After Update playing radio stream disconnects bot #160

Closed Glowsome closed 4 years ago

Glowsome commented 4 years ago

Behaviour : After update when issueing command to play a preconfigured radiostream then bot disconnects

Affected version INFO MainThread] bot: botamusique version 6.3,

To Reproduce

  1. issue !radio [preconfigured alias]
  2. Bot responds with adding it to queue, then disconnects

Expected behavior => bot should not disconnect, but play defined music stream

Log from bot : botamusique-error-23-052020.log

Desktop (please complete the following information): Not applicable

Smartphone (please complete the following information): Not applicable

Additional context OS the bot is running of is Debian Buster / latest stable release

As this has lead to a non-desired situation i have reverted the update ( its running on a LXC container, so i restored the functional bot from 24Hrs back) In this a full procedure of upgrade can be re-performed.

TerryGeng commented 4 years ago

Hi. We updated the logging mechanism in the last release. I'm not sure whether that is the cause since the error log you uploaded is certainly messed up. I have tested it on my Mac and CentOS and it works fine.

I suggest you disable the logfile (empty that option)

[bot]
logfile=

and run the bot again to see if it happens again.

Thanks.

Glowsome commented 4 years ago

@TerryGeng I run multiple instances of the bot for multiple mumble servers, disabling logging is not to an option here, i keep track by having all instances log to their specific instances .... others are more active then others, but this logging is just the thing that enabled me to post a log. Asking me to turn this feature off is like forcing me into the dark .... So i need a more strong motivation then just 'we updated and suggest going without logging' here.

I mean the thing i appreciate is that i can make things visible, and i like to keep things visible, your suggestion might solve the stabilsation, but it will pull the wool over my eyes .... .. and i dont like the trade-off.

[forgive my bluntness] Happy to work with any kind of debugging, or testing, but don't put me into the dark without clarification .. i mean my mumble users are enjoying the bot, and are even requesting it and asking when its not up, but this is like M$ .=>. you have an error in your log, ok, lets create a patch that filters it from your logs .. oh, that doesnt solve your issue,? .. why, it doesnt show up in your logs ?

TerryGeng commented 4 years ago

Sorry to confuse you. I don't mean to let you disable the logging feature from now on, and it is certainly not a practical way to leave the logging mechanism broken on some platform.

Currently, I'm still trying to locate the error, however, I cannot reproduce the error you have reported on my servers. Would you mind helping me by disabling the logfile and see if the bot works so I'd know that's the wrong part and consider possible fixes?

And what happens if you play other stuff like local music?

Glowsome commented 4 years ago

The musicbot/botamusique is primarily used to play internet ( youtube/ mp3) streams, no local folder has been configured, nor is webinterface enabled.

TerryGeng commented 4 years ago

And just to clarify, the logging mechanism update is not for messing things up... We have users reported that when the bot crash, the exception message is not logged in the log file... So we proposed a way to capture the stderr and stdout, but in your case, it seems our "hook" has caused an infinite loop...

This is not the expected behavior, nor something I have seen when testing on many platforms... Your bug report is valuable for us. And if you could help me confirm, this bug is caused by the logging mechanism so I can do something to it.

Looking forward to your result!

Glowsome commented 4 years ago

as its now 04:30 AM i will require some sleep but will defo test the hypothesis, will report back to you when done

Glowsome commented 4 years ago

Ok, i have replayed the whole upgrade :

The bot did not lauch on restarting (over systemd) after this, so :

Then attempted to run a !radio command, which didnt make the bot disconnect on previous attempt , but generated an error : [01:17:05] (Channel) MusicBot ♫: Now Playing JOE WALSH - ROCKY MOUNTAIN WAY from http://stream.gal.io/arrow added by Glowsome [01:17:05] (Private) MusicBot ♫: Added: JOE WALSH - ROCKY MOUNTAIN WAY from http://stream.gal.io/arrow added by Glowsome. [01:17:11] (Channel) MusicBot ♫: Unable to play http://stream.gal.io/arrow. Removed from the library. ==> so this did retrieve info, but didnt start playing, and no disconnect...

Then tried a different stream, and it started playing : [01:17:39] To The Lounge: !radio radio538 [01:17:41] (Channel) MusicBot ♫: Now Playing DE DIJK - IK KAN HET NIET ALLEEN from http://playerservices.streamtheworld.com/api/livestream-redirect/RADIO538.mp3 added by Glowsome [01:17:41] (Private) MusicBot ♫: Added: DE DIJK - IK KAN HET NIET ALLEEN from http://playerservices.streamtheworld.com/api/livestream-redirect/RADIO538.mp3 added by Glowsome.

So unsure as to whats borking the 1st stream, as when i run same url over VLC it works fine ... maybe a glitch ... need to test more

atleast the primary stream seems to function as it should ... but i have not yet tested re-enabling the logfile.

TerryGeng commented 4 years ago

Thanks for your reply!

We use ffmpeg to handle the radio stream. So connections problem can be debugged by looking into the FFmpeg debug log. in the config file, there's a section called [debug] and you can see an FFmpeg option in it. If you're interested in what happened to the 1st stream, this is your weapon :)

But the main concern now is the logging facilities. Looking forward to more feedback from you!

Glowsome commented 4 years ago

Tested a bit further, and re-enabling the logfile = logs/<mylogfile.log> and reloaded the bot, on executing a !radio from predefined disconnects it as stated in the initial issue. So it seems the whole issue is based around the logger.

Glowsome commented 4 years ago

@TerryGeng you mentioned changing 2 lines in util.py ... but for some reason my file-length/line-count does not match with the version on github : My version : cat util.py | wc -l replies with 354 The file on git has 416 lines ¿?

So is it possible the update didnt process the changes in that file ? i tested by renaming 'my' file, and downloading the one from github, (the 416 lines one) restarted the bot after re-enabling logging parameter, but no change detected .. it kills itself as soon as the logging is enabled.

This makes me think that the update went thru only partial, and i have absolutely no idea what files were successfully updated, and which were skipped ...

azlux commented 4 years ago

Update, if your config version is stable, use the release. So it's the files from last release. Currently,it's https://github.com/azlux/botamusique/tree/6.3

Glowsome commented 4 years ago

@azlux i updated via console : ./update.sh stable Still the issue remains with the enabling of the logfile :(

azlux commented 4 years ago

My current version of ffmpeg is 4.1.4-1~deb10u1. What's yours ? What the output of ffmpeg -v debug -nostdin -i http://stream.gal.io/arrow -ac 1 -f s16le -ar 48000 /tmp/test.mp3 ? Is there are any error, or the file /tmp/test.mp3 is created and have the radio music saved ?

Glowsome commented 4 years ago

as for the stream-being-removed issue : Version is : ffmpeg version 4.1.4-1~deb10u1 Copyright (c) 2000-2019 the FFmpeg developers built with gcc 8 (Debian 8.3.0-6)

When i issue the command it prints all green, and starts building up a ffmpeg-output-26052020.log

I have had ffmpeg issues in the past ( documented in another issue), then changed to the repo you reccomended, since then its been good... but somehow its acting up again

TerryGeng commented 4 years ago

Thanks for testing for us. It looks like the problem did stem from the logging. The two lines I mentioned are

https://github.com/azlux/botamusique/blob/d288bfa658467f3de617b8be13ae6b2b5f4ede22/util.py#L346-L353

L350 and L353 for v6.3.

I updated util.py later after the last release so line numbers changed a little bit.

TerryGeng commented 4 years ago

As for the ffmpeg issue, I think it is not related to the logging. I'd suggest you open another issue if it keeps bothering you. Thanks!

Glowsome commented 4 years ago

@TerryGeng i agree we need to split those in separate issues

TerryGeng commented 4 years ago

Hi! Everything works fine since then?

Glowsome commented 4 years ago

@TerryGeng since i disabled logging, and also disabled the logging lines you referred to (for now). The bot seems to be functioning according to expectations. Thing that remains is the one stream that seems to timeout ( but as said this should be adressed in another thread which i have not opened yet due to local debugging 1st)

class LoggerIOWrapper(io.TextIOWrapper):
    def __init__(self, logger: logging.Logger, logging_level, fallback_io_buffer):
        super().__init__(fallback_io_buffer, write_through=True)
        self.logger = logger
        self.logging_level = logging_level

    def write(self, text):
        if isinstance(text, bytes):
            msg = text.decode('utf-8').rstrip()
            self.logger.log(self.logging_level, msg)
#            super().write(msg + "\n")
        else:
            self.logger.log(self.logging_level, text.rstrip())
#            super().write(text + "\n")

For as far as i could determine this is what you were after in regards of disabling the write to log. I have not tested enabling the log itself in the configuration.ini since... But i can test this within a few hours.

TerryGeng commented 4 years ago

Hi, I think this bug has been fixed. Can I close this issue?

Glowsome commented 4 years ago

Hi @TerryGeng i just updated the bot tonight, i'll need a bit of time to test. Had some issues after the update to get the bot back up running, but thats been solved by @azlux

Glowsome commented 4 years ago

sorry for reporting late, still need to test it but had some IRL stuff that needed handling 1st - hope to do it tomorrow.

TerryGeng commented 4 years ago

It has been weeks since the fix and now I assume this bug has been fixed.