200313_ncspot.log

[2020-03-13][11:41:44] [ncspot::config] [TRACE] "C:\\Users\\jonas.frei\\.config\\ncspot\\config"
[2020-03-13][11:41:44] [ncspot::config] [TRACE] "C:\\Users\\jonas.frei\\.config\\ncspot\\config"
[2020-03-13][11:41:44] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:44] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:44] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:44] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:44] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:44] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:44] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:44] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:44] [tokio_threadpool::builder] [TRACE] build; num-workers=8
[2020-03-13][11:41:44] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:44] [ncspot::spotify] [INFO] Setting HTTP proxy http://127.0.0.1:9999
[2020-03-13][11:41:44] [tokio_reactor::background] [DEBUG] starting background reactor
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:44] [hyper::client::pool] [TRACE] park; waiting for idle connection: "http://apresolve.spotify.com"
[2020-03-13][11:41:44] [hyper::client::connect] [TRACE] Http::connect("http://127.0.0.1:9999/")
[2020-03-13][11:41:44] [hyper::client::connect] [DEBUG] connecting to 127.0.0.1:9999
[2020-03-13][11:41:44] [tokio_reactor] [DEBUG] adding I/O source: 0
[2020-03-13][11:41:44] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] register Token(0) Readable | Writable
[2020-03-13][11:41:44] [mio::sys::windows::tcp] [TRACE] scheduling a connect
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:41:44] [tokio_reactor::registration] [DEBUG] scheduling Write for: 0
[2020-03-13][11:41:44] [mio::sys::windows::tcp] [TRACE] finished a connect
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] consuming notification queue
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:44] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop poll - 107.152µs
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190097.220745105s }
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] event Writable Token(0)
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop process, 131.393µs
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:44] [hyper::proto::h1::conn] [TRACE] read_keep_alive; is_mid_message=false
[2020-03-13][11:41:44] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:41:44] [hyper::proto] [TRACE] should_keep_alive(version=Http11, header=None) = true
[2020-03-13][11:41:44] [hyper::proto::h1::role] [TRACE] Client::encode has_body=false, method=None
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] set readiness to (empty)
[2020-03-13][11:41:44] [mio::sys::windows::tcp] [TRACE] scheduling a write of 75 bytes
[2020-03-13][11:41:44] [mio::sys::windows::tcp] [TRACE] done immediately with 75 bytes
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:44] [hyper::proto::h1::io] [TRACE] reclaiming write buf Vec
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:44] [hyper::proto::h1::io] [DEBUG] flushed 75 bytes
[2020-03-13][11:41:44] [hyper::proto::h1::conn] [TRACE] flushed State { reading: Init, writing: KeepAlive, keep_alive: Busy, error: None }
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] event Writable Token(0)
[2020-03-13][11:41:44] [hyper::proto::h1::conn] [TRACE] wants_read_again? false
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop poll - 936.727µs
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190097.222105589s }
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop process, 112µs
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:41:44] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] event Readable | Writable Token(0)
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:44] [hyper::proto::h1::conn] [TRACE] Conn::read_head
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:41:44] [hyper::proto::h1::io] [DEBUG] read 736 bytes
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:44] [hyper::proto::h1::role] [TRACE] Response.parse([Header; 100], [u8; 736])
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:44] [hyper::proto::h1::role] [TRACE] Response.parse Complete(318)
[2020-03-13][11:41:44] [hyper::header] [TRACE] maybe_literal not found, copying "Via"
[2020-03-13][11:41:44] [hyper::header] [TRACE] maybe_literal not found, copying "Keep-Alive"
[2020-03-13][11:41:44] [hyper::header] [TRACE] maybe_literal not found, copying "Via"
[2020-03-13][11:41:44] [hyper::proto::h1::io] [DEBUG] parsed 9 headers (318 bytes)
[2020-03-13][11:41:44] [hyper::proto::h1::conn] [DEBUG] incoming body is content-length (418 bytes)
[2020-03-13][11:41:44] [hyper::proto] [TRACE] expecting_continue(version=Http11, header=None) = false
[2020-03-13][11:41:44] [hyper::proto] [TRACE] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
[2020-03-13][11:41:44] [hyper::proto::h1::conn] [TRACE] Conn::read_body
[2020-03-13][11:41:44] [hyper::proto::h1::decode] [TRACE] decode; state=Length(418)
[2020-03-13][11:41:44] [hyper::proto::h1::conn] [TRACE] flushed State { reading: Body(Length(0)), writing: KeepAlive, keep_alive: Busy, error: None }
[2020-03-13][11:41:44] [hyper::proto::h1::conn] [TRACE] wants_read_again? false
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop poll - 144.430476ms
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190097.366703337s }
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop process, 55.273µs
[2020-03-13][11:41:44] [hyper::proto::h1::conn] [TRACE] Conn::read_body
[2020-03-13][11:41:44] [hyper::proto::h1::decode] [TRACE] decode; state=Length(0)
[2020-03-13][11:41:44] [hyper::proto::h1::conn] [DEBUG] incoming body completed
[2020-03-13][11:41:44] [hyper::proto::h1::io] [DEBUG] read 0 bytes
[2020-03-13][11:41:44] [hyper::proto::h1::conn] [TRACE] read_keep_alive; is_mid_message=false
[2020-03-13][11:41:44] [hyper::proto::h1::io] [DEBUG] read 0 bytes
[2020-03-13][11:41:44] [hyper::proto::h1::conn] [TRACE] try_io_read; found EOF on connection: State { reading: Init, writing: Init, keep_alive: Idle, error: None }
[2020-03-13][11:41:44] [hyper::proto::h1::conn] [TRACE] State::close_read()
[2020-03-13][11:41:44] [hyper::proto::h1::conn] [TRACE] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
[2020-03-13][11:41:44] [hyper::proto::h1::conn] [TRACE] wants_read_again? false
[2020-03-13][11:41:44] [hyper::proto::h1::conn] [TRACE] shut down IO
[2020-03-13][11:41:44] [mio::poll] [TRACE] deregistering handle with poller
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] deregistering
[2020-03-13][11:41:44] [tokio_reactor] [DEBUG] dropping I/O source: 0
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:44] [want] [TRACE] signal: Closed
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop poll - 789.818µs
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190097.367728306s }
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop process, 73.697µs
[2020-03-13][11:41:44] [librespot_core::session] [INFO] Connecting to AP "gew1-accesspoint-b-dq2m.ap.spotify.com:443"
[2020-03-13][11:41:44] [librespot_core::connection] [INFO] Using proxy "http://127.0.0.1:9999/"
[2020-03-13][11:41:44] [tokio_reactor] [DEBUG] adding I/O source: 4194304
[2020-03-13][11:41:44] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] register Token(4194304) Readable | Writable
[2020-03-13][11:41:44] [mio::sys::windows::tcp] [TRACE] scheduling a connect
[2020-03-13][11:41:44] [tokio_reactor::registration] [DEBUG] scheduling Write for: 0
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop poll - 19.879µs
[2020-03-13][11:41:44] [mio::sys::windows::tcp] [TRACE] finished a connect
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190097.368448306s }
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop process, 83.878µs
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:44] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop poll - 278.303µs
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190097.36888176s }
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop process, 81.939µs
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] set readiness to (empty)
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:44] [mio::sys::windows::tcp] [TRACE] scheduling a write of 63 bytes
[2020-03-13][11:41:44] [mio::sys::windows::tcp] [TRACE] done immediately with 63 bytes
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:44] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:41:44] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] event Readable | Writable Token(4194304)
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop poll - 164.128405ms
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190097.533516347s }
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop process, 96µs
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] set readiness to Readable
[2020-03-13][11:41:44] [mio::sys::windows::tcp] [TRACE] scheduling a write of 151 bytes
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] event Readable Token(4194304)
[2020-03-13][11:41:44] [mio::sys::windows::tcp] [TRACE] done immediately with 151 bytes
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:44] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:44] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:41:44] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] event Readable | Writable Token(4194304)
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop poll - 61.145182ms
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190097.726920859s }
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:44] [tokio_core::reactor] [DEBUG] loop process, 96µs
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:44] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:44] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] set readiness to Readable
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] scheduling a write of 36 bytes
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] event Readable Token(4194304)
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] done immediately with 36 bytes
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] event Readable | Writable Token(4194304)
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:45] [tokio_io::_tokio_codec::framed_write] [TRACE] flushing framed transport
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [tokio_io::_tokio_codec::framed_write] [TRACE] writing; remaining=125
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] set readiness to Readable
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] scheduling a write of 125 bytes
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] done immediately with 125 bytes
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] event Readable Token(4194304)
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:45] [tokio_io::_tokio_codec::framed_write] [TRACE] framed transport flushed
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=Some(0ns)
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] event Readable | Writable Token(4194304)
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop poll - 363.156187ms
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190098.226938071s }
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop process, 88.728µs
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:41:45] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:41:45] [librespot_core::session] [INFO] Authenticated as "xxx" !
[2020-03-13][11:41:45] [librespot_core::session] [DEBUG] new Session[0]
[2020-03-13][11:41:45] [librespot_core::session] [DEBUG] drop Session[0]
[2020-03-13][11:41:45] [tokio_threadpool::pool] [TRACE] shutdown; state=pool::State { lifecycle: Running, num_futures: 0 }
[2020-03-13][11:41:45] [tokio_threadpool::pool] [TRACE]   -> transitioned to shutdown
[2020-03-13][11:41:45] [tokio_threadpool::pool] [TRACE]   -> shutting down workers
[2020-03-13][11:41:45] [librespot_core::session] [DEBUG] drop Dispatch
[2020-03-13][11:41:45] [mio::poll] [TRACE] deregistering handle with poller
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] deregistering
[2020-03-13][11:41:45] [tokio_reactor] [DEBUG] dropping I/O source: 0
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:45] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:45] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:45] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:45] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:45] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:45] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:45] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:45] [tokio_threadpool::builder] [TRACE] build; num-workers=8
[2020-03-13][11:41:45] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:45] [ncspot::spotify] [INFO] Setting HTTP proxy http://127.0.0.1:9999
[2020-03-13][11:41:45] [ncspot::spotify] [DEBUG] opening spotify session
[2020-03-13][11:41:45] [tokio_reactor::background] [DEBUG] starting background reactor
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [hyper::client::pool] [TRACE] park; waiting for idle connection: "http://apresolve.spotify.com"
[2020-03-13][11:41:45] [hyper::client::connect] [TRACE] Http::connect("http://127.0.0.1:9999/")
[2020-03-13][11:41:45] [hyper::client::connect] [DEBUG] connecting to 127.0.0.1:9999
[2020-03-13][11:41:45] [tokio_reactor] [DEBUG] adding I/O source: 0
[2020-03-13][11:41:45] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] register Token(0) Readable | Writable
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] scheduling a connect
[2020-03-13][11:41:45] [tokio_reactor::registration] [DEBUG] scheduling Write for: 0
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] consuming notification queue
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] finished a connect
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop poll - 62.546µs
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190098.265127629s }
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop process, 86.787µs
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] event Writable Token(0)
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop poll - 131.879µs
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190098.265398174s }
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop process, 115.394µs
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [hyper::proto::h1::conn] [TRACE] read_keep_alive; is_mid_message=false
[2020-03-13][11:41:45] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:41:45] [hyper::proto] [TRACE] should_keep_alive(version=Http11, header=None) = true
[2020-03-13][11:41:45] [hyper::proto::h1::role] [TRACE] Client::encode has_body=false, method=None
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] set readiness to (empty)
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] scheduling a write of 75 bytes
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] done immediately with 75 bytes
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:45] [hyper::proto::h1::io] [TRACE] reclaiming write buf Vec
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [hyper::proto::h1::io] [DEBUG] flushed 75 bytes
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] event Writable Token(0)
[2020-03-13][11:41:45] [hyper::proto::h1::conn] [TRACE] flushed State { reading: Init, writing: KeepAlive, keep_alive: Busy, error: None }
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:45] [hyper::proto::h1::conn] [TRACE] wants_read_again? false
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop poll - 544.97µs
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190098.26617781s }
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop process, 91.151µs
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] event Readable | Writable Token(0)
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:45] [hyper::proto::h1::conn] [TRACE] Conn::read_head
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [hyper::proto::h1::io] [DEBUG] read 736 bytes
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:41:45] [hyper::proto::h1::role] [TRACE] Response.parse([Header; 100], [u8; 736])
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:45] [hyper::proto::h1::role] [TRACE] Response.parse Complete(318)
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [hyper::header] [TRACE] maybe_literal not found, copying "Via"
[2020-03-13][11:41:45] [hyper::header] [TRACE] maybe_literal not found, copying "Keep-Alive"
[2020-03-13][11:41:45] [hyper::header] [TRACE] maybe_literal not found, copying "Via"
[2020-03-13][11:41:45] [hyper::proto::h1::io] [DEBUG] parsed 9 headers (318 bytes)
[2020-03-13][11:41:45] [hyper::proto::h1::conn] [DEBUG] incoming body is content-length (418 bytes)
[2020-03-13][11:41:45] [hyper::proto] [TRACE] expecting_continue(version=Http11, header=None) = false
[2020-03-13][11:41:45] [hyper::proto] [TRACE] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
[2020-03-13][11:41:45] [hyper::proto::h1::conn] [TRACE] Conn::read_body
[2020-03-13][11:41:45] [hyper::proto::h1::decode] [TRACE] decode; state=Length(418)
[2020-03-13][11:41:45] [hyper::proto::h1::conn] [TRACE] flushed State { reading: Body(Length(0)), writing: KeepAlive, keep_alive: Busy, error: None }
[2020-03-13][11:41:45] [hyper::proto::h1::conn] [TRACE] wants_read_again? false
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop poll - 128.524059ms
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190098.394839081s }
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop process, 91.151µs
[2020-03-13][11:41:45] [hyper::proto::h1::conn] [TRACE] Conn::read_body
[2020-03-13][11:41:45] [hyper::proto::h1::decode] [TRACE] decode; state=Length(0)
[2020-03-13][11:41:45] [hyper::proto::h1::conn] [DEBUG] incoming body completed
[2020-03-13][11:41:45] [hyper::proto::h1::io] [DEBUG] read 0 bytes
[2020-03-13][11:41:45] [hyper::proto::h1::conn] [TRACE] read_keep_alive; is_mid_message=false
[2020-03-13][11:41:45] [hyper::proto::h1::io] [DEBUG] read 0 bytes
[2020-03-13][11:41:45] [hyper::proto::h1::conn] [TRACE] try_io_read; found EOF on connection: State { reading: Init, writing: Init, keep_alive: Idle, error: None }
[2020-03-13][11:41:45] [hyper::proto::h1::conn] [TRACE] State::close_read()
[2020-03-13][11:41:45] [hyper::proto::h1::conn] [TRACE] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
[2020-03-13][11:41:45] [hyper::proto::h1::conn] [TRACE] wants_read_again? false
[2020-03-13][11:41:45] [hyper::proto::h1::conn] [TRACE] shut down IO
[2020-03-13][11:41:45] [mio::poll] [TRACE] deregistering handle with poller
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] deregistering
[2020-03-13][11:41:45] [tokio_reactor] [DEBUG] dropping I/O source: 0
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [want] [TRACE] signal: Closed
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop poll - 1.047757ms
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190098.396131201s }
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop process, 87.758µs
[2020-03-13][11:41:45] [librespot_core::session] [INFO] Connecting to AP "gew1-accesspoint-b-k718.ap.spotify.com:443"
[2020-03-13][11:41:45] [librespot_core::connection] [INFO] Using proxy "http://127.0.0.1:9999/"
[2020-03-13][11:41:45] [tokio_reactor] [DEBUG] adding I/O source: 4194304
[2020-03-13][11:41:45] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] register Token(4194304) Readable | Writable
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] scheduling a connect
[2020-03-13][11:41:45] [tokio_reactor::registration] [DEBUG] scheduling Write for: 0
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop poll - 7.757µs
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] finished a connect
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190098.396770716s }
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop process, 83.394µs
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop poll - 188.122µs
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190098.397092171s }
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop process, 133.333µs
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] set readiness to (empty)
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] scheduling a write of 63 bytes
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] done immediately with 63 bytes
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:45] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] event Readable | Writable Token(4194304)
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop poll - 161.126225ms
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190098.558701304s }
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop process, 110.061µs
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] set readiness to Readable
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] scheduling a write of 151 bytes
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] done immediately with 151 bytes
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] event Readable Token(4194304)
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=Some(0ns)
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:41:45] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] event Readable | Writable Token(4194304)
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop poll - 58.41985ms
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190098.750682302s }
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:45] [tokio_core::reactor] [DEBUG] loop process, 91.637µs
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:45] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:45] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] set readiness to Readable
[2020-03-13][11:41:46] [mio::sys::windows::tcp] [TRACE] scheduling a write of 36 bytes
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:46] [mio::sys::windows::tcp] [TRACE] done immediately with 36 bytes
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] event Readable Token(4194304)
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; timeout=Some(0ns)
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] event Readable | Writable Token(4194304)
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_write] [TRACE] flushing framed transport
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_write] [TRACE] writing; remaining=125
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] set readiness to Readable
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:46] [mio::sys::windows::tcp] [TRACE] scheduling a write of 125 bytes
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:46] [mio::sys::windows::tcp] [TRACE] done immediately with 125 bytes
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] event Readable Token(4194304)
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_write] [TRACE] framed transport flushed
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; timeout=Some(0ns)
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:46] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:46] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:41:46] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] event Readable | Writable Token(4194304)
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:46] [tokio_core::reactor] [DEBUG] loop poll - 271.240596ms
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:46] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190099.163847678s }
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:46] [tokio_core::reactor] [DEBUG] loop process, 102.787µs
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:41:46] [librespot_core::session] [INFO] Authenticated as "xxx" !
[2020-03-13][11:41:46] [librespot_core::session] [DEBUG] new Session[1]
[2020-03-13][11:41:46] [ncspot::spotify] [DEBUG] worker thread ready.
[2020-03-13][11:41:46] [ncspot::spotify] [DEBUG] message received!
[2020-03-13][11:41:46] [librespot::component] [DEBUG] new MercuryManager
[2020-03-13][11:41:46] [librespot_playback::player] [DEBUG] new Player[1]
[2020-03-13][11:41:46] [librespot_playback::audio_backend::rodio] [DEBUG] Using rodio sink
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:41:46] [librespot_core::session] [DEBUG] Session[1] strong=3 weak=2
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:41:46] [librespot_core::session] [INFO] Country: "CH"
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:46] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:46] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_write] [TRACE] flushing framed transport
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_write] [TRACE] writing; remaining=353
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] set readiness to (empty)
[2020-03-13][11:41:46] [mio::sys::windows::tcp] [TRACE] scheduling a write of 353 bytes
[2020-03-13][11:41:46] [mio::sys::windows::tcp] [TRACE] done immediately with 353 bytes
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_write] [TRACE] framed transport flushed
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:46] [tokio_core::reactor] [DEBUG] loop poll - 4.684604ms
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:41:46] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190099.174527915s }
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:46] [tokio_core::reactor] [DEBUG] loop process, 111.03µs
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:41:46] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] event Readable | Writable Token(4194304)
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:46] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:46] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_write] [TRACE] flushing framed transport
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_write] [TRACE] framed transport flushed
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:46] [tokio_core::reactor] [DEBUG] loop poll - 61.509304ms
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:46] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190099.23620934s }
[2020-03-13][11:41:46] [tokio_core::reactor] [DEBUG] loop process, 79.03µs
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:41:46] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] event Readable | Writable Token(4194304)
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:46] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:46] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_write] [TRACE] flushing framed transport
[2020-03-13][11:41:46] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:41:46] [tokio_io::_tokio_codec::framed_write] [TRACE] framed transport flushed
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:46] [tokio_core::reactor] [DEBUG] loop poll - 55.743973ms
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:46] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190099.292083252s }
[2020-03-13][11:41:46] [tokio_core::reactor] [DEBUG] loop process, 80.969µs
[2020-03-13][11:41:46] [ncspot::spotify] [INFO] new token received: Token { access_token: "BQAm7bP2uc_N4CAHGgbyJbq9Jmws877dhw3losdhqtesTJMvILMvjHH8UDpiTXxgan7vwXg-RLvb8GOJGXXt76kuw98nYXiWJV-cFsIBhAINaNr8k28q2Uv8rjX6ouIe1e_gMVx36S1iERzLQ45U8vMthbscmuOZucpgdJCwJBfUI6_whLdsrwpv-cQwCWZxUws0j5rKjDg2VtpzAy-2vMDCDYkw_qNM2PCClvkGA7OgCQWb2_smf3bMRKJSM9SrQA5n", expires_in: 3600, token_type: "Bearer", scope: ["user-read-private", "playlist-read-private", "playlist-read-collaborative", "playlist-modify-public", "playlist-modify-private", "user-follow-modify", "user-follow-read", "user-library-read", "user-library-modify", "user-top-read", "user-read-recently-played"] }
[2020-03-13][11:41:46] [ncspot::spotify] [INFO] token updated!
[2020-03-13][11:41:46] [tokio_core::reactor] [DEBUG] loop poll - 7.757µs
[2020-03-13][11:41:46] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190099.292433797s }
[2020-03-13][11:41:46] [tokio_core::reactor] [DEBUG] loop process, 59.636µs
[2020-03-13][11:41:46] [reqwest::blocking::wait] [TRACE] (ThreadId(1)) park without timeout
[2020-03-13][11:41:46] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:46] [reqwest::blocking::client] [TRACE] (ThreadId(15)) start runtime::block_on
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:46] [reqwest::blocking::wait] [TRACE] wait at most 30s
[2020-03-13][11:41:46] [reqwest::blocking::wait] [TRACE] (ThreadId(1)) park timeout 29.999989334s
[2020-03-13][11:41:46] [hyper::client::pool] [TRACE] checkout waiting for idle connection: ("https", api.spotify.com)
[2020-03-13][11:41:46] [reqwest::connect] [DEBUG] starting new connection: https://api.spotify.com/
[2020-03-13][11:41:46] [reqwest::connect] [DEBUG] proxy(https://127.0.0.1:9999) intercepts 'https://api.spotify.com/'
[2020-03-13][11:41:46] [hyper::client::connect::http] [TRACE] Http::connect; scheme=Some("https"), host=Some("127.0.0.1"), port=Some(Port(9999))
[2020-03-13][11:41:46] [hyper::client::connect::http] [DEBUG] connecting to 127.0.0.1:9999
[2020-03-13][11:41:46] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] register Token(0) Readable | Writable
[2020-03-13][11:41:46] [mio::sys::windows::tcp] [TRACE] scheduling a connect
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; timeout=Some(0ns)
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:41:46] [mio::sys::windows::tcp] [TRACE] finished a connect
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:46] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:46] [hyper::client::connect::http] [DEBUG] connected to 127.0.0.1:9999
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] set readiness to (empty)
[2020-03-13][11:41:46] [mio::sys::windows::tcp] [TRACE] scheduling a write of 147 bytes
[2020-03-13][11:41:46] [mio::sys::windows::tcp] [TRACE] done immediately with 147 bytes
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; timeout=Some(0ns)
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:41:46] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:41:46] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:41:46] [mio::poll] [TRACE] deregistering handle with poller
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] deregistering
[2020-03-13][11:41:46] [hyper::client::pool] [TRACE] checkout dropped for ("https", api.spotify.com)
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; timeout=Some(0ns)
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:41:46] [tokio_core::reactor] [DEBUG] loop poll - 7.39733ms
[2020-03-13][11:41:46] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190099.299920824s }
[2020-03-13][11:41:46] [tokio_core::reactor] [DEBUG] loop process, 110.06µs
[2020-03-13][11:41:46] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:51:52] [ncspot::config] [TRACE] "C:\\Users\\jonas.frei\\.config\\ncspot\\config"
[2020-03-13][11:51:52] [ncspot::config] [TRACE] "C:\\Users\\jonas.frei\\.config\\ncspot\\config"
[2020-03-13][11:51:52] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:52] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:52] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:52] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:52] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:52] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:52] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:52] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:52] [tokio_threadpool::builder] [TRACE] build; num-workers=8
[2020-03-13][11:51:52] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:52] [ncspot::spotify] [INFO] Setting HTTP proxy http://127.0.0.1:9999
[2020-03-13][11:51:52] [tokio_reactor::background] [DEBUG] starting background reactor
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:52] [hyper::client::pool] [TRACE] park; waiting for idle connection: "http://apresolve.spotify.com"
[2020-03-13][11:51:52] [hyper::client::connect] [TRACE] Http::connect("http://127.0.0.1:9999/")
[2020-03-13][11:51:52] [hyper::client::connect] [DEBUG] connecting to 127.0.0.1:9999
[2020-03-13][11:51:52] [tokio_reactor] [DEBUG] adding I/O source: 0
[2020-03-13][11:51:52] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] register Token(0) Readable | Writable
[2020-03-13][11:51:52] [mio::sys::windows::tcp] [TRACE] scheduling a connect
[2020-03-13][11:51:52] [tokio_reactor::registration] [DEBUG] scheduling Write for: 0
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:51:52] [mio::sys::windows::tcp] [TRACE] finished a connect
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] consuming notification queue
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop poll - 86.303µs
[2020-03-13][11:51:52] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190705.402419198s }
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop process, 157.576µs
[2020-03-13][11:51:52] [tokio_reactor] [TRACE] event Writable Token(0)
[2020-03-13][11:51:52] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop poll - 49.939µs
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190705.402695077s }
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop process, 95.515µs
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:52] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:52] [hyper::proto::h1::conn] [TRACE] read_keep_alive; is_mid_message=false
[2020-03-13][11:51:52] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:51:52] [hyper::proto] [TRACE] should_keep_alive(version=Http11, header=None) = true
[2020-03-13][11:51:52] [hyper::proto::h1::role] [TRACE] Client::encode has_body=false, method=None
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] set readiness to (empty)
[2020-03-13][11:51:52] [mio::sys::windows::tcp] [TRACE] scheduling a write of 75 bytes
[2020-03-13][11:51:52] [mio::sys::windows::tcp] [TRACE] done immediately with 75 bytes
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:52] [hyper::proto::h1::io] [TRACE] reclaiming write buf Vec
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:52] [hyper::proto::h1::io] [DEBUG] flushed 75 bytes
[2020-03-13][11:51:52] [tokio_reactor] [TRACE] event Writable Token(0)
[2020-03-13][11:51:52] [hyper::proto::h1::conn] [TRACE] flushed State { reading: Init, writing: KeepAlive, keep_alive: Busy, error: None }
[2020-03-13][11:51:52] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:52] [hyper::proto::h1::conn] [TRACE] wants_read_again? false
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop poll - 607.03µs
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190705.403570228s }
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop process, 223.03µs
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:51:52] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:52] [tokio_reactor] [TRACE] event Readable | Writable Token(0)
[2020-03-13][11:51:52] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:52] [hyper::proto::h1::conn] [TRACE] Conn::read_head
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:52] [hyper::proto::h1::io] [DEBUG] read 736 bytes
[2020-03-13][11:51:52] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:51:52] [hyper::proto::h1::role] [TRACE] Response.parse([Header; 100], [u8; 736])
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:52] [hyper::proto::h1::role] [TRACE] Response.parse Complete(318)
[2020-03-13][11:51:52] [hyper::header] [TRACE] maybe_literal not found, copying "Via"
[2020-03-13][11:51:52] [hyper::header] [TRACE] maybe_literal not found, copying "Keep-Alive"
[2020-03-13][11:51:52] [hyper::header] [TRACE] maybe_literal not found, copying "Via"
[2020-03-13][11:51:52] [hyper::proto::h1::io] [DEBUG] parsed 9 headers (318 bytes)
[2020-03-13][11:51:52] [hyper::proto::h1::conn] [DEBUG] incoming body is content-length (418 bytes)
[2020-03-13][11:51:52] [hyper::proto] [TRACE] expecting_continue(version=Http11, header=None) = false
[2020-03-13][11:51:52] [hyper::proto] [TRACE] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
[2020-03-13][11:51:52] [hyper::proto::h1::conn] [TRACE] Conn::read_body
[2020-03-13][11:51:52] [hyper::proto::h1::decode] [TRACE] decode; state=Length(418)
[2020-03-13][11:51:52] [hyper::proto::h1::conn] [TRACE] flushed State { reading: Body(Length(0)), writing: KeepAlive, keep_alive: Busy, error: None }
[2020-03-13][11:51:52] [hyper::proto::h1::conn] [TRACE] wants_read_again? false
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop poll - 148.52017ms
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190705.552350277s }
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop process, 57.212µs
[2020-03-13][11:51:52] [hyper::proto::h1::conn] [TRACE] Conn::read_body
[2020-03-13][11:51:52] [hyper::proto::h1::decode] [TRACE] decode; state=Length(0)
[2020-03-13][11:51:52] [hyper::proto::h1::conn] [DEBUG] incoming body completed
[2020-03-13][11:51:52] [hyper::proto::h1::io] [DEBUG] read 0 bytes
[2020-03-13][11:51:52] [hyper::proto::h1::conn] [TRACE] read_keep_alive; is_mid_message=false
[2020-03-13][11:51:52] [hyper::proto::h1::io] [DEBUG] read 0 bytes
[2020-03-13][11:51:52] [hyper::proto::h1::conn] [TRACE] try_io_read; found EOF on connection: State { reading: Init, writing: Init, keep_alive: Idle, error: None }
[2020-03-13][11:51:52] [hyper::proto::h1::conn] [TRACE] State::close_read()
[2020-03-13][11:51:52] [hyper::proto::h1::conn] [TRACE] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
[2020-03-13][11:51:52] [hyper::proto::h1::conn] [TRACE] wants_read_again? false
[2020-03-13][11:51:52] [hyper::proto::h1::conn] [TRACE] shut down IO
[2020-03-13][11:51:52] [mio::poll] [TRACE] deregistering handle with poller
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] deregistering
[2020-03-13][11:51:52] [tokio_reactor] [DEBUG] dropping I/O source: 0
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:52] [want] [TRACE] signal: Closed
[2020-03-13][11:51:52] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop poll - 895.03µs
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190705.55349161s }
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop process, 102.788µs
[2020-03-13][11:51:52] [librespot_core::session] [INFO] Connecting to AP "gew1-accesspoint-b-80lk.ap.spotify.com:443"
[2020-03-13][11:51:52] [librespot_core::connection] [INFO] Using proxy "http://127.0.0.1:9999/"
[2020-03-13][11:51:52] [tokio_reactor] [DEBUG] adding I/O source: 4194304
[2020-03-13][11:51:52] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] register Token(4194304) Readable | Writable
[2020-03-13][11:51:52] [mio::sys::windows::tcp] [TRACE] scheduling a connect
[2020-03-13][11:51:52] [tokio_reactor::registration] [DEBUG] scheduling Write for: 0
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop poll - 6.303µs
[2020-03-13][11:51:52] [mio::sys::windows::tcp] [TRACE] finished a connect
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190705.554228094s }
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop process, 117.819µs
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:52] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:52] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:51:52] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop poll - 234.667µs
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190705.554651367s }
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop process, 81.939µs
[2020-03-13][11:51:52] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] set readiness to (empty)
[2020-03-13][11:51:52] [mio::sys::windows::tcp] [TRACE] scheduling a write of 63 bytes
[2020-03-13][11:51:52] [mio::sys::windows::tcp] [TRACE] done immediately with 63 bytes
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:52] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:52] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:51:52] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:51:52] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:52] [tokio_reactor] [TRACE] event Readable | Writable Token(4194304)
[2020-03-13][11:51:52] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop poll - 170.423191ms
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190705.725520133s }
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:52] [tokio_core::reactor] [DEBUG] loop process, 106.666µs
[2020-03-13][11:51:52] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:52] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] set readiness to Readable
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] scheduling a write of 151 bytes
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] done immediately with 151 bytes
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] event Readable Token(4194304)
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=Some(0ns)
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] event Readable | Writable Token(4194304)
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop poll - 58.960457ms
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190705.921405129s }
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop process, 101.333µs
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] set readiness to Readable
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] scheduling a write of 36 bytes
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] event Readable Token(4194304)
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] done immediately with 36 bytes
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] event Readable | Writable Token(4194304)
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [tokio_io::_tokio_codec::framed_write] [TRACE] flushing framed transport
[2020-03-13][11:51:53] [tokio_io::_tokio_codec::framed_write] [TRACE] writing; remaining=125
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] set readiness to Readable
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] scheduling a write of 125 bytes
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] done immediately with 125 bytes
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] event Readable Token(4194304)
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:53] [tokio_io::_tokio_codec::framed_write] [TRACE] framed transport flushed
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=Some(0ns)
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] event Readable | Writable Token(4194304)
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop poll - 288.166164ms
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190706.349357891s }
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop process, 93.091µs
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:51:53] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:51:53] [librespot_core::session] [INFO] Authenticated as "xxx" !
[2020-03-13][11:51:53] [librespot_core::session] [DEBUG] new Session[0]
[2020-03-13][11:51:53] [librespot_core::session] [DEBUG] drop Session[0]
[2020-03-13][11:51:53] [tokio_threadpool::pool] [TRACE] shutdown; state=pool::State { lifecycle: Running, num_futures: 0 }
[2020-03-13][11:51:53] [tokio_threadpool::pool] [TRACE]   -> transitioned to shutdown
[2020-03-13][11:51:53] [tokio_threadpool::pool] [TRACE]   -> shutting down workers
[2020-03-13][11:51:53] [librespot_core::session] [DEBUG] drop Dispatch
[2020-03-13][11:51:53] [mio::poll] [TRACE] deregistering handle with poller
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] deregistering
[2020-03-13][11:51:53] [tokio_reactor] [DEBUG] dropping I/O source: 0
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:53] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:53] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:53] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:53] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:53] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:53] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:53] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:53] [tokio_threadpool::builder] [TRACE] build; num-workers=8
[2020-03-13][11:51:53] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:53] [ncspot::spotify] [INFO] Setting HTTP proxy http://127.0.0.1:9999
[2020-03-13][11:51:53] [ncspot::spotify] [DEBUG] opening spotify session
[2020-03-13][11:51:53] [tokio_reactor::background] [DEBUG] starting background reactor
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [hyper::client::pool] [TRACE] park; waiting for idle connection: "http://apresolve.spotify.com"
[2020-03-13][11:51:53] [hyper::client::connect] [TRACE] Http::connect("http://127.0.0.1:9999/")
[2020-03-13][11:51:53] [hyper::client::connect] [DEBUG] connecting to 127.0.0.1:9999
[2020-03-13][11:51:53] [tokio_reactor] [DEBUG] adding I/O source: 0
[2020-03-13][11:51:53] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] register Token(0) Readable | Writable
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] scheduling a connect
[2020-03-13][11:51:53] [tokio_reactor::registration] [DEBUG] scheduling Write for: 0
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] consuming notification queue
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] finished a connect
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop poll - 77.576µs
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190706.380503573s }
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop process, 86.787µs
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] event Writable Token(0)
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop poll - 131.394µs
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190706.380777512s }
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop process, 107.636µs
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [hyper::proto::h1::conn] [TRACE] read_keep_alive; is_mid_message=false
[2020-03-13][11:51:53] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:51:53] [hyper::proto] [TRACE] should_keep_alive(version=Http11, header=None) = true
[2020-03-13][11:51:53] [hyper::proto::h1::role] [TRACE] Client::encode has_body=false, method=None
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] set readiness to (empty)
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] scheduling a write of 75 bytes
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] done immediately with 75 bytes
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:53] [hyper::proto::h1::io] [TRACE] reclaiming write buf Vec
[2020-03-13][11:51:53] [hyper::proto::h1::io] [DEBUG] flushed 75 bytes
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [hyper::proto::h1::conn] [TRACE] flushed State { reading: Init, writing: KeepAlive, keep_alive: Busy, error: None }
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] event Writable Token(0)
[2020-03-13][11:51:53] [hyper::proto::h1::conn] [TRACE] wants_read_again? false
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop poll - 619.151µs
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190706.381637148s }
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop process, 121.212µs
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] event Readable | Writable Token(0)
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:53] [hyper::proto::h1::conn] [TRACE] Conn::read_head
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [hyper::proto::h1::io] [DEBUG] read 736 bytes
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [hyper::proto::h1::role] [TRACE] Response.parse([Header; 100], [u8; 736])
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:51:53] [hyper::proto::h1::role] [TRACE] Response.parse Complete(318)
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [hyper::header] [TRACE] maybe_literal not found, copying "Via"
[2020-03-13][11:51:53] [hyper::header] [TRACE] maybe_literal not found, copying "Keep-Alive"
[2020-03-13][11:51:53] [hyper::header] [TRACE] maybe_literal not found, copying "Via"
[2020-03-13][11:51:53] [hyper::proto::h1::io] [DEBUG] parsed 9 headers (318 bytes)
[2020-03-13][11:51:53] [hyper::proto::h1::conn] [DEBUG] incoming body is content-length (418 bytes)
[2020-03-13][11:51:53] [hyper::proto] [TRACE] expecting_continue(version=Http11, header=None) = false
[2020-03-13][11:51:53] [hyper::proto] [TRACE] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
[2020-03-13][11:51:53] [hyper::proto::h1::conn] [TRACE] Conn::read_body
[2020-03-13][11:51:53] [hyper::proto::h1::decode] [TRACE] decode; state=Length(418)
[2020-03-13][11:51:53] [hyper::proto::h1::conn] [TRACE] flushed State { reading: Body(Length(0)), writing: KeepAlive, keep_alive: Busy, error: None }
[2020-03-13][11:51:53] [hyper::proto::h1::conn] [TRACE] wants_read_again? false
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop poll - 126.669029ms
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190706.508485086s }
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop process, 63.031µs
[2020-03-13][11:51:53] [hyper::proto::h1::conn] [TRACE] Conn::read_body
[2020-03-13][11:51:53] [hyper::proto::h1::decode] [TRACE] decode; state=Length(0)
[2020-03-13][11:51:53] [hyper::proto::h1::conn] [DEBUG] incoming body completed
[2020-03-13][11:51:53] [hyper::proto::h1::io] [DEBUG] read 0 bytes
[2020-03-13][11:51:53] [hyper::proto::h1::conn] [TRACE] read_keep_alive; is_mid_message=false
[2020-03-13][11:51:53] [hyper::proto::h1::io] [DEBUG] read 0 bytes
[2020-03-13][11:51:53] [hyper::proto::h1::conn] [TRACE] try_io_read; found EOF on connection: State { reading: Init, writing: Init, keep_alive: Idle, error: None }
[2020-03-13][11:51:53] [hyper::proto::h1::conn] [TRACE] State::close_read()
[2020-03-13][11:51:53] [hyper::proto::h1::conn] [TRACE] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
[2020-03-13][11:51:53] [hyper::proto::h1::conn] [TRACE] wants_read_again? false
[2020-03-13][11:51:53] [hyper::proto::h1::conn] [TRACE] shut down IO
[2020-03-13][11:51:53] [mio::poll] [TRACE] deregistering handle with poller
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] deregistering
[2020-03-13][11:51:53] [tokio_reactor] [DEBUG] dropping I/O source: 0
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [want] [TRACE] signal: Closed
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop poll - 771.879µs
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190706.509516359s }
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop process, 76.121µs
[2020-03-13][11:51:53] [librespot_core::session] [INFO] Connecting to AP "gew1-accesspoint-b-1hnz.ap.spotify.com:443"
[2020-03-13][11:51:53] [librespot_core::connection] [INFO] Using proxy "http://127.0.0.1:9999/"
[2020-03-13][11:51:53] [tokio_reactor] [DEBUG] adding I/O source: 4194304
[2020-03-13][11:51:53] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] register Token(4194304) Readable | Writable
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] scheduling a connect
[2020-03-13][11:51:53] [tokio_reactor::registration] [DEBUG] scheduling Write for: 0
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop poll - 7.758µs
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] finished a connect
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190706.510156843s }
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop process, 117.818µs
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop poll - 253.576µs
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190706.51058157s }
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop process, 118.303µs
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] set readiness to (empty)
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] scheduling a write of 63 bytes
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] done immediately with 63 bytes
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:53] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:51:53] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] event Readable | Writable Token(4194304)
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop poll - 170.31119ms
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190706.681369851s }
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:53] [tokio_core::reactor] [DEBUG] loop process, 125.091µs
[2020-03-13][11:51:53] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:53] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Readable
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] scheduling a write of 151 bytes
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] done immediately with 151 bytes
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] event Readable Token(4194304)
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=Some(0ns)
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] event Readable | Writable Token(4194304)
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop poll - 62.314636ms
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190706.87700418s }
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop process, 93.091µs
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Readable
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] scheduling a write of 36 bytes
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] event Readable Token(4194304)
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] done immediately with 36 bytes
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] event Readable | Writable Token(4194304)
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_write] [TRACE] flushing framed transport
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_write] [TRACE] writing; remaining=125
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Readable
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] scheduling a write of 125 bytes
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] done immediately with 125 bytes
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] event Readable Token(4194304)
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_write] [TRACE] framed transport flushed
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=Some(0ns)
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] event Readable | Writable Token(4194304)
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop poll - 394.820172ms
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190707.406442469s }
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop process, 111.03µs
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:51:54] [librespot_core::session] [INFO] Authenticated as "xxx" !
[2020-03-13][11:51:54] [librespot_core::session] [DEBUG] new Session[1]
[2020-03-13][11:51:54] [ncspot::spotify] [DEBUG] worker thread ready.
[2020-03-13][11:51:54] [ncspot::spotify] [DEBUG] message received!
[2020-03-13][11:51:54] [librespot::component] [DEBUG] new MercuryManager
[2020-03-13][11:51:54] [librespot_playback::player] [DEBUG] new Player[1]
[2020-03-13][11:51:54] [librespot_playback::audio_backend::rodio] [DEBUG] Using rodio sink
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:51:54] [librespot_core::session] [DEBUG] Session[1] strong=3 weak=2
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:51:54] [librespot_core::session] [INFO] Country: "CH"
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_write] [TRACE] flushing framed transport
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_write] [TRACE] writing; remaining=353
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to (empty)
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] scheduling a write of 353 bytes
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] done immediately with 353 bytes
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_write] [TRACE] framed transport flushed
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop poll - 1.809454ms
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190707.413286102s }
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop process, 144.97µs
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] event Readable | Writable Token(4194304)
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_write] [TRACE] flushing framed transport
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_write] [TRACE] framed transport flushed
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop poll - 26.719017ms
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190707.440233483s }
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop process, 105.212µs
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] event Readable | Writable Token(4194304)
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:51:54] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_write] [TRACE] flushing framed transport
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_write] [TRACE] framed transport flushed
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop poll - 32.567257ms
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190707.472948619s }
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop process, 84.363µs
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] event Readable | Writable Token(4194304)
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] loop process - 0 events, 0.000s
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] frame decoded from buffer
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_read] [TRACE] attempting to decode a frame
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [tokio_reactor::registration] [DEBUG] scheduling Read for: 0
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] event Writable Token(4194304)
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_write] [TRACE] flushing framed transport
[2020-03-13][11:51:54] [tokio_reactor] [TRACE] loop process - 1 events, 0.000s
[2020-03-13][11:51:54] [tokio_io::_tokio_codec::framed_write] [TRACE] framed transport flushed
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop poll - 31.568954ms
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190707.504709088s }
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop process, 89.212µs
[2020-03-13][11:51:54] [ncspot::spotify] [INFO] new token received: Token { access_token: "BQDvJJwLafBlfgYspACqfq9RRAqmIZ1l5VVOjd5MrECNiUMlpi813qpZZkmh2vMnVBrtL1EXaD2O9ap8OO0vBsVpoRpylRAYTfNMP8_ExV0UrCNJVGCcjTh3gjqq47bc9iRh70e3MzzX4H2Vi6Ur8YtWlfh6BU0rm6Ygm7_fjrlX_rkbhC5fB4mCLTVwtwnFTebJqEQtUoczidnugFOcPoBsbmHnBcK-JKTGgnL2vfYYVCH4PBMBPyMV7yaWTJmLgGhA", expires_in: 3600, token_type: "Bearer", scope: ["user-read-private", "playlist-read-private", "playlist-read-collaborative", "playlist-modify-public", "playlist-modify-private", "user-follow-modify", "user-follow-read", "user-library-read", "user-library-modify", "user-top-read", "user-read-recently-played"] }
[2020-03-13][11:51:54] [ncspot::spotify] [INFO] token updated!
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop poll - 8.243µs
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190707.505107149s }
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop process, 68.848µs
[2020-03-13][11:51:54] [reqwest::blocking::wait] [TRACE] (ThreadId(1)) park without timeout
[2020-03-13][11:51:54] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:54] [reqwest::blocking::client] [TRACE] (ThreadId(16)) start runtime::block_on
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [reqwest::blocking::wait] [TRACE] wait at most 30s
[2020-03-13][11:51:54] [reqwest::blocking::wait] [TRACE] (ThreadId(1)) park timeout 29.999969454s
[2020-03-13][11:51:54] [hyper::client::pool] [TRACE] checkout waiting for idle connection: ("https", api.spotify.com)
[2020-03-13][11:51:54] [reqwest::connect] [DEBUG] starting new connection: https://api.spotify.com/
[2020-03-13][11:51:54] [reqwest::connect] [DEBUG] proxy(https://127.0.0.1:9999) intercepts 'https://api.spotify.com/'
[2020-03-13][11:51:54] [hyper::client::connect::http] [TRACE] Http::connect; scheme=Some("https"), host=Some("127.0.0.1"), port=Some(Port(9999))
[2020-03-13][11:51:54] [hyper::client::connect::http] [DEBUG] connecting to 127.0.0.1:9999
[2020-03-13][11:51:54] [mio::poll] [TRACE] registering with poller
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] register Token(0) Readable | Writable
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] scheduling a connect
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=Some(0ns)
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] finished a connect
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [hyper::client::connect::http] [DEBUG] connected to 127.0.0.1:9999
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to (empty)
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] scheduling a write of 147 bytes
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] done immediately with 147 bytes
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=Some(0ns)
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; -> got overlapped
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] finished a read: 0
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Writable
[2020-03-13][11:51:54] [mio::sys::windows::tcp] [TRACE] scheduling a read
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] set readiness to Readable | Writable
[2020-03-13][11:51:54] [mio::poll] [TRACE] deregistering handle with poller
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] deregistering
[2020-03-13][11:51:54] [hyper::client::pool] [TRACE] checkout dropped for ("https", api.spotify.com)
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=Some(0ns)
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] returning
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; timeout=None
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] polling IOCP
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop poll - 204.075053ms
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop time - Instant { t: 190707.709314565s }
[2020-03-13][11:51:54] [tokio_core::reactor] [DEBUG] loop process, 152.727µs
[2020-03-13][11:51:54] [mio::sys::windows::selector] [TRACE] select; -> got overlapped