search

SecUpwN / Spotify-AdKiller

Your Party with Spotify - without ads!
https://github.com/SecUpwN/Spotify-AdKiller
GNU General Public License v3.0
836 stars 83 forks source link

Ad is not muted. #46

Open jaybourn opened 8 years ago

jaybourn commented 8 years ago

The first ad to play is not muted. Any consecutive ads are muted as expected.

Debug output of two ads. 

PAUSED:   Yes
AD:       Can't say
LOCAL:    No
admute: 0; pausesignal: 0; adfinished: 0
## Paused by User ##

PAUSED:   No
AD:       Yes
LOCAL:    No
admute: 0; pausesignal: 0; adfinished: 0
pactl: mute
## Muting sink 452 ##

Config 

CUSTOM_MODE="simple"
CUSTOM_PLAYER=""
CUSTOM_LOOPOPT=""
CUSTOM_VOLUME=""
CUSTOM_MUSIC=""
CUSTOM_ALERT=""
DEBUG="1"

Spotify Version: 1.0.19.106.gb8a7150f

SecUpwN commented 8 years ago

Thanks for filing this. What do you suggest us to do, @Feltzer?

hcgrove commented 8 years ago

I experience the same, here is what was written to the log file (running in debug mode), when playing a regular track, and the two ads that spotify chose to play afterwards (yes two ads in a row):

--------------------------------------------------------------------------------
PAUSED:   No
AD:       No
LOCAL:    No
admute: 0; pausesignal: 0; adfinished: 0
## Regular track ##
--------------------------------------------------------------------------------
PAUSED:   Yes
AD:       Can't say
LOCAL:    No
admute: 0; pausesignal: 0; adfinished: 0
## Paused by User ##
--------------------------------------------------------------------------------
PAUSED:   No
AD:       Yes
LOCAL:    No
admute: 0; pausesignal: 0; adfinished: 0
pactl: mute
## Muting sink 42 ##
--------------------------------------------------------------------------------

It would seem the problem is the PAUSED: Yes, I didn't pause anyhting.

Running spotify version 1.0.24.104.g92a2268 on debian Jessie (8.3).

Config:

CUSTOM_MODE=""
CUSTOM_PLAYER=""
CUSTOM_LOOPOPT=""
CUSTOM_VOLUME=""
CUSTOM_MUSIC=""
DEBUG="1"
hcgrove commented 8 years ago

Reading the other issues this seems to be the same as in #50 and #52.

SecUpwN commented 8 years ago

Thanks for linking the other Issues as DUPLICATE, @hcgrove. Sadly, I am currently not able to digg so deep into the script like @Feltzer and @OlegSmelov are able to. Hoping to see them back again soon. In the meantime, please try to help me improving our script. Pull requests are gladly accepted!

Feltzer commented 8 years ago

Sorry guys, I am very short on time right now. Another reason this has taken me some time to address is because I use Spotify 0.9.x on my main PC which has worked perfectly fine with the script for months now.

I put some time aside today and tried reproducing this on my notebook which runs Spotify 1.0.25.127.g58007b4c-22 on Ubuntu 14.04. No 'luck' so far. Everything seems to be working fine on my end, but given the number of reports something must be amiss.

Here's what you can do to help:

The next time you experience an ad not being muted please run the following command in a terminal and paste the output here:

pacmd list-sink-inputs | grep -B 25 "application.process.binary = \"Spotify\""

Right now it looks like something is wrong with the pause detection method used in the script. The output of the command above will hopefully help me track down the cause.

fooblon commented 8 years ago

Hi @Feltzer and thanks for your time! Here the output you asked, but not sure it'll be useful... 

foo@foo-pc:~$ pacmd list-sink-inputs | grep -B 25 "application.process.binary = \"spotify\""
    driver: <protocol-native.c>
    flags: START_CORKED 
    state: RUNNING
    sink: 2 <alsa_output.pci-0000_00_1b.0.analog-stereo>
    volume: 0: 100% 1: 100%
            0: -0,00 dB 1: -0,00 dB
            balance 0,00
    muted: no
    current latency: 1638,30 ms
    requested latency: 371,52 ms
    sample spec: s16le 2ch 44100Hz
    channel map: front-left,front-right
                 Stéréo
    resample method: (null)
    module: 9
    client: 170 <spotify>
    properties:
        media.role = "music"
        media.name = "Spotify"
        application.name = "spotify"
        native-protocol.peer = "UNIX socket client"
        native-protocol.version = "28"
        application.process.id = "2902"
        application.process.user = "foo"
        application.process.host = "foo-pc"
        application.process.binary = "spotify"

