Exception in thread "track-handler-3958962" java.lang.NullPointerException #48

loeffelpan · 2019-02-16T00:05:47Z

There is one issue left while connecting via zeroconf.
On first attempt after starting the service I always got this. Second attempt is successful.

Feb 16 00:59:02 osmc java[23308]: 2019-02-16 00:59:02 TRACE DiffieHellman:45 - Computed shared key successfully!
Feb 16 00:59:03 osmc java[23308]: 2019-02-16 00:59:03 INFO  Session:65 - Created new session! {deviceId: 7b5633ea-a432-4187-b699-69c51df2211d, ap: gew1-accesspoint-b-sp6x.ap.spotify.com/104.199.64.161}
Feb 16 00:59:04 osmc java[23308]: 2019-02-16 00:59:04 TRACE DiffieHellman:45 - Computed shared key successfully!
Feb 16 00:59:07 osmc java[23308]: 2019-02-16 00:59:07 INFO  Session:197 - Connected successfully!
Feb 16 00:59:07 osmc java[23308]: 2019-02-16 00:59:07 TRACE Session:640 - Handled Ping
Feb 16 00:59:07 osmc java[23308]: 2019-02-16 00:59:07 INFO  Session:676 - Skipping SecretBlock
Feb 16 00:59:07 osmc java[23308]: 2019-02-16 00:59:07 INFO  Session:656 - Received LicenseVersion: 1, 1.0.0-DE
Feb 16 00:59:07 osmc java[23308]: 2019-02-16 00:59:07 INFO  Session:649 - Received CountryCode: DE
Feb 16 00:59:07 osmc java[23308]: 2019-02-16 00:59:07 INFO  Session:676 - Skipping ProductInfo
Feb 16 00:59:07 osmc java[23308]: 2019-02-16 00:59:07 INFO  Session:676 - Skipping LegacyWelcome
Feb 16 00:59:07 osmc java[23308]: 2019-02-16 00:59:07 INFO  Session:676 - Skipping UnknownData_AllZeros
Feb 16 00:59:07 osmc java[23308]: 2019-02-16 00:59:07 DEBUG Session:659 - Received 0x10: 82B1BE31C7D831D1D9B505319E9FB3905436927A
Feb 16 00:59:07 osmc java[23308]: 2019-02-16 00:59:07 TRACE Session:646 - Handled PongAck
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE MercuryClient:104 - Send Mercury request, seq: 1, uri: hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/, method: SUB
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE MercuryClient:146 - Handling packet, cmd: MercurySub, seq: 1, flags: 1, parts: 1
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE MercuryClient:52 - Subscribed successfully to hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/!
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE SpotifyIrc:101 - Send frame, type: kMessageTypeHello
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE MercuryClient:104 - Send Mercury request, seq: 2, uri: hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/, method: SEND
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE MercuryClient:146 - Handling packet, cmd: MercuryReq, seq: 2, flags: 1, parts: 1
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE SpotifyIrc:115 - Frame sent successfully, type: kMessageTypeHello
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE MercuryClient:146 - Handling packet, cmd: MercurySubEvent, seq: 813183406740340736, flags: 1, parts: 2
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE SpotifyIrc:191 - Handling frame, type: kMessageTypeNotify, ident: 1fd5615e7a0791aecc498bacef34f531e85ddfc3
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 INFO  Session:216 - Authenticated as 3va30l8lqcu4tl1rj2xdks9bz!
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE MercuryClient:146 - Handling packet, cmd: MercurySubEvent, seq: 957298594816196608, flags: 1, parts: 2
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE SpotifyIrc:191 - Handling frame, type: kMessageTypeLoad, ident: 1fd5615e7a0791aecc498bacef34f531e85ddfc3
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 DEBUG Player:268 - Loading context, uri: spotify:user:3va30l8lqcu4tl1rj2xdks9bz:playlist:7yhLc9ygpxUaB2Tyx9A84m
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE DiffieHellman:45 - Computed shared key successfully!
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE SpotifyIrc:101 - Send frame, type: kMessageTypeNotify
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE MercuryClient:146 - Handling packet, cmd: MercurySubEvent, seq: 1029356188854124544, flags: 1, parts: 2
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE SpotifyIrc:191 - Handling frame, type: kMessageTypeNotify, ident: 1fd5615e7a0791aecc498bacef34f531e85ddfc3
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE MercuryClient:104 - Send Mercury request, seq: 3, uri: hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/, method: SEND
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE MercuryClient:146 - Handling packet, cmd: MercuryReq, seq: 3, flags: 1, parts: 1
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE SpotifyIrc:115 - Frame sent successfully, type: kMessageTypeNotify
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE SpotifyIrc:101 - Send frame, type: kMessageTypeGoodbye
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE MercuryClient:104 - Send Mercury request, seq: 4, uri: hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/, method: SEND
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE MercuryClient:146 - Handling packet, cmd: MercuryReq, seq: 4, flags: 1, parts: 1
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE SpotifyIrc:115 - Frame sent successfully, type: kMessageTypeGoodbye
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE MercuryClient:104 - Send Mercury request, seq: 5, uri: hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/, method: UNSUB
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE SpotifyIrc:101 - Send frame, type: kMessageTypeNotify
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE MercuryClient:104 - Send Mercury request, seq: 6, uri: hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/, method: SEND
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE MercuryClient:146 - Handling packet, cmd: MercuryUnsub, seq: 5, flags: 1, parts: 1
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE MercuryClient:60 - Unsubscribed successfully from hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/!
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 INFO  Session:278 - Closed session. {deviceId: 7b5633ea-a432-4187-b699-69c51df2211d, ap: gew1-accesspoint-b-sp6x.ap.spotify.com/104.199.64.161}
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 TRACE MercuryClient:104 - Send Mercury request, seq: 7, uri: hm://metadata/4/track/016E5A53FF6946C88684C42CBBB66CB4, method: GET
Feb 16 00:59:08 osmc java[23308]: Exception in thread "track-handler-3958962" java.lang.NullPointerException
Feb 16 00:59:08 osmc java[23308]:         at xyz.gianlu.librespot.core.Session.sendUnchecked(Session.java:282)
Feb 16 00:59:08 osmc java[23308]:         at xyz.gianlu.librespot.core.Session.send(Session.java:299)
Feb 16 00:59:08 osmc java[23308]:         at xyz.gianlu.librespot.mercury.MercuryClient.send(MercuryClient.java:122)
Feb 16 00:59:08 osmc java[23308]:         at xyz.gianlu.librespot.mercury.MercuryClient.sendSync(MercuryClient.java:66)
Feb 16 00:59:08 osmc java[23308]:         at xyz.gianlu.librespot.mercury.MercuryClient.sendSync(MercuryClient.java:85)
Feb 16 00:59:08 osmc java[23308]:         at xyz.gianlu.librespot.mercury.MercuryClient.sendSync(MercuryClient.java:92)
Feb 16 00:59:08 osmc java[23308]:         at xyz.gianlu.librespot.player.StreamFeeder.load(StreamFeeder.java:81)
Feb 16 00:59:08 osmc java[23308]:         at xyz.gianlu.librespot.player.TrackHandler.load(TrackHandler.java:45)
Feb 16 00:59:08 osmc java[23308]:         at xyz.gianlu.librespot.player.TrackHandler.access$600(TrackHandler.java:21)
Feb 16 00:59:08 osmc java[23308]:         at xyz.gianlu.librespot.player.TrackHandler$Looper.run(TrackHandler.java:166)
Feb 16 00:59:08 osmc java[23308]:         at java.lang.Thread.run(Thread.java:748)
Feb 16 00:59:08 osmc java[23308]: 2019-02-16 00:59:08 INFO  Session:65 - Created new session! {deviceId: 7b5633ea-a432-4187-b699-69c51df2211d, ap: gew1-accesspoint-b-xnrm.ap.spotify.com/104.199.65.196}
Feb 16 00:59:09 osmc java[23308]: 2019-02-16 00:59:09 TRACE DiffieHellman:45 - Computed shared key successfully!
Feb 16 00:59:10 osmc java[23308]: 2019-02-16 00:59:10 INFO  Session:197 - Connected successfully!
Feb 16 00:59:10 osmc java[23308]: 2019-02-16 00:59:10 TRACE Session:640 - Handled Ping
Feb 16 00:59:10 osmc java[23308]: 2019-02-16 00:59:10 INFO  Session:676 - Skipping SecretBlock
Feb 16 00:59:10 osmc java[23308]: 2019-02-16 00:59:10 INFO  Session:656 - Received LicenseVersion: 1, 1.0.0-DE
Feb 16 00:59:10 osmc java[23308]: 2019-02-16 00:59:10 TRACE MercuryClient:104 - Send Mercury request, seq: 1, uri: hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/, method: SUB
Feb 16 00:59:10 osmc java[23308]: 2019-02-16 00:59:10 INFO  Session:649 - Received CountryCode: DE
Feb 16 00:59:10 osmc java[23308]: 2019-02-16 00:59:10 INFO  Session:676 - Skipping ProductInfo
Feb 16 00:59:10 osmc java[23308]: 2019-02-16 00:59:10 INFO  Session:676 - Skipping LegacyWelcome
Feb 16 00:59:10 osmc java[23308]: 2019-02-16 00:59:10 INFO  Session:676 - Skipping UnknownData_AllZeros
Feb 16 00:59:10 osmc java[23308]: 2019-02-16 00:59:10 DEBUG Session:659 - Received 0x10: DDC624B95A8A4D2D812FAC9CF99B84C604A4454C
Feb 16 00:59:10 osmc java[23308]: 2019-02-16 00:59:10 TRACE Session:646 - Handled PongAck

