search

gmdfalk / blockify

mute spotify adverts on linux
MIT License
354 stars 42 forks source link

blockify doesn't stop ads any longer #52

Closed Dan-cer closed 9 years ago

Dan-cer commented 9 years ago

Since few weeks blockify doesn't block ads any longer. Is this because of some changes in spotify?

gmdfalk commented 9 years ago

Blockify works fine with Spotify 0.9.4.183 here on Archlinux.

If you are running the new beta version of Spotify (>= 1.0.0) then yes, that would render blockify useless atm.

You'll need to provide more information if you want more than a guess.

Dan-cer commented 9 years ago

I found an older version - 0.9.17.8 - , deinstalled the newer one and installed the older, but without positive effect. I'm running ubuntu 15.04 64bit and blockify version 1.8.8. any other information necessary?

gmdfalk commented 9 years ago

Blockify should work with that version. Do a reboot, if you haven't since the downgrade.

If that doesn't help, you'll need to provide logs and information about your system and configuration as per the instructions in the troubleshooting section of the README.md.

Dan-cer commented 9 years ago

Rebooting didn't help. And I got trouble with logging: <<<rainer@rainer-pc:~$ blockify-ui -vvv -l logfile No handlers could be found for logger "util" 2015-07-26 21:58:22 ERROR main A blockify process is already running. Exiting.>>>

gmdfalk commented 9 years ago

And that error message didn't help you?

Dan-cer commented 9 years ago

No, I'm sorry not. I restarted system and spotify, then I opened terminal with ///blockify -ui -vvv -l logfile/// and got again the message ///No handlers could be found for logger "util"/// Same with ///blockify --version/// EDIT: I just see that the blocklist is empty. Is that normal?

gmdfalk commented 9 years ago

Do this please:

blockify -vvv -l blockify.log
blockify --version >> blockify.log
pacmd list-sink-inputs >> blockify.log
curl -F "c=blockify.log" https://ptpbw.pw
Dan-cer commented 9 years ago

with spotify started?

gmdfalk commented 9 years ago

Yes, and do a kill $(pgrep blockify) first, please, i.e. stop any blockify processes.

Dan-cer commented 9 years ago

Sorry, nothing worked. The kill-cmd didn't, and the others neither, as You might see in the following output: ///rainer@rainer-pc:~$ kill $(pgrep blockify) kill: Gebrauch: kill [-s Signalname | -n Signalnummer | -Signalname] [pid | job] ... oder kill -l [Signalname] rainer@rainer-pc:~$ kill -pgrep blockify bash: kill: pgrep: Ungültige Signalbezeichnung. rainer@rainer-pc:~$ blockify -vvv -l blockify.log No handlers could be found for logger "util"

rainer@rainer-pc:~$ blockify --version >> blockify.log No handlers could be found for logger "util"

rainer@rainer-pc:~$ pacmd list-sink-inputs >> blockify.log rainer@rainer-pc:~$ curl -F "c=blockify.log" https://ptpbw.pw curl: (6) Could not resolve host: ptpbw.pw /// Maybe the commands are a bit different in ubuntu? What does it mean: "No handlers could be found for logger "util"?

gmdfalk commented 9 years ago

It means python couldn't attach a logger to the util module but that message is not your problem. Your problem might be that you're trying to run multiple instances of blockify. Whatever you use on Ubuntu to manage processes, please use it to make sure no blockify process is running and then produce debug ouput with blockify -vvv and paste it here.

Dan-cer commented 9 years ago

rainer@rainer-pc:~$ blockify -vvv No handlers could be found for logger "util"

gmdfalk commented 9 years ago

I'm sorry mate. I don't know what the problem is and you're not giving me a lot to work with here.

For future reference, please don't use an issue tracker if you can't give detailed information about the issue you are experiencing. You'll either need to find a way to provide more information about your issue or move on. There are similar projects to blockify linked in the README, maybe try one of those.

Dan-cer commented 9 years ago

Yes, sorry for can't provide more information. Thank You for Your help and reference zu similar projects. That is great and I appreciate that!

JP-Ellis commented 9 years ago

I had the same issue, and this was fixed when I installed python2-docopt (I run Arch Linux).

The underlying issue is with

log = logging.getLogger("util")

though I am not sure exactly what it is. The reason installing docopt package fixes it is that the logger is used when it fails to find docopt:

try:
    from docopt import docopt
except ImportError:
    log.error("ImportError: Please install docopt to use the CLI.")

So as long as no errors are encountered and the logger isn't called, everything should be fine.

The error can be re-introduced if you add

log.error("I'm an error!")

straight after the log = ....

