Potential regression with storeCredentials = true about spocon HOT 19 CLOSED

Do you have some logs for this? Try journalctl -u spocon -f --no-pager.

from spocon.

There is no activity on the logs when I open the app on the mobile and try to connect. I'm at INFO level. Should I try with TRACE ?

from spocon.

What excatly do you mean with "There is no activity" are you having any logs ?
Can you show us the output from :
journalctl --no-pager -u spocon

or if you want to write them in a file :
journalctl --no-pager -u spocon > spocon.log

from spocon.

Sorry. I meant there is no log activity associated to the action of attempting to connect to spocon from android.
I can provide the startup logs:

Apr 04 17:00:20 jukebox systemd[1]: Started SpoCon.
Apr 04 17:00:22 jukebox java[5970]: 2020-04-04 17:00:22 INFO  ApResolver:66 - Loaded aps into pool: {accesspoint=[gew1-accesspoint-b-t4d7.ap.spotify.com:4070, gew1-accesspoint-b-cfc4.ap.spotify.com:443, gew1-accesspoint-b-fmt6.ap.spotify.com:80, gew1-accesspoint-b-1ts2.ap.spotify.com:4070, gew1-accesspoint-b-czzt.ap.spotify.com:443, gew1-accesspoint-b-slc1.ap.spotify.com:80, guc3-accesspoint-b-5nb1.ap.spotify.com:4070, guc3-accesspoint-b-dmgp.ap.spotify.com:443, guc3-accesspoint-b-c9hq.ap.spotify.com:80], dealer=[gew-dealer.spotify.com:443, gae-dealer.spotify.com:443, guc-dealer.spotify.com:443], spclient=[gew-spclient.spotify.com:443, guc-spclient.spotify.com:443, gae-spclient.spotify.com:443]}
Apr 04 17:00:24 jukebox java[5970]: 2020-04-04 17:00:24 INFO  Session:107 - Created new session! {deviceId: yE9SqFjqHgEJx9pL5GSfKC0xQrn4UnpaeNyirGyHqK1W2tzonk, ap: gew1-accesspoint-b-czzt.ap.spotify.com:443, proxy: false}
Apr 04 17:00:25 jukebox java[5970]: 2020-04-04 17:00:25 INFO  Session:277 - Connected successfully!
Apr 04 17:00:25 jukebox java[5970]: 2020-04-04 17:00:25 INFO  CacheManager:71 - There are 386 cached entries.
Apr 04 17:00:26 jukebox java[5970]: 2020-04-04 17:00:26 INFO  LineHelper:61 - Available mixers: 'M2496 [default]', 'M2496 [plughw:1,0]'
Apr 04 17:00:26 jukebox java[5970]: 2020-04-04 17:00:26 INFO  Session:1023 - Skipping SecretBlock
Apr 04 17:00:26 jukebox java[5970]: 2020-04-04 17:00:26 INFO  Session:1002 - Received LicenseVersion: 0
Apr 04 17:00:26 jukebox java[5970]: 2020-04-04 17:00:26 INFO  Session:992 - Received CountryCode: DE
Apr 04 17:00:26 jukebox java[5970]: 2020-04-04 17:00:26 INFO  Session:1023 - Skipping ProductInfo
Apr 04 17:00:26 jukebox java[5970]: 2020-04-04 17:00:26 INFO  Session:1023 - Skipping LegacyWelcome
Apr 04 17:00:26 jukebox java[5970]: 2020-04-04 17:00:26 INFO  Session:1023 - Skipping UnknownData_AllZeros
Apr 04 17:00:26 jukebox java[5970]: 2020-04-04 17:00:26 INFO  Session:957 - Skipping unknown command {cmd: 0x75, payload: 000000}

From this point, the android app doesn't see the device.

Then, I open the spotify client from ubuntu laptop.

Apr 04 17:01:49 jukebox java[5970]: 2020-04-04 17:01:49 INFO  DeviceStateHandler:203 - Put state. {ts: 1586012509268, connId: eUU5U3[truncated], reason: PLAYER_STATE_CHANGED, request: <available for TRACE only>}
Apr 04 17:01:50 jukebox java[5970]: 2020-04-04 17:01:50 INFO  DeviceStateHandler:203 - Put state. {ts: 1586012510252, connId: eUU5U3[truncated], reason: PLAYER_STATE_CHANGED, request: <available for TRACE only>}

The player is ready to stream.

from spocon.

Interesting fact.
While the ubuntu client is paired with spocon. The android app works as expected.

from spocon.

When starting the client this way, it will only be visible on devices with the same account logged in. If this is the case, we might have an issue, but I definitely cannot reproduce it.

from spocon.

yes, this is the same account. I check the content of the file, keeping the credentials, same account also.
If I manage to come up with a reproducible case. I'll document it.
Thanks for looking into it.

from spocon.

I think this might be related to many other issues with connectivity where the client may not be able to dispatch itself again (due to a bug that I haven't been able to trace down yet).

Update:
I've added a commit recently to fix this (hopefully).

from spocon.

you mean librespot-org/librespot-java@a3edb34 ?

I'll try to build and test it.

from spocon.

Yes, that one

from spocon.

I'm afraid the issue still persist, with a new build against master.
Don't worry too much, using storeCrendentials=false just feels less snappy. But still provides, great experience.

from spocon.

You need to build dev to have the changes, master points to the latest stable release.

from spocon.

ah ah ! thx for tip, I will try again.

from spocon.

in fact I was on the default branch, which is dev. this is the HEAD I used 8f232bcaab2ea671c8f0c45ecdb03dd0eeae1bb5.

I've been trying something new. I deleted the credentials.json file and restarted the service.
Now everything works as expected. Maybe the token we store in the file become stale ?

from spocon.

Seems like that problem is solved. Closing this

from spocon.

As we need to wait few more days, I'll re-open if I can add more information helping you tracking it down.

from spocon.

Hi,
I upgraded to 1.3.1 and now I don't need to wait to observe the misbehaviour.
But I made another discovery that I will try to describe my best.

You have to imagining me in front of my laptop and my phone next to it.
Both are authenticated to spotify using the same account.

[on the phone]
spocon is not avaialble or not discovered.
[on the laptop]
I choose to play the music from spocon (rapsberrypi)
[on the phone]
spocon appears immediately
[on the laptop]
I choose to listen the music locally on the laptop
[on the phone]
spocon diseapper
[on the laptop]
I choose to play the music from spocon (rapsberrypi)
[on the phone]
spocon appears immediately
...

All of it real time, kind of funny to play with.

If I disable storeCrendentials all of this goes away, I can use the phone and the laptop normally, both like a remote controller.

from spocon.

That's peculiar indeed. I wonder why the phone has problems, but the laptop doesn't. The authentication is done in the same way expect for the the credentials, but they are given by Spotify itself.

@ticosax Do you have this problem from the beginning? Or did it appear recently?

from spocon.

It happened since 1.30 release, because I activated storeCredentials=true manually.

I don't think it is related to the phone specifically, but rather to the first device emitting the credentials. it used to worked on the phone at the beginning. Probably because I used my phone first, before the laptop.
Do you, yourself, use multiple devices to control spocon ? Did you had a chance to repeat the actions I described ?

from spocon.