The text was updated successfully, but these errors were encountered:

loeffelpan · 2019-02-24T16:22:05Z

Just made a new build and unfortunately I faced the same issue again.
After you fixed this without any ERROR in log.
What else cause this behaviour?

devgianlu · 2019-02-24T16:48:05Z

I don't see how this might be possible. Can you provide a new stacktrace?

Also I can't really test this because I'd need two accounts or do I? How do you reproduce this?

loeffelpan · 2019-02-27T19:43:56Z

I'll do my very best!

First attempt after restart of the service:

Feb 27 20:41:01 osmc java[23768]: 2019-02-27 20:41:01 INFO  Utils:83 - Cryptography restrictions removal not needed.
Feb 27 20:41:02 osmc java[23768]: 2019-02-27 20:41:02 INFO  ZeroconfServer:307 - Zeroconf HTTP server started successfully on port 26409!
Feb 27 20:41:02 osmc java[23768]: 2019-02-27 20:41:02 TRACE ZeroconfServer:162 - Adding addresses of eth0 (displayName: eth0)
Feb 27 20:41:02 osmc java[23768]: 2019-02-27 20:41:02 DEBUG ZeroconfServer:104 - Registering service on [/172.20.2.4]
Feb 27 20:41:02 osmc java[23768]: 2019-02-27 20:41:02 INFO  ZeroconfServer:117 - SpotifyConnect service registered successfully!
Feb 27 20:41:07 osmc java[23768]: 2019-02-27 20:41:07 TRACE ZeroconfServer:343 - Handling request: GET /?action=getInfo HTTP/1.1, headers: {Keep-Alive=0, Connection=keep-alive, User-Agent=Spotify/8.4.94 iOS/12.1.4 (iPhone7,2), Host=172.20.2.4, Accept-Encoding=gzip, Content-Type=application/x-www-form-urlencoded}
Feb 27 20:41:09 osmc java[23768]: 2019-02-27 20:41:09 TRACE ZeroconfServer:343 - Handling request: GET /?action=getInfo HTTP/1.1, headers: {Keep-Alive=0, Connection=keep-alive, User-Agent=Spotify/8.4.94 iOS/12.1.4 (iPhone7,2), Host=172.20.2.4, Accept-Encoding=gzip, Content-Type=application/x-www-form-urlencoded}
Feb 27 20:41:11 osmc java[23768]: 2019-02-27 20:41:11 TRACE ZeroconfServer:343 - Handling request: GET /?action=getInfo HTTP/1.1, headers: {Keep-Alive=0, Connection=keep-alive, User-Agent=Spotify/8.4.94 iOS/12.1.4 (iPhone7,2), Host=172.20.2.4, Accept-Encoding=gzip, Content-Type=application/x-www-form-urlencoded}
Feb 27 20:41:13 osmc java[23768]: 2019-02-27 20:41:13 TRACE ZeroconfServer:343 - Handling request: GET /?action=getInfo HTTP/1.1, headers: {Keep-Alive=0, Connection=keep-alive, User-Agent=Spotify/8.4.94 iOS/12.1.4 (iPhone7,2), Host=172.20.2.4, Accept-Encoding=gzip, Content-Type=application/x-www-form-urlencoded}
Feb 27 20:41:15 osmc java[23768]: 2019-02-27 20:41:15 TRACE ZeroconfServer:343 - Handling request: GET /?action=getInfo HTTP/1.1, headers: {Keep-Alive=0, Connection=keep-alive, User-Agent=Spotify/8.4.94 iOS/12.1.4 (iPhone7,2), Host=172.20.2.4, Accept-Encoding=gzip, Content-Type=application/x-www-form-urlencoded}
Feb 27 20:41:16 osmc java[23768]: 2019-02-27 20:41:16 TRACE ZeroconfServer:343 - Handling request: POST / HTTP/1.1, headers: {Keep-Alive=0, Connection=keep-alive, User-Agent=Spotify/8.4.94 iOS/12.1.4 (iPhone7,2), Host=172.20.2.4, Accept-Encoding=gzip, Content-Length=724, Content-Type=application/x-www-form-urlencoded}
Feb 27 20:41:17 osmc java[23768]: 2019-02-27 20:41:17 TRACE DiffieHellman:45 - Computed shared key successfully!
Feb 27 20:41:18 osmc java[23768]: 2019-02-27 20:41:18 INFO  Session:65 - Created new session! {deviceId: 0a63f7fe-ebac-43f8-9b7c-00838bb3e69f, ap: guc3-accesspoint-b-wf5l.ap.spotify.com/104.154.126.137}
Feb 27 20:41:19 osmc java[23768]: 2019-02-27 20:41:19 TRACE DiffieHellman:45 - Computed shared key successfully!
Feb 27 20:41:20 osmc java[23768]: 2019-02-27 20:41:20 INFO  Session:197 - Connected successfully!
Feb 27 20:41:21 osmc java[23768]: 2019-02-27 20:41:21 TRACE Session:640 - Handled Ping
Feb 27 20:41:21 osmc java[23768]: 2019-02-27 20:41:21 INFO  Session:676 - Skipping SecretBlock
Feb 27 20:41:21 osmc java[23768]: 2019-02-27 20:41:21 INFO  Session:656 - Received LicenseVersion: 1, 1.0.0-DE
Feb 27 20:41:21 osmc java[23768]: 2019-02-27 20:41:21 INFO  Session:649 - Received CountryCode: DE
Feb 27 20:41:21 osmc java[23768]: 2019-02-27 20:41:21 INFO  Session:676 - Skipping ProductInfo
Feb 27 20:41:21 osmc java[23768]: 2019-02-27 20:41:21 INFO  Session:676 - Skipping LegacyWelcome
Feb 27 20:41:21 osmc java[23768]: 2019-02-27 20:41:21 INFO  Session:676 - Skipping UnknownData_AllZeros
Feb 27 20:41:21 osmc java[23768]: 2019-02-27 20:41:21 TRACE MercuryClient:104 - Send Mercury request, seq: 1, uri: hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/, method: SUB
Feb 27 20:41:21 osmc java[23768]: 2019-02-27 20:41:21 DEBUG Session:659 - Received 0x10: B90E01C88B969C6870250861732B2A1FB1A8217E
Feb 27 20:41:21 osmc java[23768]: 2019-02-27 20:41:21 TRACE Session:646 - Handled PongAck
Feb 27 20:41:21 osmc java[23768]: 2019-02-27 20:41:21 TRACE MercuryClient:146 - Handling packet, cmd: MercurySub, seq: 1, flags: 1, parts: 1
Feb 27 20:41:21 osmc java[23768]: 2019-02-27 20:41:21 TRACE MercuryClient:52 - Subscribed successfully to hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/!
Feb 27 20:41:21 osmc java[23768]: 2019-02-27 20:41:21 TRACE SpotifyIrc:101 - Send frame, type: kMessageTypeHello
Feb 27 20:41:21 osmc java[23768]: 2019-02-27 20:41:21 TRACE MercuryClient:104 - Send Mercury request, seq: 2, uri: hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/, method: SEND
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 TRACE MercuryClient:146 - Handling packet, cmd: MercuryReq, seq: 2, flags: 1, parts: 1
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 TRACE SpotifyIrc:115 - Frame sent successfully, type: kMessageTypeHello
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 INFO  Session:211 - Authenticated as 3va30l8lqcu4tl1rj2xdks9bz!
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 TRACE MercuryClient:146 - Handling packet, cmd: MercurySubEvent, seq: 3103854255002353664, flags: 1, parts: 2
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 TRACE SpotifyIrc:191 - Handling frame, type: kMessageTypeNotify, ident: 8c1d42106a761e0625cef98e02fadfe6fb117a4c
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 TRACE DiffieHellman:45 - Computed shared key successfully!
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 TRACE SpotifyIrc:101 - Send frame, type: kMessageTypeGoodbye
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 TRACE MercuryClient:104 - Send Mercury request, seq: 3, uri: hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/, method: SEND
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 TRACE MercuryClient:146 - Handling packet, cmd: MercurySubEvent, seq: 3175911849040281600, flags: 1, parts: 2
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 TRACE SpotifyIrc:191 - Handling frame, type: kMessageTypeLoad, ident: 8c1d42106a761e0625cef98e02fadfe6fb117a4c
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 DEBUG Player:268 - Loading context, uri: spotify:user:3va30l8lqcu4tl1rj2xdks9bz:playlist:7yhLc9ygpxUaB2Tyx9A84m
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 TRACE MercuryClient:146 - Handling packet, cmd: MercurySubEvent, seq: 3247969443078209536, flags: 1, parts: 2
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 TRACE SpotifyIrc:191 - Handling frame, type: kMessageTypeNotify, ident: 8c1d42106a761e0625cef98e02fadfe6fb117a4c
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 TRACE MercuryClient:146 - Handling packet, cmd: MercuryReq, seq: 3, flags: 1, parts: 1
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 TRACE SpotifyIrc:115 - Frame sent successfully, type: kMessageTypeGoodbye
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 TRACE SpotifyIrc:101 - Send frame, type: kMessageTypeNotify
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 TRACE MercuryClient:104 - Send Mercury request, seq: 4, uri: hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/, method: UNSUB
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 TRACE MercuryClient:104 - Send Mercury request, seq: 5, uri: hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/, method: SEND
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 TRACE MercuryClient:104 - Send Mercury request, seq: 6, uri: hm://metadata/4/track/892F34400D7B4CB5B3948E362A14CA69, method: GET
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 TRACE MercuryClient:146 - Handling packet, cmd: MercuryUnsub, seq: 4, flags: 1, parts: 1
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 TRACE MercuryClient:60 - Unsubscribed successfully from hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/!
Feb 27 20:41:22 osmc java[23768]: 2019-02-27 20:41:22 INFO  Session:278 - Closed session. {deviceId: 0a63f7fe-ebac-43f8-9b7c-00838bb3e69f, ap: guc3-accesspoint-b-wf5l.ap.spotify.com/104.154.126.137}
Feb 27 20:41:23 osmc java[23768]: 2019-02-27 20:41:23 INFO  Session:65 - Created new session! {deviceId: 0a63f7fe-ebac-43f8-9b7c-00838bb3e69f, ap: gew1-accesspoint-b-5lxn.ap.spotify.com/104.199.64.114}
Feb 27 20:41:23 osmc java[23768]: 2019-02-27 20:41:23 TRACE DiffieHellman:45 - Computed shared key successfully!
Feb 27 20:41:24 osmc java[23768]: 2019-02-27 20:41:24 INFO  Session:197 - Connected successfully!
Feb 27 20:41:24 osmc java[23768]: 2019-02-27 20:41:24 TRACE Session:640 - Handled Ping
Feb 27 20:41:24 osmc java[23768]: 2019-02-27 20:41:24 INFO  Session:676 - Skipping SecretBlock
Feb 27 20:41:24 osmc java[23768]: 2019-02-27 20:41:24 TRACE MercuryClient:104 - Send Mercury request, seq: 1, uri: hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/, method: SUB
Feb 27 20:41:24 osmc java[23768]: 2019-02-27 20:41:24 INFO  Session:656 - Received LicenseVersion: 1, 1.0.0-DE
Feb 27 20:41:24 osmc java[23768]: 2019-02-27 20:41:24 INFO  Session:649 - Received CountryCode: DE
Feb 27 20:41:24 osmc java[23768]: 2019-02-27 20:41:24 INFO  Session:676 - Skipping ProductInfo
Feb 27 20:41:24 osmc java[23768]: 2019-02-27 20:41:24 INFO  Session:676 - Skipping LegacyWelcome
Feb 27 20:41:24 osmc java[23768]: 2019-02-27 20:41:24 INFO  Session:676 - Skipping UnknownData_AllZeros
Feb 27 20:41:24 osmc java[23768]: 2019-02-27 20:41:24 DEBUG Session:659 - Received 0x10: 2A788429830F920DAFC354AF2C884ED4F7877002
Feb 27 20:41:24 osmc java[23768]: 2019-02-27 20:41:24 TRACE Session:646 - Handled PongAck
Feb 27 20:41:24 osmc java[23768]: 2019-02-27 20:41:24 TRACE MercuryClient:146 - Handling packet, cmd: MercurySub, seq: 1, flags: 1, parts: 1
Feb 27 20:41:24 osmc java[23768]: 2019-02-27 20:41:24 TRACE MercuryClient:52 - Subscribed successfully to hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/!
Feb 27 20:41:24 osmc java[23768]: 2019-02-27 20:41:24 TRACE SpotifyIrc:101 - Send frame, type: kMessageTypeHello
Feb 27 20:41:24 osmc java[23768]: 2019-02-27 20:41:24 TRACE MercuryClient:104 - Send Mercury request, seq: 2, uri: hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/, method: SEND
Feb 27 20:41:24 osmc java[23768]: 2019-02-27 20:41:24 TRACE MercuryClient:146 - Handling packet, cmd: MercuryReq, seq: 2, flags: 1, parts: 1
Feb 27 20:41:24 osmc java[23768]: 2019-02-27 20:41:24 TRACE SpotifyIrc:115 - Frame sent successfully, type: kMessageTypeHello
Feb 27 20:41:24 osmc java[23768]: 2019-02-27 20:41:24 INFO  Session:211 - Authenticated as 3va30l8lqcu4tl1rj2xdks9bz!
Feb 27 20:41:24 osmc java[23768]: 2019-02-27 20:41:24 TRACE MercuryClient:146 - Handling packet, cmd: MercurySubEvent, seq: 6087527491042279424, flags: 1, parts: 2
Feb 27 20:41:24 osmc java[23768]: 2019-02-27 20:41:24 TRACE SpotifyIrc:191 - Handling frame, type: kMessageTypeNotify, ident: 8c1d42106a761e0625cef98e02fadfe6fb117a4c

