azlux / botamusique

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

ValueError: Uncached item of id $id in media/cache.py #266

Closed mweinelt closed 3 years ago

mweinelt commented 3 years ago

Describe the bug

botamusique[2463]: [May 04 18:16:22 INFO] bot: play music [url] “Someone in the Crowd” - La La Land (2016) (https://www.youtube.com/watch?v=ocHKTdv-l9U) from playlist La La Land (2016) - F>
botamusique[2463]: Traceback (most recent call last):
botamusique[2463]:   File "/nix/store/slcm3hnfpv03pyvvqd7rrci1imp52vvm-botamusique-unstable-2021-03-13/share/botamusique/.mumbleBot.py-wrapped", line 896, in <module>
botamusique[2463]:     var.bot.loop()
botamusique[2463]:   File "/nix/store/slcm3hnfpv03pyvvqd7rrci1imp52vvm-botamusique-unstable-2021-03-13/share/botamusique/.mumbleBot.py-wrapped", line 560, in loop
botamusique[2463]:     self.async_download_next()
botamusique[2463]:   File "/nix/store/slcm3hnfpv03pyvvqd7rrci1imp52vvm-botamusique-unstable-2021-03-13/share/botamusique/.mumbleBot.py-wrapped", line 415, in async_download_next
botamusique[2463]:     if not next.is_ready():
botamusique[2463]:   File "/nix/store/slcm3hnfpv03pyvvqd7rrci1imp52vvm-botamusique-unstable-2021-03-13/share/botamusique/media/cache.py", line 188, in is_ready
botamusique[2463]:     return self.item().is_ready()
botamusique[2463]:   File "/nix/store/slcm3hnfpv03pyvvqd7rrci1imp52vvm-botamusique-unstable-2021-03-13/share/botamusique/media/cache.py", line 145, in item
botamusique[2463]:     raise ValueError(f"Uncached item of id {self.id}.")
botamusique[2463]: ValueError: Uncached item of id 40d56eeac2a7a5b53af4506829a2e297.
systemd[1]: botamusique.service: Main process exited, code=exited, status=1/FAILURE

Affected version df38c7dbd6d59c6790cf2364d1f344b7f6f72107

To Reproduce Unclear, I wasn't using the bot at the time, the users said a song finished properly and the bot just quit the mumble session.

Expected behavior Don't crash on caching issues.

Additional context https://github.com/azlux/botamusique/blob/master/media/cache.py#L145

mweinelt commented 3 years ago

Crashed again, this time it finished a playlist and due to repeat tried to play it again, when it happened.

May 05 01:48:34 juno botamusique[16273]: Traceback (most recent call last):
May 05 01:48:34 juno botamusique[16273]:   File "/nix/store/slcm3hnfpv03pyvvqd7rrci1imp52vvm-botamusique-unstable-2021-03-13/share/botamusique/.mumbleBot.py-wrapped", line 896, in <module>
May 05 01:48:34 juno botamusique[16273]:     var.bot.loop()
May 05 01:48:34 juno botamusique[16273]:   File "/nix/store/slcm3hnfpv03pyvvqd7rrci1imp52vvm-botamusique-unstable-2021-03-13/share/botamusique/.mumbleBot.py-wrapped", line 560, in loop
May 05 01:48:34 juno botamusique[16273]:     self.async_download_next()
May 05 01:48:34 juno botamusique[16273]:   File "/nix/store/slcm3hnfpv03pyvvqd7rrci1imp52vvm-botamusique-unstable-2021-03-13/share/botamusique/.mumbleBot.py-wrapped", line 415, in async_download_next
May 05 01:48:34 juno botamusique[16273]:     if not next.is_ready():
May 05 01:48:34 juno botamusique[16273]:   File "/nix/store/slcm3hnfpv03pyvvqd7rrci1imp52vvm-botamusique-unstable-2021-03-13/share/botamusique/media/cache.py", line 188, in is_ready
May 05 01:48:34 juno botamusique[16273]:     return self.item().is_ready()
May 05 01:48:34 juno botamusique[16273]:   File "/nix/store/slcm3hnfpv03pyvvqd7rrci1imp52vvm-botamusique-unstable-2021-03-13/share/botamusique/media/cache.py", line 145, in item
May 05 01:48:34 juno botamusique[16273]:     raise ValueError(f"Uncached item of id {self.id}.")
May 05 01:48:34 juno botamusique[16273]: ValueError: Uncached item of id 0530fd5d23f9e2948b00349d5cf35bec.
May 05 01:48:34 juno systemd[1]: botamusique.service: Main process exited, code=exited, status=1/FAILURE
May 05 01:48:39 juno botamusique[17833]: [https @ 0x28a28c0] Opening 'https://manifest.googlevideo.com/api/manifest/hls_playlist/expire/1620187225/ei/-cORYKLuIcXy1gKN8IXYAQ/ip/2a01:4f8:1c1c:f3b4:0:0:0:1/id/5qap5aO4i9A.0/itag/96/source/yt_live_broadcast/requiressl/yes/ratebypass/yes/live/1/sgoap/gir%3Dyes%3Bitag%3D140/sgovp/gir%3Dyes%3Bitag%3D137/hls_chunk_host/r2---sn-4g5edney.googlevideo.com/playlist_duration/30/manifest>
May 05 01:48:39 juno botamusique[17833]: [hls @ 0x20d69c0] Skip ('#EXT-X-VERSION:3')
May 05 01:48:39 juno botamusique[17833]: [hls @ 0x20d69c0] Skip ('#EXT-X-DISCONTINUITY-SEQUENCE:13089')
May 05 01:48:39 juno botamusique[17833]: [hls @ 0x20d69c0] Skip ('#EXT-X-PROGRAM-DATE-TIME:2021-05-04T23:48:01.713+00:00')
May 05 01:48:39 juno botamusique[17833]: [https @ 0x235bf40] Opening 'https://r2---sn-4g5edney.googlevideo.com/videoplayback/id/5qap5aO4i9A.0/itag/96/source/yt_live_broadcast/expire/1620187225/ei/-cORYKLuIcXy1gKN8IXYAQ/ip/2a01:4f8:1c1c:f3b4:0:0:0:1/requiressl/yes/ratebypass/yes/live/1/sgoap/gir%3Dyes%3Bitag%3D140/sgovp/gir%3Dyes%3Bitag%3D137/hls_chunk_host/r2---sn-4g5edney.googlevideo.com/playlist_duration/30/manifest_dur>
May 05 01:48:39 juno botamusique[17833]: frame=195248 fps= 30 q=-1.0 Lsize=  600684kB time=01:48:28.29 bitrate= 756.1kbits/s speed=   1x
May 05 01:48:39 juno botamusique[17833]: video:495397kB audio:101692kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: 0.602040%
May 05 01:48:39 juno botamusique[17833]: Exiting normally, received signal 15.
May 05 01:48:39 juno systemd[1]: botamusique.service: Failed with result 'exit-code'.
TerryGeng commented 3 years ago

I have been using the bot for more than a year and I have never seen such an error.

I need to know more about the situations when this bug happens like what operation have you done and what is the necessary step to reproduce this error.

mweinelt commented 3 years ago

Hit this again when someone queries the queue.

May 13 22:38:17 juno botamusique[757]: [May 13 22:38:17 INFO] bot: received command q -  by hexa-
May 13 22:38:17 juno botamusique[757]: [May 13 22:38:17 INFO] bot: q matches queue
May 13 22:38:17 juno botamusique[757]: [May 13 22:38:17 ERROR] bot: command queue failed with error: Traceback (most recent call last):
May 13 22:38:17 juno botamusique[757]:   File "/nix/store/slcm3hnfpv03pyvvqd7rrci1imp52vvm-botamusique-unstable-2021-03-13/share/botamusique/.mumbleBot.py-wrapped", line 321, in message_received
May 13 22:38:17 juno botamusique[757]:     self.cmd_handle[command_exc]['handle'](self, user, text, command_exc, parameter)
May 13 22:38:17 juno botamusique[757]:   File "/nix/store/slcm3hnfpv03pyvvqd7rrci1imp52vvm-botamusique-unstable-2021-03-13/share/botamusique/command.py", line 839, in cmd_queue
May 13 22:38:17 juno botamusique[757]:     if len(music.item().tags) > 0:
May 13 22:38:17 juno botamusique[757]:   File "/nix/store/slcm3hnfpv03pyvvqd7rrci1imp52vvm-botamusique-unstable-2021-03-13/share/botamusique/media/cache.py", line 145, in item
May 13 22:38:17 juno botamusique[757]:     raise ValueError(f"Uncached item of id {self.id}.")
May 13 22:38:17 juno botamusique[757]: ValueError: Uncached item of id 27ede7e805514401c54335d10ec43235.

This issue was three hours in the making, someone added a playlist and the error first turned up in the Validating thread, so it really feels like a race condition or sth?

May 13 19:46:07 juno botamusique[757]: [youtube] Downloading just video tVA4AxyT7T0 because of --no-playlist
May 13 19:46:08 juno botamusique[757]: [May 13 19:46:08 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=Z_EkWBf7hy0
May 13 19:46:08 juno botamusique[757]: [youtube] Z_EkWBf7hy0: Downloading webpage
May 13 19:46:08 juno botamusique[757]: [youtube] Downloading just video Z_EkWBf7hy0 because of --no-playlist
May 13 19:46:08 juno botamusique[757]: [May 13 19:46:08 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=tZWytKNv_pk
May 13 19:46:08 juno botamusique[757]: [youtube] tZWytKNv_pk: Downloading webpage
May 13 19:46:11 juno botamusique[757]: [May 13 19:46:11 INFO] bot: play music [url] Two Steps From Hell - Red Carpets (https://www.youtube.com/watch?v=xJtfaaSyZRQ) from playlist Two Steps From Hell - Legend (Full Album)
May 13 19:46:11 juno botamusique[757]: [May 13 19:46:11 INFO] url: music file missed for [url] Two Steps From Hell - Perilous Journey (https://www.youtube.com/watch?v=uZKaZQuiR3c) from playlist Two Steps From Hell - Legend (Full Album)
May 13 19:46:11 juno botamusique[757]: [May 13 19:46:11 INFO] bot: start preparing item in thread: [url] Two Steps From Hell - Perilous Journey (https://www.youtube.com/watch?v=uZKaZQuiR3c) from playlist Two Steps From Hell - Legend (Full Album)
May 13 19:46:11 juno botamusique[757]: [May 13 19:46:11 INFO] Cleaning tmp folder
May 13 19:46:11 juno botamusique[757]: [May 13 19:46:11 INFO] bot: downloading url (Two Steps From Hell - Perilous Journey) https://www.youtube.com/watch?v=uZKaZQuiR3c
May 13 19:46:11 juno botamusique[757]: [May 13 19:46:11 INFO] bot: download attempts 1 / 2
May 13 19:46:11 juno botamusique[757]: [youtube] uZKaZQuiR3c: Downloading webpage
May 13 19:46:11 juno botamusique[757]: ['/tmp/de7e4b71b491136457fe5255f3242a51', '/tmp/37c3bbea9b6479abacac99bfaaa6842b.jpg', '/tmp/37c3bbea9b6479abacac99bfaaa6842b', '/tmp/da1c9a348dc7b832d7455c4477c5e630.jpg', '/tmp/da1c9a348dc7b832d7455c4477c5e630', '/tmp/784ac331c2258e4bc5943c158bf24d45.jpg', '/tmp/784ac331c2258e4bc5943c158bf24d45', '/tmp/16156153c1abf8af0df34f0d22caa87b.jpg', '/tmp/16156153c1abf8af0df34f0d22caa87b', '/tmp/8b2acd616e519aa6536dfca5960780f8.jpg']
May 13 19:46:12 juno botamusique[757]: [youtube] Downloading just video uZKaZQuiR3c because of --no-playlist
May 13 19:46:12 juno botamusique[757]: [youtube] uZKaZQuiR3c: Downloading MPD manifest
May 13 19:46:12 juno botamusique[757]: [youtube] uZKaZQuiR3c: Downloading thumbnail ...
May 13 19:46:12 juno botamusique[757]: [youtube] uZKaZQuiR3c: Writing thumbnail to: /tmp/a96f1cb6f66dc34672468085b9cb632c.jpg
May 13 19:46:12 juno botamusique[757]: [youtube] Downloading just video tZWytKNv_pk because of --no-playlist
May 13 19:46:12 juno botamusique[757]: [download] Destination: /tmp/a96f1cb6f66dc34672468085b9cb632c
May 13 19:46:12 juno botamusique[757]: [470B blob data]
May 13 19:46:12 juno botamusique[757]: [youtube] XGeGhYZaTMI: Downloading webpage
May 13 19:46:13 juno botamusique[757]: [248B blob data]
May 13 19:46:13 juno botamusique[757]: [ffmpeg] Correcting container in "/tmp/a96f1cb6f66dc34672468085b9cb632c"
May 13 19:46:13 juno botamusique[757]: [May 13 19:46:13 INFO] bot: finished downloading url (Two Steps From Hell - Perilous Journey) https://www.youtube.com/watch?v=uZKaZQuiR3c, saved to /tmp/a96f1cb6f66dc34672468085b9cb632c.
May 13 19:46:13 juno botamusique[757]: [youtube] Downloading just video XGeGhYZaTMI because of --no-playlist
May 13 19:46:13 juno botamusique[757]: [May 13 19:46:13 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=RjoSgKgnbDE
May 13 19:46:13 juno botamusique[757]: [youtube] RjoSgKgnbDE: Downloading webpage
May 13 19:46:14 juno botamusique[757]: [youtube] Downloading just video RjoSgKgnbDE because of --no-playlist
May 13 19:46:14 juno botamusique[757]: [May 13 19:46:14 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=IuTLkt2wlUk
May 13 19:46:14 juno botamusique[757]: [youtube] IuTLkt2wlUk: Downloading webpage
May 13 19:46:14 juno botamusique[757]: [youtube] Downloading just video IuTLkt2wlUk because of --no-playlist
May 13 19:46:14 juno botamusique[757]: [May 13 19:46:14 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=gL-g5ca6X_E
May 13 19:46:14 juno botamusique[757]: [youtube] gL-g5ca6X_E: Downloading webpage
May 13 19:46:15 juno botamusique[757]: [youtube] Downloading just video gL-g5ca6X_E because of --no-playlist
May 13 19:46:15 juno botamusique[757]: [May 13 19:46:15 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=QpRsFk2fpm8
May 13 19:46:15 juno botamusique[757]: [youtube] QpRsFk2fpm8: Downloading webpage
May 13 19:46:15 juno botamusique[757]: [youtube] Downloading just video QpRsFk2fpm8 because of --no-playlist
May 13 19:46:15 juno botamusique[757]: [May 13 19:46:15 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=ktmUs5-eruM
May 13 19:46:15 juno botamusique[757]: [youtube] ktmUs5-eruM: Downloading webpage
May 13 19:46:16 juno botamusique[757]: [youtube] Downloading just video ktmUs5-eruM because of --no-playlist
May 13 19:46:16 juno botamusique[757]: [May 13 19:46:16 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=9KuQRJt_Y7o
May 13 19:46:16 juno botamusique[757]: [youtube] 9KuQRJt_Y7o: Downloading webpage
May 13 19:46:17 juno botamusique[757]: [youtube] Downloading just video 9KuQRJt_Y7o because of --no-playlist
May 13 19:46:17 juno botamusique[757]: [May 13 19:46:17 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=wE1vS3radK8
May 13 19:46:17 juno botamusique[757]: [youtube] wE1vS3radK8: Downloading webpage
May 13 19:46:17 juno botamusique[757]: [youtube] Downloading just video wE1vS3radK8 because of --no-playlist
May 13 19:46:17 juno botamusique[757]: [May 13 19:46:17 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=CzCf89z1t0U
May 13 19:46:17 juno botamusique[757]: [youtube] CzCf89z1t0U: Downloading webpage
May 13 19:46:18 juno botamusique[757]: [youtube] Downloading just video CzCf89z1t0U because of --no-playlist
May 13 19:46:19 juno botamusique[757]: [May 13 19:46:19 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=Ak0zy49qsHE
May 13 19:46:19 juno botamusique[757]: [youtube] Ak0zy49qsHE: Downloading webpage
May 13 19:46:19 juno botamusique[757]: [youtube] Downloading just video Ak0zy49qsHE because of --no-playlist
May 13 19:46:19 juno botamusique[757]: [May 13 19:46:19 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=eLtQ_KygbuM
May 13 19:46:19 juno botamusique[757]: [youtube] eLtQ_KygbuM: Downloading webpage
May 13 19:46:20 juno botamusique[757]: [youtube] Downloading just video eLtQ_KygbuM because of --no-playlist
May 13 19:46:20 juno botamusique[757]: [May 13 19:46:20 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=qVlsuaQUSIU
May 13 19:46:20 juno botamusique[757]: [youtube] qVlsuaQUSIU: Downloading webpage
May 13 19:46:21 juno botamusique[757]: [youtube] Downloading just video qVlsuaQUSIU because of --no-playlist
May 13 19:46:21 juno botamusique[757]: [May 13 19:46:21 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=LqUi2L7641I
May 13 19:46:21 juno botamusique[757]: [youtube] LqUi2L7641I: Downloading webpage
May 13 19:46:22 juno botamusique[757]: [youtube] Downloading just video LqUi2L7641I because of --no-playlist
May 13 19:46:22 juno botamusique[757]: [May 13 19:46:22 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=WlkeUFKE8iM
May 13 19:46:22 juno botamusique[757]: [youtube] WlkeUFKE8iM: Downloading webpage
May 13 19:46:22 juno botamusique[757]: [youtube] Downloading just video WlkeUFKE8iM because of --no-playlist
May 13 19:46:22 juno botamusique[757]: [May 13 19:46:22 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=iC5JjKZLSOs
May 13 19:46:22 juno botamusique[757]: [youtube] iC5JjKZLSOs: Downloading webpage
May 13 19:46:23 juno botamusique[757]: [youtube] Downloading just video iC5JjKZLSOs because of --no-playlist
May 13 19:46:23 juno botamusique[757]: [May 13 19:46:23 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=7WCUPbHunNo
May 13 19:46:23 juno botamusique[757]: [youtube] 7WCUPbHunNo: Downloading webpage
May 13 19:46:23 juno botamusique[757]: [youtube] Downloading just video 7WCUPbHunNo because of --no-playlist
May 13 19:46:23 juno botamusique[757]: [May 13 19:46:23 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=ZxMdImpj4mk
May 13 19:46:23 juno botamusique[757]: [youtube] ZxMdImpj4mk: Downloading webpage
May 13 19:46:24 juno botamusique[757]: [youtube] Downloading just video ZxMdImpj4mk because of --no-playlist
May 13 19:46:24 juno botamusique[757]: [May 13 19:46:24 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=j1pf6s8MGrs
May 13 19:46:24 juno botamusique[757]: [youtube] j1pf6s8MGrs: Downloading webpage
May 13 19:46:25 juno botamusique[757]: [youtube] Downloading just video j1pf6s8MGrs because of --no-playlist
May 13 19:46:25 juno botamusique[757]: [May 13 19:46:25 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=x2J5Oifxp7w
May 13 19:46:25 juno botamusique[757]: [youtube] x2J5Oifxp7w: Downloading webpage
May 13 19:46:25 juno botamusique[757]: [youtube] Downloading just video x2J5Oifxp7w because of --no-playlist
May 13 19:46:25 juno botamusique[757]: [May 13 19:46:25 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=1T5_82U3JVo
May 13 19:46:25 juno botamusique[757]: [youtube] 1T5_82U3JVo: Downloading webpage
May 13 19:46:26 juno botamusique[757]: [youtube] Downloading just video 1T5_82U3JVo because of --no-playlist
May 13 19:46:26 juno botamusique[757]: [May 13 19:46:26 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=-C2wCcuKmLI
May 13 19:46:26 juno botamusique[757]: [youtube] -C2wCcuKmLI: Downloading webpage
May 13 19:46:26 juno botamusique[757]: [youtube] Downloading just video -C2wCcuKmLI because of --no-playlist
May 13 19:46:26 juno botamusique[757]: [May 13 19:46:26 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=LqcXAPejbj0
May 13 19:46:26 juno botamusique[757]: [youtube] LqcXAPejbj0: Downloading webpage
May 13 19:46:27 juno botamusique[757]: [youtube] Downloading just video LqcXAPejbj0 because of --no-playlist
May 13 19:46:27 juno botamusique[757]: [May 13 19:46:27 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=w42CTq5QZtI
May 13 19:46:27 juno botamusique[757]: [youtube] w42CTq5QZtI: Downloading webpage
May 13 19:46:27 juno botamusique[757]: [youtube] Downloading just video w42CTq5QZtI because of --no-playlist
May 13 19:46:27 juno botamusique[757]: [May 13 19:46:27 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=RaEzKRngCyY
May 13 19:46:28 juno botamusique[757]: [youtube] RaEzKRngCyY: Downloading webpage
May 13 19:46:28 juno botamusique[757]: [youtube] Downloading just video RaEzKRngCyY because of --no-playlist
May 13 19:46:28 juno botamusique[757]: [May 13 19:46:28 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=Qemb3iBlp1o
May 13 19:46:28 juno botamusique[757]: [youtube] Qemb3iBlp1o: Downloading webpage
May 13 19:46:29 juno botamusique[757]: [youtube] Downloading just video Qemb3iBlp1o because of --no-playlist
May 13 19:46:29 juno botamusique[757]: [May 13 19:46:29 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=_bglf5NuXWI
May 13 19:46:29 juno botamusique[757]: [youtube] _bglf5NuXWI: Downloading webpage
May 13 19:46:29 juno botamusique[757]: [youtube] Downloading just video _bglf5NuXWI because of --no-playlist
May 13 19:46:29 juno botamusique[757]: [May 13 19:46:29 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=hGFR50v7d-k
May 13 19:46:29 juno botamusique[757]: [youtube] hGFR50v7d-k: Downloading webpage
May 13 19:46:30 juno botamusique[757]: [youtube] Downloading just video hGFR50v7d-k because of --no-playlist
May 13 19:46:30 juno botamusique[757]: [May 13 19:46:30 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=R-M3k7TqfDA
May 13 19:46:30 juno botamusique[757]: [youtube] R-M3k7TqfDA: Downloading webpage
May 13 19:46:30 juno botamusique[757]: [youtube] Downloading just video R-M3k7TqfDA because of --no-playlist
May 13 19:46:30 juno botamusique[757]: [May 13 19:46:30 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=N_XCBsOJHLU
May 13 19:46:30 juno botamusique[757]: [youtube] N_XCBsOJHLU: Downloading webpage
May 13 19:46:30 juno botamusique[757]: [youtube] Downloading just video N_XCBsOJHLU because of --no-playlist
May 13 19:46:30 juno botamusique[757]: ERROR: No video formats found; please report this issue on https://yt-dl.org/bug . Make sure you are using the latest version; see  https://yt-dl.org/update  on how to update. Be sure to call youtube-dl with the --verbose flag and include its complete output.
May 13 19:46:31 juno botamusique[757]: [youtube] N_XCBsOJHLU: Downloading webpage
May 13 19:46:31 juno botamusique[757]: [youtube] Downloading just video N_XCBsOJHLU because of --no-playlist
May 13 19:46:31 juno botamusique[757]: ERROR: No video formats found; please report this issue on https://yt-dl.org/bug . Make sure you are using the latest version; see  https://yt-dl.org/update  on how to update. Be sure to call youtube-dl with the --verbose flag and include its complete output.
May 13 19:46:31 juno botamusique[757]: [May 13 19:46:31 ERROR] url: error while fetching info from the URL
May 13 19:46:31 juno botamusique[757]: [May 13 19:46:31 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=Pf-cg9W5fQY
May 13 19:46:31 juno botamusique[757]: [youtube] Pf-cg9W5fQY: Downloading webpage
May 13 19:46:31 juno botamusique[757]: [youtube] Downloading just video Pf-cg9W5fQY because of --no-playlist
May 13 19:46:31 juno botamusique[757]: [May 13 19:46:31 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=KKgxn3R48Ac
May 13 19:46:31 juno botamusique[757]: [youtube] KKgxn3R48Ac: Downloading webpage
May 13 19:46:32 juno botamusique[757]: [youtube] Downloading just video KKgxn3R48Ac because of --no-playlist
May 13 19:46:32 juno botamusique[757]: [May 13 19:46:32 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=lAttuezmWKs
May 13 19:46:32 juno botamusique[757]: [youtube] lAttuezmWKs: Downloading webpage
May 13 19:46:32 juno botamusique[757]: [youtube] Downloading just video lAttuezmWKs because of --no-playlist
May 13 19:46:33 juno botamusique[757]: [May 13 19:46:33 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=n3OWQ7987Jo
May 13 19:46:33 juno botamusique[757]: [youtube] n3OWQ7987Jo: Downloading webpage
May 13 19:46:33 juno botamusique[757]: [youtube] Downloading just video n3OWQ7987Jo because of --no-playlist
May 13 19:46:34 juno botamusique[757]: [May 13 19:46:34 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=RKkWMj8QQt8
May 13 19:46:34 juno botamusique[757]: [youtube] RKkWMj8QQt8: Downloading webpage
May 13 19:46:34 juno botamusique[757]: [youtube] Downloading just video RKkWMj8QQt8 because of --no-playlist
May 13 19:46:34 juno botamusique[757]: [May 13 19:46:34 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=gHz1i6CPGHM
May 13 19:46:34 juno botamusique[757]: [youtube] gHz1i6CPGHM: Downloading webpage
May 13 19:46:35 juno botamusique[757]: [youtube] Downloading just video gHz1i6CPGHM because of --no-playlist
May 13 19:46:35 juno botamusique[757]: [May 13 19:46:35 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=UDvoYj2eVEw
May 13 19:46:35 juno botamusique[757]: [youtube] UDvoYj2eVEw: Downloading webpage
May 13 19:46:39 juno botamusique[757]: [youtube] Downloading just video UDvoYj2eVEw because of --no-playlist
May 13 19:46:39 juno botamusique[757]: [May 13 19:46:39 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=VM1vU-jFivE
May 13 19:46:39 juno botamusique[757]: [youtube] VM1vU-jFivE: Downloading webpage
May 13 19:46:39 juno botamusique[757]: [youtube] Downloading just video VM1vU-jFivE because of --no-playlist
May 13 19:46:40 juno botamusique[757]: [May 13 19:46:40 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=DaEJU2wqvZQ
May 13 19:46:40 juno botamusique[757]: [youtube] DaEJU2wqvZQ: Downloading webpage
May 13 19:46:40 juno botamusique[757]: [youtube] Downloading just video DaEJU2wqvZQ because of --no-playlist
May 13 19:46:40 juno botamusique[757]: [May 13 19:46:40 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=yh9Izdc9GZY
May 13 19:46:40 juno botamusique[757]: [youtube] yh9Izdc9GZY: Downloading webpage
May 13 19:46:41 juno botamusique[757]: [youtube] Downloading just video yh9Izdc9GZY because of --no-playlist
May 13 19:46:41 juno botamusique[757]: [May 13 19:46:41 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=8T9dvUqWGWs
May 13 19:46:41 juno botamusique[757]: [youtube] 8T9dvUqWGWs: Downloading webpage
May 13 19:46:41 juno botamusique[757]: [youtube] Downloading just video 8T9dvUqWGWs because of --no-playlist
May 13 19:46:41 juno botamusique[757]: [May 13 19:46:41 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=ZM-XAtAeYBY
May 13 19:46:41 juno botamusique[757]: [youtube] ZM-XAtAeYBY: Downloading webpage
May 13 19:46:42 juno botamusique[757]: [youtube] Downloading just video ZM-XAtAeYBY because of --no-playlist
May 13 19:46:42 juno botamusique[757]: [May 13 19:46:42 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=0u8gmvSV3bg
May 13 19:46:42 juno botamusique[757]: [youtube] 0u8gmvSV3bg: Downloading webpage
May 13 19:46:43 juno botamusique[757]: [youtube] Downloading just video 0u8gmvSV3bg because of --no-playlist
May 13 19:46:43 juno botamusique[757]: [May 13 19:46:43 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=YRUNYoQ7YSk
May 13 19:46:43 juno botamusique[757]: [youtube] YRUNYoQ7YSk: Downloading webpage
May 13 19:46:43 juno botamusique[757]: [youtube] Downloading just video YRUNYoQ7YSk because of --no-playlist
May 13 19:46:44 juno botamusique[757]: [May 13 19:46:44 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=1Hva1SH5Eo4
May 13 19:46:44 juno botamusique[757]: [youtube] 1Hva1SH5Eo4: Downloading webpage
May 13 19:46:44 juno botamusique[757]: [youtube] Downloading just video 1Hva1SH5Eo4 because of --no-playlist
May 13 19:46:45 juno botamusique[757]: [May 13 19:46:45 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=UG4PGGdNPc0
May 13 19:46:45 juno botamusique[757]: [youtube] UG4PGGdNPc0: Downloading webpage
May 13 19:46:45 juno botamusique[757]: [youtube] Downloading just video UG4PGGdNPc0 because of --no-playlist
May 13 19:46:45 juno botamusique[757]: [May 13 19:46:45 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=B2wMju-Lhtw
May 13 19:46:46 juno botamusique[757]: [youtube] B2wMju-Lhtw: Downloading webpage
May 13 19:46:46 juno botamusique[757]: [youtube] Downloading just video B2wMju-Lhtw because of --no-playlist
May 13 19:46:46 juno botamusique[757]: [May 13 19:46:46 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=J8WOIcwv1mo
May 13 19:46:46 juno botamusique[757]: [youtube] J8WOIcwv1mo: Downloading webpage
May 13 19:46:47 juno botamusique[757]: [youtube] Downloading just video J8WOIcwv1mo because of --no-playlist
May 13 19:46:47 juno botamusique[757]: [May 13 19:46:47 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=QN3BntTh7fE
May 13 19:46:47 juno botamusique[757]: [youtube] QN3BntTh7fE: Downloading webpage
May 13 19:46:47 juno botamusique[757]: [youtube] Downloading just video QN3BntTh7fE because of --no-playlist
May 13 19:46:48 juno botamusique[757]: [May 13 19:46:48 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=YHfAIoc2XbA
May 13 19:46:48 juno botamusique[757]: [youtube] YHfAIoc2XbA: Downloading webpage
May 13 19:46:48 juno botamusique[757]: [youtube] Downloading just video YHfAIoc2XbA because of --no-playlist
May 13 19:46:48 juno botamusique[757]: [May 13 19:46:48 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=XinMmcZpBbI
May 13 19:46:48 juno botamusique[757]: [youtube] XinMmcZpBbI: Downloading webpage
May 13 19:46:49 juno botamusique[757]: [youtube] Downloading just video XinMmcZpBbI because of --no-playlist
May 13 19:46:49 juno botamusique[757]: [May 13 19:46:49 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=P0CYq-GWYYk
May 13 19:46:49 juno botamusique[757]: [youtube] P0CYq-GWYYk: Downloading webpage
May 13 19:46:50 juno botamusique[757]: [youtube] Downloading just video P0CYq-GWYYk because of --no-playlist
May 13 19:46:50 juno botamusique[757]: [May 13 19:46:50 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=FhtbrNOSk7M
May 13 19:46:50 juno botamusique[757]: [youtube] FhtbrNOSk7M: Downloading webpage
May 13 19:46:55 juno botamusique[757]: [youtube] Downloading just video FhtbrNOSk7M because of --no-playlist
May 13 19:46:55 juno botamusique[757]: [May 13 19:46:55 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=yq7gB7TsB_M
May 13 19:46:55 juno botamusique[757]: [youtube] yq7gB7TsB_M: Downloading webpage
May 13 19:46:55 juno botamusique[757]: [youtube] Downloading just video yq7gB7TsB_M because of --no-playlist
May 13 19:46:55 juno botamusique[757]: [May 13 19:46:55 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=S7tJLbjPUnc
May 13 19:46:55 juno botamusique[757]: [youtube] S7tJLbjPUnc: Downloading webpage
May 13 19:46:56 juno botamusique[757]: [youtube] Downloading just video S7tJLbjPUnc because of --no-playlist
May 13 19:46:56 juno botamusique[757]: [May 13 19:46:56 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=rZ1xVKyEEeg
May 13 19:46:56 juno botamusique[757]: [youtube] rZ1xVKyEEeg: Downloading webpage
May 13 19:46:56 juno botamusique[757]: [youtube] Downloading just video rZ1xVKyEEeg because of --no-playlist
May 13 19:46:56 juno botamusique[757]: [May 13 19:46:56 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=kEOCr8FGLZA
May 13 19:46:56 juno botamusique[757]: [youtube] kEOCr8FGLZA: Downloading webpage
May 13 19:46:57 juno botamusique[757]: [youtube] Downloading just video kEOCr8FGLZA because of --no-playlist
May 13 19:46:57 juno botamusique[757]: [May 13 19:46:57 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=Ia5-JGVeDkw
May 13 19:46:57 juno botamusique[757]: [youtube] Ia5-JGVeDkw: Downloading webpage
May 13 19:46:57 juno botamusique[757]: [youtube] Downloading just video Ia5-JGVeDkw because of --no-playlist
May 13 19:46:58 juno botamusique[757]: [May 13 19:46:58 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=VVC92ZKowWc
May 13 19:46:58 juno botamusique[757]: [youtube] VVC92ZKowWc: Downloading webpage
May 13 19:46:58 juno botamusique[757]: [youtube] Downloading just video VVC92ZKowWc because of --no-playlist
May 13 19:46:59 juno botamusique[757]: [May 13 19:46:59 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=XiCt9QDi-og
May 13 19:46:59 juno botamusique[757]: [youtube] XiCt9QDi-og: Downloading webpage
May 13 19:46:59 juno botamusique[757]: [youtube] Downloading just video XiCt9QDi-og because of --no-playlist
May 13 19:46:59 juno botamusique[757]: [May 13 19:46:59 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=i8dqRMDoTqk
May 13 19:46:59 juno botamusique[757]: [youtube] i8dqRMDoTqk: Downloading webpage
May 13 19:47:00 juno botamusique[757]: [youtube] Downloading just video i8dqRMDoTqk because of --no-playlist
May 13 19:47:00 juno botamusique[757]: [May 13 19:47:00 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=WulDIz5X9v4
May 13 19:47:00 juno botamusique[757]: [youtube] WulDIz5X9v4: Downloading webpage
May 13 19:47:00 juno botamusique[757]: [youtube] Downloading just video WulDIz5X9v4 because of --no-playlist
May 13 19:47:00 juno botamusique[757]: [May 13 19:47:00 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=M25FVTaxpRE
May 13 19:47:00 juno botamusique[757]: [youtube] M25FVTaxpRE: Downloading webpage
May 13 19:47:01 juno botamusique[757]: [youtube] Downloading just video M25FVTaxpRE because of --no-playlist
May 13 19:47:01 juno botamusique[757]: [May 13 19:47:01 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=0MEwlgYLLmU
May 13 19:47:01 juno botamusique[757]: [youtube] 0MEwlgYLLmU: Downloading webpage
May 13 19:47:01 juno botamusique[757]: [youtube] Downloading just video 0MEwlgYLLmU because of --no-playlist
May 13 19:47:01 juno botamusique[757]: [May 13 19:47:01 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=OL9L3ayHYJo
May 13 19:47:01 juno botamusique[757]: [youtube] OL9L3ayHYJo: Downloading webpage
May 13 19:47:02 juno botamusique[757]: [youtube] Downloading just video OL9L3ayHYJo because of --no-playlist
May 13 19:47:02 juno botamusique[757]: [May 13 19:47:02 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=RYT9FYnFlBE
May 13 19:47:02 juno botamusique[757]: [youtube] RYT9FYnFlBE: Downloading webpage
May 13 19:47:03 juno botamusique[757]: [youtube] Downloading just video RYT9FYnFlBE because of --no-playlist
May 13 19:47:03 juno botamusique[757]: [May 13 19:47:03 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=q2E-WMXXyEY
May 13 19:47:03 juno botamusique[757]: [youtube] q2E-WMXXyEY: Downloading webpage
May 13 19:47:03 juno botamusique[757]: [youtube] Downloading just video q2E-WMXXyEY because of --no-playlist
May 13 19:47:03 juno botamusique[757]: [May 13 19:47:03 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=VeG390ltW0M
May 13 19:47:03 juno botamusique[757]: [youtube] VeG390ltW0M: Downloading webpage
May 13 19:47:04 juno botamusique[757]: [youtube] Downloading just video VeG390ltW0M because of --no-playlist
May 13 19:47:04 juno botamusique[757]: [May 13 19:47:04 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=G8oULMXVZ6o
May 13 19:47:04 juno botamusique[757]: [youtube] G8oULMXVZ6o: Downloading webpage
May 13 19:47:04 juno botamusique[757]: [youtube] Downloading just video G8oULMXVZ6o because of --no-playlist
May 13 19:47:05 juno botamusique[757]: [May 13 19:47:05 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=JGRBhOQjGUc
May 13 19:47:05 juno botamusique[757]: [youtube] JGRBhOQjGUc: Downloading webpage
May 13 19:47:05 juno botamusique[757]: [youtube] Downloading just video JGRBhOQjGUc because of --no-playlist
May 13 19:47:05 juno botamusique[757]: [May 13 19:47:05 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=mMr2PvNqbPs
May 13 19:47:05 juno botamusique[757]: [youtube] mMr2PvNqbPs: Downloading webpage
May 13 19:47:06 juno botamusique[757]: [youtube] Downloading just video mMr2PvNqbPs because of --no-playlist
May 13 19:47:06 juno botamusique[757]: [May 13 19:47:06 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=tbbSPh-K2EM
May 13 19:47:06 juno botamusique[757]: [youtube] tbbSPh-K2EM: Downloading webpage
May 13 19:47:07 juno botamusique[757]: [youtube] Downloading just video tbbSPh-K2EM because of --no-playlist
May 13 19:47:07 juno botamusique[757]: [May 13 19:47:07 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=2t-1uRlyph4
May 13 19:47:07 juno botamusique[757]: [youtube] 2t-1uRlyph4: Downloading webpage
May 13 19:47:08 juno botamusique[757]: [youtube] Downloading just video 2t-1uRlyph4 because of --no-playlist
May 13 19:47:08 juno botamusique[757]: [May 13 19:47:08 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=_7hj6qP167k
May 13 19:47:08 juno botamusique[757]: [youtube] _7hj6qP167k: Downloading webpage
May 13 19:47:09 juno botamusique[757]: [youtube] Downloading just video _7hj6qP167k because of --no-playlist
May 13 19:47:09 juno botamusique[757]: [May 13 19:47:09 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=pefoJcg6JzQ
May 13 19:47:09 juno botamusique[757]: [youtube] pefoJcg6JzQ: Downloading webpage
May 13 19:47:09 juno botamusique[757]: [youtube] Downloading just video pefoJcg6JzQ because of --no-playlist
May 13 19:47:10 juno botamusique[757]: [May 13 19:47:10 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=oSXCR1Q_e4Q
May 13 19:47:10 juno botamusique[757]: [youtube] oSXCR1Q_e4Q: Downloading webpage
May 13 19:47:10 juno botamusique[757]: [youtube] Downloading just video oSXCR1Q_e4Q because of --no-playlist
May 13 19:47:10 juno botamusique[757]: [May 13 19:47:10 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=Ts0b3jtCOho
May 13 19:47:10 juno botamusique[757]: [youtube] Ts0b3jtCOho: Downloading webpage
May 13 19:47:11 juno botamusique[757]: [youtube] Downloading just video Ts0b3jtCOho because of --no-playlist
May 13 19:47:11 juno botamusique[757]: [May 13 19:47:11 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=LNGPKSECJeg
May 13 19:47:11 juno botamusique[757]: [youtube] LNGPKSECJeg: Downloading webpage
May 13 19:47:11 juno botamusique[757]: [youtube] Downloading just video LNGPKSECJeg because of --no-playlist
May 13 19:47:12 juno botamusique[757]: [May 13 19:47:12 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=z3kG8n1zM6Y
May 13 19:47:12 juno botamusique[757]: [youtube] z3kG8n1zM6Y: Downloading webpage
May 13 19:47:12 juno botamusique[757]: [May 13 19:47:12 INFO] bot: play music [url] Two Steps From Hell - Perilous Journey (https://www.youtube.com/watch?v=uZKaZQuiR3c) from playlist Two Steps From Hell - Legend (Full Album)
May 13 19:47:12 juno botamusique[757]: [May 13 19:47:12 INFO] url: music file missed for [url] Two Steps From Hell - Voyager (https://www.youtube.com/watch?v=0ibumMsFn9c) from playlist Two Steps From Hell - Legend (Full Album)
May 13 19:47:12 juno botamusique[757]: [May 13 19:47:12 INFO] bot: start preparing item in thread: [url] Two Steps From Hell - Voyager (https://www.youtube.com/watch?v=0ibumMsFn9c) from playlist Two Steps From Hell - Legend (Full Album)
May 13 19:47:12 juno botamusique[757]: [May 13 19:47:12 INFO] bot: downloading url (Two Steps From Hell - Voyager) https://www.youtube.com/watch?v=0ibumMsFn9c
May 13 19:47:12 juno botamusique[757]: [May 13 19:47:12 INFO] bot: download attempts 1 / 2
May 13 19:47:12 juno botamusique[757]: [youtube] 0ibumMsFn9c: Downloading webpage
May 13 19:47:12 juno botamusique[757]: [youtube] Downloading just video z3kG8n1zM6Y because of --no-playlist
May 13 19:47:12 juno botamusique[757]: [May 13 19:47:12 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=zaGjg8tszjw
May 13 19:47:12 juno botamusique[757]: [youtube] zaGjg8tszjw: Downloading webpage
May 13 19:47:13 juno botamusique[757]: [youtube] Downloading just video zaGjg8tszjw because of --no-playlist
May 13 19:47:13 juno botamusique[757]: [May 13 19:47:13 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=RB9GcngJXt4
May 13 19:47:13 juno botamusique[757]: [youtube] RB9GcngJXt4: Downloading webpage
May 13 19:47:13 juno botamusique[757]: [youtube] Downloading just video RB9GcngJXt4 because of --no-playlist
May 13 19:47:14 juno botamusique[757]: [May 13 19:47:14 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=aV6_85w0pI8
May 13 19:47:14 juno botamusique[757]: [youtube] aV6_85w0pI8: Downloading webpage
May 13 19:47:14 juno botamusique[757]: [youtube] Downloading just video aV6_85w0pI8 because of --no-playlist
May 13 19:47:14 juno botamusique[757]: [May 13 19:47:14 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=ipgng_U_X1o
May 13 19:47:14 juno botamusique[757]: [youtube] ipgng_U_X1o: Downloading webpage
May 13 19:47:15 juno botamusique[757]: [youtube] Downloading just video ipgng_U_X1o because of --no-playlist
May 13 19:47:15 juno botamusique[757]: [May 13 19:47:15 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=ek8bqQV_zuo
May 13 19:47:15 juno botamusique[757]: [youtube] ek8bqQV_zuo: Downloading webpage
May 13 19:47:16 juno botamusique[757]: [youtube] Downloading just video ek8bqQV_zuo because of --no-playlist
May 13 19:47:16 juno botamusique[757]: [May 13 19:47:16 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=IcMk3d4M-sU
May 13 19:47:16 juno botamusique[757]: [youtube] IcMk3d4M-sU: Downloading webpage
May 13 19:47:16 juno botamusique[757]: [youtube] Downloading just video IcMk3d4M-sU because of --no-playlist
May 13 19:47:16 juno botamusique[757]: [May 13 19:47:16 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=LXWIUiyBWK0
May 13 19:47:16 juno botamusique[757]: [youtube] LXWIUiyBWK0: Downloading webpage
May 13 19:47:17 juno botamusique[757]: [youtube] Downloading just video LXWIUiyBWK0 because of --no-playlist
May 13 19:47:17 juno botamusique[757]: [May 13 19:47:17 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=0ymbJEJrBzo
May 13 19:47:17 juno botamusique[757]: [youtube] 0ymbJEJrBzo: Downloading webpage
May 13 19:47:17 juno botamusique[757]: [youtube] Downloading just video 0ymbJEJrBzo because of --no-playlist
May 13 19:47:17 juno botamusique[757]: [May 13 19:47:17 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=HwshWAd7dj8
May 13 19:47:17 juno botamusique[757]: [youtube] HwshWAd7dj8: Downloading webpage
May 13 19:47:18 juno botamusique[757]: [youtube] Downloading just video HwshWAd7dj8 because of --no-playlist
May 13 19:47:18 juno botamusique[757]: [May 13 19:47:18 INFO] url: fetching metadata of url https://www.youtube.com/watch?v=2RSIPxloWKA
May 13 19:47:18 juno botamusique[757]: [youtube] 2RSIPxloWKA: Downloading webpage
May 13 19:47:19 juno botamusique[757]: [youtube] Downloading just video 2RSIPxloWKA because of --no-playlist
May 13 19:47:19 juno botamusique[757]: [youtube] Downloading just video 0ibumMsFn9c because of --no-playlist
May 13 19:47:19 juno botamusique[757]: [youtube] 0ibumMsFn9c: Downloading thumbnail ...
May 13 19:47:19 juno botamusique[757]: [youtube] 0ibumMsFn9c: Writing thumbnail to: /tmp/488ddf62879bbf9cacecbc8e4c93b2a7.jpg
May 13 19:47:19 juno botamusique[757]: [download] Destination: /tmp/488ddf62879bbf9cacecbc8e4c93b2a7
May 13 19:47:19 juno botamusique[757]: [622B blob data]
May 13 19:47:19 juno botamusique[757]: [ffmpeg] Correcting container in "/tmp/488ddf62879bbf9cacecbc8e4c93b2a7"
May 13 19:47:19 juno botamusique[757]: [May 13 19:47:19 INFO] bot: finished downloading url (Two Steps From Hell - Voyager) https://www.youtube.com/watch?v=0ibumMsFn9c, saved to /tmp/488ddf62879bbf9cacecbc8e4c93b2a7.
May 13 19:47:28 juno botamusique[757]: Exception in thread Validating:
May 13 19:47:28 juno botamusique[757]: Traceback (most recent call last):
May 13 19:47:28 juno botamusique[757]:   File "/nix/store/q6gfck5czr67090pwm53xrdyhpg6bx67-python3-3.8.9/lib/python3.8/threading.py", line 932, in _bootstrap_inner
May 13 19:47:28 juno botamusique[757]:     self.run()
May 13 19:47:28 juno botamusique[757]:   File "/nix/store/q6gfck5czr67090pwm53xrdyhpg6bx67-python3-3.8.9/lib/python3.8/threading.py", line 870, in run
May 13 19:47:28 juno botamusique[757]:     self._target(*self._args, **self._kwargs)
May 13 19:47:28 juno botamusique[757]:   File "/nix/store/slcm3hnfpv03pyvvqd7rrci1imp52vvm-botamusique-unstable-2021-03-13/share/botamusique/media/playlist.py", line 227, in _check_valid
May 13 19:47:28 juno botamusique[757]:     self.log.debug("playlist: validating %s" % item.format_debug_string())
May 13 19:47:28 juno botamusique[757]:   File "/nix/store/slcm3hnfpv03pyvvqd7rrci1imp52vvm-botamusique-unstable-2021-03-13/share/botamusique/media/cache.py", line 203, in format_debug_string
May 13 19:47:28 juno botamusique[757]:     return self.item().format_debug_string()
May 13 19:47:28 juno botamusique[757]:   File "/nix/store/slcm3hnfpv03pyvvqd7rrci1imp52vvm-botamusique-unstable-2021-03-13/share/botamusique/media/cache.py", line 145, in item
May 13 19:47:28 juno botamusique[757]:     raise ValueError(f"Uncached item of id {self.id}.")
May 13 19:47:28 juno botamusique[757]: ValueError: Uncached item of id 27ede7e805514401c54335d10ec43235.
TerryGeng commented 3 years ago

I'm still confused. @azlux can you reproduce this bug?

azlux commented 3 years ago

@TerryGeng I've never saw that. Is that possible, to have an item cache type created, but the ID doesn't exist ? @mweinelt Cache is link to values in the cache database. Is that possible to have yours ? I just add the type in the debug message in case the crash occur again. https://github.com/azlux/botamusique/commit/abc8c72c7f7ab4b8ac25333f43891ac546683a0f

mweinelt commented 3 years ago

ValueError: Uncached item of id 40d56eeac2a7a5b53af4506829a2e297.

missing

ValueError: Uncached item of id 0530fd5d23f9e2948b00349d5cf35bec.

sqlite> SELECT * FROM music WHERE id = "0530fd5d23f9e2948b00349d5cf35bec";
0530fd5d23f9e2948b00349d5cf35bec|url|Face to Face|Face to Face|{"ready": "yes", "duration": 313, "url": "https://www.youtube.com/watch?v=th6Ui7ahFxc", "thumbnail": ""}||/tmp/0530fd5d23f9e2948b00349d5cf35bec|2021-05-05 11:33:09

ValueError: Uncached item of id 27ede7e805514401c54335d10ec43235.

missing

TerryGeng commented 3 years ago

Can you enable verbose mode by adding -v to the CLI when starting the bot? I can't see debug information from the log you have posted.

TerryGeng commented 3 years ago

to have an item cache type created, but the ID doesn't exist ?

It's not possible according to the design, since adding an item to the playlist will automatically cache it, and freeing it will automatically remove it from the playlist.

I can't rule out the possibility that one item was accidentally freed in another thread. With the verbose mode, I will be able to see when an item is freed from cache, and that would be crucial for me to identify the cause.

mweinelt commented 3 years ago

New log, with -v, the type is url.

May 16 04:02:16 juno systemd[1]: Started botamusique.service.
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,582] > [MainThread] > [cache.py:109] library: rebuild directory cache
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,594] > [MainThread] > [.mumbleBot.py-wrapped:40] bot: botamusique version unknown, starting...
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,683] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: shortlist
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,684] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: sl
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,685] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: addtag
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,685] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: password
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,686] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: clear
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,684] > [UpdateThread] > [util.py:110] update: checking for updates...
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,686] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: np
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,689] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: now
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,689] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: delete
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,689] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: duck
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,690] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: duckthres
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,690] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: duckv
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,690] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: findtagged
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,690] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: ft
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,691] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: help
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,691] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: joinme
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,692] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: last
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,692] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: listfile
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,693] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: mode
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,693] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: pause
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,693] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: p
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,693] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: play
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,693] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: file
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,693] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: f
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,694] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: filematch
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,695] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: fm
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,695] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: playlist
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,695] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: radio
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,695] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: tag
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,695] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: url
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,696] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: queue
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,696] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: random
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,697] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: rbplay
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,698] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: rbquery
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,698] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: rm
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,698] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: untag
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,698] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: repeat
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,698] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: web
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,698] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: rescan
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,699] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: search
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,699] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: skip
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,700] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: stop
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,700] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: oust
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,700] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: version
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,700] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: volume
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,701] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: yplay
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,701] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: ysearch
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,702] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: webuseradd
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,702] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: dropdatabase
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,702] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: kill
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,702] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: webuserlist
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,703] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: webuserdel
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,703] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: update
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,703] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: urlban
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,703] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: urlbanlist
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,704] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: urlunban
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,704] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: urlunwhitelist
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,704] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: urlunw
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,704] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: urlwhitelist
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,705] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: urlw
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,705] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: urlwhitelistlist
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,705] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: urlwls
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,706] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: userban
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,706] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: userunban
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,706] > [MainThread] > [.mumbleBot.py-wrapped:229] bot: command added: rtrms
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,708] > [MainThread] > [.mumbleBot.py-wrapped:883] bot: load playlist from previous session
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,711] > [MainThread] > [.mumbleBot.py-wrapped:895] Starting web interface on localhost:8181
May 16 04:02:18 juno botamusique[8720]:  * Serving Flask app "interface" (lazy loading)
May 16 04:02:18 juno botamusique[8720]:  * Environment: development
May 16 04:02:18 juno botamusique[8720]:  * Debug mode: off
May 16 04:02:18 juno botamusique[8720]:  * Running on http://localhost:8181/ (Press CTRL+C to quit)
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,813] > [Validating] > [playlist.py:223] playlist: start validating...
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,824] > [MainThread] > [cache.py:100] library: cache freed for item: [url] Two Steps From Hell - Freedom Fighters (Invincible) (https://www.youtube.com/watch?v=YP1QHVNHMAE)
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,835] > [MainThread] > [.mumbleBot.py-wrapped:536] bot: next into the song: [url] Man In The Iron Mask - Heart of a King (https://www.youtube.com/watch?v=RBfvCN47XyQ)
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,835] > [MainThread] > [url.py:70] url: music file missed for [url] Man In The Iron Mask - Heart of a King (https://www.youtube.com/watch?v=RBfvCN47XyQ)
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,835] > [MainThread] > [.mumbleBot.py-wrapped:435] bot: current music isn't ready, start downloading.
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,835] > [MainThread] > [.mumbleBot.py-wrapped:428] bot: start preparing item in thread: [url] Man In The Iron Mask - Heart of a King (https://www.youtube.com/watch?v=RBfvCN47XyQ)
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,834] > [Validating] > [playlist.py:227] playlist: validating [url] Star Wars and The Attack of the Clones Soundtrack-11 The Tusken Camp-The Homestead (https://www.youtube.com/watch?v=WulDIz5X9v4)
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,836] > [Validating] > [playlist.py:227] playlist: validating [url] Riven Soundtrack - 20 Bonus Track (https://www.youtube.com/watch?v=iDu2ohV9McE)
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,836] > [Validating] > [playlist.py:227] playlist: validating [url] Two Steps From Hell - Archangel (Voice)(Choir) (Archangel) (https://www.youtube.com/watch?v=mLUguXpUIb0)
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,837] > [Validating] > [playlist.py:227] playlist: validating [url] Man In The Iron Mask - Heart of a King (https://www.youtube.com/watch?v=RBfvCN47XyQ)
May 16 04:02:18 juno botamusique[8720]: Exception in thread Validating:
May 16 04:02:18 juno botamusique[8720]: Traceback (most recent call last):
May 16 04:02:18 juno botamusique[8720]:   File "/nix/store/q6gfck5czr67090pwm53xrdyhpg6bx67-python3-3.8.9/lib/python3.8/threading.py", line 932, in _bootstrap_inner
May 16 04:02:18 juno botamusique[8720]:     self.run()
May 16 04:02:18 juno botamusique[8720]:   File "/nix/store/q6gfck5czr67090pwm53xrdyhpg6bx67-python3-3.8.9/lib/python3.8/threading.py", line 870, in run
May 16 04:02:18 juno botamusique[8720]:     self._target(*self._args, **self._kwargs)
May 16 04:02:18 juno botamusique[8720]:   File "/nix/store/rm38jl4kq8g5jhryc6y6ynzh779xm5yd-botamusique-unstable-2021-05-16/share/botamusique/media/playlist.py", line 227, in _check_valid
May 16 04:02:18 juno botamusique[8720]:     self.log.debug("playlist: validating %s" % item.format_debug_string())
May 16 04:02:18 juno botamusique[8720]:   File "/nix/store/rm38jl4kq8g5jhryc6y6ynzh779xm5yd-botamusique-unstable-2021-05-16/share/botamusique/media/cache.py", line 203, in format_debug_string
May 16 04:02:18 juno botamusique[8720]:     return self.item().format_debug_string()
May 16 04:02:18 juno botamusique[8720]:   File "/nix/store/rm38jl4kq8g5jhryc6y6ynzh779xm5yd-botamusique-unstable-2021-05-16/share/botamusique/media/cache.py", line 145, in item
May 16 04:02:18 juno botamusique[8720]:     raise ValueError(f"Uncached item of id {self.id}, type {self.type}.")
May 16 04:02:18 juno botamusique[8720]: ValueError: Uncached item of id c27745bad6653ac8d900cbd8aefaa511, type url.
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,840] > [Validating] > [playlist.py:223] playlist: start validating...
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,841] > [Prepare-985842b] > [url.py:163] bot: downloading url (Man In The Iron Mask - Heart of a King) https://www.youtube.com/watch?v=RBfvCN47XyQ
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,857] > [Prepare-985842b] > [url.py:185] bot: download attempts 1 / 2
May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,932] > [UpdateThread] > [util.py:114] update: new version 7.2 found, current installed version unknown.
sqlite> SELECT * FROM music WHERE id = 'c27745bad6653ac8d900cbd8aefaa511';
c27745bad6653ac8d900cbd8aefaa511|url|Two Steps From Hell - Freedom Fighters (Invincible)|Two Steps From Hell - Freedom Fighters (Invincible)|{"ready": "yes", "duration": 149, "url": "https://www.youtube.com/watch?v=YP1QHVNHMAE", "thumbnail": "/9j/4AAQSkZJRgABAQAAAQABAAD/2wBDAAgGBgcGBQgHBwcJCQgKDBQNDAsLDBkSEw8UHRofHh0aHBwgJC4nICIsIxwcKDcpLDAxNDQ0Hyc5PTgyPC4zNDL/2wBDAQkJCQwLDBgNDRgyIRwhMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjL/wAARCAA4AGQDASIAAhEBAxEB/8QAHwAAAQUBAQEBAQEAAAAAAAAAAAECAwQFBgcICQoL/8QAtRAAAgEDAwIEAwUFBAQAAAF9AQIDAAQRBRIhMUEGE1FhByJxFDKBkaEII0KxwRVS0fAkM2JyggkKFhcYGRolJicoKSo0NTY3ODk6Q0RFRkdISUpTVFVWV1hZWmNkZWZnaGlqc3R1dnd4eXqDhIWGh4iJipKTlJWWl5iZmqKjpKWmp6ipqrKztLW2t7i5usLDxMXGx8jJytLT1NXW19jZ2uHi4+Tl5ufo6erx8vP09fb3+Pn6/8QAHwEAAwEBAQEBAQEBAQAAAAAAAAECAwQFBgcICQoL/8QAtREAAgECBAQDBAcFBAQAAQJ3AAECAxEEBSExBhJBUQdhcRMiMoEIFEKRobHBCSMzUvAVYnLRChYkNOEl8RcYGRomJygpKjU2Nzg5OkNERUZHSElKU1RVVldYWVpjZGVmZ2hpanN0dXZ3eHl6goOEhYaHiImKkpOUlZaXmJmaoqOkpaanqKmqsrO0tba3uLm6wsPExcbHyMnK0tPU1dbX2Nna4uPk5ebn6Onq8vP09fb3+Pn6/9oADAMBAAIRAxEAPwD5/rovCqSSNeLGxXKKDj61zta+hXUsDzxw/elAGR7HNTNXiXB2kjVuQbeZYxyin5gD1P1qSLUQ0yFlConzN74Gf6Vmz3U07kOc88cYotVkFxG2eA65/OsuXTU05tdC7Z6p5Nz55tUcY48wnr61WnitooDKsZMrMSWY5NVbu92zMyfeJz9KrG+mlCxnaB0GF6dqpR6ic+hf0q8VNQhEsayQlxvRxkEd69hutF0vRV+26Iv2WC9hTzoA5MZPqAfunNeHpNJETMDhlxjI69R+NdJN8QdUv2tk1BImhgG1RAnl4HA6dD07/nU1IN7BCaW5r/EFg+n6XMyskscskR3fxKQrfof51xqIJQo3HB/Suh8a3K6hpGjXcLO0A82NS3pkEfnXGh2Xoxqqa91Cm/eZsM9jHEVVnaTaRuYcE1gVZBUgliScVWq0rESdwoooqiQq7p0ohMrd9uBVKpYGwxpPVDTsy7E5ds849qntuL2Mbs4y35AmqfmqjEgHNS2LZuyxPSNyPyqWikywozLtYbs+tS39p5MNq6Ig3ksAo+bgd/8APamLkSo2OhBq3qjuXt0MPmBY2MZB6A9c4qb6ouyszFIkMBDh8bQy5z0z29sk16N4U0DTbnQ47qfS4rifcxLjoAOnX/A15zB/GrRs6Y+bacECvTfAuovB4edI5ihEp6gHt0+lKs2o6BSSvqZ/jOzMPhwJ5e2OG8Ugg5GWV849s154WJGO1exePkH/AAhbIUww2Pz7Nz/6FXjwwKKLvEVVe8IFJGcVBVwMNpHtVOtjMKKKKBBVm1KgSbiAMDn8arVbsLU3UpTdtAGSfak9hrcfDbSXk+yFc5PU9B9a6STwzHpulm7luA1wRjaDgAH2qCEW0CLHEZAFIO5cdfepPM80uftG/wBpOorGUm9jaMUtyhbL5s0YI4qPWJSZkQkhQoBIFXLCKWO//eQSSQHO144ywB9Onc8VSv7e5uNkkcEzqeRiMnj8qpLUlv3TMUgZIYhu1d74IZBbS5O7ad+Mcg1wwsrs8i1nwDgnyzwRnPb2P5Gus8OXj6Na3cssMxcD5IxGSXbj5Txx2J+o9aKqvGyCk7S1N7x1q9vceXp/IQIGcH1POD+QrztrMSFvIYZAztJ6/SrN3PNe3ktxeSM0jtufjGPYDtT/AC0WASIsaj0PJ/OlFcisOT5mY/TIqGtCcxylmI2t7Vn1qmZNBRRRTEFWLWYxM2CRkYOKKKANSC632ly+SDEisuPdgP61LKsa2rXMbFtoQOhOCrHn8QR0PsaKKxej+f8AkdsEnHXs/wBf8iTKre2sCSyiK4kVkKyEHyz06d85/I1Xsk+1QIn2idX8wgR+YQHQAZAPqAfxAooqbtR/rzNFTi5pNbv/AOR/zIlkeGzhlM105uQ5bZKQAQSMe55yc9jU8G+S4sw1xcfv4Xlc+cfvDd/8QKKKqTdvv/UiEIuaVv5fxsJLGgmudxd9tssysWznO38xyfQ8Co7eJZLWRpdyssqoFJIzlSccA88Ciikm7FOnFT27/qZZJPXrUNFFbnAwooooEf/Z", "playlist_url": "https://www.youtube.com/playlist?list=PL3ow_X7fvuqLejbiRXqRMt-5d9sHK5Vyc", "playlist_title": "Best of Two Steps From Hell"}||/tmp/c27745bad6653ac8d900cbd8aefaa511|2021-05-08 23:49:39
TerryGeng commented 3 years ago

You see the problematic line

May 16 04:02:18 juno botamusique[8720]: [2021-05-16 04:02:18,824] > [MainThread] > [cache.py:100] library: cache freed for item: [url] Two Steps From Hell - Freedom Fighters (Invincible) (https://www.youtube.com/watch?v=YP1QHVNHMAE)

That's the cause of the problem.

Can you throw an exception at https://github.com/azlux/botamusique/blob/f9cc9c78722db8b16375ff34ed097cb70025bb47/media/cache.py#L98-L101

so I can check the traceback to see who invoked the free method?

mweinelt commented 3 years ago
May 16 04:43:05 juno botamusique[9650]: [2021-05-16 04:43:05,470] > [Prepare-a0ef9a7] > [url.py:198] bot: finished downloading url (Dr. Ford (Westworld Soundtrack)) https://www.youtube.com/watch?v=4A9H4uiaFsA, saved to /tmp/a0ef9a7c1d1ba191bc0f79e20c0a5b7e.
May 16 04:43:05 juno botamusique[9650]: [2021-05-16 04:43:05,470] > [Prepare-a0ef9a7] > [cache.py:81] library: music save into database: [url] Dr. Ford (Westworld Soundtrack) (https://www.youtube.com/watch?v=4A9H4uiaFsA)
May 16 04:45:58 juno botamusique[9650]: [2021-05-16 04:45:58,411] > [MainThread] > [cache.py:100] library: cache freed for item: [url] Astronomia (Medieval Style) [Tavern Version] (https://www.youtube.com/watch?v=R16cVvg2OyY)
May 16 04:45:58 juno botamusique[9650]: Traceback (most recent call last):
May 16 04:45:58 juno botamusique[9650]:   File "/nix/store/2d4a5ms3sqqf2g72g4n09mz2qzn9im4q-botamusique-unstable-2021-05-16/share/botamusique/.mumbleBot.py-wrapped", line 899, in <module>
May 16 04:45:58 juno botamusique[9650]:     var.bot.loop()
May 16 04:45:58 juno botamusique[9650]:   File "/nix/store/2d4a5ms3sqqf2g72g4n09mz2qzn9im4q-botamusique-unstable-2021-05-16/share/botamusique/.mumbleBot.py-wrapped", line 534, in loop
May 16 04:45:58 juno botamusique[9650]:     if var.playlist.next():
May 16 04:45:58 juno botamusique[9650]:   File "/nix/store/2d4a5ms3sqqf2g72g4n09mz2qzn9im4q-botamusique-unstable-2021-05-16/share/botamusique/media/playlist.py", line 379, in next
May 16 04:45:58 juno botamusique[9650]:     return super().next()
May 16 04:45:58 juno botamusique[9650]:   File "/nix/store/2d4a5ms3sqqf2g72g4n09mz2qzn9im4q-botamusique-unstable-2021-05-16/share/botamusique/media/playlist.py", line 273, in next
May 16 04:45:58 juno botamusique[9650]:     super().__delitem__(self.current_index)
May 16 04:45:58 juno botamusique[9650]:   File "/nix/store/2d4a5ms3sqqf2g72g4n09mz2qzn9im4q-botamusique-unstable-2021-05-16/share/botamusique/media/playlist.py", line 112, in __delitem__
May 16 04:45:58 juno botamusique[9650]:     return self.remove(key)
May 16 04:45:58 juno botamusique[9650]:   File "/nix/store/2d4a5ms3sqqf2g72g4n09mz2qzn9im4q-botamusique-unstable-2021-05-16/share/botamusique/media/playlist.py", line 132, in remove
May 16 04:45:58 juno botamusique[9650]:     var.cache.free(removed.id)
May 16 04:45:58 juno botamusique[9650]:   File "/nix/store/2d4a5ms3sqqf2g72g4n09mz2qzn9im4q-botamusique-unstable-2021-05-16/share/botamusique/media/cache.py", line 102, in free
May 16 04:45:58 juno botamusique[9650]:     raise
May 16 04:45:58 juno botamusique[9650]: RuntimeError: No active exception to reraise
TerryGeng commented 3 years ago

Looks like a race condition occurred. I will add a mutex later. Thanks for the log.

mweinelt commented 3 years ago

The playlist was just about to end, when the mode was switched to autoplay.

[16:54:45] To musique.lossy.network: !mode
[16:54:45] (Private) musique.lossy.network: Current playback mode is repeat.
[16:54:49] To musique.lossy.network: !mode autoplay
[16:54:49] (Private) musique.lossy.network: Playback mode set to autoplay by deraffe.
[16:54:53] musique.lossy.network left channel and disconnected.
May 16 16:54:45 juno botamusique[11251]: [2021-05-16 16:54:45,995] > [Thread-259] > [.mumbleBot.py-wrapped:248] raw: !mode
May 16 16:54:45 juno botamusique[11251]: [2021-05-16 16:54:45,997] > [Thread-259] > [.mumbleBot.py-wrapped:266] bot: received command "mode" with arguments "None" from deraffe
May 16 16:54:49 juno botamusique[11251]: [2021-05-16 16:54:49,046] > [Thread-260] > [.mumbleBot.py-wrapped:248] raw: !mode autoplay
May 16 16:54:49 juno botamusique[11251]: [2021-05-16 16:54:49,047] > [Thread-260] > [.mumbleBot.py-wrapped:266] bot: received command "mode" with arguments "autoplay" from deraffe
May 16 16:54:49 juno botamusique[11251]: [2021-05-16 16:54:49,210] > [Validating] > [playlist.py:223] playlist: start validating...
May 16 16:54:49 juno botamusique[11251]: [2021-05-16 16:54:49,212] > [Thread-260] > [command.py:893] command: playback mode changed to autoplay.
May 16 16:54:49 juno botamusique[11251]: [2021-05-16 16:54:49,213] > [Validating] > [playlist.py:227] playlist: validating [url] Alugalug Cat X The Kiffness (Soulful Singing Cat Live Looping Remix) (https://www.youtube.com/watch?v=kG2JvYSqGR4)
May 16 16:54:49 juno botamusique[11251]: [2021-05-16 16:54:49,215] > [Validating] > [playlist.py:243] playlist: validating finished.
May 16 16:54:53 juno botamusique[11251]: [2021-05-16 16:54:53,785] > [MainThread] > [cache.py:100] library: cache freed for item: [url] Alugalug Cat X The Kiffness (Soulful Singing Cat Live Looping Remix) (https://www.youtube.com/watch?v=kG2JvYSqGR4)
May 16 16:54:53 juno botamusique[11251]: Traceback (most recent call last):
May 16 16:54:53 juno botamusique[11251]:   File "/nix/store/fpwmyadlcnqmgfs90xqrcjv06pbl7ri5-botamusique-unstable-2021-05-16/share/botamusique/.mumbleBot.py-wrapped", line 901, in <module>
May 16 16:54:53 juno botamusique[11251]:     var.bot.loop()
May 16 16:54:53 juno botamusique[11251]:   File "/nix/store/fpwmyadlcnqmgfs90xqrcjv06pbl7ri5-botamusique-unstable-2021-05-16/share/botamusique/.mumbleBot.py-wrapped", line 536, in loop
May 16 16:54:53 juno botamusique[11251]:     if var.playlist.next():
May 16 16:54:53 juno botamusique[11251]:   File "/nix/store/fpwmyadlcnqmgfs90xqrcjv06pbl7ri5-botamusique-unstable-2021-05-16/share/botamusique/media/playlist.py", line 379, in next
May 16 16:54:53 juno botamusique[11251]:     return super().next()
May 16 16:54:53 juno botamusique[11251]:   File "/nix/store/fpwmyadlcnqmgfs90xqrcjv06pbl7ri5-botamusique-unstable-2021-05-16/share/botamusique/media/playlist.py", line 273, in next
May 16 16:54:53 juno botamusique[11251]:     super().__delitem__(self.current_index)
May 16 16:54:53 juno botamusique[11251]:   File "/nix/store/fpwmyadlcnqmgfs90xqrcjv06pbl7ri5-botamusique-unstable-2021-05-16/share/botamusique/media/playlist.py", line 112, in __delitem__
May 16 16:54:53 juno botamusique[11251]:     return self.remove(key)
May 16 16:54:53 juno botamusique[11251]:   File "/nix/store/fpwmyadlcnqmgfs90xqrcjv06pbl7ri5-botamusique-unstable-2021-05-16/share/botamusique/media/playlist.py", line 132, in remove
May 16 16:54:53 juno botamusique[11251]:     var.cache.free(removed.id)
May 16 16:54:53 juno botamusique[11251]:   File "/nix/store/fpwmyadlcnqmgfs90xqrcjv06pbl7ri5-botamusique-unstable-2021-05-16/share/botamusique/media/cache.py", line 102, in free
May 16 16:54:53 juno botamusique[11251]:     raise
May 16 16:54:53 juno botamusique[11251]: RuntimeError: No active exception to reraise
May 16 16:54:54 juno systemd[1]: botamusique.service: Main process exited, code=exited, status=1/FAILURE

So yeah, probably racy. Also probably related to autoplay.

TerryGeng commented 3 years ago

Just out of curiosity, what platform are you running the bot from?

This bug never happens before. I feel there must be something special presented on your platform.

mweinelt commented 3 years ago

NixOS 20.09 (Linux 5.4.114, x86_64), nothing special really. Python 3.8.8

TerryGeng commented 3 years ago

If the whole thing really bothers you, a quick workaround would be changing the 0.1 in https://github.com/azlux/botamusique/blob/f9cc9c78722db8b16375ff34ed097cb70025bb47/media/playlist.py#L215-L220

to 0.5 or even 1.

From my experience 0.1 should be fine. But apparently, the validating thread started too fast. I'm wondering what slows your main thread.

Edit: Nevermind. The bug might be caused by something else.