gmdfalk commented 9 years ago

@JP-Ellis Thanks, though you should point out that the problem you are fixing by installing docopt does not solve this issue. Installing docopt gets rid of a (cosmetic) error log message that no handlers could be found for 'util'. It has no effect on functionality of blockify other than adding access to the command-line interface.

Since I can't reproduce the issue i'm closing this now.

Regards

JP-Ellis commented 9 years ago

Sorry, my bad. It fixes the logging issue which will then allow for more useful error logs to be submitted by the original poster. I have the same issue and I have been investigating what might be the cause. If I fix it, I'll send a pull-request, or open another issue.

gmdfalk commented 9 years ago

Blockify does not block ads for you? What OS are you running?

JP-Ellis commented 9 years ago

I run Arch Linux, with Spotify 0.9.17.8 and Blockify 1.8.8 (both from AUR). Blockify recognizes when Spotify is paused or playing a song (the log shows "Unmuting" or "Forcing unmute" repeatedly, about 5 times per second). When an ad comes on however, the log just stops:

2015-08-16 01:19:41 INFO     main     Unmuting.
2015-08-16 01:19:41 INFO     main     Unmuting.
2015-08-16 01:19:41 INFO     main     Unmuting.
2015-08-16 01:19:42 INFO     main     Unmuting.
2015-08-16 01:19:42 INFO     main     Unmuting.
2015-08-16 01:19:42 INFO     main     Unmuting.  <-- Ad comes on
2015-08-16 01:20:44 INFO     main     Unmuting.  <-- Next song starts
2015-08-16 01:20:44 INFO     main     Unmuting.
2015-08-16 01:20:44 INFO     main     Unmuting.
2015-08-16 01:20:44 INFO     main     Unmuting.
2015-08-16 01:20:45 INFO     main     Unmuting.
2015-08-16 01:20:45 INFO     main     Unmuting.

So I'm not sure how much such a log can help... I was going to try and debug it at some point, but I'll see when I have more time next.

gmdfalk commented 9 years ago

That does help. I did experience that log spam, too. While trying to figure out where it came from it disappeared.

Try this: Stop all spotify and blockify processes, then start them again and see if you still get the same log spam. If you do, try a reboot.

I believe there might be an initialization issue somewhere between dbus, pulse and spotify sometimes.

JP-Ellis commented 9 years ago

This log was taken after a fresh boot, with neither spotify nor blockify being run beforehand. When I launch spotify, there are multiple processes launched, but this seems to be intended behaviour:

31382 ?        S      0:00 /bin/sh /usr/bin/spotify
31383 ?        Sl     0:03 /usr/share/spotify/spotify-client/spotify
31391 ?        S      0:00 /usr/share/spotify/spotify-client/spotify
31392 ?        S      0:00 /usr/share/spotify/spotify-client/Data/SpotifyHelper --type=zygote --no-sandbox --lang=en-US --locales-dir-path=/usr/share/spotify/spotify-client/Data/locales --log-severity=disable --resources-dir-path=/usr/share/spotify/spotify-client/Data
31433 ?        Sl     0:12 /usr/share/spotify/spotify-client/Data/SpotifyHelper --type=renderer --js-flags=--harmony-proxies --no-sandbox --user-agent=Mozilla/5.0 (X11; Linux) AppleWebKit/537.36 (KHTML, like Gecko) Spotify/0.9.17.8.gd06432d7 --lang=en-US --lang=en-US --locales-dir-path=/usr/share/spotify/spotify-client/Data/locales --log-severity=disable --resources-dir-path=/usr/share/spotify/spotify-client/Data --disable-accelerated-2d-canvas --disable-accelerated-video-decode --channel=31383.1.163914652
31436 ?        Sl     0:00 /usr/share/spotify/spotify-client/Data/SpotifyHelper --type=renderer --js-flags=--harmony-proxies --no-sandbox --user-agent=Mozilla/5.0 (X11; Linux) AppleWebKit/537.36 (KHTML, like Gecko) Spotify/0.9.17.8.gd06432d7 --lang=en-US --lang=en-US --locales-dir-path=/usr/share/spotify/spotify-client/Data/locales --log-severity=disable --resources-dir-path=/usr/share/spotify/spotify-client/Data --disable-accelerated-2d-canvas --disable-accelerated-video-decode --channel=31383.2.2089087295
31439 ?        Sl     0:01 /usr/share/spotify/spotify-client/Data/SpotifyHelper --type=renderer --js-flags=--harmony-proxies --no-sandbox --user-agent=Mozilla/5.0 (X11; Linux) AppleWebKit/537.36 (KHTML, like Gecko) Spotify/0.9.17.8.gd06432d7 --lang=en-US --lang=en-US --locales-dir-path=/usr/share/spotify/spotify-client/Data/locales --log-severity=disable --resources-dir-path=/usr/share/spotify/spotify-client/Data --disable-accelerated-2d-canvas --disable-accelerated-video-decode --channel=31383.3.1407441944
31444 ?        Sl     0:01 /usr/share/spotify/spotify-client/Data/SpotifyHelper --type=renderer --js-flags=--harmony-proxies --no-sandbox --user-agent=Mozilla/5.0 (X11; Linux) AppleWebKit/537.36 (KHTML, like Gecko) Spotify/0.9.17.8.gd06432d7 --lang=en-US --lang=en-US --locales-dir-path=/usr/share/spotify/spotify-client/Data/locales --log-severity=disable --resources-dir-path=/usr/share/spotify/spotify-client/Data --disable-accelerated-2d-canvas --disable-accelerated-video-decode --channel=31383.4.2014445120
31477 ?        Sl     0:00 /usr/share/spotify/spotify-client/Data/SpotifyHelper --type=gpu-process --channel=31383.5.1268262306 --no-sandbox --lang=en-US --locales-dir-path=/usr/share/spotify/spotify-client/Data/locales --log-severity=disable --resources-dir-path=/usr/share/spotify/spotify-client/Data --supports-dual-gpus=false --gpu-driver-bug-workarounds=0,6,19 --gpu-vendor-id=0x8086 --gpu-device-id=0x0a2e --gpu-driver-vendor --gpu-driver-version --lang=en-US --locales-dir-path=/usr/share/spotify/spotify-client/Data/locales --log-severity=disable --resources-dir-path=/usr/share/spotify/spotify-client/Data
31937 pts/3    S+     0:00 grep --color=auto spotify