during an unmuted ad

hcgrove commented 8 years ago

I don't know if it's different from fooblon's output in any interesting way, but here goes:

grove@solitaire> pacmd list-sink-inputs | grep -B 25 "application.process.binary = \"spotify\""
    index: 51
        driver: <protocol-native.c>
        flags: START_CORKED 
        state: RUNNING
        sink: 1 <alsa_output.pci-0000_00_1b.0.analog-stereo>
        volume: front-left: 34733 /  53% / -16,54 dB,   front-right: 34733 /  53% / -16,54 dB
                balance 0,00
        muted: no
        current latency: 1613,20 ms
        requested latency: 371,52 ms
        sample spec: s16le 2ch 44100Hz
        channel map: front-left,front-right
                     Stereo
        resample method: (null)
        module: 8
        client: 175 <Spotify>
        properties:
                media.role = "music"
                media.name = "Spotify"
                application.name = "Spotify"
                native-protocol.peer = "UNIX socket client"
                native-protocol.version = "29"
                application.process.id = "3546"
                application.process.user = "grove"
                application.process.host = "solitaire"
                application.process.binary = "spotify"

@Feltzer I understand you - if I could I would also still be on 0.9.17, unfortunately I've hit one of the "known" (as in reported by multiple users on their forum, but of course not acknowledged by anyone connected to spotify) bugs that made 0.9.17 unable to go online.

Feltzer commented 8 years ago

Thanks for posting these, guys. Sadly they look perfectly normal to me.

Just to confirm: You only experience this issue when an ad comes up after having manually skipped a track? Everything works fine when ads come on during uninterrupted playback?

dsmaugy commented 8 years ago

I am having this same problem ever since spotify updated a couple of weeks ago. Also as a sidenote, the Spotify ad-blocker I use for windows has stopped working from the recent update as well. It seems as if everyone is having trouble with the windows ad-blocker while in our case, it may be just a bug.

Here is the page to the windows ad-blocker if you are interested.

EDIT: By recent update, I mean the recent spotify update released on March 18

fooblon commented 8 years ago

@Feltzer sadly no. I personally experience issues at each new ad. But in facts there are two distinct bugs, the twos depending on the ad detector which seems to be (a bit) crazy.

1) Sometimes songs are muted because the AdKiller thinks it's an ad but it's not :

PAUSED:   No
AD:       Yes
LOCAL:    No
admute: 0; pausesignal: 0; adfinished: 0
pactl: mute
## Muting sink 12 ##

and then after that, some songs are muted and others are not. Randomly.

2) When an ad comes while it's in normal mode (i.e. I can listen my unmuted music!) after a few tracks, it's not muted. I need to pause/unpause so the detector can detect the ad. After two ads it comes back to my playlist but the detector still believes it's an ad. Here, pause/unpause doesn't do the trick, it's bugued. I need to pass 2 or 3 tracks to be unmuted.

Here I am, I'll dive in it when I'll have time, but let us know if you have any useful idea. Thanks again for this.

rjd22 commented 8 years ago

@Feltzer @SecUpwN

Spotify seems to change the state to CORKED for a second when an ad starts and moments later change it to RUNNING.

1 sink input(s) available.
    index: 51
    driver: <protocol-native.c>
    flags: START_CORKED 
    state: RUNNING
    sink: 3 <bluez_sink.0C_E0_E4_64_20_99>
    volume: front-left: 65535 / 100% / -0,00 dB,   front-right: 65535 / 100% / -0,00 dB
            balance 0,00
    muted: no
    current latency: 1952,59 ms
    requested latency: 45,32 ms
    sample spec: s16le 2ch 44100Hz
    channel map: front-left,front-right
                 Stereo
    resample method: (null)
    module: 9
    client: 197 <Spotify>
    properties:
        media.role = "music"
        media.name = "Spotify"
        application.name = "Spotify"
        native-protocol.peer = "UNIX socket client"
        native-protocol.version = "30"
        application.process.id = "23986"
        application.process.user = "<private>"
        application.process.host = "<private>"
        application.process.binary = "spotify"
        window.x11.display = ":1"
        application.language = "en_US.UTF-8"
        application.process.machine_id = "c31035cab1e94343807bd4ca54339a05"
        application.process.session_id = "c3"
        application.icon_name = "spotify-client"
        module-stream-restore.id = "sink-input-by-media-role:music"