Second attempt:

Feb 27 20:41:48 osmc java[23768]: 2019-02-27 20:41:48 TRACE MercuryClient:146 - Handling packet, cmd: MercurySubEvent, seq: -3640247704077991936, flags: 1, parts: 2
Feb 27 20:41:48 osmc java[23768]: 2019-02-27 20:41:48 TRACE SpotifyIrc:191 - Handling frame, type: kMessageTypeNotify, ident: 8c1d42106a761e0625cef98e02fadfe6fb117a4c
Feb 27 20:42:33 osmc java[23768]: 2019-02-27 20:42:33 TRACE MercuryClient:146 - Handling packet, cmd: MercurySubEvent, seq: -8972228187907948544, flags: 1, parts: 2
Feb 27 20:42:33 osmc java[23768]: 2019-02-27 20:42:33 TRACE MercuryClient:146 - Handling packet, cmd: MercurySubEvent, seq: -8900170593870020608, flags: 1, parts: 2
Feb 27 20:42:33 osmc java[23768]: 2019-02-27 20:42:33 TRACE SpotifyIrc:191 - Handling frame, type: kMessageTypeNotify, ident: 8c1d42106a761e0625cef98e02fadfe6fb117a4c
Feb 27 20:42:33 osmc java[23768]: 2019-02-27 20:42:33 TRACE SpotifyIrc:191 - Handling frame, type: kMessageTypeNotify, ident: 8c1d42106a761e0625cef98e02fadfe6fb117a4c
Feb 27 20:42:33 osmc java[23768]: 2019-02-27 20:42:33 TRACE MercuryClient:146 - Handling packet, cmd: MercurySubEvent, seq: -8828112999832092672, flags: 1, parts: 2
Feb 27 20:42:33 osmc java[23768]: 2019-02-27 20:42:33 TRACE SpotifyIrc:191 - Handling frame, type: kMessageTypeNotify, ident: 8c1d42106a761e0625cef98e02fadfe6fb117a4c
Feb 27 20:42:33 osmc java[23768]: 2019-02-27 20:42:33 TRACE MercuryClient:146 - Handling packet, cmd: MercurySubEvent, seq: -8756055405794164736, flags: 1, parts: 2
Feb 27 20:42:33 osmc java[23768]: 2019-02-27 20:42:33 TRACE SpotifyIrc:191 - Handling frame, type: kMessageTypeNotify, ident: 8c1d42106a761e0625cef98e02fadfe6fb117a4c
Feb 27 20:42:34 osmc java[23768]: 2019-02-27 20:42:34 TRACE MercuryClient:146 - Handling packet, cmd: MercurySubEvent, seq: -8467825029642452992, flags: 1, parts: 2
Feb 27 20:42:34 osmc java[23768]: 2019-02-27 20:42:34 TRACE SpotifyIrc:191 - Handling frame, type: kMessageTypeNotify, ident: 8c1d42106a761e0625cef98e02fadfe6fb117a4c
Feb 27 20:42:36 osmc java[23768]: 2019-02-27 20:42:36 TRACE MercuryClient:146 - Handling packet, cmd: MercurySubEvent, seq: -7891364277339029504, flags: 1, parts: 2
Feb 27 20:42:36 osmc java[23768]: 2019-02-27 20:42:36 TRACE SpotifyIrc:191 - Handling frame, type: kMessageTypeLoad, ident: 8c1d42106a761e0625cef98e02fadfe6fb117a4c
Feb 27 20:42:36 osmc java[23768]: 2019-02-27 20:42:36 DEBUG Player:268 - Loading context, uri: spotify:user:3va30l8lqcu4tl1rj2xdks9bz:playlist:7yhLc9ygpxUaB2Tyx9A84m
Feb 27 20:42:36 osmc java[23768]: 2019-02-27 20:42:36 TRACE SpotifyIrc:101 - Send frame, type: kMessageTypeNotify
Feb 27 20:42:36 osmc java[23768]: 2019-02-27 20:42:36 TRACE MercuryClient:104 - Send Mercury request, seq: 3, uri: hm://metadata/4/track/892F34400D7B4CB5B3948E362A14CA69, method: GET
Feb 27 20:42:36 osmc java[23768]: 2019-02-27 20:42:36 TRACE MercuryClient:104 - Send Mercury request, seq: 4, uri: hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/, method: SEND
Feb 27 20:42:36 osmc java[23768]: 2019-02-27 20:42:36 TRACE MercuryClient:146 - Handling packet, cmd: MercuryReq, seq: 4, flags: 1, parts: 1
Feb 27 20:42:36 osmc java[23768]: 2019-02-27 20:42:36 TRACE SpotifyIrc:115 - Frame sent successfully, type: kMessageTypeNotify
Feb 27 20:42:36 osmc java[23768]: 2019-02-27 20:42:36 TRACE SpotifyIrc:101 - Send frame, type: kMessageTypeNotify
Feb 27 20:42:36 osmc java[23768]: 2019-02-27 20:42:36 TRACE MercuryClient:104 - Send Mercury request, seq: 5, uri: hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/, method: SEND
Feb 27 20:42:36 osmc java[23768]: 2019-02-27 20:42:36 TRACE MercuryClient:146 - Handling packet, cmd: MercuryReq, seq: 3, flags: 1, parts: 2
Feb 27 20:42:36 osmc java[23768]: 2019-02-27 20:42:36 TRACE MercuryClient:146 - Handling packet, cmd: MercuryReq, seq: 5, flags: 1, parts: 1
Feb 27 20:42:36 osmc java[23768]: 2019-02-27 20:42:36 TRACE SpotifyIrc:115 - Frame sent successfully, type: kMessageTypeNotify
Feb 27 20:42:36 osmc java[23768]: 2019-02-27 20:42:36 INFO  Session:676 - Skipping UnknownData_AllZeros
Feb 27 20:42:37 osmc java[23768]: 2019-02-27 20:42:37 TRACE AudioFileStreaming:69 - Track size: 9064592
Feb 27 20:42:37 osmc java[23768]: 2019-02-27 20:42:37 TRACE AudioFileStreaming:71 - Track has 70 chunks.
Feb 27 20:42:37 osmc java[23768]: 2019-02-27 20:42:37 TRACE MercuryClient:146 - Handling packet, cmd: MercurySubEvent, seq: -7747249089263173632, flags: 1, parts: 2
Feb 27 20:42:37 osmc java[23768]: 2019-02-27 20:42:37 TRACE SpotifyIrc:191 - Handling frame, type: kMessageTypeNotify, ident: 8c1d42106a761e0625cef98e02fadfe6fb117a4c
Feb 27 20:42:37 osmc java[23768]: 2019-02-27 20:42:37 TRACE AudioFileStreaming:99 - Chunk 0/70 completed, cached: false, fileId: 1087F04B91E5FE94AE630DB6D29522C3CCFC7056
Feb 27 20:42:37 osmc java[23768]: 2019-02-27 20:42:37 TRACE StreamFeeder:59 - Loaded normalization data, track_gain: -9.27, track_peak: 1.07, album_gain: -9.27, album_peak: 1.07
Feb 27 20:42:37 osmc java[23768]: 2019-02-27 20:42:37 INFO  TrackHandler:50 - Loaded track, name: 'The Calling (Da Tweekaz Remix)', artists: 'TheFatRat, Laura Brehm', gid: 892F34400D7B4CB5B3948E362A14CA69
Feb 27 20:42:38 osmc java[23768]: 2019-02-27 20:42:38 INFO  LinesHolder:104 - Mixer for playback 'Device [default]', maxLines: 1
Feb 27 20:42:38 osmc java[23768]: 2019-02-27 20:42:38 DEBUG LinesHolder:69 - Got first line from mixer 'Device [default]'
Feb 27 20:42:38 osmc java[23768]: 2019-02-27 20:42:38 TRACE PlayerRunner:77 - Player ready for playback, fileId: 1087F04B91E5FE94AE630DB6D29522C3CCFC7056
Feb 27 20:42:38 osmc java[23768]: 2019-02-27 20:42:38 TRACE SpotifyIrc:101 - Send frame, type: kMessageTypeNotify
Feb 27 20:42:38 osmc java[23768]: 2019-02-27 20:42:38 TRACE MercuryClient:104 - Send Mercury request, seq: 6, uri: hm://remote/user/3va30l8lqcu4tl1rj2xdks9bz/, method: SEND
Feb 27 20:42:38 osmc java[23768]: 2019-02-27 20:42:38 TRACE AudioFileStreaming:99 - Chunk 1/70 completed, cached: false, fileId: 1087F04B91E5FE94AE630DB6D29522C3CCFC7056
Feb 27 20:42:38 osmc java[23768]: 2019-02-27 20:42:38 TRACE MercuryClient:146 - Handling packet, cmd: MercuryReq, seq: 6, flags: 1, parts: 1
Feb 27 20:42:38 osmc java[23768]: 2019-02-27 20:42:38 TRACE SpotifyIrc:115 - Frame sent successfully, type: kMessageTypeNotify
Feb 27 20:42:39 osmc java[23768]: 2019-02-27 20:42:39 TRACE AudioFileStreaming:99 - Chunk 39/70 completed, cached: false, fileId: 1087F04B91E5FE94AE630DB6D29522C3CCFC7056
Feb 27 20:42:39 osmc java[23768]: 2019-02-27 20:42:39 TRACE AudioFileStreaming:99 - Chunk 40/70 completed, cached: false, fileId: 1087F04B91E5FE94AE630DB6D29522C3CCFC7056

