Panic: zero-initalisation of ov_callbacks #719
Description
Description
I had successfully compiled and used Spotifyd for several days prior to this issue. I then decided I wanted to enable additional feature flags, so uninstalled the original instance and built again.
However, after installing this new instance, I receive the following log messages when trying to play music from a Connect-capable client:
No proxy specified
Using software volume controller.
Connecting to AP "gew1-accesspoint-b-qzv4.ap.spotify.com:443"
Authenticated as "USERNAME" !
Country: "GB"
Unhandled DBus message: (Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired"))
Unhandled DBus message: (Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired"))
Loading <Broken> with Spotify URI <spotify:track:6qF9QltwbDeujrVrzpCoLj>
Caught panic with message: attempted to zero-initialize type `librespot_tremor::tremor_sys::ov_callbacks`, which is invalid
Caught panic with message: called `Result::unwrap()` on an `Err` value: "SendError(..)"
Player thread panicked!
The application then exits.
Upon realising this, I attempted to rebuild the source with the original options and reinstall that, however the same error displays as above. I tried a variety of build options and appropriate configuration tweaking to no end, including using the crates.io release to no avail.
To Reproduce
Not something I can describe to reproduce, as it occurred suddenly and is persistent among rebuilds.
Logs
Click to show logs
Loading config from "/home/pi/.config/spotifyd/spotifyd.conf"CliConfig { config_path: None, no_daemon: true, verbose: true, pid: None, shared_config: SharedConfigValues { username: Some("taken out for privacy"), password: Some("taken out for privacy"), password_cmd: None, use_keyring: false, on_song_change_hook: None, cache_path: None, no-audio-cache: false, backend: Some(PulseAudio), volume_controller: None, device: None, control: None, mixer: None, device_name: Some("RaspberryPiTV"), bitrate: Some(Bitrate320), volume_normalisation: false, normalisation_pregain: None, zeroconf_port: None, proxy: None } }
Found shell "/bin/bash" using SHELL environment variable.
No proxy specified
registering with poller
registering with poller
registering with poller
registering with poller
build; num-workers=4
registering with poller
Using software volume controller.
starting background reactor
adding I/O source: 0
registering with poller
Zeroconf server listening on 0.0.0.0:37183
adding I/O source: 4194305
registering with poller
event Writable Token(4194305)
adding I/O source: 8388610
registering with poller
loop process - 1 events, 0.000s
event Writable Token(8388610)
loop process - 1 events, 0.000s
adding I/O source: 12582915
registering with poller
event Writable Token(12582915)
loop process - 1 events, 0.000s
park; waiting for idle connection: "http://apresolve.spotify.com"
Http::connect("http://apresolve.spotify.com/")
consuming notification queue
resolving host="apresolve.spotify.com", port=80
scheduling Read for: 0
scheduling Read for: 1
sending packet to 224.0.0.251:5353
event Readable | Writable Token(4194305)
loop process - 1 events, 0.000s
scheduling Read for: 2
sending packet to [ff02::fb]:5353
scheduling Read for: 3
loop poll - 1.90442ms
loop time - Instant { tv_sec: 5973, tv_nsec: 505571470 }
loop process, 41.351µs
event Readable | Writable Token(8388610)
loop process - 1 events, 0.000s
received packet from 192.168.1.182:5353
received packet from 192.168.1.182:5353 with no query
scheduling Read for: 1
scheduling Read for: 1
received packet from [fe80::6c2e:d9c1:337:5394]:5353
received packet from [fe80::6c2e:d9c1:337:5394]:5353 with no query
scheduling Read for: 2
scheduling Read for: 2
loop poll - 326.755µs
loop time - Instant { tv_sec: 5973, tv_nsec: 505963465 }
loop process, 36.055µs
scheduling Read for: 1
scheduling Read for: 2
loop poll - 45.666µs
loop time - Instant { tv_sec: 5973, tv_nsec: 506065445 }
loop process, 34µs
loop poll - 128.534738ms
loop time - Instant { tv_sec: 5973, tv_nsec: 634651312 }
loop process, 56.574µs
connecting to 34.98.74.57:80
adding I/O source: 16777220
registering with poller
scheduling Write for: 4
event Writable Token(16777220)
loop process - 1 events, 0.000s
loop poll - 18.134288ms
loop time - Instant { tv_sec: 5973, tv_nsec: 653032245 }
loop process, 22.926µs
read_keep_alive; is_mid_message=false
scheduling Read for: 4
should_keep_alive(version=Http11, header=None) = true
Client::encode has_body=false, method=None
reclaiming write buf Vec
flushed 47 bytes
flushed State { reading: Init, writing: KeepAlive, keep_alive: Busy, error: None }
wants_read_again? false
loop poll - 199.664µs
loop time - Instant { tv_sec: 5973, tv_nsec: 653334649 }
loop process, 16.074µs
event Readable | Writable Token(16777220)
loop process - 1 events, 0.000s
Conn::read_head
read 594 bytes
Response.parse([Header; 100], [u8; 594])
Response.parse Complete(176)
maybe_literal not found, copying "Via"
parsed 5 headers (176 bytes)
incoming body is content-length (418 bytes)
expecting_continue(version=Http11, header=None) = false
should_keep_alive(version=Http11, header=None) = true
Conn::read_body
decode; state=Length(418)
flushed State { reading: Body(Length(0)), writing: KeepAlive, keep_alive: Busy, error: None }
wants_read_again? false
loop poll - 27.867997ms
loop time - Instant { tv_sec: 5973, tv_nsec: 681227461 }
loop process, 18.445µs
Conn::read_body
decode; state=Length(0)
incoming body completed
scheduling Read for: 4
maybe_notify; read_from_io blocked
read_keep_alive; is_mid_message=false
scheduling Read for: 4
signal: Want
flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
wants_read_again? false
poll_want: taker wants!
pool dropped, dropping pooled ("http://apresolve.spotify.com")
loop poll - 169.128µs
loop time - Instant { tv_sec: 5973, tv_nsec: 681475440 }
loop process, 17.796µs
Connecting to AP "gew1-accesspoint-b-n2lk.ap.spotify.com:443"
adding I/O source: 20971525
registering with poller
scheduling Write for: 5
read_keep_alive; is_mid_message=false
scheduling Read for: 4
client tx closed
State::close_read()
State::close_write()
flushed State { reading: Closed, writing: Closed, keep_alive: Disabled, error: None }
wants_read_again? false
shut down IO
deregistering handle with poller
dropping I/O source: 4
signal: Closed
loop poll - 152.628µs
loop time - Instant { tv_sec: 5973, tv_nsec: 814064256 }
loop process, 18.722µs
event Writable Token(20971525)
loop process - 1 events, 0.000s
loop poll - 24.842684ms
loop time - Instant { tv_sec: 5973, tv_nsec: 838934625 }
loop process, 22.519µs
scheduling Read for: 5
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
loop poll - 22.965875ms
loop time - Instant { tv_sec: 5973, tv_nsec: 884802432 }
loop process, 22.981µs
flushing framed transport
writing; remaining=133
framed transport flushed
scheduling Read for: 5
event Readable | Writable Token(4194305)
loop process - 1 events, 0.000s
received packet from 192.168.1.237:5353
scheduling Read for: 1
scheduling Read for: 1
scheduling Read for: 2
loop poll - 179.811013ms
loop time - Instant { tv_sec: 5974, tv_nsec: 87816409 }
loop process, 22.759µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
loop poll - 619.45243ms
loop time - Instant { tv_sec: 5974, tv_nsec: 707304894 }
loop process, 119.943µs
attempting to decode a frame
frame decoded from buffer
Authenticated as "REDACTED" !
new Session[0]
new Spirc[0]
new MercuryManager
input volume:65535 to mixer: 65535
attempting to decode a frame
frame decoded from buffer
Session[0] strong=4 weak=2
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
frame decoded from buffer
Country: "GB"
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
writing; remaining=876
framed transport flushed
loop poll - 562.548µs
loop time - Instant { tv_sec: 5974, tv_nsec: 708687302 }
loop process, 40.351µs
new Player[0]
Using PulseAudio sink
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 17.572444ms
loop time - Instant { tv_sec: 5974, tv_nsec: 726319912 }
loop process, 39.629µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 16.785861ms
loop time - Instant { tv_sec: 5974, tv_nsec: 743167309 }
loop process, 39.944µs
subscribed uri=hm://remote/user/REDACTED/ count=0
loop poll - 8.352µs
loop time - Instant { tv_sec: 5974, tv_nsec: 743305474 }
loop process, 38.499µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 2.744613ms
loop time - Instant { tv_sec: 5974, tv_nsec: 746107697 }
loop process, 37.463µs
Modify_watch: Watch { fd: 23, read: true, write: false }, poll_now: false
adding I/O source: 25165828
registering with poller
Dropping AConnection
scheduling Read for: 4
scheduling Read for: 4
D-Bus i/o poll ready: 23 is NotReady
handle_msgs: (Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired"))
handle_msgs: (Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired"))
loop poll - 216.682µs
loop time - Instant { tv_sec: 5974, tv_nsec: 751050023 }
loop process, 45.592µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 49.369448ms
loop time - Instant { tv_sec: 5974, tv_nsec: 800487322 }
loop process, 44.703µs
Polling message stream
msgstream found Ok(Ready(Some((Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired")))))
Unhandled DBus message: (Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired"))
Polling message stream
msgstream found Ok(Ready(Some((Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired")))))
Unhandled DBus message: (Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired"))
Polling message stream
msgstream found Ok(NotReady)
kMessageTypeNotify "Nokia 5.3" a0f1362bbbc96bff82ba9a7ebcfc56ffcacfdeda 1698217680 1605868501989
loop poll - 12.981µs
loop time - Instant { tv_sec: 5974, tv_nsec: 800946334 }
loop process, 48.759µs
event Readable | Writable Token(4194305)
loop process - 1 events, 0.000s
received packet from 192.168.1.237:5353
scheduling Read for: 1
scheduling Read for: 1
scheduling Read for: 2
loop poll - 295.089105ms
loop time - Instant { tv_sec: 5975, tv_nsec: 96105753 }
loop process, 48.814µs
event Readable | Writable Token(4194305)
loop process - 1 events, 0.000s
received packet from 192.168.1.237:5353
scheduling Read for: 1
scheduling Read for: 1
scheduling Read for: 2
loop poll - 4.213226017s
loop time - Instant { tv_sec: 5979, tv_nsec: 309408065 }
loop process, 21.741µs
event Readable | Writable Token(4194305)
loop process - 1 events, 0.000s
received packet from 192.168.1.237:5353
scheduling Read for: 1
scheduling Read for: 1
sending packet to 224.0.0.251:5353
event Readable | Writable Token(4194305)
loop process - 1 events, 0.000s
event Readable | Writable Token(4194305)
loop process - 1 events, 0.000s
scheduling Read for: 2
loop poll - 196.614689ms
loop time - Instant { tv_sec: 5979, tv_nsec: 506057828 }
loop process, 22.703µs
received packet from 192.168.1.182:5353
received packet from 192.168.1.182:5353 with no query
scheduling Read for: 1
scheduling Read for: 1
scheduling Read for: 2
loop poll - 74.851µs
loop time - Instant { tv_sec: 5979, tv_nsec: 506169549 }
loop process, 17.518µs
event Readable Token(0)
loop process - 1 events, 0.000s
scheduling Read for: 0
loop poll - 66.485193ms
loop time - Instant { tv_sec: 5979, tv_nsec: 572681649 }
loop process, 20.259µs
Conn::read_head
adding I/O source: 29360134
registering with poller
scheduling Read for: 6
event Writable Token(29360134)
loop process - 1 events, 0.000s
flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
wants_read_again? false
loop poll - 107.906µs
loop time - Instant { tv_sec: 5979, tv_nsec: 572822221 }
loop process, 16.407µs
event Readable | Writable Token(29360134)
loop process - 1 events, 0.000s
Conn::read_head
read 222 bytes
Request.parse([Header; 100], [u8; 222])
Request.parse Complete(222)
maybe_literal not found, copying "Keep-Alive"
parsed 6 headers (222 bytes)
incoming body is content-length (0 bytes)
expecting_continue(version=Http11, header=None) = false
should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
read_keep_alive; is_mid_message=true
should_keep_alive(version=Http11, header=None) = true
Server::encode has_body=true, method=Some(Get)
encoding chunked 450B
flushed 546 bytes
scheduling Read for: 6
maybe_notify; read_from_io blocked
flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
wants_read_again? false
loop poll - 1.541295ms
loop time - Instant { tv_sec: 5979, tv_nsec: 574388849 }
loop process, 18.092µs
event Readable | Writable Token(29360134)
loop process - 1 events, 0.000s
Conn::read_head
read 0 bytes
parse eof
State::close_read()
read eof
read_keep_alive; is_mid_message=true
flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
wants_read_again? false
shut down IO
deregistering handle with poller
dropping I/O source: 6
loop poll - 3.530881ms
loop time - Instant { tv_sec: 5979, tv_nsec: 577948026 }
loop process, 17.259µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 294.498761ms
loop time - Instant { tv_sec: 5979, tv_nsec: 872473657 }
loop process, 47.518µs
Polling message stream
msgstream found Ok(NotReady)
kMessageTypeHello "Nokia 5.3" a0f1362bbbc96bff82ba9a7ebcfc56ffcacfdeda 1698222811 1605868507120
scheduling Read for: 5
flushing framed transport
writing; remaining=393
framed transport flushed
loop poll - 212.275µs
loop time - Instant { tv_sec: 5979, tv_nsec: 873014465 }
loop process, 43.981µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 27.351412ms
loop time - Instant { tv_sec: 5979, tv_nsec: 900432468 }
loop process, 46.426µs
Polling message stream
msgstream found Ok(NotReady)
loop poll - 12.148µs
loop time - Instant { tv_sec: 5979, tv_nsec: 900612003 }
loop process, 49.203µs
event Readable | Writable Token(4194305)
loop process - 1 events, 0.000s
received packet from 192.168.1.237:5353
scheduling Read for: 1
scheduling Read for: 1
scheduling Read for: 2
loop poll - 407.842414ms
loop time - Instant { tv_sec: 5980, tv_nsec: 308527657 }
loop process, 47.777µs
event Readable Token(0)
loop process - 1 events, 0.000s
scheduling Read for: 0
loop poll - 220.500978ms
loop time - Instant { tv_sec: 5980, tv_nsec: 529104893 }
loop process, 47.907µs
Conn::read_head
adding I/O source: 33554438
registering with poller
scheduling Read for: 6
event Writable Token(33554438)
loop process - 1 events, 0.000s
flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
wants_read_again? false
loop poll - 268.849µs
loop time - Instant { tv_sec: 5980, tv_nsec: 529448093 }
loop process, 58.462µs
event Readable | Writable Token(33554438)
loop process - 1 events, 0.000s
Conn::read_head
read 222 bytes
Request.parse([Header; 100], [u8; 222])
Request.parse Complete(222)
maybe_literal not found, copying "Keep-Alive"
parsed 6 headers (222 bytes)
incoming body is content-length (0 bytes)
expecting_continue(version=Http11, header=None) = false
should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
read_keep_alive; is_mid_message=true
should_keep_alive(version=Http11, header=None) = true
Server::encode has_body=true, method=Some(Get)
encoding chunked 450B
flushed 546 bytes
scheduling Read for: 6
maybe_notify; read_from_io blocked
flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
wants_read_again? false
loop poll - 847.934µs
loop time - Instant { tv_sec: 5980, tv_nsec: 530378970 }
loop process, 43.407µs
event Readable | Writable Token(33554438)
loop process - 1 events, 0.000s
Conn::read_head
read 0 bytes
parse eof
State::close_read()
read eof
read_keep_alive; is_mid_message=true
flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
wants_read_again? false
shut down IO
deregistering handle with poller
dropping I/O source: 6
loop poll - 7.834475ms
loop time - Instant { tv_sec: 5980, tv_nsec: 538281777 }
loop process, 47.296µs
event Readable | Writable Token(4194305)
loop process - 1 events, 0.000s
received packet from 192.168.1.237:5353
scheduling Read for: 1
scheduling Read for: 1
sending packet to 224.0.0.251:5353
scheduling Read for: 2
loop poll - 77.209149ms
loop time - Instant { tv_sec: 5980, tv_nsec: 615564184 }
loop process, 45.148µs
event Readable | Writable Token(4194305)
loop process - 1 events, 0.000s
received packet from 192.168.1.182:5353
received packet from 192.168.1.182:5353 with no query
scheduling Read for: 1
scheduling Read for: 1
scheduling Read for: 2
loop poll - 318.811µs
loop time - Instant { tv_sec: 5980, tv_nsec: 615953865 }
loop process, 39.129µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 227.069635ms
loop time - Instant { tv_sec: 5980, tv_nsec: 843083388 }
loop process, 46.537µs
Polling message stream
msgstream found Ok(NotReady)
kMessageTypeNotify "Nokia 5.3" a0f1362bbbc96bff82ba9a7ebcfc56ffcacfdeda 1698223783 1605868508092
loop poll - 10.407µs
loop time - Instant { tv_sec: 5980, tv_nsec: 843346959 }
loop process, 44.536µs
event Readable | Writable Token(4194305)
loop process - 1 events, 0.000s
received packet from 192.168.1.237:5353
scheduling Read for: 1
scheduling Read for: 1
scheduling Read for: 2
loop poll - 478.45311ms
loop time - Instant { tv_sec: 5981, tv_nsec: 321866568 }
loop process, 41.704µs
event Readable Token(0)
loop process - 1 events, 0.000s
scheduling Read for: 0
loop poll - 938.291809ms
loop time - Instant { tv_sec: 5982, tv_nsec: 260224080 }
loop process, 48.315µs
Conn::read_head
adding I/O source: 37748742
registering with poller
event Readable | Writable Token(37748742)
loop process - 1 events, 0.000s
read 222 bytes
Request.parse([Header; 100], [u8; 222])
Request.parse Complete(222)
maybe_literal not found, copying "Keep-Alive"
parsed 6 headers (222 bytes)
incoming body is content-length (0 bytes)
expecting_continue(version=Http11, header=None) = false
should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
read_keep_alive; is_mid_message=true
should_keep_alive(version=Http11, header=None) = true
Server::encode has_body=true, method=Some(Get)
encoding chunked 450B
flushed 546 bytes
scheduling Read for: 6
maybe_notify; read_from_io blocked
flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
wants_read_again? false
loop poll - 843.86µs
loop time - Instant { tv_sec: 5982, tv_nsec: 261142976 }
loop process, 42.648µs
event Readable | Writable Token(37748742)
loop process - 1 events, 0.000s
Conn::read_head
read 0 bytes
parse eof
State::close_read()
read eof
read_keep_alive; is_mid_message=true
flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
wants_read_again? false
shut down IO
deregistering handle with poller
dropping I/O source: 6
loop poll - 2.008289ms
loop time - Instant { tv_sec: 5982, tv_nsec: 263217857 }
loop process, 43.518µs
event Readable | Writable Token(4194305)
loop process - 1 events, 0.000s
received packet from 192.168.1.237:5353
scheduling Read for: 1
scheduling Read for: 1
sending packet to 224.0.0.251:5353
event Readable | Writable Token(4194305)
loop process - 1 events, 0.000s
scheduling Read for: 2
loop poll - 93.033412ms
loop time - Instant { tv_sec: 5982, tv_nsec: 356318842 }
loop process, 49.073µs
received packet from 192.168.1.182:5353
received packet from 192.168.1.182:5353 with no query
scheduling Read for: 1
scheduling Read for: 1
scheduling Read for: 2
loop poll - 221.33µs
loop time - Instant { tv_sec: 5982, tv_nsec: 356617671 }
loop process, 44.907µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 259.871256ms
loop time - Instant { tv_sec: 5982, tv_nsec: 616556834 }
loop process, 49.444µs
Polling message stream
msgstream found Ok(NotReady)
kMessageTypeNotify "Nokia 5.3" a0f1362bbbc96bff82ba9a7ebcfc56ffcacfdeda 1698225544 1605868509853
loop poll - 12.573µs
loop time - Instant { tv_sec: 5982, tv_nsec: 616906329 }
loop process, 53.907µs
event Readable Token(0)
loop process - 1 events, 0.000s
scheduling Read for: 0
loop poll - 543.555099ms
loop time - Instant { tv_sec: 5983, tv_nsec: 160539298 }
loop process, 43.388µs
Conn::read_head
adding I/O source: 41943046
registering with poller
event Readable | Writable Token(41943046)
loop process - 1 events, 0.000s
read 222 bytes
Request.parse([Header; 100], [u8; 222])
Request.parse Complete(222)
maybe_literal not found, copying "Keep-Alive"
parsed 6 headers (222 bytes)
incoming body is content-length (0 bytes)
expecting_continue(version=Http11, header=None) = false
should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
read_keep_alive; is_mid_message=true
should_keep_alive(version=Http11, header=None) = true
Server::encode has_body=true, method=Some(Get)
encoding chunked 450B
flushed 546 bytes
scheduling Read for: 6
maybe_notify; read_from_io blocked
flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
wants_read_again? false
loop poll - 787.379µs
loop time - Instant { tv_sec: 5983, tv_nsec: 161394954 }
loop process, 38.092µs
event Readable | Writable Token(41943046)
loop process - 1 events, 0.000s
Conn::read_head
read 0 bytes
parse eof
State::close_read()
read eof
read_keep_alive; is_mid_message=true
flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
wants_read_again? false
shut down IO
deregistering handle with poller
dropping I/O source: 6
loop poll - 4.593349ms
loop time - Instant { tv_sec: 5983, tv_nsec: 166047450 }
loop process, 43.944µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 41.998152ms
loop time - Instant { tv_sec: 5983, tv_nsec: 208114046 }
loop process, 41.425µs
Polling message stream
msgstream found Ok(NotReady)
kMessageTypeLoad "Nokia 5.3" a0f1362bbbc96bff82ba9a7ebcfc56ffcacfdeda 1698226110 1605868509853
State: context_uri: "spotify:album:69fOwmdCZIaWPE4OLLnuQi" index: 2 position_ms: 7039 status: kPlayStatusPause position_measured_at: 1605868510465 context_description: "" shuffle: false repeat: false playing_from_fallback: true row: 0 playing_track_index: 2 track {gid: "\031\327?\022\326@J\305\246*\272\372\235\n\334%"} track {gid: "#(\261\262\022\310G\235\267.O\203\333v8\366"} track {gid: "\323E\211\022\224\232NA\257o\303\371X\236-\025"} track {gid: "2|8p\322^Kl\203\321Loz\351\363e"} track {gid: "oUlG\312\005HF\210\266s!\3548\210m"} track {gid: "\350\312\377(\233|E.\252x\302k*\256\326A"} track {gid: "%\002\306[\262\023D\313\253\302V\213-Y\000\265"} track {gid: "_\372\34678\377MR\254\034\321\333\3013\036e"} track {gid: "?\357\312\321\336NK\022\242\343\226c\301~#\203"} track {gid: "\200\022\345\251\2455C[\246\245\271\352\206\031\2504"} track {gid: "\211\320!W/\H\221\203hN\376<6\361\220"} track {gid: "\275\261\002\316\377DI\231\221\252l\032Q\267l\205"} track {gid: "\201\345-\2178BG\213\255\306\231\211\322&"} track {gid: "\344<7!t\036C\005\227:y\242G\037\302\373"} track {gid: "\310\252\t\254\343AM\336\253\230\206JRa\310~"} track {gid: "$\327*\310\237cK\340\256\231\353\215\215\365\200\"} track {gid: "\252\365\n\227r\023O\272\251\023\234\352H\251\335\345"} track {gid: "\306\017\265\0252<EA\270\300\254#\316\306\206@"} track {gid: "@ty\372\201\251G\377\220\213\r\221\302\333\202\331"}
Frame has 19 tracks
Loading context: spotify:album:69fOwmdCZIaWPE4OLLnuQi index: [2] of 19
command=Load(SpotifyId { id: 280828155756069103410723341265459358997, audio_type: Track }, false, 7039)
scheduling Read for: 5
flushing framed transport
writing; remaining=899
framed transport flushed
loop poll - 198.812µs
loop time - Instant { tv_sec: 5983, tv_nsec: 209566175 }
loop process, 40.203µs
event Readable | Writable Token(4194305)
loop process - 1 events, 0.000s
received packet from 192.168.1.237:5353
scheduling Read for: 1
scheduling Read for: 1
sending packet to 224.0.0.251:5353
event Readable | Writable Token(4194305)
loop process - 1 events, 0.000s
scheduling Read for: 2
loop poll - 9.944059ms
loop time - Instant { tv_sec: 5983, tv_nsec: 219570696 }
loop process, 44.148µs
received packet from 192.168.1.182:5353
received packet from 192.168.1.182:5353 with no query
scheduling Read for: 1
scheduling Read for: 1
scheduling Read for: 2
loop poll - 167.257µs
loop time - Instant { tv_sec: 5983, tv_nsec: 219807786 }
loop process, 40.777µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 13.378034ms
loop time - Instant { tv_sec: 5983, tv_nsec: 233247819 }
loop process, 46.814µs
Polling message stream
msgstream found Ok(NotReady)
Loading with Spotify URI spotify:track:6qF9QltwbDeujrVrzpCoLj
new AudioKeyManager
loop poll - 12µs
loop time - Instant { tv_sec: 5983, tv_nsec: 233424817 }
loop process, 141.387µs
Downloading file 18e55e1787e41646e9d2725de2f0c9648c046ee0
requesting chunk 0
new ChannelManager
scheduling Read for: 5
flushing framed transport
writing; remaining=102
framed transport flushed
loop poll - 345.07µs
loop time - Instant { tv_sec: 5983, tv_nsec: 233940218 }
loop process, 47.036µs
consuming notification queue
loop poll - 105.147µs
loop time - Instant { tv_sec: 5983, tv_nsec: 234118882 }
loop process, 52.203µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 24.65365ms
loop time - Instant { tv_sec: 5983, tv_nsec: 258847753 }
loop process, 44.685µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 13.338442ms
loop time - Instant { tv_sec: 5983, tv_nsec: 272257268 }
loop process, 47.703µs
consuming notification queue
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
loop poll - 384.828µs
loop time - Instant { tv_sec: 5983, tv_nsec: 272715392 }
loop process, 45.499µs
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 115.499µs
loop time - Instant { tv_sec: 5983, tv_nsec: 272900223 }
loop process, 41.037µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 5.391635ms
loop time - Instant { tv_sec: 5983, tv_nsec: 278354765 }
loop process, 41.777µs
loop poll - 46.869µs
loop time - Instant { tv_sec: 5983, tv_nsec: 278465763 }
loop process, 42.815µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
attempting to decode a frame
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 12.544063ms
loop time - Instant { tv_sec: 5983, tv_nsec: 291074196 }
loop process, 49.166µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
loop poll - 322.348µs
loop time - Instant { tv_sec: 5983, tv_nsec: 291470821 }
loop process, 78.906µs
attempting to decode a frame
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 1.434075ms
loop time - Instant { tv_sec: 5983, tv_nsec: 293007468 }
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
loop process, 318.922µs
attempting to decode a frame
attempting to decode a frame
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 921.878µs
loop time - Instant { tv_sec: 5983, tv_nsec: 294275989 }
loop process, 43.758µs
loop poll - 80.61µs
loop time - Instant { tv_sec: 5983, tv_nsec: 294424172 }
loop process, 43.222µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 829.805µs
loop time - Instant { tv_sec: 5983, tv_nsec: 295319124 }
loop process, 41.61µs
loop poll - 44.759µs
loop time - Instant { tv_sec: 5983, tv_nsec: 295427863 }
loop process, 42.129µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 3.165756ms
loop time - Instant { tv_sec: 5983, tv_nsec: 298657118 }
loop process, 41.277µs
loop poll - 46.221µs
loop time - Instant { tv_sec: 5983, tv_nsec: 298766783 }
loop process, 42.204µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 16.197906ms
loop time - Instant { tv_sec: 5983, tv_nsec: 315028244 }
loop process, 44.962µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 5.874888ms
loop time - Instant { tv_sec: 5983, tv_nsec: 321299090 }
loop process, 48.573µs
loop poll - 537.234µs
loop time - Instant { tv_sec: 5983, tv_nsec: 321912767 }
loop process, 44.129µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 15.654931ms
loop time - Instant { tv_sec: 5983, tv_nsec: 337634031 }
loop process, 39.814µs
chunk 0 / 26 complete
requesting chunk 1
loop poll - 146.72µs
loop time - Instant { tv_sec: 5983, tv_nsec: 337842824 }
loop process, 39.426µs
scheduling Read for: 5
Normalisation Data: NormalisationData { track_gain_db: -6.9300003, track_peak: 0.9973827, album_gain_db: -10.010002, album_peak: 1.0153364 }
Applied normalisation factor: 0.45029798
flushing framed transport
writing; remaining=53
Caught panic with message: attempted to zero-initialize type librespot_tremor::tremor_sys::ov_callbacks, which is invalid
framed transport flushed
loop poll - 289.238µs
loop time - Instant { tv_sec: 5983, tv_nsec: 338198487 }
loop process, 50.258µs
loop poll - 16.778µs
loop time - Instant { tv_sec: 5983, tv_nsec: 338295245 }
loop process, 49.036µs
drop Player[0]
loop poll - 474.254µs
loop time - Instant { tv_sec: 5983, tv_nsec: 338848775 }
loop process, 44.647µs
Polling message stream
msgstream found Ok(NotReady)
loop poll - 14.74µs
loop time - Instant { tv_sec: 5983, tv_nsec: 339007976 }
loop process, 38.537µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 33.415502ms
loop time - Instant { tv_sec: 5983, tv_nsec: 372480922 }
loop process, 41.962µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 18.377471ms
loop time - Instant { tv_sec: 5983, tv_nsec: 390924947 }
loop process, 41.703µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 17.24143ms
loop time - Instant { tv_sec: 5983, tv_nsec: 408231820 }
loop process, 39.666µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 57.642046ms
loop time - Instant { tv_sec: 5983, tv_nsec: 465937365 }
loop process, 46.647µs
Polling message stream
msgstream found Ok(NotReady)
kMessageTypeNotify "Nokia 5.3" a0f1362bbbc96bff82ba9a7ebcfc56ffcacfdeda 1698226403 1605868510712
loop poll - 12.5µs
loop time - Instant { tv_sec: 5983, tv_nsec: 466218380 }
loop process, 45.999µs
event Readable | Writable Token(20971525)
loop process - 1 events, 0.000s
attempting to decode a frame
frame decoded from buffer
attempting to decode a frame
scheduling Read for: 5
flushing framed transport
framed transport flushed
loop poll - 1.208130976s
loop time - Instant { tv_sec: 5984, tv_nsec: 674418207 }
loop process, 41.963µs
Polling message stream
msgstream found Ok(NotReady)
kMessageTypePlay "Nokia 5.3" a0f1362bbbc96bff82ba9a7ebcfc56ffcacfdeda 1698227616 1605868510712
Caught panic with message: called Result::unwrap() on an Err value: "SendError(..)"
drop Spirc[0]
Shutting down player thread ...
Player thread panicked!
drop Session[0]
drop AudioKeyManager
drop ChannelManager
drop MercuryManager
Dropping AMessageStream
AMessageStream telling ADriver to quit
shutdown; state=pool::State { lifecycle: Running, num_futures: 0 }
-> transitioned to shutdown
-> shutting down workers
dropping I/O source: 3
dropping I/O source: 4
deregistering handle with poller
dropping I/O source: 0
deregistering handle with poller
dropping I/O source: 1
deregistering handle with poller
dropping I/O source: 2
drop Dispatch
deregistering handle with poller
dropping I/O source: 5
Compilation flags
- dbus_mpris
- dbus_keyring
- alsa_backend
- portaudio_backend
- pulseaudio_backend
- rodio_backend
Note that this occurs regardless of features enabled; the working version originally only had alsa_backend enabled, and this no longer works.
Versions (please complete the following information):
- OS: Raspian Buster (armhf) on Kernel 5.4.75-v7l+
- Spotifyd: v0.2.24, both crates.io release and 39106ed
- cargo: cargo 1.48.0 (65cbdd2dc 2020-10-14)