Nightcore - Dreamers
Nightcore - Dreamers
PAUSED:   No
AD:       No
LOCAL:    No
admute: 0; pausesignal: 0; adfinished: 0
## Regular track ##

1 sink input(s) available.
    index: 51
    driver: <protocol-native.c>
    flags: START_CORKED 
    state: CORKED
    sink: 3 <bluez_sink.0C_E0_E4_64_20_99>
    volume: front-left: 65535 / 100% / -0,00 dB,   front-right: 65535 / 100% / -0,00 dB
            balance 0,00
    muted: no
    current latency: 0,00 ms
    requested latency: 45,32 ms
    sample spec: s16le 2ch 44100Hz
    channel map: front-left,front-right
                 Stereo
    resample method: (null)
    module: 9
    client: 197 <Spotify>
    properties:
        media.role = "music"
        media.name = "Spotify"
        application.name = "Spotify"
        native-protocol.peer = "UNIX socket client"
        native-protocol.version = "30"
        application.process.id = "23986"
        application.process.user = "<private>"
        application.process.host = "<private>"
        application.process.binary = "spotify"
        window.x11.display = ":1"
        application.language = "en_US.UTF-8"
        application.process.machine_id = "c31035cab1e94343807bd4ca54339a05"
        application.process.session_id = "c3"
        application.icon_name = "spotify-client"
        module-stream-restore.id = "sink-input-by-media-role:music"
Spotify Premium
- Spotify Premium
PAUSED:   Yes
AD:       Not sure
LOCAL:    No
admute: 0; pausesignal: 0; adfinished: 0
## Restoring state ##
pactl: unmute
## Unmuting sink 51 and 52 ##

2 sink input(s) available.
    index: 51
    driver: <protocol-native.c>
    flags: START_CORKED 
    state: CORKED
    sink: 3 <bluez_sink.0C_E0_E4_64_20_99>
    volume: front-left: 65535 / 100% / -0,00 dB,   front-right: 65535 / 100% / -0,00 dB
            balance 0,00
    muted: no
    current latency: 1956,28 ms
    requested latency: 45,32 ms
    sample spec: s16le 2ch 44100Hz
    channel map: front-left,front-right
                 Stereo
    resample method: (null)
    module: 9
    client: 197 <Spotify>
    properties:
        media.role = "music"
        media.name = "Spotify"
        application.name = "Spotify"
        native-protocol.peer = "UNIX socket client"
        native-protocol.version = "30"
        application.process.id = "23986"
        application.process.user = "<private>"
        application.process.host = "<private>"
        application.process.binary = "spotify"
        window.x11.display = ":1"
        application.language = "en_US.UTF-8"
        application.process.machine_id = "c31035cab1e94343807bd4ca54339a05"
        application.process.session_id = "c3"
        application.icon_name = "spotify-client"
        module-stream-restore.id = "sink-input-by-media-role:music"
Spotify
- Spotify Premium
PAUSED:   Yes
AD:       Not sure
LOCAL:    No
admute: 0; pausesignal: 0; adfinished: 0
## Restoring state ##
pactl: unmute
## Unmuting sink 51 and 52 ##

1 sink input(s) available.
    index: 51
    driver: <protocol-native.c>
    flags: START_CORKED 
    state: RUNNING
    sink: 3 <bluez_sink.0C_E0_E4_64_20_99>
    volume: front-left: 65535 / 100% / -0,00 dB,   front-right: 65535 / 100% / -0,00 dB
            balance 0,00
    muted: no
    current latency: 1935,96 ms
    requested latency: 45,32 ms
    sample spec: s16le 2ch 44100Hz
    channel map: front-left,front-right
                 Stereo
    resample method: (null)
    module: 9
    client: 197 <Spotify>
    properties:
        media.role = "music"
        media.name = "Spotify"
        application.name = "Spotify"
        native-protocol.peer = "UNIX socket client"
        native-protocol.version = "30"
        application.process.id = "23986"
        application.process.user = "<private>"
        application.process.host = "<private>"
        application.process.binary = "spotify"
        window.x11.display = ":1"
        application.language = "en_US.UTF-8"
        application.process.machine_id = "c31035cab1e94343807bd4ca54339a05"
        application.process.session_id = "c3"
        application.icon_name = "spotify-client"
        module-stream-restore.id = "sink-input-by-media-role:music"