devgianlu · 2019-02-28T13:00:56Z

Looks fine to me. Isn't it?

loeffelpan · 2019-02-28T17:47:41Z

Unfortunately not.
First attempt isn’t successful.
Must choose Spotify Connect Device second time to be connected.

The same on my iPad and iPhone and Windows PC every first time after restarting the service.

crsmoro · 2019-02-28T17:55:30Z

That's true, it's happening the same here too..
first attempt unsuccessful, second ok

devgianlu · 2019-03-02T11:51:41Z

I've changed the logging a little bit. Could you run this again?

loeffelpan · 2019-03-02T15:47:36Z

Whatever you've done.
It's solved for me.

I tried to generate another stacktrace as you requested. But the first connection attempt is successful now.

devgianlu · 2019-03-02T16:34:02Z

@crsmoro Can you confirm?

crsmoro · 2019-03-02T19:51:13Z

unfortunately i’m not at home now (no pc), just on monday Em sáb, 2 de mar de 2019 às 13:34, Gianlu <[email protected]> escreveu:

…

@crsmoro <https://github.com/crsmoro> Can you confirm? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#48 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AA2lsRSyeDUzn46dvjT9SmBZMlDSOOkmks5vSqf6gaJpZM4a-paQ> .

crsmoro · 2019-03-04T23:45:24Z

