Script started on 2018-12-18 22:44:33+01:00 [TERM="screen" TTY="/dev/pts/3" COLUMNS="213" LINES="56"] [alarm@alarmpi ~]$ (reverse-i-search)`': s': lso': sudo vim /etc/asound.conf  ([8@failed reverse-i-search)`sop': sudo vim /etc/a^C [alarm@alarmpi ~]$ (reverse-i-search)`': s': lsp': spotifyd --no-daemon -v[1@o': [1@t': [1@i': [1@f': [1@y': [1@d': [alarm@alarmpi ~]$ 22:44:40 [TRACE] mio::poll: [:785] registering with poller 22:44:40 [TRACE] tokio_threadpool::builder: [:401] build; num-workers=4 22:44:40 [DEBUG] tokio_reactor::background: starting background reactor 22:44:40 [INFO] Using software volume controller. 22:44:40 [DEBUG] librespot_connect::discovery: Zeroconf server listening on 0.0.0.0:0 22:44:40 [TRACE] mio::poll: [:785] registering with poller 22:44:40 [TRACE] mio::poll: [:785] registering with poller 22:44:40 [TRACE] mio::poll: [:785] registering with poller 22:44:40 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:44:40 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:44:40 [TRACE] mio::poll: [:785] registering with poller 22:44:40 [TRACE] tokio_reactor: [:368] event Writable Token(8388610) 22:44:40 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:44:40 [DEBUG] tokio_core::reactor: consuming notification queue 22:44:40 [TRACE] tokio_reactor: [:368] event Writable Token(12582915) 22:44:40 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:44:40 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:44:40 [TRACE] mdns::fsm: [:247] sending packet to V4(224.0.0.251:5353) 22:44:40 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:44:40 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:44:40 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:44:40 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:44:40 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:44:40 [TRACE] mdns::fsm: [:247] sending packet to V6([ff02::fb]:5353) 22:44:40 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(8388610) 22:44:40 [DEBUG] tokio_core::reactor: loop poll - 1.440659ms 22:44:40 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23616, tv_nsec: 905879627 } 22:44:40 [DEBUG] tokio_core::reactor: loop process, 160.102µs 22:44:40 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:44:40 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.253:5353) 22:44:40 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(8388610) 22:44:40 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:44:40 [TRACE] mdns::fsm: [:88] received packet from V4(192.168.3.253:5353) with no query 22:44:40 [TRACE] mdns::fsm: [:77] received packet from V6([fe80::ba27:ebff:fe42:e843]:5353) 22:44:40 [TRACE] mdns::fsm: [:88] received packet from V6([fe80::ba27:ebff:fe42:e843]:5353) with no query 22:44:40 [DEBUG] tokio_core::reactor: loop poll - 403.224µs 22:44:40 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23616, tv_nsec: 906505660 } 22:44:40 [DEBUG] tokio_core::reactor: loop process, 79.374µs 22:44:42 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:44:42 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:44:42 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.26:5353) 22:44:42 [DEBUG] mdns::fsm: received question: IN _D2CA5178._sub._googlecast._tcp.local 22:44:42 [DEBUG] mdns::fsm: received question: IN _googlecast._tcp.local 22:44:42 [DEBUG] tokio_core::reactor: loop poll - 1.905254963s 22:44:42 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23618, tv_nsec: 811882653 } 22:44:42 [DEBUG] tokio_core::reactor: loop process, 167.03µs 22:44:57 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:44:57 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:44:57 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:36574) 22:44:57 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local 22:44:57 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:44:57 [TRACE] mdns::fsm: [:247] sending packet to V4(192.168.3.23:36574) 22:44:57 [DEBUG] tokio_core::reactor: loop poll - 15.59096128s 22:44:57 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23634, tv_nsec: 403087732 } 22:44:57 [DEBUG] tokio_core::reactor: loop process, 98.175µs 22:44:57 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:44:57 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:44:57 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:44:57 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:44:57 [DEBUG] tokio_core::reactor: loop poll - 10.143933ms 22:44:57 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23634, tv_nsec: 413376871 } 22:44:57 [DEBUG] tokio_core::reactor: loop process, 131.04µs 22:44:57 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:44:57 [TRACE] mio::poll: [:785] registering with poller 22:44:57 [TRACE] tokio_reactor: [:368] event Writable Token(16777220) 22:44:57 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:44:57 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:44:57 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:44:57 [DEBUG] tokio_core::reactor: loop poll - 447.39µs 22:44:57 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23634, tv_nsec: 414004727 } 22:44:57 [DEBUG] tokio_core::reactor: loop process, 127.707µs 22:44:57 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(16777220) 22:44:57 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:44:57 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:44:57 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:44:57 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:44:57 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:44:57 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:44:57 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:44:57 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:44:57 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:44:57 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:44:57 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:44:57 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:44:57 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:44:57 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:44:57 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:44:57 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:44:57 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:44:57 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:44:57 [DEBUG] tokio_core::reactor: loop poll - 1.335192ms 22:44:57 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23634, tv_nsec: 415510750 } 22:44:57 [DEBUG] tokio_core::reactor: loop process, 86.613µs 22:44:57 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(16777220) 22:44:57 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:44:57 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:44:57 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:44:57 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:44:57 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:44:57 [DEBUG] hyper::proto::h1::conn: read eof 22:44:57 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:44:57 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:44:57 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:44:57 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:44:57 [TRACE] mio::poll: [:905] deregistering handle with poller 22:44:57 [DEBUG] tokio_reactor: dropping I/O source: 4 22:44:57 [DEBUG] tokio_core::reactor: loop poll - 2.297314ms 22:44:57 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23634, tv_nsec: 417943270 } 22:44:57 [DEBUG] tokio_core::reactor: loop process, 82.239µs 22:45:00 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:00 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:5353) 22:45:00 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:00 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:00 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:00 [DEBUG] mdns::fsm: received question: IN _CC32E753._sub._googlecast._tcp.local 22:45:00 [DEBUG] mdns::fsm: received question: IN _googlecast._tcp.local 22:45:00 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:5353) 22:45:00 [DEBUG] mdns::fsm: received question: IN _CC32E753._sub._googlecast._tcp.local 22:45:00 [DEBUG] mdns::fsm: received question: IN _googlecast._tcp.local 22:45:00 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:36574) 22:45:00 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local 22:45:00 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:45:00 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:5353) 22:45:00 [DEBUG] mdns::fsm: received question: IN _CC32E753._sub._googlecast._tcp.local 22:45:00 [DEBUG] mdns::fsm: received question: IN _googlecast._tcp.local 22:45:00 [TRACE] mdns::fsm: [:247] sending packet to V4(192.168.3.23:36574) 22:45:00 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 2.337957925s 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23636, tv_nsec: 756029319 } 22:45:00 [DEBUG] tokio_core::reactor: loop process, 292.757µs 22:45:00 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 184.737µs 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23636, tv_nsec: 756605249 } 22:45:00 [DEBUG] tokio_core::reactor: loop process, 164.685µs 22:45:00 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:00 [TRACE] mio::poll: [:785] registering with poller 22:45:00 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(20971524) 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:00 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:00 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 650.512µs 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23636, tv_nsec: 757495810 } 22:45:00 [DEBUG] tokio_core::reactor: loop process, 156.665µs 22:45:00 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:00 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:45:00 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:45:00 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:45:00 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:00 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:45:00 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:45:00 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:00 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:00 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:00 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:00 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:45:00 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:45:00 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:45:00 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:45:00 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:00 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 1.980651ms 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23636, tv_nsec: 759714792 } 22:45:00 [DEBUG] tokio_core::reactor: loop process, 152.603µs 22:45:00 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(20971524) 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:00 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:00 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:00 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:00 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:00 [DEBUG] hyper::proto::h1::conn: read eof 22:45:00 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:00 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:00 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:00 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:00 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:00 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 21.745242ms 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23636, tv_nsec: 781692011 } 22:45:00 [DEBUG] tokio_core::reactor: loop process, 177.498µs 22:45:00 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(20971524) 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.001s 22:45:00 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:00 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:40972) 22:45:00 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local 22:45:00 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:45:00 [TRACE] mdns::fsm: [:247] sending packet to V4(192.168.3.23:40972) 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 603.641749ms 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23637, tv_nsec: 385596257 } 22:45:00 [DEBUG] tokio_core::reactor: loop process, 228.851µs 22:45:00 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:00 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 1.577219ms 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23637, tv_nsec: 387492170 } 22:45:00 [DEBUG] tokio_core::reactor: loop process, 231.976µs 22:45:00 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:00 [TRACE] mio::poll: [:785] registering with poller 22:45:00 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(25165828) 22:45:00 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:00 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 800.823µs 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23637, tv_nsec: 388614291 } 22:45:00 [DEBUG] tokio_core::reactor: loop process, 194.581µs 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:00 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:00 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:45:00 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:45:00 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:45:00 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:00 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:45:00 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:45:00 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:00 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:00 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:00 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:00 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:00 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:45:00 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:45:00 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:45:00 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:00 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:00 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? true 22:45:00 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:00 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:00 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:00 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:00 [DEBUG] hyper::proto::h1::conn: read eof 22:45:00 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:00 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:00 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:00 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:00 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:00 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 3.227927ms 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23637, tv_nsec: 392334608 } 22:45:00 [DEBUG] tokio_core::reactor: loop process, 171.665µs 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 154.321µs 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23637, tv_nsec: 392743874 } 22:45:00 [DEBUG] tokio_core::reactor: loop process, 281.871µs 22:45:00 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:00 [TRACE] mio::poll: [:785] registering with poller 22:45:00 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:00 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:00 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(29360132) 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 503.223µs 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23637, tv_nsec: 393611259 } 22:45:00 [DEBUG] tokio_core::reactor: loop process, 287.704µs 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:00 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:00 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:45:00 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:45:00 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:45:00 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:00 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:45:00 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:45:00 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:00 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:00 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:00 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:00 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:45:00 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:45:00 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:45:00 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:45:00 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:00 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 2.037057ms 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23637, tv_nsec: 396025134 } 22:45:00 [DEBUG] tokio_core::reactor: loop process, 162.289µs 22:45:00 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(29360132) 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:00 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:00 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:00 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:00 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:00 [DEBUG] hyper::proto::h1::conn: read eof 22:45:00 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:00 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:00 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:00 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:00 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:00 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 5.713417ms 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23637, tv_nsec: 401988912 } 22:45:00 [DEBUG] tokio_core::reactor: loop process, 158.435µs 22:45:02 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:02 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 1.290219208s 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 692453169 } 22:45:02 [DEBUG] tokio_core::reactor: loop process, 188.122µs 22:45:02 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:02 [TRACE] mio::poll: [:785] registering with poller 22:45:02 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(33554436) 22:45:02 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:02 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:02 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 759.001µs 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 693486958 } 22:45:02 [DEBUG] tokio_core::reactor: loop process, 212.132µs 22:45:02 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:02 [DEBUG] hyper::proto::h1::io: read 906 bytes 22:45:02 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 906]) 22:45:02 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(227) 22:45:02 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:02 [DEBUG] hyper::proto::h1::io: parsed 7 headers (227 bytes) 22:45:02 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (679 bytes) 22:45:02 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:02 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:02 [DEBUG] librespot_connect::discovery: Post "/" {} 22:45:02 [TRACE] hyper::proto::h1::conn: [:279] Conn::read_body 22:45:02 [TRACE] hyper::proto::h1::decode: [:88] decode; state=Length(679) 22:45:02 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Body(Length(0)), writing: Init, keep_alive: Busy, error: None } 22:45:02 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 1.775811ms 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 695558598 } 22:45:02 [DEBUG] tokio_core::reactor: loop process, 161.195µs 22:45:02 [TRACE] hyper::proto::h1::conn: [:279] Conn::read_body 22:45:02 [TRACE] hyper::proto::h1::decode: [:88] decode; state=Length(0) 22:45:02 [DEBUG] hyper::proto::h1::conn: incoming body completed 22:45:02 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:02 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:02 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Post) 22:45:02 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 57B 22:45:02 [DEBUG] hyper::proto::h1::io: flushed 152 bytes 22:45:02 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:45:02 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:02 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 67.327836ms 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 763130076 } 22:45:02 [DEBUG] tokio_core::reactor: loop process, 119.582µs 22:45:02 [TRACE] hyper::client::pool: [:125] park; waiting for idle connection: "http://apresolve.spotify.com" 22:45:02 [TRACE] hyper::client::connect: [:118] Http::connect("http://apresolve.spotify.com/") 22:45:02 [DEBUG] hyper::client::dns: resolving host="apresolve.spotify.com", port=80 22:45:02 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:02 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:02 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 328.485µs 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 764932136 } 22:45:02 [DEBUG] tokio_core::reactor: loop process, 86.926µs 22:45:02 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(33554436) 22:45:02 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:02 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:02 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:02 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:02 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:02 [DEBUG] hyper::proto::h1::conn: read eof 22:45:02 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:02 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:02 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:02 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:02 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:02 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 3.590631ms 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 768653703 } 22:45:02 [DEBUG] tokio_core::reactor: loop process, 90.728µs 22:45:02 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:02 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:02 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.26:5353) 22:45:02 [DEBUG] mdns::fsm: received question: IN _D2CA5178._sub._googlecast._tcp.local 22:45:02 [DEBUG] mdns::fsm: received question: IN _googlecast._tcp.local 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 32.881142ms 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 801673958 } 22:45:02 [DEBUG] tokio_core::reactor: loop process, 190.831µs 22:45:02 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:02 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:02 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:40972) 22:45:02 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local 22:45:02 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:45:02 [TRACE] mdns::fsm: [:247] sending packet to V4(192.168.3.23:40972) 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 17.858ms 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 819816277 } 22:45:02 [DEBUG] tokio_core::reactor: loop process, 373.225µs 22:45:02 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:45:02 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 49.9141ms 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 870220632 } 22:45:02 [DEBUG] tokio_core::reactor: loop process, 299.996µs 22:45:02 [DEBUG] hyper::client::connect: connecting to 104.199.64.136:80 22:45:02 [TRACE] mio::poll: [:785] registering with poller 22:45:02 [TRACE] tokio_reactor: [:368] event Writable Token(37748740) 22:45:02 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 110.050413ms 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 981348167 } 22:45:02 [DEBUG] tokio_core::reactor: loop process, 367.912µs 22:45:02 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=false 22:45:02 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:02 [TRACE] hyper::proto::h1::role: [:349] Client::encode has_body=false, method=None 22:45:02 [TRACE] hyper::proto::h1::io: [:546] reclaiming write buf Vec 22:45:02 [DEBUG] hyper::proto::h1::io: flushed 47 bytes 22:45:02 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: KeepAlive, keep_alive: Busy, error: None } 22:45:02 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 1.031706ms 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 983070125 } 22:45:02 [DEBUG] tokio_core::reactor: loop process, 184.685µs 22:45:02 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(37748740) 22:45:02 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:02 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:02 [DEBUG] hyper::proto::h1::io: read 686 bytes 22:45:02 [TRACE] hyper::proto::h1::role: [:254] Response.parse([Header; 100], [u8; 686]) 22:45:02 [TRACE] hyper::proto::h1::role: [:259] Response.parse Complete(268) 22:45:02 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:02 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Vary" 22:45:02 [DEBUG] hyper::proto::h1::io: parsed 9 headers (268 bytes) 22:45:02 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (418 bytes) 22:45:02 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:02 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:02 [TRACE] hyper::proto::h1::conn: [:279] Conn::read_body 22:45:02 [TRACE] hyper::proto::h1::decode: [:88] decode; state=Length(418) 22:45:02 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Body(Length(0)), writing: KeepAlive, keep_alive: Busy, error: None } 22:45:02 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 77.824525ms 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 61170427 } 22:45:02 [DEBUG] tokio_core::reactor: loop process, 175.31µs 22:45:02 [TRACE] hyper::proto::h1::conn: [:279] Conn::read_body 22:45:02 [TRACE] hyper::proto::h1::decode: [:88] decode; state=Length(0) 22:45:02 [DEBUG] hyper::proto::h1::conn: incoming body completed 22:45:02 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:45:02 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=false 22:45:02 [TRACE] want: [:268] signal: Want 22:45:02 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:02 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:02 [TRACE] want: [:132] poll_want: taker wants! 22:45:02 [TRACE] hyper::client::pool: [:306] pool dropped, dropping pooled ("http://apresolve.spotify.com") 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 1.020924ms 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 62672386 } 22:45:02 [DEBUG] tokio_core::reactor: loop process, 185.206µs 22:45:02 [INFO] Connecting to AP "******" 22:45:02 [TRACE] mio::poll: [:785] registering with poller 22:45:02 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=false 22:45:02 [TRACE] hyper::proto::h1::dispatch: [:414] client tx closed 22:45:02 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:02 [TRACE] hyper::proto::h1::conn: [:914] State::close_write() 22:45:02 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Closed, keep_alive: Disabled, error: None } 22:45:02 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:02 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:02 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:02 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:02 [TRACE] want: [:261] signal: Closed 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 1.131965ms 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 204089534 } 22:45:02 [DEBUG] tokio_core::reactor: loop process, 195.102µs 22:45:02 [TRACE] tokio_reactor: [:368] event Writable Token(41943045) 22:45:02 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 85.936139ms 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 290312805 } 22:45:02 [DEBUG] tokio_core::reactor: loop process, 911.186µs 22:45:02 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:02 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 95.585495ms 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 455433347 } 22:45:02 [DEBUG] tokio_core::reactor: loop process, 281.559µs 22:45:03 [TRACE] tokio_io::framed_write: [:188] flushing framed transport 22:45:03 [TRACE] tokio_io::framed_write: [:191] writing; remaining=268 22:45:03 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 22:45:03 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 232.946392ms 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 757033391 } 22:45:03 [DEBUG] tokio_core::reactor: loop process, 828.636µs 22:45:03 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:03 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 22:45:03 [INFO] Authenticated as "****" ! 22:45:03 [DEBUG] librespot_core::session: new Session[0] 22:45:03 [DEBUG] librespot_connect::spirc: new Spirc[0] 22:45:03 [DEBUG] librespot::component: new MercuryManager 22:45:03 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:03 [DEBUG] librespot_playback::player: new Player[0] 22:45:03 [DEBUG] librespot_playback::audio_backend::pulseaudio: Using PulseAudio sink 22:45:03 [DEBUG] librespot_connect::spirc: input volume:65535 to mixer: 65535 22:45:03 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 22:45:03 [DEBUG] librespot_core::session: Session[0] strong=3 weak=2 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:03 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 22:45:03 [INFO] Country: "CH" 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_write: [:188] flushing framed transport 22:45:03 [TRACE] tokio_io::framed_write: [:191] writing; remaining=398 22:45:03 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 2.670852ms 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 764677721 } 22:45:03 [DEBUG] tokio_core::reactor: loop process, 173.487µs 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.002s 22:45:03 [TRACE] tokio_io::framed_write: [:188] flushing framed transport 22:45:03 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 366.349µs 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 765303181 } 22:45:03 [DEBUG] tokio_core::reactor: loop process, 151.561µs 22:45:03 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_write: [:188] flushing framed transport 22:45:03 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 98.871807ms 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 864404725 } 22:45:03 [DEBUG] tokio_core::reactor: loop process, 159.477µs 22:45:03 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 22:45:03 [DEBUG] librespot_core::mercury: unknown subscription uri=hm://remote/3/user/****/2474f3a27a3a14398ce839d7094d6e96a1ad34ba 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_write: [:188] flushing framed transport 22:45:03 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 57.543534ms 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 922198308 } 22:45:03 [DEBUG] tokio_core::reactor: loop process, 148.227µs 22:45:03 [DEBUG] librespot_core::mercury: subscribed uri=hm://remote/3/user/****/ count=0 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 27.343µs 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 922627677 } 22:45:03 [DEBUG] tokio_core::reactor: loop process, 155.884µs 22:45:03 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_write: [:188] flushing framed transport 22:45:03 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 705.668µs 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 923560530 } 22:45:03 [DEBUG] tokio_core::reactor: loop process, 206.299µs 22:45:03 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_write: [:188] flushing framed transport 22:45:03 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 492.65µs 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 924348541 } 22:45:03 [DEBUG] tokio_core::reactor: loop process, 149.894µs 22:45:03 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_write: [:188] flushing framed transport 22:45:03 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 533.795µs 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 925113739 } 22:45:03 [DEBUG] tokio_core::reactor: loop process, 146.509µs 22:45:03 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_write: [:188] flushing framed transport 22:45:03 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 106.525563ms 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 31854716 } 22:45:03 [DEBUG] tokio_core::reactor: loop process, 158.696µs 22:45:03 [DEBUG] librespot_connect::spirc: kMessageTypeNotify "BAH-W09" f4e1aff727d403458a4ff5d3bee0b289d7c6b1fd 1128761214 1545169503407 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 27.812µs 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 32806058 } 22:45:03 [DEBUG] tokio_core::reactor: loop process, 180.571µs 22:45:03 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:03 [TRACE] tokio_io::framed_write: [:188] flushing framed transport 22:45:03 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 129.088555ms 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 162153881 } 22:45:03 [DEBUG] tokio_core::reactor: loop process, 168.436µs 22:45:03 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_write: [:188] flushing framed transport 22:45:03 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 708.22µs 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 163115275 } 22:45:03 [DEBUG] tokio_core::reactor: loop process, 137.811µs 22:45:03 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:03 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_write: [:188] flushing framed transport 22:45:03 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 1.888987ms 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 165214155 } 22:45:03 [DEBUG] tokio_core::reactor: loop process, 194.476µs 22:45:03 [DEBUG] librespot_connect::spirc: kMessageTypeLoad "BAH-W09" f4e1aff727d403458a4ff5d3bee0b289d7c6b1fd 2 1545169503407 22:45:03 [DEBUG] librespot_playback::player: command=Load(SpotifyId(u128!(310569114975204433575564076815579724266)), true, 26782) 22:45:03 [TRACE] tokio_io::framed_write: [:188] flushing framed transport 22:45:03 [TRACE] tokio_io::framed_write: [:191] writing; remaining=2415 22:45:03 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 701.136µs 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 167561572 } 22:45:03 [DEBUG] tokio_core::reactor: loop process, 159.686µs 22:45:03 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_write: [:188] flushing framed transport 22:45:03 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 173.478977ms 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 341278359 } 22:45:03 [DEBUG] tokio_core::reactor: loop process, 157.81µs 22:45:03 [DEBUG] librespot_connect::spirc: kMessageTypeNotify "Web Player (Chrome)" 2474f3a27a3a14398ce839d7094d6e96a1ad34ba 1128761593 1545169503786 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 18.229µs 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 341826008 } 22:45:03 [DEBUG] tokio_core::reactor: loop process, 153.696µs 22:45:03 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 22:45:03 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:03 [TRACE] tokio_io::framed_write: [:188] flushing framed transport 22:45:03 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 42.460342ms 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 384511086 } 22:45:03 [DEBUG] tokio_core::reactor: loop process, 161.873µs 22:45:03 [DEBUG] librespot_connect::spirc: kMessageTypeNotify "BAH-W09" f4e1aff727d403458a4ff5d3bee0b289d7c6b1fd 1128761675 1545169503868 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 28.385µs 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 385099152 } 22:45:03 [DEBUG] tokio_core::reactor: loop process, 159.425µs 22:45:04 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:04 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:04 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 22:45:04 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:04 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 22:45:04 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:04 [TRACE] tokio_io::framed_write: [:188] flushing framed transport 22:45:04 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 124.430386ms 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 509764066 } 22:45:04 [DEBUG] tokio_core::reactor: loop process, 146.925µs 22:45:04 [INFO] Loading track "Ivory Gardens" with Spotify URI "spotify:track:76SOCUGCiF3tgkm9FwEPSG" 22:45:04 [DEBUG] librespot::component: new AudioKeyManager 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 29.114µs 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 510190050 } 22:45:04 [DEBUG] tokio_core::reactor: loop process, 326.975µs 22:45:04 [TRACE] tokio_io::framed_write: [:188] flushing framed transport 22:45:04 [TRACE] tokio_io::framed_write: [:191] writing; remaining=49 22:45:04 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 375.672µs 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 510971602 } 22:45:04 [DEBUG] tokio_core::reactor: loop process, 150.467µs 22:45:04 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:04 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:04 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 22:45:04 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:04 [DEBUG] librespot_audio::fetch: Downloading file 562391fdb29101f16123809e0f00ea47f2df11d0 22:45:04 [TRACE] librespot_audio::fetch: [/home/alarm/.cargo/git/checkouts/librespot-06fda9f186b35c32/3614404/audio/src/fetch.rs:173] requesting chunk 0 22:45:04 [DEBUG] librespot::component: new ChannelManager 22:45:04 [TRACE] tokio_io::framed_write: [:188] flushing framed transport 22:45:04 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 105.256829ms 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 616456710 } 22:45:04 [DEBUG] tokio_core::reactor: loop process, 162.134µs 22:45:04 [DEBUG] tokio_core::reactor: consuming notification queue 22:45:04 [TRACE] tokio_io::framed_write: [:188] flushing framed transport 22:45:04 [TRACE] tokio_io::framed_write: [:191] writing; remaining=53 22:45:04 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 492.546µs 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 617194774 } 22:45:04 [DEBUG] tokio_core::reactor: loop process, 163.07µs 22:45:04 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:04 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:04 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 22:45:04 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:04 [TRACE] tokio_io::framed_write: [:188] flushing framed transport 22:45:04 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 141.513189ms 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 758948532 } 22:45:04 [DEBUG] tokio_core::reactor: loop process, 146.873µs 22:45:04 [DEBUG] librespot_connect::spirc: kMessageTypeNotify "BAH-W09" f4e1aff727d403458a4ff5d3bee0b289d7c6b1fd 1128761955 1545169504148 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 20.26µs 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 759465712 } 22:45:04 [DEBUG] tokio_core::reactor: loop process, 136.665µs 22:45:04 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:04 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:35829) 22:45:04 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local 22:45:04 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:45:04 [TRACE] mdns::fsm: [:247] sending packet to V4(192.168.3.23:35829) 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 63.208045ms 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 822873703 } 22:45:04 [DEBUG] tokio_core::reactor: loop process, 182.862µs 22:45:04 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:04 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 1.560866ms 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 824707742 } 22:45:04 [DEBUG] tokio_core::reactor: loop process, 184.529µs 22:45:04 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:04 [TRACE] mio::poll: [:785] registering with poller 22:45:04 [TRACE] tokio_reactor: [:368] event Writable Token(46137348) 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:04 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:04 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 847.542µs 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 825825957 } 22:45:04 [DEBUG] tokio_core::reactor: loop process, 159.893µs 22:45:04 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(46137348) 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:04 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(46137348) 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:04 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:04 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:45:04 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:45:04 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:45:04 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:04 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:45:04 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:45:04 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:04 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:04 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:04 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:04 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:45:04 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:45:04 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:45:04 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:04 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:04 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? true 22:45:04 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:04 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:04 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:04 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:04 [DEBUG] hyper::proto::h1::conn: read eof 22:45:04 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:04 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:04 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:04 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:04 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:04 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 5.228266ms 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 831294584 } 22:45:04 [DEBUG] tokio_core::reactor: loop process, 163.071µs 22:45:04 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 2.412105ms 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 833952832 } 22:45:04 [DEBUG] tokio_core::reactor: loop process, 183.226µs 22:45:04 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:04 [TRACE] mio::poll: [:785] registering with poller 22:45:04 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:04 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 491.244µs 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 834747353 } 22:45:04 [DEBUG] tokio_core::reactor: loop process, 152.914µs 22:45:04 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(50331652) 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:04 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:04 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:45:04 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:45:04 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:45:04 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:04 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:45:04 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:45:04 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:04 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:04 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:04 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:04 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:45:04 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:45:04 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:45:04 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:45:04 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:04 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 4.266664ms 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 839295055 } 22:45:04 [DEBUG] tokio_core::reactor: loop process, 177.81µs 22:45:04 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(50331652) 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:04 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(50331652) 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:04 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:04 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:04 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:04 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:04 [DEBUG] hyper::proto::h1::conn: read eof 22:45:04 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:04 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:04 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:04 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:04 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:04 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 7.885055ms 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 847442190 } 22:45:04 [DEBUG] tokio_core::reactor: loop process, 90.103µs 22:45:04 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:04 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:04 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 2222:45:04 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame :4522:45:04 [TRACE] tokio_io::framed_write: [:188] flushing framed transport :022:45:04 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 4 [ERROR] 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 48.292923ms channel error: 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 895872924 } 2 22:45:04 [DEBUG] tokio_core::reactor: loop process, 281.142µs 1 22:45:04 [ERROR] Caught panic with message: called `Result::unwrap()` on an `Err` value: ChannelError 22:45:04 [DEBUG] librespot_playback::player: drop Player[0] 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 1.957735ms 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 898211436 } 22:45:04 [DEBUG] tokio_core::reactor: loop process, 300.048µs 22:45:06 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:06 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:06 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:35829) 22:45:06 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local 22:45:06 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:45:06 [TRACE] mdns::fsm: [:247] sending packet to V4(192.168.3.23:35829) 22:45:06 [DEBUG] tokio_core::reactor: loop poll - 1.924627806s 22:45:06 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23642, tv_nsec: 823297309 } 22:45:06 [DEBUG] tokio_core::reactor: loop process, 191.82µs 22:45:06 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:45:06 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:06 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:06 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:06 [DEBUG] tokio_core::reactor: loop poll - 2.835016ms 22:45:06 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23642, tv_nsec: 826424144 } 22:45:06 [DEBUG] tokio_core::reactor: loop process, 234.112µs 22:45:06 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:06 [TRACE] mio::poll: [:785] registering with poller 22:45:06 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:06 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:06 [DEBUG] tokio_core::reactor: loop poll - 472.494µs 22:45:06 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23642, tv_nsec: 827210644 } 22:45:06 [DEBUG] tokio_core::reactor: loop process, 165.832µs 22:45:06 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(54525956) 22:45:06 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:06 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:06 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:45:06 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:45:06 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:45:06 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:06 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:45:06 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:45:06 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:06 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:06 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:06 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:06 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:45:06 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:45:06 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:45:06 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:45:06 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:06 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:06 [DEBUG] tokio_core::reactor: loop poll - 2.423719ms 22:45:06 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23642, tv_nsec: 829888995 } 22:45:06 [DEBUG] tokio_core::reactor: loop process, 273.539µs 22:45:06 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(54525956) 22:45:06 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:06 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:06 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:06 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:06 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:06 [DEBUG] hyper::proto::h1::conn: read eof 22:45:06 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:06 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:06 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:06 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:06 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:06 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:06 [DEBUG] tokio_core::reactor: loop poll - 7.294698ms 22:45:06 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23642, tv_nsec: 837553220 } 22:45:06 [DEBUG] tokio_core::reactor: loop process, 153.8µs 22:45:08 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:08 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:08 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:35829) 22:45:08 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local 22:45:08 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:45:08 [TRACE] mdns::fsm: [:247] sending packet to V4(192.168.3.23:35829) 22:45:08 [DEBUG] tokio_core::reactor: loop poll - 1.986724669s 22:45:08 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23644, tv_nsec: 824514865 } 22:45:08 [DEBUG] tokio_core::reactor: loop process, 201.664µs 22:45:08 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:45:08 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:08 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:08 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:08 [DEBUG] tokio_core::reactor: loop poll - 1.050195ms 22:45:08 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23644, tv_nsec: 825865369 } 22:45:08 [DEBUG] tokio_core::reactor: loop process, 180.778µs 22:45:08 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:08 [TRACE] mio::poll: [:785] registering with poller 22:45:08 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(58720260) 22:45:08 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:08 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:08 [DEBUG] tokio_core::reactor: loop poll - 618.378µs 22:45:08 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23644, tv_nsec: 826754420 } 22:45:08 [DEBUG] tokio_core::reactor: loop process, 171.977µs 22:45:08 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:08 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:45:08 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:45:08 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:45:08 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:08 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:08 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:45:08 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:45:08 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:08 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:08 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:08 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:08 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:45:08 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:45:08 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:45:08 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:45:08 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:08 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:08 [DEBUG] tokio_core::reactor: loop poll - 2.197784ms 22:45:08 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23644, tv_nsec: 829216471 } 22:45:08 [DEBUG] tokio_core::reactor: loop process, 161.196µs 22:45:08 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(58720260) 22:45:08 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:08 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:08 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:08 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:08 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:08 [DEBUG] hyper::proto::h1::conn: read eof 22:45:08 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:08 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:08 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:08 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:08 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:08 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:08 [DEBUG] tokio_core::reactor: loop poll - 4.924676ms 22:45:08 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23644, tv_nsec: 834391405 } 22:45:08 [DEBUG] tokio_core::reactor: loop process, 164.165µs 22:45:10 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:10 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:10 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:35829) 22:45:10 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local 22:45:10 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:45:10 [TRACE] mdns::fsm: [:247] sending packet to V4(192.168.3.23:35829) 22:45:10 [DEBUG] tokio_core::reactor: loop poll - 2.004670743s 22:45:10 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23646, tv_nsec: 839309072 } 22:45:10 [DEBUG] tokio_core::reactor: loop process, 188.278µs 22:45:10 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:45:10 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:10 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:10 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:10 [DEBUG] tokio_core::reactor: loop poll - 1.133631ms 22:45:10 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23646, tv_nsec: 840716397 } 22:45:10 [DEBUG] tokio_core::reactor: loop process, 173.019µs 22:45:10 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:10 [TRACE] mio::poll: [:785] registering with poller 22:45:10 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(62914564) 22:45:10 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:10 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:10 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:10 [DEBUG] tokio_core::reactor: loop poll - 617.023µs 22:45:10 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23646, tv_nsec: 841587792 } 22:45:10 [DEBUG] tokio_core::reactor: loop process, 316.298µs 22:45:10 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:10 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:45:10 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:45:10 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:45:10 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:10 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:45:10 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:45:10 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:10 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:10 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:10 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:10 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:45:10 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:45:10 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:45:10 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:45:10 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:10 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:10 [DEBUG] tokio_core::reactor: loop poll - 1.96435ms 22:45:10 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23646, tv_nsec: 843950158 } 22:45:10 [DEBUG] tokio_core::reactor: loop process, 153.852µs 22:45:10 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(62914564) 22:45:10 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:10 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:10 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:10 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:10 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:10 [DEBUG] hyper::proto::h1::conn: read eof 22:45:10 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:10 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:10 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:10 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:10 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:10 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:10 [DEBUG] tokio_core::reactor: loop poll - 5.492534ms 22:45:10 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23646, tv_nsec: 849675085 } 22:45:10 [DEBUG] tokio_core::reactor: loop process, 157.602µs 22:45:12 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:12 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:12 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:35829) 22:45:12 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local 22:45:12 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:45:12 [TRACE] mdns::fsm: [:247] sending packet to V4(192.168.3.23:35829) 22:45:12 [DEBUG] tokio_core::reactor: loop poll - 1.989680519s 22:45:12 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23648, tv_nsec: 839594924 } 22:45:12 [DEBUG] tokio_core::reactor: loop process, 181.352µs 22:45:12 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:45:12 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:12 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:12 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:12 [DEBUG] tokio_core::reactor: loop poll - 1.179881ms 22:45:12 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23648, tv_nsec: 841057353 } 22:45:12 [DEBUG] tokio_core::reactor: loop process, 270.934µs 22:45:12 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:12 [TRACE] mio::poll: [:785] registering with poller 22:45:12 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:12 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:12 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(67108868) 22:45:12 [DEBUG] tokio_core::reactor: loop poll - 489.16µs 22:45:12 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23648, tv_nsec: 841897759 } 22:45:12 [DEBUG] tokio_core::reactor: loop process, 301.194µs 22:45:12 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:12 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:12 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:45:12 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:45:12 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:45:12 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:12 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:45:12 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:45:12 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:12 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:12 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:12 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:12 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:45:12 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:45:12 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:45:12 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:45:12 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:12 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:12 [DEBUG] tokio_core::reactor: loop poll - 2.067109ms 22:45:12 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23648, tv_nsec: 844346790 } 22:45:12 [DEBUG] tokio_core::reactor: loop process, 150.884µs 22:45:12 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(67108868) 22:45:12 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:12 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:12 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:12 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:12 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:12 [DEBUG] hyper::proto::h1::conn: read eof 22:45:12 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:12 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:12 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:12 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:12 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:12 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:12 [DEBUG] tokio_core::reactor: loop poll - 6.112734ms 22:45:12 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23648, tv_nsec: 850691917 } 22:45:12 [DEBUG] tokio_core::reactor: loop process, 171.248µs 22:45:14 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:14 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:14 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:35829) 22:45:14 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local 22:45:14 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:45:14 [TRACE] mdns::fsm: [:247] sending packet to V4(192.168.3.23:35829) 22:45:14 [DEBUG] tokio_core::reactor: loop poll - 1.989736354s 22:45:14 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23650, tv_nsec: 840683528 } 22:45:14 [DEBUG] tokio_core::reactor: loop process, 200.987µs 22:45:14 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:45:14 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:14 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:14 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:14 [DEBUG] tokio_core::reactor: loop poll - 1.13509ms 22:45:14 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23650, tv_nsec: 842118041 } 22:45:14 [DEBUG] tokio_core::reactor: loop process, 188.956µs 22:45:14 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:14 [TRACE] mio::poll: [:785] registering with poller 22:45:14 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(71303172) 22:45:14 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:14 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:14 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:14 [DEBUG] tokio_core::reactor: loop poll - 744.001µs 22:45:14 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23650, tv_nsec: 843133184 } 22:45:14 [DEBUG] tokio_core::reactor: loop process, 147.602µs 22:45:14 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:14 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:45:14 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:45:14 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:45:14 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:14 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:45:14 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:45:14 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:14 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:14 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:14 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:14 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:45:14 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:45:14 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:45:14 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:45:14 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:14 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:14 [DEBUG] tokio_core::reactor: loop poll - 1.934715ms 22:45:14 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23650, tv_nsec: 845288313 } 22:45:14 [DEBUG] tokio_core::reactor: loop process, 155.675µs 22:45:14 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(71303172) 22:45:14 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:14 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:14 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:14 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:14 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:14 [DEBUG] hyper::proto::h1::conn: read eof 22:45:14 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:14 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:14 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:14 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:14 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:14 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:14 [DEBUG] tokio_core::reactor: loop poll - 5.630865ms 22:45:14 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23650, tv_nsec: 851155633 } 22:45:14 [DEBUG] tokio_core::reactor: loop process, 144.894µs 22:45:16 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:16 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:16 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:35829) 22:45:16 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local 22:45:16 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:45:16 [TRACE] mdns::fsm: [:247] sending packet to V4(192.168.3.23:35829) 22:45:16 [DEBUG] tokio_core::reactor: loop poll - 1.991890285s 22:45:16 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23652, tv_nsec: 843273103 } 22:45:16 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:45:16 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:16 [DEBUG] tokio_core::reactor: loop process, 182.498µs 22:45:16 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:16 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:16 [DEBUG] tokio_core::reactor: loop poll - 4.901447ms 22:45:16 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23652, tv_nsec: 848688867 } 22:45:16 [DEBUG] tokio_core::reactor: loop process, 177.706µs 22:45:16 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:16 [TRACE] mio::poll: [:785] registering with poller 22:45:16 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(75497476) 22:45:16 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:16 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:16 [DEBUG] tokio_core::reactor: loop poll - 647.335µs 22:45:16 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23652, tv_nsec: 849597345 } 22:45:16 [DEBUG] tokio_core::reactor: loop process, 179.842µs 22:45:16 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:16 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:45:16 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:45:16 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:45:16 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:16 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:45:16 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:45:16 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:16 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:16 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:16 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:16 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:16 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:45:16 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:45:16 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:45:16 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:45:16 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:16 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:16 [DEBUG] tokio_core::reactor: loop poll - 2.094869ms 22:45:16 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23652, tv_nsec: 851949919 } 22:45:16 [DEBUG] tokio_core::reactor: loop process, 166.509µs 22:45:16 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(75497476) 22:45:16 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:16 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:16 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:16 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:16 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:16 [DEBUG] hyper::proto::h1::conn: read eof 22:45:16 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:16 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:16 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:16 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:16 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:16 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:16 [DEBUG] tokio_core::reactor: loop poll - 6.428459ms 22:45:16 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23652, tv_nsec: 858626240 } 22:45:16 [DEBUG] tokio_core::reactor: loop process, 153.644µs 22:45:18 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:18 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:18 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:35829) 22:45:18 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local 22:45:18 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:45:18 [TRACE] mdns::fsm: [:247] sending packet to V4(192.168.3.23:35829) 22:45:18 [DEBUG] tokio_core::reactor: loop poll - 1.968184185s 22:45:18 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23654, tv_nsec: 827044901 } 22:45:18 [DEBUG] tokio_core::reactor: loop process, 189.372µs 22:45:18 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:45:18 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:18 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:18 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:18 [DEBUG] tokio_core::reactor: loop poll - 3.415164ms 22:45:18 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23654, tv_nsec: 830809696 } 22:45:18 [DEBUG] tokio_core::reactor: loop process, 618.69µs 22:45:18 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:18 [TRACE] mio::poll: [:785] registering with poller 22:45:18 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:18 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:18 [DEBUG] tokio_core::reactor: loop poll - 494.525µs 22:45:18 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23654, tv_nsec: 832027285 } 22:45:18 [DEBUG] tokio_core::reactor: loop process, 159.581µs 22:45:18 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(79691780) 22:45:18 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:18 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:18 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:45:18 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:45:18 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:45:18 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:18 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:45:18 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:45:18 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:18 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:18 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:18 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:18 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:45:18 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:45:18 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:45:18 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:45:18 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:18 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:18 [DEBUG] tokio_core::reactor: loop poll - 2.221117ms 22:45:18 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23654, tv_nsec: 834507409 } 22:45:18 [DEBUG] tokio_core::reactor: loop process, 149.998µs 22:45:18 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(79691780) 22:45:18 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:18 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:18 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:18 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:18 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:18 [DEBUG] hyper::proto::h1::conn: read eof 22:45:18 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:18 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:18 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:18 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:18 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:18 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:18 [DEBUG] tokio_core::reactor: loop poll - 6.142474ms 22:45:18 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23654, tv_nsec: 840881026 } 22:45:18 [DEBUG] tokio_core::reactor: loop process, 164.789µs 22:45:20 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:20 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:20 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:5353) 22:45:20 [DEBUG] mdns::fsm: received question: IN _CC32E753._sub._googlecast._tcp.local 22:45:20 [DEBUG] mdns::fsm: received question: IN _googlecast._tcp.local 22:45:20 [DEBUG] tokio_core::reactor: loop poll - 1.819113177s 22:45:20 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23656, tv_nsec: 660241022 } 22:45:20 [DEBUG] tokio_core::reactor: loop process, 166.977µs 22:45:20 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:20 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:20 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:35829) 22:45:20 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local 22:45:20 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:45:20 [TRACE] mdns::fsm: [:247] sending packet to V4(192.168.3.23:35829) 22:45:20 [DEBUG] tokio_core::reactor: loop poll - 167.135673ms 22:45:20 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23656, tv_nsec: 827625234 } 22:45:20 [DEBUG] tokio_core::reactor: loop process, 177.81µs 22:45:20 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:45:20 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:20 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:20 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:20 [DEBUG] tokio_core::reactor: loop poll - 2.656633ms 22:45:20 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23656, tv_nsec: 830560405 } 22:45:20 [DEBUG] tokio_core::reactor: loop process, 177.185µs 22:45:20 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:20 [TRACE] mio::poll: [:785] registering with poller 22:45:20 [TRACE] tokio_reactor: [:368] event Writable Token(83886084) 22:45:20 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:20 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:20 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:20 [DEBUG] tokio_core::reactor: loop poll - 733.323µs 22:45:20 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23656, tv_nsec: 831554298 } 22:45:20 [DEBUG] tokio_core::reactor: loop process, 148.019µs 22:45:20 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(83886084) 22:45:20 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:20 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:20 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:45:20 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:45:20 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:45:20 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:20 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:45:20 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:45:20 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:20 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:20 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:20 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:20 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:45:20 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:45:20 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:45:20 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:45:20 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:20 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:20 [DEBUG] tokio_core::reactor: loop poll - 3.943699ms 22:45:20 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23656, tv_nsec: 835720651 } 22:45:20 [DEBUG] tokio_core::reactor: loop process, 158.8µs 22:45:20 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(83886084) 22:45:20 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:20 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:20 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:20 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:20 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:20 [DEBUG] hyper::proto::h1::conn: read eof 22:45:20 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:20 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:20 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:20 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:20 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:20 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:20 [DEBUG] tokio_core::reactor: loop poll - 6.177004ms 22:45:20 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23656, tv_nsec: 842133746 } 22:45:20 [DEBUG] tokio_core::reactor: loop process, 161.717µs 22:45:22 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:22 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:22 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.26:5353) 22:45:22 [DEBUG] mdns::fsm: received question: IN _D2CA5178._sub._googlecast._tcp.local 22:45:22 [DEBUG] mdns::fsm: received question: IN _googlecast._tcp.local 22:45:22 [DEBUG] tokio_core::reactor: loop poll - 1.964117728s 22:45:22 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23658, tv_nsec: 806494857 } 22:45:22 [DEBUG] tokio_core::reactor: loop process, 166.3µs 22:45:22 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:22 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:22 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:35829) 22:45:22 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local 22:45:22 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:45:22 [TRACE] mdns::fsm: [:247] sending packet to V4(192.168.3.23:35829) 22:45:22 [DEBUG] tokio_core::reactor: loop poll - 21.847064ms 22:45:22 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23658, tv_nsec: 828592752 } 22:45:22 [DEBUG] tokio_core::reactor: loop process, 193.122µs 22:45:22 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:45:22 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:22 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:22 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:22 [DEBUG] tokio_core::reactor: loop poll - 2.62257ms 22:45:22 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23658, tv_nsec: 831508235 } 22:45:22 [DEBUG] tokio_core::reactor: loop process, 183.123µs 22:45:22 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:22 [TRACE] mio::poll: [:785] registering with poller 22:45:22 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(88080388) 22:45:22 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:22 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:22 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:22 [DEBUG] tokio_core::reactor: loop poll - 966.602µs 22:45:22 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23658, tv_nsec: 832743844 } 22:45:22 [DEBUG] tokio_core::reactor: loop process, 151.405µs 22:45:22 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:22 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:45:22 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:45:22 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:45:22 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:22 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:45:22 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:45:22 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:22 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:22 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:22 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:22 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:45:22 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:45:22 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:45:22 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:45:22 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:22 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:22 [DEBUG] tokio_core::reactor: loop poll - 1.997266ms 22:45:22 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23658, tv_nsec: 834964597 } 22:45:22 [DEBUG] tokio_core::reactor: loop process, 156.352µs 22:45:22 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(88080388) 22:45:22 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:22 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:22 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:22 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:22 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:22 [DEBUG] hyper::proto::h1::conn: read eof 22:45:22 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:22 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:22 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:22 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:22 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:22 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:22 [DEBUG] tokio_core::reactor: loop poll - 5.204413ms 22:45:22 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23658, tv_nsec: 840402653 } 22:45:22 [DEBUG] tokio_core::reactor: loop process, 155.571µs 22:45:24 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:24 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:24 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:35829) 22:45:24 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local 22:45:24 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:45:24 [TRACE] mdns::fsm: [:247] sending packet to V4(192.168.3.23:35829) 22:45:24 [DEBUG] tokio_core::reactor: loop poll - 2.00478997s 22:45:24 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23660, tv_nsec: 845428401 } 22:45:24 [DEBUG] tokio_core::reactor: loop process, 176.56µs 22:45:24 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:45:24 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:24 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:24 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:24 [DEBUG] tokio_core::reactor: loop poll - 1.562115ms 22:45:24 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23660, tv_nsec: 847253638 } 22:45:24 [DEBUG] tokio_core::reactor: loop process, 167.706µs 22:45:24 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:24 [TRACE] mio::poll: [:785] registering with poller 22:45:24 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(92274692) 22:45:24 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:24 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:24 [DEBUG] tokio_core::reactor: loop poll - 622.127µs 22:45:24 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23660, tv_nsec: 848125814 } 22:45:24 [DEBUG] tokio_core::reactor: loop process, 175.05µs 22:45:24 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:24 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:24 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:45:24 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:45:24 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:45:24 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:24 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:45:24 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:45:24 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:24 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:24 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:24 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:24 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:45:24 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:45:24 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:45:24 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:45:24 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:24 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:24 [DEBUG] tokio_core::reactor: loop poll - 2.173879ms 22:45:24 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23660, tv_nsec: 850564742 } 22:45:24 [DEBUG] tokio_core::reactor: loop process, 159.268µs 22:45:24 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(92274692) 22:45:24 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:24 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:24 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:24 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:24 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:24 [DEBUG] hyper::proto::h1::conn: read eof 22:45:24 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:24 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:24 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:24 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:24 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:24 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:24 [DEBUG] tokio_core::reactor: loop poll - 5.971487ms 22:45:24 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23660, tv_nsec: 856779298 } 22:45:24 [DEBUG] tokio_core::reactor: loop process, 164.737µs 22:45:26 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:26 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:26 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:35829) 22:45:26 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local 22:45:26 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:45:26 [TRACE] mdns::fsm: [:247] sending packet to V4(192.168.3.23:35829) 22:45:26 [DEBUG] tokio_core::reactor: loop poll - 1.990688694s 22:45:26 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23662, tv_nsec: 847715332 } 22:45:26 [DEBUG] tokio_core::reactor: loop process, 200.831µs 22:45:26 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:45:26 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:26 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:26 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:26 [DEBUG] tokio_core::reactor: loop poll - 1.556594ms 22:45:26 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23662, tv_nsec: 849577391 } 22:45:26 [DEBUG] tokio_core::reactor: loop process, 360.204µs 22:45:26 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:26 [TRACE] mio::poll: [:785] registering with poller 22:45:26 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(96468996) 22:45:26 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:26 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:26 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:26 [DEBUG] tokio_core::reactor: loop poll - 1.831956ms 22:45:26 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23662, tv_nsec: 851957986 } 22:45:26 [DEBUG] tokio_core::reactor: loop process, 186.195µs 22:45:26 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:26 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:45:26 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:45:26 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:45:26 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:26 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:45:26 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:45:26 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:26 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:26 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:26 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:26 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:45:26 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:45:26 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:45:26 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:45:26 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:26 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:26 [DEBUG] tokio_core::reactor: loop poll - 2.24169ms 22:45:26 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23662, tv_nsec: 854468787 } 22:45:26 [DEBUG] tokio_core::reactor: loop process, 155.415µs 22:45:26 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(96468996) 22:45:26 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:26 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:26 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(96468996) 22:45:26 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:26 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:26 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:26 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:26 [DEBUG] hyper::proto::h1::conn: read eof 22:45:26 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:26 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:26 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:26 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:26 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:26 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:26 [DEBUG] tokio_core::reactor: loop poll - 5.266131ms 22:45:26 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23662, tv_nsec: 859974550 } 22:45:26 [DEBUG] tokio_core::reactor: loop process, 264.788µs 22:45:28 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:28 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:28 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:35829) 22:45:28 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local 22:45:28 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:45:28 [TRACE] mdns::fsm: [:247] sending packet to V4(192.168.3.23:35829) 22:45:28 [DEBUG] tokio_core::reactor: loop poll - 1.98857992s 22:45:28 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23664, tv_nsec: 848905403 } 22:45:28 [DEBUG] tokio_core::reactor: loop process, 198.748µs 22:45:28 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:45:28 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:28 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:28 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:28 [DEBUG] tokio_core::reactor: loop poll - 1.901955ms 22:45:28 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23664, tv_nsec: 851104906 } 22:45:28 [DEBUG] tokio_core::reactor: loop process, 197.029µs 22:45:28 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:28 [TRACE] mio::poll: [:785] registering with poller 22:45:28 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:28 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:28 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(100663300) 22:45:28 [DEBUG] tokio_core::reactor: loop poll - 548.378µs 22:45:28 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23664, tv_nsec: 851944687 } 22:45:28 [DEBUG] tokio_core::reactor: loop process, 325.256µs 22:45:28 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:28 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:28 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:45:28 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:45:28 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:45:28 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:28 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:45:28 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:45:28 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:28 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:28 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:28 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:28 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:45:28 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:45:28 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:45:28 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:45:28 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:28 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:28 [DEBUG] tokio_core::reactor: loop poll - 2.151848ms 22:45:28 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23664, tv_nsec: 854510644 } 22:45:28 [DEBUG] tokio_core::reactor: loop process, 156.769µs 22:45:28 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(100663300) 22:45:28 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:28 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(100663300) 22:45:28 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:28 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:28 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:28 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:28 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:28 [DEBUG] hyper::proto::h1::conn: read eof 22:45:28 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:28 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:28 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:28 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:28 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:28 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:28 [DEBUG] tokio_core::reactor: loop poll - 4.782699ms 22:45:28 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23664, tv_nsec: 859533288 } 22:45:28 [DEBUG] tokio_core::reactor: loop process, 156.456µs 22:45:30 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:30 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:30 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:35829) 22:45:30 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local 22:45:30 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:45:30 [TRACE] mdns::fsm: [:247] sending packet to V4(192.168.3.23:35829) 22:45:30 [DEBUG] tokio_core::reactor: loop poll - 1.986608489s 22:45:30 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23666, tv_nsec: 846381409 } 22:45:30 [DEBUG] tokio_core::reactor: loop process, 199.685µs 22:45:30 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:45:30 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:30 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:30 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:30 [DEBUG] tokio_core::reactor: loop poll - 1.62123ms 22:45:30 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23666, tv_nsec: 848308676 } 22:45:30 [DEBUG] tokio_core::reactor: loop process, 171.195µs 22:45:30 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:30 [TRACE] mio::poll: [:785] registering with poller 22:45:30 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(104857604) 22:45:30 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:30 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:30 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:30 [DEBUG] tokio_core::reactor: loop poll - 742.23µs 22:45:30 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23666, tv_nsec: 849298663 } 22:45:30 [DEBUG] tokio_core::reactor: loop process, 156.977µs 22:45:30 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:30 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:45:30 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:45:30 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:45:30 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:30 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:45:30 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:45:30 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:30 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:30 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:30 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:30 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:45:30 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:45:30 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:45:30 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:45:30 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:30 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:30 [DEBUG] tokio_core::reactor: loop poll - 2.123619ms 22:45:30 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23666, tv_nsec: 851663737 } 22:45:30 [DEBUG] tokio_core::reactor: loop process, 160.206µs 22:45:30 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(104857604) 22:45:30 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:30 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:30 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:30 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:30 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:30 [DEBUG] hyper::proto::h1::conn: read eof 22:45:30 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:30 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:30 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:30 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:30 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:30 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:30 [DEBUG] tokio_core::reactor: loop poll - 6.151536ms 22:45:30 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23666, tv_nsec: 858058811 } 22:45:30 [DEBUG] tokio_core::reactor: loop process, 152.759µs 22:45:32 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:32 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:32 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:35829) 22:45:32 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local 22:45:32 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:45:32 [TRACE] mdns::fsm: [:247] sending packet to V4(192.168.3.23:35829) 22:45:32 [DEBUG] tokio_core::reactor: loop poll - 1.992448155s 22:45:32 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23668, tv_nsec: 850740661 } 22:45:32 [DEBUG] tokio_core::reactor: loop process, 192.55µs 22:45:32 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:45:32 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:32 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:32 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:32 [DEBUG] tokio_core::reactor: loop poll - 1.083111ms 22:45:32 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23668, tv_nsec: 852109914 } 22:45:32 [DEBUG] tokio_core::reactor: loop process, 179.685µs 22:45:32 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:32 [TRACE] mio::poll: [:785] registering with poller 22:45:32 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(109051908) 22:45:32 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:32 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:32 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:32 [DEBUG] tokio_core::reactor: loop poll - 807.646µs 22:45:32 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23668, tv_nsec: 853181203 } 22:45:32 [DEBUG] tokio_core::reactor: loop process, 169.581µs 22:45:32 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:32 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:45:32 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:45:32 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:45:32 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:32 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:45:32 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:45:32 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:32 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:32 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:32 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:32 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:45:32 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:45:32 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:45:32 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:45:32 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:32 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:32 [DEBUG] tokio_core::reactor: loop poll - 2.444604ms 22:45:32 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23668, tv_nsec: 855881689 } 22:45:32 [DEBUG] tokio_core::reactor: loop process, 180.571µs 22:45:32 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(109051908) 22:45:32 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:32 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:32 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:32 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:32 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:32 [DEBUG] hyper::proto::h1::conn: read eof 22:45:32 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:32 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:32 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:32 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:32 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:32 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:32 [DEBUG] tokio_core::reactor: loop poll - 5.238267ms 22:45:32 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23668, tv_nsec: 861382296 } 22:45:32 [DEBUG] tokio_core::reactor: loop process, 154.581µs 22:45:34 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:34 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:34 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:35829) 22:45:34 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local 22:45:34 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:45:34 [TRACE] mdns::fsm: [:247] sending packet to V4(192.168.3.23:35829) 22:45:34 [DEBUG] tokio_core::reactor: loop poll - 1.974775569s 22:45:34 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23670, tv_nsec: 836389112 } 22:45:34 [DEBUG] tokio_core::reactor: loop process, 621.086µs 22:45:34 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:45:34 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:34 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:34 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:34 [DEBUG] tokio_core::reactor: loop poll - 2.783141ms 22:45:34 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23670, tv_nsec: 839961775 } 22:45:34 [DEBUG] tokio_core::reactor: loop process, 317.548µs 22:45:34 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:34 [TRACE] mio::poll: [:785] registering with poller 22:45:34 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:34 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:34 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(113246212) 22:45:34 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:34 [DEBUG] tokio_core::reactor: loop poll - 630.773µs 22:45:34 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23670, tv_nsec: 841001137 } 22:45:34 [DEBUG] tokio_core::reactor: loop process, 499.629µs 22:45:34 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:34 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:45:34 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:45:34 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:45:34 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:34 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:45:34 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:45:34 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:34 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:34 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:34 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:34 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:45:34 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:45:34 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:45:34 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:45:34 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:34 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:34 [DEBUG] tokio_core::reactor: loop poll - 3.302978ms 22:45:34 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23670, tv_nsec: 844888795 } 22:45:34 [DEBUG] tokio_core::reactor: loop process, 201.456µs 22:45:34 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(113246212) 22:45:34 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:34 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:34 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:34 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:34 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:34 [DEBUG] hyper::proto::h1::conn: read eof 22:45:34 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:34 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:34 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:34 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:34 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:34 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:34 [DEBUG] tokio_core::reactor: loop poll - 5.430764ms 22:45:34 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23670, tv_nsec: 850630701 } 22:45:34 [DEBUG] tokio_core::reactor: loop process, 178.279µs 22:45:36 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(4194305) 22:45:36 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:36 [TRACE] mdns::fsm: [:77] received packet from V4(192.168.3.23:35829) 22:45:36 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local 22:45:36 [TRACE] mdns::fsm: [:183] found interface Interface { name: "eth0", addr: V4(Ifv4Addr { ip: 192.168.3.253, netmask: 255.255.255.0, broadcast: Some(192.168.3.255) }) } 22:45:36 [TRACE] mdns::fsm: [:247] sending packet to V4(192.168.3.23:35829) 22:45:36 [DEBUG] tokio_core::reactor: loop poll - 1.985563454s 22:45:36 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23672, tv_nsec: 836462589 } 22:45:36 [DEBUG] tokio_core::reactor: loop process, 174.477µs 22:45:36 [TRACE] tokio_reactor: [:368] event Writable Token(4194305) 22:45:36 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:36 [TRACE] tokio_reactor: [:368] event Readable Token(0) 22:45:36 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:36 [DEBUG] tokio_core::reactor: loop poll - 2.994441ms 22:45:36 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23672, tv_nsec: 839719839 } 22:45:36 [DEBUG] tokio_core::reactor: loop process, 176.508µs 22:45:36 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:36 [TRACE] mio::poll: [:785] registering with poller 22:45:36 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(117440516) 22:45:36 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None } 22:45:36 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:36 [DEBUG] tokio_core::reactor: loop poll - 714.574µs 22:45:36 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23672, tv_nsec: 840695347 } 22:45:36 [DEBUG] tokio_core::reactor: loop process, 171.561µs 22:45:36 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:36 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:36 [DEBUG] hyper::proto::h1::io: read 220 bytes 22:45:36 [TRACE] hyper::proto::h1::role: [:46] Request.parse([Header; 100], [u8; 220]) 22:45:36 [TRACE] hyper::proto::h1::role: [:50] Request.parse Complete(220) 22:45:36 [TRACE] hyper::header: [:355] maybe_literal not found, copying "Keep-Alive" 22:45:36 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes) 22:45:36 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes) 22:45:36 [TRACE] hyper::proto: [:133] expecting_continue(version=Http11, header=None) = false 22:45:36 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true 22:45:36 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:36 [TRACE] hyper::proto: [:122] should_keep_alive(version=Http11, header=None) = true 22:45:36 [TRACE] hyper::proto::h1::role: [:129] Server::encode has_body=true, method=Some(Get) 22:45:36 [TRACE] hyper::proto::h1::encode: [:100] encoding chunked 453B 22:45:36 [DEBUG] hyper::proto::h1::io: flushed 549 bytes 22:45:36 [TRACE] hyper::proto::h1::conn: [:460] maybe_notify; read_from_io blocked 22:45:36 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None } 22:45:36 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:36 [DEBUG] tokio_core::reactor: loop poll - 2.066953ms 22:45:36 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23672, tv_nsec: 843019328 } 22:45:36 [DEBUG] tokio_core::reactor: loop process, 152.29µs 22:45:36 [TRACE] tokio_reactor: [:368] event Readable | Writable | Hup Token(117440516) 22:45:36 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:36 [TRACE] hyper::proto::h1::conn: [:193] Conn::read_head 22:45:36 [DEBUG] hyper::proto::h1::io: read 0 bytes 22:45:36 [TRACE] hyper::proto::h1::io: [:127] parse eof 22:45:36 [TRACE] hyper::proto::h1::conn: [:904] State::close_read() 22:45:36 [DEBUG] hyper::proto::h1::conn: read eof 22:45:36 [TRACE] hyper::proto::h1::conn: [:317] read_keep_alive; is_mid_message=true 22:45:36 [TRACE] hyper::proto::h1::conn: [:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None } 22:45:36 [TRACE] hyper::proto::h1::conn: [:337] wants_read_again? false 22:45:36 [TRACE] hyper::proto::h1::conn: [:662] shut down IO 22:45:36 [TRACE] mio::poll: [:905] deregistering handle with poller 22:45:36 [DEBUG] tokio_reactor: dropping I/O source: 4 22:45:36 [DEBUG] tokio_core::reactor: loop poll - 6.628977ms 22:45:36 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23672, tv_nsec: 849882938 } 22:45:36 [DEBUG] tokio_core::reactor: loop process, 230.779µs 22:45:36 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:36 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:36 [TRACE] tokio_reactor: [:368] event Readable | Writable Token(41943045) 22:45:36 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:36 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:36 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:36 [TRACE] tokio_io::framed_read: [:198] frame decoded from buffer 22:45:36 [TRACE] tokio_io::framed_read: [:195] attempting to decode a frame 22:45:36 [TRACE] tokio_io::framed_write: [:188] flushing framed transport 22:45:36 [TRACE] tokio_io::framed_write: [:208] framed transport flushed 22:45:36 [DEBUG] tokio_core::reactor: loop poll - 225.374565ms 22:45:36 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23673, tv_nsec: 75579999 } 22:45:36 [DEBUG] tokio_core::reactor: loop process, 141.092µs 22:45:36 [DEBUG] librespot_connect::spirc: kMessageTypePause "BAH-W09" f4e1aff727d403458a4ff5d3bee0b289d7c6b1fd 3 1545169504148 22:45:36 [ERROR] Caught panic with message: called `Result::unwrap()` on an `Err` value: "SendError(..)" 22:45:36 [DEBUG] librespot_connect::spirc: drop Spirc[0] 22:45:36 [DEBUG] librespot_playback::player: Shutting down player thread ... 22:45:36 [ERROR] Player thread panicked! 22:45:36 [DEBUG] librespot_core::session: drop Session[0] 22:45:36 [DEBUG] librespot::component: drop AudioKeyManager 22:45:36 [DEBUG] librespot::component: drop ChannelManager 22:45:36 [DEBUG] librespot::component: drop MercuryManager 22:45:36 [TRACE] tokio_threadpool::pool: [:137] shutdown; state=pool::State { lifecycle: Running, num_futures: 0 } 22:45:36 [TRACE] tokio_threadpool::pool: [:183] -> transitioned to shutdown 22:45:36 [TRACE] tokio_threadpool::pool: [:214] -> shutting down workers 22:45:36 [TRACE] tokio_reactor: [:368] event Readable Token(4194303) 22:45:36 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s 22:45:36 [DEBUG] tokio_reactor::background: shutting background reactor down NOW 22:45:36 [DEBUG] tokio_reactor::background: background reactor has shutdown 22:45:36 [DEBUG] librespot_core::session: drop Dispatch [alarm@alarmpi ~]$ exit Script done on 2018-12-18 22:45:45+01:00 [COMMAND_EXIT_CODE="101"]