As for blockify, there is a single process runnning:

29829 pts/2    S      0:06 /usr/bin/python2 /usr/bin/blockify -vvv
32280 pts/3    S+     0:00 grep --color=auto blockify
gmdfalk commented 9 years ago

Alright strike the reboot. It might still be a "first launch" kind of initialization issue that is resolved with restarting either spotify or blockify or both, if you'd like to try that.

JP-Ellis commented 9 years ago

So, quitting both spotify and blockify, and then re-opening them both still has the same issue. (I did make sure both where completely closed, with pgrep being empty).

Here is the log when I open both spotify and blockify (with spotify first):

2015-08-16 01:35:20 DEBUG    util     Added logging console handler.
2015-08-16 01:35:20 INFO     util     Loglevel is 10 (10=DEBUG, 20=INFO, 30=WARN).
2015-08-16 01:35:20 INFO     util     Loading configuration.
2015-08-16 01:35:20 INFO     util     Configuration file loaded from /home/josh/.config/blockify/blockify.ini.
2015-08-16 01:35:20 INFO     list     Blocklist loaded from /home/josh/.config/blockify/blocklist.txt.
** Message: pygobject_register_sinkfunc is deprecated (GstObject)
2015-08-16 01:35:20 INFO     player   InterludePlayer initialized.
2015-08-16 01:35:20 ERROR    player   Could not parse playlist source: [Errno 2] No such file or directory: '/home/josh/.config/blockify/playlist.m3u'
2015-08-16 01:35:20 DEBUG    player   Loading playlist.
2015-08-16 01:35:20 DEBUG    player   Stop: State is (<enum GST_STATE_CHANGE_SUCCESS of type GstStateChangeReturn>, <enum GST_STATE_NULL of type GstState>, <enum GST_STATE_VOID_PENDING of type GstState>).
2015-08-16 01:35:20 INFO     player   Playlist loaded (Length: 0).
2015-08-16 01:35:20 INFO     player   Playlist: []
2015-08-16 01:35:20 DEBUG    main     Mute method is pulse sink.
2015-08-16 01:35:20 INFO     main     Blockify initialized.
2015-08-16 01:35:20 INFO     main     Blockify started.
2015-08-16 01:36:08 INFO     main     Unmuting.   <-- Start playing a song (and 
2015-08-16 01:36:08 INFO     main     Unmuting.
2015-08-16 01:36:09 INFO     main     Unmuting.

This seems all good except for calling a deprecated function

After closing spotify, blockify returns:

2015-08-16 01:38:54 INFO     main     Forcing unmute.
2015-08-16 01:38:54 INFO     main     Forcing unmute.
2015-08-16 01:38:54 ERROR    dbus     Failed to get DBus property. Disabling dbus-mode. Msg: org.freedesktop.DBus.Error.NoReply: Message did not receive a reply (timeout by message bus)

and if I start spotify again, I get errors:

Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/blockify/blockify.py", line 208, in unmute_with_delay
    self.toggle_mute()
  File "/usr/lib/python2.7/site-packages/blockify/blockify.py", line 250, in toggle_mute
    self.mutemethod(mode)
  File "/usr/lib/python2.7/site-packages/blockify/blockify.py", line 327, in pulsesink_mute
    index, muted_value = self.extract_pulse_sink_status(pacmd_out)
  File "/usr/lib/python2.7/site-packages/blockify/blockify.py", line 311, in extract_pulse_sink_status
    pid = [k for k in idxd.keys() if k in self.spotify_pids][0]
IndexError: list index out of range
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/blockify/blockify.py", line 208, in unmute_with_delay
    self.toggle_mute()
  File "/usr/lib/python2.7/site-packages/blockify/blockify.py", line 250, in toggle_mute
    self.mutemethod(mode)
  File "/usr/lib/python2.7/site-packages/blockify/blockify.py", line 327, in pulsesink_mute
    index, muted_value = self.extract_pulse_sink_status(pacmd_out)
  File "/usr/lib/python2.7/site-packages/blockify/blockify.py", line 311, in extract_pulse_sink_status
    pid = [k for k in idxd.keys() if k in self.spotify_pids][0]
IndexError: list index out of range

Closing blockify and re-opening it (whilst keeping spotify open) results in this log:

2015-08-16 01:41:08 DEBUG    util     Added logging console handler.
2015-08-16 01:41:08 INFO     util     Loglevel is 10 (10=DEBUG, 20=INFO, 30=WARN).
2015-08-16 01:41:08 INFO     util     Loading configuration.
2015-08-16 01:41:08 INFO     util     Configuration file loaded from /home/josh/.config/blockify/blockify.ini.
2015-08-16 01:41:08 INFO     list     Blocklist loaded from /home/josh/.config/blockify/blocklist.txt.
** Message: pygobject_register_sinkfunc is deprecated (GstObject)
2015-08-16 01:41:09 INFO     player   InterludePlayer initialized.
2015-08-16 01:41:09 ERROR    player   Could not parse playlist source: [Errno 2] No such file or directory: '/home/josh/.config/blockify/playlist.m3u'
2015-08-16 01:41:09 DEBUG    player   Loading playlist.
2015-08-16 01:41:09 DEBUG    player   Stop: State is (<enum GST_STATE_CHANGE_SUCCESS of type GstStateChangeReturn>, <enum GST_STATE_NULL of type GstState>, <enum GST_STATE_VOID_PENDING of type GstState>).
2015-08-16 01:41:09 INFO     player   Playlist loaded (Length: 0).
2015-08-16 01:41:09 INFO     player   Playlist: []
2015-08-16 01:41:09 INFO     main     Forcing unmute.
2015-08-16 01:41:09 DEBUG    main     Mute method is pulse sink.
2015-08-16 01:41:09 INFO     main     Blockify initialized.
2015-08-16 01:41:09 INFO     main     Blockify started.
gmdfalk commented 9 years ago

Ah, i believe i have found a way to reproduce this.

  1. start spotify (but don't start playback yet)
  2. start blockify
  3. use the buttons within blockify to start playback

when using spotify-buttons instead of blockify-playback-buttons in step 3, the issue does not occur, so i might be able to fix this, after all.

JP-Ellis commented 9 years ago

I don't use the blockify gui. My general procedure is:

  1. Start Spotify;
  2. Start Blockify;
  3. Use the buttons with Spotify to start playback.

Though it is interesting that closing and opening blockify again sometimes resolves the log spam. I think it may be to do with whether Spotify has a song currently playing/loaded, or not?

gmdfalk commented 9 years ago

@JP-Ellis Exactly. Although the problem lies a little deeper and it is, indeed, an initialization problem. Spotify does not automatically create a pulse sink when it is started. That sink is created when playback starts for the first time. Blockify, however, relies on the existance of a pulse sink when it is started. So, if blockify is started before a song in Spotify is playing, blockify can't find a sink and fails its initialization leading it to think the sink is muted. -> It tries to unmute.

I am pushing a fix in a minute which removes that reliance on an existing spotify pulse sink at blockify startup.

MInner commented 8 years ago

For those who might face this issue at some point if the future: I had a similar issue today (Failed to get DBus property. Disabling dbus-mode. Msg: org.freedesktop.DBus.Error.NoReply: Message did not receive a reply (timeout by message bus)) and killall -9'ing multiple spawns of spotify and blockify did the trick.

Thank you for the thing, @mikar ! :)