i can confirm it's working, tested 3 times..
but what i mentioned here about the "no sound" part it's still happening, but now is only when click "next"..
but i think it's better to open a new issue about that..

devgianlu · 2019-03-05T06:31:52Z

I thought I had fixed that issue. I'll take a look today.

Closing this.

devgianlu added the bug Something isn't working label Feb 16, 2019

devgianlu closed this as completed in 803d1ad Feb 16, 2019

loeffelpan mentioned this issue Feb 16, 2019

BufferUnderflowExeption? #49

Closed

devgianlu reopened this Feb 28, 2019

devgianlu closed this as completed Mar 5, 2019

funtax mentioned this issue Mar 2, 2020

Deadlock after pause followed by seek #175

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Exception in thread "track-handler-3958962" java.lang.NullPointerException #48

Exception in thread "track-handler-3958962" java.lang.NullPointerException #48

loeffelpan commented Feb 16, 2019

loeffelpan commented Feb 24, 2019

devgianlu commented Feb 24, 2019 •

edited

Loading

loeffelpan commented Feb 27, 2019

devgianlu commented Feb 28, 2019

loeffelpan commented Feb 28, 2019

crsmoro commented Feb 28, 2019

devgianlu commented Mar 2, 2019

loeffelpan commented Mar 2, 2019

devgianlu commented Mar 2, 2019

crsmoro commented Mar 2, 2019 via email

crsmoro commented Mar 4, 2019 •

edited

Loading

devgianlu commented Mar 5, 2019

Exception in thread "track-handler-3958962" java.lang.NullPointerException #48

Exception in thread "track-handler-3958962" java.lang.NullPointerException #48

Comments

loeffelpan commented Feb 16, 2019

loeffelpan commented Feb 24, 2019

devgianlu commented Feb 24, 2019 • edited Loading

loeffelpan commented Feb 27, 2019

devgianlu commented Feb 28, 2019

loeffelpan commented Feb 28, 2019

crsmoro commented Feb 28, 2019

devgianlu commented Mar 2, 2019

loeffelpan commented Mar 2, 2019

devgianlu commented Mar 2, 2019

crsmoro commented Mar 2, 2019 via email

crsmoro commented Mar 4, 2019 • edited Loading

devgianlu commented Mar 5, 2019

devgianlu commented Feb 24, 2019 •

edited

Loading

crsmoro commented Mar 4, 2019 •

edited

Loading