Spotify Premium
- Spotify Premium
PAUSED:   No
AD:       Yes
LOCAL:    No
admute: 0; pausesignal: 0; adfinished: 0
pactl: mute
## Muting sink 51 and 52 ##

2 sink input(s) available.
    index: 51
    driver: <protocol-native.c>
    flags: START_CORKED 
    state: RUNNING
    sink: 3 <bluez_sink.0C_E0_E4_64_20_99>
    volume: front-left: 65535 / 100% / -0,00 dB,   front-right: 65535 / 100% / -0,00 dB
            balance 0,00
    muted: yes
    current latency: 859,91 ms
    requested latency: 45,32 ms
    sample spec: s16le 2ch 44100Hz
    channel map: front-left,front-right
                 Stereo
    resample method: (null)
    module: 9
    client: 197 <Spotify>
    properties:
        media.role = "music"
        media.name = "Spotify"
        application.name = "Spotify"
        native-protocol.peer = "UNIX socket client"
        native-protocol.version = "30"
        application.process.id = "23986"
        application.process.user = "<private>"
        application.process.host = "<private>"
        application.process.binary = "spotify"
        window.x11.display = ":1"
        application.language = "en_US.UTF-8"
        application.process.machine_id = "c31035cab1e94343807bd4ca54339a05"
        application.process.session_id = "c3"
        application.icon_name = "spotify-client"
        module-stream-restore.id = "sink-input-by-media-role:music"
Lazy Sunday Music
- Lazy Sunday Music
PAUSED:   No
AD:       Yes
LOCAL:    No
admute: 1; pausesignal: 0; adfinished: 0
pactl: mute
## Muting sink 51 and 52 ##

1 sink input(s) available.
    index: 51
    driver: <protocol-native.c>
    flags: START_CORKED 
    state: RUNNING
    sink: 3 <bluez_sink.0C_E0_E4_64_20_99>
    volume: front-left: 65535 / 100% / -0,00 dB,   front-right: 65535 / 100% / -0,00 dB
            balance 0,00
    muted: yes
    current latency: 883,72 ms
    requested latency: 45,32 ms
    sample spec: s16le 2ch 44100Hz
    channel map: front-left,front-right
                 Stereo
    resample method: (null)
    module: 9
    client: 197 <Spotify>
    properties:
        media.role = "music"
        media.name = "Spotify"
        application.name = "Spotify"
        native-protocol.peer = "UNIX socket client"
        native-protocol.version = "30"
        application.process.id = "23986"
        application.process.user = "<private>"
        application.process.host = "<private>"
        application.process.binary = "spotify"
        window.x11.display = ":1"
        application.language = "en_US.UTF-8"
        application.process.machine_id = "c31035cab1e94343807bd4ca54339a05"
        application.process.session_id = "c3"
        application.icon_name = "spotify-client"
        module-stream-restore.id = "sink-input-by-media-role:music"
Nightcore - Running Away
Nightcore - Running Away
PAUSED:   No
AD:       No
LOCAL:    No
admute: 1; pausesignal: 0; adfinished: 0
pactl: unmute
## Unmuting sink 51 and 52 ##
hcgrove commented 8 years ago

Hmm, good question. My feeling was that I experienced this when doing absolutly nothing (related to spotify or the adkiller), but I do occasionally restart (through DBus, using a script I found somewhere calling the Previous method) tracks, and haven't really considered whether that affected it, but yesterday I also experienced that sometimes all ads were muted. Below are some conclusions from two listening sessions where I tried to be more observant on this.

I hadn't tried the pause/unpause trick on undetected ads before. It seems to work.

Whether I pause playback between two ad "breaks" has no influence on whether the first ad in a "break" get muted or not. I have observed all combinations when not affecting playback in any other way.

The actual ads doesn't seem to matter, I have experienced the same ad being muted and not muted.

Restarting tracks doesn't seem to have any effect.

I haven't experienced songs being identified as ads.

I have a feeling it works a little worse when tracks are long, but I can't back that with any data.

SecUpwN commented 8 years ago

Just found the wonderful openSUSE Spotify Installer and hope @aspiers can help us a bit here.

Feltzer commented 8 years ago

Thanks for the insights, guys. I am still having trouble reproducing the bug on my end, but I will keep trying. At this point I have to wonder if I'm just lucky or if there's something different about my setup that keeps the script working fine.

@rjd22, thanks for these logs. They've been very helpful! I am now convinced that the pause detection is at fault. I'll see if I can investigate further in that direction.

rjd22 commented 8 years ago

@Feltzer It seems that the script checks a little bit too soon if the stream is paused. A second later it tells me it's running.

I use the following versions. ubuntu 15.10 kernel 4.2.0-34-generic Spotify version 1.0.24.104 pacmd 6.0 Compiled with libpulse 6.0.0 Linked with libpulse 6.0.0

gelderwe commented 8 years ago

I also have encountered that the first of 2 ads is not muted.

Spotify version: 1.0.24.104.g92a22684 AdKiller version: master (commit 7e1a7337ae74444504125ae4d880cbc60710e984) Operating system: Ubuntu 14.04 LTS Kernel: 3.16.0-67-generic pacmd 4.0 Compiled with libpulse 4.0.0 Linked with libpulse 4.0.0

Feltzer commented 8 years ago

Alright guys, I've pushed a commit to the repo which will hopefully fix most of these issues (26c28e00961d0647556e3cc6a8bafdbd69d02dbb). What this commit does is introduce a small delay when a paused track is detected, as suggested by @rjd22 (thanks!). This is to make sure that Spotify is actually paused and not just going through a temporary status change. The downside to this is that - under some circumstances - you might hear an ad for a fraction of a second before the mute sets in.

It's not a very elegant solution, but I don't see any other way to fix this until Spotify reactivate playback status querying via DBUS.

Everyone, please give the latest revision of the script a try and report back if this issue have been fixed for you.

Feltzer commented 8 years ago

Sorry, guys: looks like the script is still having some issues, even after these latest changes. As I am very short on time right now I won't be able to keep on debugging this. So if you are experiencing these issues it might be best to either consider downgrading to Spotify 0.9x (if possible on your platform) or using one of the other adblocking projects listed in our README for the time being (blockify would be my first choice).

I hope I'll be able to get back on this when I have some more time on my hands, but it might be several weeks until that's the case.

SecUpwN commented 8 years ago

@mikar, would you please have a look at our script and see if you can fix this? Vielen lieben Dank! ;-)

gmdfalk commented 8 years ago

I just looked into it and failed to reproduce this issue. I did fix an issue of spotify-adkiller not finding mp3 files in my LOCAL_MUSIC folder and submitted a pull request.

However, i found these issues: 1: even though the ad is found on the first attempt, spotify is then muted via spotify_dbus PlayPause so that the script can no longer determine if an ad is playing 2: exiting the script via ctrl-c leaves my spotify sink muted

I'll see if i can fix those. I'd also appreciate some confirmation on issue 1. does the ad get muted for anyone who is experiencing the topic issue here?

Regards Max

P.S.: Regarding issue 2, i just saw that behaviour is intended in the restore_settings function:

    # I would love to restore the mute state here but unfortunately it's impossible.
    # `pactl` can only control active sinks, i.e. if Spotify isn't running we can't
    # control its mute state. So we have to resort to unmuting Spotify on every initial
    # run of this script (INITIALRUN=1)

Why not use a blanket unmute here? I think it's unlikely someone wants to keep Spotify muted when exiting Adkiller since manually unmuting a sink is a hassle.

kupiqu commented 7 years ago

63 does not fix it for me.

I could fix it with the following modification in spotify-adkiller.sh (using spotify-client 1.0.38.171):

get_state_beta(){
  get_track_info_beta

  # check if track paused
  debuginfo "$(get_pactl_info_beta)"
  if get_pactl_info_beta | grep 'state: CORKED' > /dev/null 2>&1; then
    echo "PAUSED:   No" # SA
    PAUSED="0"          # SA
    # wait and recheck
    sleep 0.75
    if get_pactl_info_beta | grep 'state: CORKED' > /dev/null 2>&1; then
      echo "PAUSED:   No" # echo "PAUSED:   Yes" # SA
      PAUSED="0"          # PAUSED="1" # SA
    fi
    get_track_info_beta
  else
    echo "PAUSED:   No"
    PAUSED="0"
  fi
.
.
.

This fix works nicely in my system, but note that I'm not very familiar with the code, so there is probably a better way to fix this, I'm not aware of. Perhaps this workaround orient you guys in the right direction...