API tools faq
paste
Advertisement
wkchu

spotifyd.crash.verbose.online

wkchu
Dec 18th, 2018
539
0
Never
Add comment
Not a member of Pastebin yet? Sign Up, it unlocks many cool features!
text 166.76 KB | None | 0 0
raw download clone embed print report
  1. Script started on 2018-12-18 22:44:33+01:00 [TERM="screen" TTY="/dev/pts/3" COLUMNS="213" LINES="56"]
  2. [alarm@alarmpi ~]$
  3. (reverse-i-search)`': s': lso': sudo vim /etc/asound.conf 
  4. ([8@failed reverse-i-search)`sop': sudo vim /etc/a^C
  5. [alarm@alarmpi ~]$
  6. (reverse-i-search)`': s': lsp': spotifyd --no-daemon -v[1@o': [1@t': [1@i': [1@f': [1@y': [1@d':
  7. [alarm@alarmpi ~]$
  8. 22:44:40 [TRACE] mio::poll: [<unknown>:785] registering with poller
  9. 22:44:40 [TRACE] tokio_threadpool::builder: [<unknown>:401] build; num-workers=4
  10. 22:44:40 [DEBUG] tokio_reactor::background: starting background reactor
  11. 22:44:40 [INFO] Using software volume controller.
  12. 22:44:40 [DEBUG] librespot_connect::discovery: Zeroconf server listening on 0.0.0.0:0
  13. 22:44:40 [TRACE] mio::poll: [<unknown>:785] registering with poller
  14. 22:44:40 [TRACE] mio::poll: [<unknown>:785] registering with poller
  15. 22:44:40 [TRACE] mio::poll: [<unknown>:785] registering with poller
  16. 22:44:40 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  17. 22:44:40 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  18. 22:44:40 [TRACE] mio::poll: [<unknown>:785] registering with poller
  19. 22:44:40 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(8388610)
  20. 22:44:40 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  21. 22:44:40 [DEBUG] tokio_core::reactor: consuming notification queue
  22. 22:44:40 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(12582915)
  23. 22:44:40 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  24. 22:44:40 [TRACE] mdns::fsm: [<unknown>: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) }) }
  25. 22:44:40 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(224.0.0.251:5353)
  26. 22:44:40 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  27. 22:44:40 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  28. 22:44:40 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  29. 22:44:40 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  30. 22:44:40 [TRACE] mdns::fsm: [<unknown>: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) }) }
  31. 22:44:40 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V6([ff02::fb]:5353)
  32. 22:44:40 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(8388610)
  33. 22:44:40 [DEBUG] tokio_core::reactor: loop poll - 1.440659ms
  34. 22:44:40 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23616, tv_nsec: 905879627 }
  35. 22:44:40 [DEBUG] tokio_core::reactor: loop process, 160.102µs
  36. 22:44:40 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  37. 22:44:40 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.253:5353)
  38. 22:44:40 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(8388610)
  39. 22:44:40 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  40. 22:44:40 [TRACE] mdns::fsm: [<unknown>:88] received packet from V4(192.168.3.253:5353) with no query
  41. 22:44:40 [TRACE] mdns::fsm: [<unknown>:77] received packet from V6([fe80::ba27:ebff:fe42:e843]:5353)
  42. 22:44:40 [TRACE] mdns::fsm: [<unknown>:88] received packet from V6([fe80::ba27:ebff:fe42:e843]:5353) with no query
  43. 22:44:40 [DEBUG] tokio_core::reactor: loop poll - 403.224µs
  44. 22:44:40 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23616, tv_nsec: 906505660 }
  45. 22:44:40 [DEBUG] tokio_core::reactor: loop process, 79.374µs
  46. 22:44:42 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  47. 22:44:42 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  48. 22:44:42 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.26:5353)
  49. 22:44:42 [DEBUG] mdns::fsm: received question: IN _D2CA5178._sub._googlecast._tcp.local
  50. 22:44:42 [DEBUG] mdns::fsm: received question: IN _googlecast._tcp.local
  51. 22:44:42 [DEBUG] tokio_core::reactor: loop poll - 1.905254963s
  52. 22:44:42 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23618, tv_nsec: 811882653 }
  53. 22:44:42 [DEBUG] tokio_core::reactor: loop process, 167.03µs
  54. 22:44:57 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  55. 22:44:57 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  56. 22:44:57 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:36574)
  57. 22:44:57 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local
  58. 22:44:57 [TRACE] mdns::fsm: [<unknown>: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) }) }
  59. 22:44:57 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(192.168.3.23:36574)
  60. 22:44:57 [DEBUG] tokio_core::reactor: loop poll - 15.59096128s
  61. 22:44:57 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23634, tv_nsec: 403087732 }
  62. 22:44:57 [DEBUG] tokio_core::reactor: loop process, 98.175µs
  63. 22:44:57 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  64. 22:44:57 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  65. 22:44:57 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  66. 22:44:57 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  67. 22:44:57 [DEBUG] tokio_core::reactor: loop poll - 10.143933ms
  68. 22:44:57 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23634, tv_nsec: 413376871 }
  69. 22:44:57 [DEBUG] tokio_core::reactor: loop process, 131.04µs
  70. 22:44:57 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  71. 22:44:57 [TRACE] mio::poll: [<unknown>:785] registering with poller
  72. 22:44:57 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(16777220)
  73. 22:44:57 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  74. 22:44:57 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  75. 22:44:57 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  76. 22:44:57 [DEBUG] tokio_core::reactor: loop poll - 447.39µs
  77. 22:44:57 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23634, tv_nsec: 414004727 }
  78. 22:44:57 [DEBUG] tokio_core::reactor: loop process, 127.707µs
  79. 22:44:57 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(16777220)
  80. 22:44:57 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  81. 22:44:57 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  82. 22:44:57 [DEBUG] hyper::proto::h1::io: read 220 bytes
  83. 22:44:57 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  84. 22:44:57 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  85. 22:44:57 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  86. 22:44:57 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  87. 22:44:57 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  88. 22:44:57 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  89. 22:44:57 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  90. 22:44:57 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  91. 22:44:57 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  92. 22:44:57 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  93. 22:44:57 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  94. 22:44:57 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  95. 22:44:57 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  96. 22:44:57 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  97. 22:44:57 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  98. 22:44:57 [DEBUG] tokio_core::reactor: loop poll - 1.335192ms
  99. 22:44:57 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23634, tv_nsec: 415510750 }
  100. 22:44:57 [DEBUG] tokio_core::reactor: loop process, 86.613µs
  101. 22:44:57 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(16777220)
  102. 22:44:57 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  103. 22:44:57 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  104. 22:44:57 [DEBUG] hyper::proto::h1::io: read 0 bytes
  105. 22:44:57 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  106. 22:44:57 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  107. 22:44:57 [DEBUG] hyper::proto::h1::conn: read eof
  108. 22:44:57 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  109. 22:44:57 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  110. 22:44:57 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  111. 22:44:57 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  112. 22:44:57 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  113. 22:44:57 [DEBUG] tokio_reactor: dropping I/O source: 4
  114. 22:44:57 [DEBUG] tokio_core::reactor: loop poll - 2.297314ms
  115. 22:44:57 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23634, tv_nsec: 417943270 }
  116. 22:44:57 [DEBUG] tokio_core::reactor: loop process, 82.239µs
  117. 22:45:00 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  118. 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  119. 22:45:00 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:5353)
  120. 22:45:00 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  121. 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  122. 22:45:00 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  123. 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  124. 22:45:00 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  125. 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  126. 22:45:00 [DEBUG] mdns::fsm: received question: IN _CC32E753._sub._googlecast._tcp.local
  127. 22:45:00 [DEBUG] mdns::fsm: received question: IN _googlecast._tcp.local
  128. 22:45:00 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:5353)
  129. 22:45:00 [DEBUG] mdns::fsm: received question: IN _CC32E753._sub._googlecast._tcp.local
  130. 22:45:00 [DEBUG] mdns::fsm: received question: IN _googlecast._tcp.local
  131. 22:45:00 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:36574)
  132. 22:45:00 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local
  133. 22:45:00 [TRACE] mdns::fsm: [<unknown>: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) }) }
  134. 22:45:00 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:5353)
  135. 22:45:00 [DEBUG] mdns::fsm: received question: IN _CC32E753._sub._googlecast._tcp.local
  136. 22:45:00 [DEBUG] mdns::fsm: received question: IN _googlecast._tcp.local
  137. 22:45:00 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(192.168.3.23:36574)
  138. 22:45:00 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  139. 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  140. 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 2.337957925s
  141. 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23636, tv_nsec: 756029319 }
  142. 22:45:00 [DEBUG] tokio_core::reactor: loop process, 292.757µs
  143. 22:45:00 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  144. 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  145. 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 184.737µs
  146. 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23636, tv_nsec: 756605249 }
  147. 22:45:00 [DEBUG] tokio_core::reactor: loop process, 164.685µs
  148. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  149. 22:45:00 [TRACE] mio::poll: [<unknown>:785] registering with poller
  150. 22:45:00 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(20971524)
  151. 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  152. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  153. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  154. 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 650.512µs
  155. 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23636, tv_nsec: 757495810 }
  156. 22:45:00 [DEBUG] tokio_core::reactor: loop process, 156.665µs
  157. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  158. 22:45:00 [DEBUG] hyper::proto::h1::io: read 220 bytes
  159. 22:45:00 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  160. 22:45:00 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  161. 22:45:00 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  162. 22:45:00 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  163. 22:45:00 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  164. 22:45:00 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  165. 22:45:00 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  166. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  167. 22:45:00 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  168. 22:45:00 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  169. 22:45:00 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  170. 22:45:00 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  171. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  172. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  173. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  174. 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 1.980651ms
  175. 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23636, tv_nsec: 759714792 }
  176. 22:45:00 [DEBUG] tokio_core::reactor: loop process, 152.603µs
  177. 22:45:00 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(20971524)
  178. 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  179. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  180. 22:45:00 [DEBUG] hyper::proto::h1::io: read 0 bytes
  181. 22:45:00 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  182. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  183. 22:45:00 [DEBUG] hyper::proto::h1::conn: read eof
  184. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  185. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  186. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  187. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  188. 22:45:00 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  189. 22:45:00 [DEBUG] tokio_reactor: dropping I/O source: 4
  190. 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 21.745242ms
  191. 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23636, tv_nsec: 781692011 }
  192. 22:45:00 [DEBUG] tokio_core::reactor: loop process, 177.498µs
  193. 22:45:00 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(20971524)
  194. 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.001s
  195. 22:45:00 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  196. 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  197. 22:45:00 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:40972)
  198. 22:45:00 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local
  199. 22:45:00 [TRACE] mdns::fsm: [<unknown>: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) }) }
  200. 22:45:00 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(192.168.3.23:40972)
  201. 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 603.641749ms
  202. 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23637, tv_nsec: 385596257 }
  203. 22:45:00 [DEBUG] tokio_core::reactor: loop process, 228.851µs
  204. 22:45:00 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  205. 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  206. 22:45:00 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  207. 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  208. 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 1.577219ms
  209. 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23637, tv_nsec: 387492170 }
  210. 22:45:00 [DEBUG] tokio_core::reactor: loop process, 231.976µs
  211. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  212. 22:45:00 [TRACE] mio::poll: [<unknown>:785] registering with poller
  213. 22:45:00 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(25165828)
  214. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  215. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  216. 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 800.823µs
  217. 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23637, tv_nsec: 388614291 }
  218. 22:45:00 [DEBUG] tokio_core::reactor: loop process, 194.581µs
  219. 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  220. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  221. 22:45:00 [DEBUG] hyper::proto::h1::io: read 220 bytes
  222. 22:45:00 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  223. 22:45:00 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  224. 22:45:00 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  225. 22:45:00 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  226. 22:45:00 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  227. 22:45:00 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  228. 22:45:00 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  229. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  230. 22:45:00 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  231. 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  232. 22:45:00 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  233. 22:45:00 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  234. 22:45:00 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  235. 22:45:00 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  236. 22:45:00 [DEBUG] hyper::proto::h1::io: read 0 bytes
  237. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  238. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? true
  239. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  240. 22:45:00 [DEBUG] hyper::proto::h1::io: read 0 bytes
  241. 22:45:00 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  242. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  243. 22:45:00 [DEBUG] hyper::proto::h1::conn: read eof
  244. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  245. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  246. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  247. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  248. 22:45:00 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  249. 22:45:00 [DEBUG] tokio_reactor: dropping I/O source: 4
  250. 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 3.227927ms
  251. 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23637, tv_nsec: 392334608 }
  252. 22:45:00 [DEBUG] tokio_core::reactor: loop process, 171.665µs
  253. 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 154.321µs
  254. 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23637, tv_nsec: 392743874 }
  255. 22:45:00 [DEBUG] tokio_core::reactor: loop process, 281.871µs
  256. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  257. 22:45:00 [TRACE] mio::poll: [<unknown>:785] registering with poller
  258. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  259. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  260. 22:45:00 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(29360132)
  261. 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 503.223µs
  262. 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23637, tv_nsec: 393611259 }
  263. 22:45:00 [DEBUG] tokio_core::reactor: loop process, 287.704µs
  264. 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  265. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  266. 22:45:00 [DEBUG] hyper::proto::h1::io: read 220 bytes
  267. 22:45:00 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  268. 22:45:00 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  269. 22:45:00 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  270. 22:45:00 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  271. 22:45:00 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  272. 22:45:00 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  273. 22:45:00 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  274. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  275. 22:45:00 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  276. 22:45:00 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  277. 22:45:00 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  278. 22:45:00 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  279. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  280. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  281. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  282. 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 2.037057ms
  283. 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23637, tv_nsec: 396025134 }
  284. 22:45:00 [DEBUG] tokio_core::reactor: loop process, 162.289µs
  285. 22:45:00 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(29360132)
  286. 22:45:00 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  287. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  288. 22:45:00 [DEBUG] hyper::proto::h1::io: read 0 bytes
  289. 22:45:00 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  290. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  291. 22:45:00 [DEBUG] hyper::proto::h1::conn: read eof
  292. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  293. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  294. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  295. 22:45:00 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  296. 22:45:00 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  297. 22:45:00 [DEBUG] tokio_reactor: dropping I/O source: 4
  298. 22:45:00 [DEBUG] tokio_core::reactor: loop poll - 5.713417ms
  299. 22:45:00 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23637, tv_nsec: 401988912 }
  300. 22:45:00 [DEBUG] tokio_core::reactor: loop process, 158.435µs
  301. 22:45:02 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  302. 22:45:02 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  303. 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 1.290219208s
  304. 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 692453169 }
  305. 22:45:02 [DEBUG] tokio_core::reactor: loop process, 188.122µs
  306. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  307. 22:45:02 [TRACE] mio::poll: [<unknown>:785] registering with poller
  308. 22:45:02 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(33554436)
  309. 22:45:02 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  310. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  311. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  312. 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 759.001µs
  313. 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 693486958 }
  314. 22:45:02 [DEBUG] tokio_core::reactor: loop process, 212.132µs
  315. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  316. 22:45:02 [DEBUG] hyper::proto::h1::io: read 906 bytes
  317. 22:45:02 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 906])
  318. 22:45:02 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(227)
  319. 22:45:02 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  320. 22:45:02 [DEBUG] hyper::proto::h1::io: parsed 7 headers (227 bytes)
  321. 22:45:02 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (679 bytes)
  322. 22:45:02 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  323. 22:45:02 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  324. 22:45:02 [DEBUG] librespot_connect::discovery: Post "/" {}
  325. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:279] Conn::read_body
  326. 22:45:02 [TRACE] hyper::proto::h1::decode: [<unknown>:88] decode; state=Length(679)
  327. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Body(Length(0)), writing: Init, keep_alive: Busy, error: None }
  328. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  329. 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 1.775811ms
  330. 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 695558598 }
  331. 22:45:02 [DEBUG] tokio_core::reactor: loop process, 161.195µs
  332. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:279] Conn::read_body
  333. 22:45:02 [TRACE] hyper::proto::h1::decode: [<unknown>:88] decode; state=Length(0)
  334. 22:45:02 [DEBUG] hyper::proto::h1::conn: incoming body completed
  335. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  336. 22:45:02 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  337. 22:45:02 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Post)
  338. 22:45:02 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 57B
  339. 22:45:02 [DEBUG] hyper::proto::h1::io: flushed 152 bytes
  340. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  341. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  342. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  343. 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 67.327836ms
  344. 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 763130076 }
  345. 22:45:02 [DEBUG] tokio_core::reactor: loop process, 119.582µs
  346. 22:45:02 [TRACE] hyper::client::pool: [<unknown>:125] park; waiting for idle connection: "http://apresolve.spotify.com"
  347. 22:45:02 [TRACE] hyper::client::connect: [<unknown>:118] Http::connect("http://apresolve.spotify.com/")
  348. 22:45:02 [DEBUG] hyper::client::dns: resolving host="apresolve.spotify.com", port=80
  349. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  350. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  351. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  352. 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 328.485µs
  353. 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 764932136 }
  354. 22:45:02 [DEBUG] tokio_core::reactor: loop process, 86.926µs
  355. 22:45:02 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(33554436)
  356. 22:45:02 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  357. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  358. 22:45:02 [DEBUG] hyper::proto::h1::io: read 0 bytes
  359. 22:45:02 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  360. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  361. 22:45:02 [DEBUG] hyper::proto::h1::conn: read eof
  362. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  363. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  364. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  365. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  366. 22:45:02 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  367. 22:45:02 [DEBUG] tokio_reactor: dropping I/O source: 4
  368. 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 3.590631ms
  369. 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 768653703 }
  370. 22:45:02 [DEBUG] tokio_core::reactor: loop process, 90.728µs
  371. 22:45:02 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  372. 22:45:02 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  373. 22:45:02 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.26:5353)
  374. 22:45:02 [DEBUG] mdns::fsm: received question: IN _D2CA5178._sub._googlecast._tcp.local
  375. 22:45:02 [DEBUG] mdns::fsm: received question: IN _googlecast._tcp.local
  376. 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 32.881142ms
  377. 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 801673958 }
  378. 22:45:02 [DEBUG] tokio_core::reactor: loop process, 190.831µs
  379. 22:45:02 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  380. 22:45:02 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  381. 22:45:02 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:40972)
  382. 22:45:02 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local
  383. 22:45:02 [TRACE] mdns::fsm: [<unknown>: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) }) }
  384. 22:45:02 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(192.168.3.23:40972)
  385. 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 17.858ms
  386. 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 819816277 }
  387. 22:45:02 [DEBUG] tokio_core::reactor: loop process, 373.225µs
  388. 22:45:02 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  389. 22:45:02 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  390. 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 49.9141ms
  391. 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 870220632 }
  392. 22:45:02 [DEBUG] tokio_core::reactor: loop process, 299.996µs
  393. 22:45:02 [DEBUG] hyper::client::connect: connecting to 104.199.64.136:80
  394. 22:45:02 [TRACE] mio::poll: [<unknown>:785] registering with poller
  395. 22:45:02 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(37748740)
  396. 22:45:02 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  397. 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 110.050413ms
  398. 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 981348167 }
  399. 22:45:02 [DEBUG] tokio_core::reactor: loop process, 367.912µs
  400. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=false
  401. 22:45:02 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  402. 22:45:02 [TRACE] hyper::proto::h1::role: [<unknown>:349] Client::encode has_body=false, method=None
  403. 22:45:02 [TRACE] hyper::proto::h1::io: [<unknown>:546] reclaiming write buf Vec
  404. 22:45:02 [DEBUG] hyper::proto::h1::io: flushed 47 bytes
  405. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: KeepAlive, keep_alive: Busy, error: None }
  406. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  407. 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 1.031706ms
  408. 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23638, tv_nsec: 983070125 }
  409. 22:45:02 [DEBUG] tokio_core::reactor: loop process, 184.685µs
  410. 22:45:02 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(37748740)
  411. 22:45:02 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  412. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  413. 22:45:02 [DEBUG] hyper::proto::h1::io: read 686 bytes
  414. 22:45:02 [TRACE] hyper::proto::h1::role: [<unknown>:254] Response.parse([Header; 100], [u8; 686])
  415. 22:45:02 [TRACE] hyper::proto::h1::role: [<unknown>:259] Response.parse Complete(268)
  416. 22:45:02 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  417. 22:45:02 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Vary"
  418. 22:45:02 [DEBUG] hyper::proto::h1::io: parsed 9 headers (268 bytes)
  419. 22:45:02 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (418 bytes)
  420. 22:45:02 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  421. 22:45:02 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  422. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:279] Conn::read_body
  423. 22:45:02 [TRACE] hyper::proto::h1::decode: [<unknown>:88] decode; state=Length(418)
  424. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Body(Length(0)), writing: KeepAlive, keep_alive: Busy, error: None }
  425. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  426. 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 77.824525ms
  427. 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 61170427 }
  428. 22:45:02 [DEBUG] tokio_core::reactor: loop process, 175.31µs
  429. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:279] Conn::read_body
  430. 22:45:02 [TRACE] hyper::proto::h1::decode: [<unknown>:88] decode; state=Length(0)
  431. 22:45:02 [DEBUG] hyper::proto::h1::conn: incoming body completed
  432. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  433. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=false
  434. 22:45:02 [TRACE] want: [<unknown>:268] signal: Want
  435. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  436. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  437. 22:45:02 [TRACE] want: [<unknown>:132] poll_want: taker wants!
  438. 22:45:02 [TRACE] hyper::client::pool: [<unknown>:306] pool dropped, dropping pooled ("http://apresolve.spotify.com")
  439. 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 1.020924ms
  440. 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 62672386 }
  441. 22:45:02 [DEBUG] tokio_core::reactor: loop process, 185.206µs
  442. 22:45:02 [INFO] Connecting to AP "******"
  443. 22:45:02 [TRACE] mio::poll: [<unknown>:785] registering with poller
  444. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=false
  445. 22:45:02 [TRACE] hyper::proto::h1::dispatch: [<unknown>:414] client tx closed
  446. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  447. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:914] State::close_write()
  448. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Closed, keep_alive: Disabled, error: None }
  449. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  450. 22:45:02 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  451. 22:45:02 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  452. 22:45:02 [DEBUG] tokio_reactor: dropping I/O source: 4
  453. 22:45:02 [TRACE] want: [<unknown>:261] signal: Closed
  454. 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 1.131965ms
  455. 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 204089534 }
  456. 22:45:02 [DEBUG] tokio_core::reactor: loop process, 195.102µs
  457. 22:45:02 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(41943045)
  458. 22:45:02 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  459. 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 85.936139ms
  460. 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 290312805 }
  461. 22:45:02 [DEBUG] tokio_core::reactor: loop process, 911.186µs
  462. 22:45:02 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  463. 22:45:02 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  464. 22:45:02 [DEBUG] tokio_core::reactor: loop poll - 95.585495ms
  465. 22:45:02 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 455433347 }
  466. 22:45:02 [DEBUG] tokio_core::reactor: loop process, 281.559µs
  467. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  468. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:191] writing; remaining=268
  469. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  470. 22:45:03 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  471. 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  472. 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 232.946392ms
  473. 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 757033391 }
  474. 22:45:03 [DEBUG] tokio_core::reactor: loop process, 828.636µs
  475. 22:45:03 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  476. 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  477. 22:45:03 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  478. 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  479. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  480. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  481. 22:45:03 [INFO] Authenticated as "****" !
  482. 22:45:03 [DEBUG] librespot_core::session: new Session[0]
  483. 22:45:03 [DEBUG] librespot_connect::spirc: new Spirc[0]
  484. 22:45:03 [DEBUG] librespot::component: new MercuryManager
  485. 22:45:03 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  486. 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  487. 22:45:03 [DEBUG] librespot_playback::player: new Player[0]
  488. 22:45:03 [DEBUG] librespot_playback::audio_backend::pulseaudio: Using PulseAudio sink
  489. 22:45:03 [DEBUG] librespot_connect::spirc: input volume:65535 to mixer: 65535
  490. 22:45:03 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  491. 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  492. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  493. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  494. 22:45:03 [DEBUG] librespot_core::session: Session[0] strong=3 weak=2
  495. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  496. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  497. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  498. 22:45:03 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  499. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  500. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  501. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  502. 22:45:03 [INFO] Country: "CH"
  503. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  504. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  505. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  506. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  507. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  508. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  509. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  510. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:191] writing; remaining=398
  511. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  512. 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 2.670852ms
  513. 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 764677721 }
  514. 22:45:03 [DEBUG] tokio_core::reactor: loop process, 173.487µs
  515. 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.002s
  516. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  517. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  518. 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 366.349µs
  519. 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 765303181 }
  520. 22:45:03 [DEBUG] tokio_core::reactor: loop process, 151.561µs
  521. 22:45:03 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  522. 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  523. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  524. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  525. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  526. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  527. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  528. 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 98.871807ms
  529. 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 864404725 }
  530. 22:45:03 [DEBUG] tokio_core::reactor: loop process, 159.477µs
  531. 22:45:03 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  532. 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  533. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  534. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  535. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  536. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  537. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  538. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  539. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  540. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  541. 22:45:03 [DEBUG] librespot_core::mercury: unknown subscription uri=hm://remote/3/user/****/2474f3a27a3a14398ce839d7094d6e96a1ad34ba
  542. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  543. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  544. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  545. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  546. 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 57.543534ms
  547. 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 922198308 }
  548. 22:45:03 [DEBUG] tokio_core::reactor: loop process, 148.227µs
  549. 22:45:03 [DEBUG] librespot_core::mercury: subscribed uri=hm://remote/3/user/****/ count=0
  550. 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 27.343µs
  551. 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 922627677 }
  552. 22:45:03 [DEBUG] tokio_core::reactor: loop process, 155.884µs
  553. 22:45:03 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  554. 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  555. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  556. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  557. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  558. 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 705.668µs
  559. 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 923560530 }
  560. 22:45:03 [DEBUG] tokio_core::reactor: loop process, 206.299µs
  561. 22:45:03 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  562. 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  563. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  564. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  565. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  566. 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 492.65µs
  567. 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 924348541 }
  568. 22:45:03 [DEBUG] tokio_core::reactor: loop process, 149.894µs
  569. 22:45:03 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  570. 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  571. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  572. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  573. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  574. 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 533.795µs
  575. 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23639, tv_nsec: 925113739 }
  576. 22:45:03 [DEBUG] tokio_core::reactor: loop process, 146.509µs
  577. 22:45:03 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  578. 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  579. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  580. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  581. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  582. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  583. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  584. 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 106.525563ms
  585. 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 31854716 }
  586. 22:45:03 [DEBUG] tokio_core::reactor: loop process, 158.696µs
  587. 22:45:03 [DEBUG] librespot_connect::spirc: kMessageTypeNotify "BAH-W09" f4e1aff727d403458a4ff5d3bee0b289d7c6b1fd 1128761214 1545169503407
  588. 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 27.812µs
  589. 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 32806058 }
  590. 22:45:03 [DEBUG] tokio_core::reactor: loop process, 180.571µs
  591. 22:45:03 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  592. 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  593. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  594. 22:45:03 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  595. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  596. 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  597. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  598. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  599. 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 129.088555ms
  600. 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 162153881 }
  601. 22:45:03 [DEBUG] tokio_core::reactor: loop process, 168.436µs
  602. 22:45:03 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  603. 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  604. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  605. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  606. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  607. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  608. 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 708.22µs
  609. 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 163115275 }
  610. 22:45:03 [DEBUG] tokio_core::reactor: loop process, 137.811µs
  611. 22:45:03 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  612. 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  613. 22:45:03 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  614. 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  615. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  616. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  617. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  618. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  619. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  620. 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 1.888987ms
  621. 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 165214155 }
  622. 22:45:03 [DEBUG] tokio_core::reactor: loop process, 194.476µs
  623. 22:45:03 [DEBUG] librespot_connect::spirc: kMessageTypeLoad "BAH-W09" f4e1aff727d403458a4ff5d3bee0b289d7c6b1fd 2 1545169503407
  624. 22:45:03 [DEBUG] librespot_playback::player: command=Load(SpotifyId(u128!(310569114975204433575564076815579724266)), true, 26782)
  625. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  626. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:191] writing; remaining=2415
  627. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  628. 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 701.136µs
  629. 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 167561572 }
  630. 22:45:03 [DEBUG] tokio_core::reactor: loop process, 159.686µs
  631. 22:45:03 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  632. 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  633. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  634. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  635. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  636. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  637. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  638. 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 173.478977ms
  639. 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 341278359 }
  640. 22:45:03 [DEBUG] tokio_core::reactor: loop process, 157.81µs
  641. 22:45:03 [DEBUG] librespot_connect::spirc: kMessageTypeNotify "Web Player (Chrome)" 2474f3a27a3a14398ce839d7094d6e96a1ad34ba 1128761593 1545169503786
  642. 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 18.229µs
  643. 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 341826008 }
  644. 22:45:03 [DEBUG] tokio_core::reactor: loop process, 153.696µs
  645. 22:45:03 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  646. 22:45:03 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  647. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  648. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  649. 22:45:03 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  650. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  651. 22:45:03 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  652. 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 42.460342ms
  653. 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 384511086 }
  654. 22:45:03 [DEBUG] tokio_core::reactor: loop process, 161.873µs
  655. 22:45:03 [DEBUG] librespot_connect::spirc: kMessageTypeNotify "BAH-W09" f4e1aff727d403458a4ff5d3bee0b289d7c6b1fd 1128761675 1545169503868
  656. 22:45:03 [DEBUG] tokio_core::reactor: loop poll - 28.385µs
  657. 22:45:03 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 385099152 }
  658. 22:45:03 [DEBUG] tokio_core::reactor: loop process, 159.425µs
  659. 22:45:04 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  660. 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  661. 22:45:04 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  662. 22:45:04 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  663. 22:45:04 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  664. 22:45:04 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  665. 22:45:04 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  666. 22:45:04 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  667. 22:45:04 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  668. 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 124.430386ms
  669. 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 509764066 }
  670. 22:45:04 [DEBUG] tokio_core::reactor: loop process, 146.925µs
  671. 22:45:04 [INFO] Loading track "Ivory Gardens" with Spotify URI "spotify:track:76SOCUGCiF3tgkm9FwEPSG"
  672. 22:45:04 [DEBUG] librespot::component: new AudioKeyManager
  673. 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 29.114µs
  674. 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 510190050 }
  675. 22:45:04 [DEBUG] tokio_core::reactor: loop process, 326.975µs
  676. 22:45:04 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  677. 22:45:04 [TRACE] tokio_io::framed_write: [<unknown>:191] writing; remaining=49
  678. 22:45:04 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  679. 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 375.672µs
  680. 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 510971602 }
  681. 22:45:04 [DEBUG] tokio_core::reactor: loop process, 150.467µs
  682. 22:45:04 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  683. 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  684. 22:45:04 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  685. 22:45:04 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  686. 22:45:04 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  687. 22:45:04 [DEBUG] librespot_audio::fetch: Downloading file 562391fdb29101f16123809e0f00ea47f2df11d0
  688. 22:45:04 [TRACE] librespot_audio::fetch: [/home/alarm/.cargo/git/checkouts/librespot-06fda9f186b35c32/3614404/audio/src/fetch.rs:173] requesting chunk 0
  689. 22:45:04 [DEBUG] librespot::component: new ChannelManager
  690. 22:45:04 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  691. 22:45:04 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  692. 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 105.256829ms
  693. 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 616456710 }
  694. 22:45:04 [DEBUG] tokio_core::reactor: loop process, 162.134µs
  695. 22:45:04 [DEBUG] tokio_core::reactor: consuming notification queue
  696. 22:45:04 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  697. 22:45:04 [TRACE] tokio_io::framed_write: [<unknown>:191] writing; remaining=53
  698. 22:45:04 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  699. 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 492.546µs
  700. 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 617194774 }
  701. 22:45:04 [DEBUG] tokio_core::reactor: loop process, 163.07µs
  702. 22:45:04 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  703. 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  704. 22:45:04 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  705. 22:45:04 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  706. 22:45:04 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  707. 22:45:04 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  708. 22:45:04 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  709. 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 141.513189ms
  710. 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 758948532 }
  711. 22:45:04 [DEBUG] tokio_core::reactor: loop process, 146.873µs
  712. 22:45:04 [DEBUG] librespot_connect::spirc: kMessageTypeNotify "BAH-W09" f4e1aff727d403458a4ff5d3bee0b289d7c6b1fd 1128761955 1545169504148
  713. 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 20.26µs
  714. 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 759465712 }
  715. 22:45:04 [DEBUG] tokio_core::reactor: loop process, 136.665µs
  716. 22:45:04 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  717. 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  718. 22:45:04 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:35829)
  719. 22:45:04 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local
  720. 22:45:04 [TRACE] mdns::fsm: [<unknown>: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) }) }
  721. 22:45:04 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(192.168.3.23:35829)
  722. 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 63.208045ms
  723. 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 822873703 }
  724. 22:45:04 [DEBUG] tokio_core::reactor: loop process, 182.862µs
  725. 22:45:04 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  726. 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  727. 22:45:04 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  728. 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  729. 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 1.560866ms
  730. 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 824707742 }
  731. 22:45:04 [DEBUG] tokio_core::reactor: loop process, 184.529µs
  732. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  733. 22:45:04 [TRACE] mio::poll: [<unknown>:785] registering with poller
  734. 22:45:04 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(46137348)
  735. 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  736. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  737. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  738. 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 847.542µs
  739. 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 825825957 }
  740. 22:45:04 [DEBUG] tokio_core::reactor: loop process, 159.893µs
  741. 22:45:04 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(46137348)
  742. 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  743. 22:45:04 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(46137348)
  744. 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  745. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  746. 22:45:04 [DEBUG] hyper::proto::h1::io: read 220 bytes
  747. 22:45:04 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  748. 22:45:04 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  749. 22:45:04 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  750. 22:45:04 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  751. 22:45:04 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  752. 22:45:04 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  753. 22:45:04 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  754. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  755. 22:45:04 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  756. 22:45:04 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  757. 22:45:04 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  758. 22:45:04 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  759. 22:45:04 [DEBUG] hyper::proto::h1::io: read 0 bytes
  760. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  761. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? true
  762. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  763. 22:45:04 [DEBUG] hyper::proto::h1::io: read 0 bytes
  764. 22:45:04 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  765. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  766. 22:45:04 [DEBUG] hyper::proto::h1::conn: read eof
  767. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  768. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  769. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  770. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  771. 22:45:04 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  772. 22:45:04 [DEBUG] tokio_reactor: dropping I/O source: 4
  773. 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 5.228266ms
  774. 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 831294584 }
  775. 22:45:04 [DEBUG] tokio_core::reactor: loop process, 163.071µs
  776. 22:45:04 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  777. 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  778. 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 2.412105ms
  779. 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 833952832 }
  780. 22:45:04 [DEBUG] tokio_core::reactor: loop process, 183.226µs
  781. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  782. 22:45:04 [TRACE] mio::poll: [<unknown>:785] registering with poller
  783. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  784. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  785. 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 491.244µs
  786. 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 834747353 }
  787. 22:45:04 [DEBUG] tokio_core::reactor: loop process, 152.914µs
  788. 22:45:04 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(50331652)
  789. 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  790. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  791. 22:45:04 [DEBUG] hyper::proto::h1::io: read 220 bytes
  792. 22:45:04 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  793. 22:45:04 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  794. 22:45:04 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  795. 22:45:04 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  796. 22:45:04 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  797. 22:45:04 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  798. 22:45:04 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  799. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  800. 22:45:04 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  801. 22:45:04 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  802. 22:45:04 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  803. 22:45:04 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  804. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  805. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  806. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  807. 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 4.266664ms
  808. 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 839295055 }
  809. 22:45:04 [DEBUG] tokio_core::reactor: loop process, 177.81µs
  810. 22:45:04 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(50331652)
  811. 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  812. 22:45:04 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(50331652)
  813. 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  814. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  815. 22:45:04 [DEBUG] hyper::proto::h1::io: read 0 bytes
  816. 22:45:04 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  817. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  818. 22:45:04 [DEBUG] hyper::proto::h1::conn: read eof
  819. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  820. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  821. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  822. 22:45:04 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  823. 22:45:04 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  824. 22:45:04 [DEBUG] tokio_reactor: dropping I/O source: 4
  825. 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 7.885055ms
  826. 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 847442190 }
  827. 22:45:04 [DEBUG] tokio_core::reactor: loop process, 90.103µs
  828. 22:45:04 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  829. 22:45:04 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  830. 22:45:04 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  831. 22:45:04 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  832. 2222:45:04 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  833. :4522:45:04 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  834. :022:45:04 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  835. 4 [ERROR] 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 48.292923ms
  836. channel error: 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 895872924 }
  837. 2 22:45:04 [DEBUG] tokio_core::reactor: loop process, 281.142µs
  838. 1
  839. 22:45:04 [ERROR] Caught panic with message: called `Result::unwrap()` on an `Err` value: ChannelError
  840. 22:45:04 [DEBUG] librespot_playback::player: drop Player[0]
  841. 22:45:04 [DEBUG] tokio_core::reactor: loop poll - 1.957735ms
  842. 22:45:04 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23640, tv_nsec: 898211436 }
  843. 22:45:04 [DEBUG] tokio_core::reactor: loop process, 300.048µs
  844. 22:45:06 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  845. 22:45:06 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  846. 22:45:06 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:35829)
  847. 22:45:06 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local
  848. 22:45:06 [TRACE] mdns::fsm: [<unknown>: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) }) }
  849. 22:45:06 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(192.168.3.23:35829)
  850. 22:45:06 [DEBUG] tokio_core::reactor: loop poll - 1.924627806s
  851. 22:45:06 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23642, tv_nsec: 823297309 }
  852. 22:45:06 [DEBUG] tokio_core::reactor: loop process, 191.82µs
  853. 22:45:06 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  854. 22:45:06 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  855. 22:45:06 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  856. 22:45:06 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  857. 22:45:06 [DEBUG] tokio_core::reactor: loop poll - 2.835016ms
  858. 22:45:06 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23642, tv_nsec: 826424144 }
  859. 22:45:06 [DEBUG] tokio_core::reactor: loop process, 234.112µs
  860. 22:45:06 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  861. 22:45:06 [TRACE] mio::poll: [<unknown>:785] registering with poller
  862. 22:45:06 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  863. 22:45:06 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  864. 22:45:06 [DEBUG] tokio_core::reactor: loop poll - 472.494µs
  865. 22:45:06 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23642, tv_nsec: 827210644 }
  866. 22:45:06 [DEBUG] tokio_core::reactor: loop process, 165.832µs
  867. 22:45:06 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(54525956)
  868. 22:45:06 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  869. 22:45:06 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  870. 22:45:06 [DEBUG] hyper::proto::h1::io: read 220 bytes
  871. 22:45:06 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  872. 22:45:06 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  873. 22:45:06 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  874. 22:45:06 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  875. 22:45:06 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  876. 22:45:06 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  877. 22:45:06 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  878. 22:45:06 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  879. 22:45:06 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  880. 22:45:06 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  881. 22:45:06 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  882. 22:45:06 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  883. 22:45:06 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  884. 22:45:06 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  885. 22:45:06 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  886. 22:45:06 [DEBUG] tokio_core::reactor: loop poll - 2.423719ms
  887. 22:45:06 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23642, tv_nsec: 829888995 }
  888. 22:45:06 [DEBUG] tokio_core::reactor: loop process, 273.539µs
  889. 22:45:06 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(54525956)
  890. 22:45:06 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  891. 22:45:06 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  892. 22:45:06 [DEBUG] hyper::proto::h1::io: read 0 bytes
  893. 22:45:06 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  894. 22:45:06 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  895. 22:45:06 [DEBUG] hyper::proto::h1::conn: read eof
  896. 22:45:06 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  897. 22:45:06 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  898. 22:45:06 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  899. 22:45:06 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  900. 22:45:06 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  901. 22:45:06 [DEBUG] tokio_reactor: dropping I/O source: 4
  902. 22:45:06 [DEBUG] tokio_core::reactor: loop poll - 7.294698ms
  903. 22:45:06 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23642, tv_nsec: 837553220 }
  904. 22:45:06 [DEBUG] tokio_core::reactor: loop process, 153.8µs
  905. 22:45:08 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  906. 22:45:08 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  907. 22:45:08 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:35829)
  908. 22:45:08 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local
  909. 22:45:08 [TRACE] mdns::fsm: [<unknown>: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) }) }
  910. 22:45:08 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(192.168.3.23:35829)
  911. 22:45:08 [DEBUG] tokio_core::reactor: loop poll - 1.986724669s
  912. 22:45:08 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23644, tv_nsec: 824514865 }
  913. 22:45:08 [DEBUG] tokio_core::reactor: loop process, 201.664µs
  914. 22:45:08 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  915. 22:45:08 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  916. 22:45:08 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  917. 22:45:08 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  918. 22:45:08 [DEBUG] tokio_core::reactor: loop poll - 1.050195ms
  919. 22:45:08 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23644, tv_nsec: 825865369 }
  920. 22:45:08 [DEBUG] tokio_core::reactor: loop process, 180.778µs
  921. 22:45:08 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  922. 22:45:08 [TRACE] mio::poll: [<unknown>:785] registering with poller
  923. 22:45:08 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(58720260)
  924. 22:45:08 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  925. 22:45:08 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  926. 22:45:08 [DEBUG] tokio_core::reactor: loop poll - 618.378µs
  927. 22:45:08 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23644, tv_nsec: 826754420 }
  928. 22:45:08 [DEBUG] tokio_core::reactor: loop process, 171.977µs
  929. 22:45:08 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  930. 22:45:08 [DEBUG] hyper::proto::h1::io: read 220 bytes
  931. 22:45:08 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  932. 22:45:08 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  933. 22:45:08 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  934. 22:45:08 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  935. 22:45:08 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  936. 22:45:08 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  937. 22:45:08 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  938. 22:45:08 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  939. 22:45:08 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  940. 22:45:08 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  941. 22:45:08 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  942. 22:45:08 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  943. 22:45:08 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  944. 22:45:08 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  945. 22:45:08 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  946. 22:45:08 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  947. 22:45:08 [DEBUG] tokio_core::reactor: loop poll - 2.197784ms
  948. 22:45:08 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23644, tv_nsec: 829216471 }
  949. 22:45:08 [DEBUG] tokio_core::reactor: loop process, 161.196µs
  950. 22:45:08 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(58720260)
  951. 22:45:08 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  952. 22:45:08 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  953. 22:45:08 [DEBUG] hyper::proto::h1::io: read 0 bytes
  954. 22:45:08 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  955. 22:45:08 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  956. 22:45:08 [DEBUG] hyper::proto::h1::conn: read eof
  957. 22:45:08 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  958. 22:45:08 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  959. 22:45:08 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  960. 22:45:08 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  961. 22:45:08 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  962. 22:45:08 [DEBUG] tokio_reactor: dropping I/O source: 4
  963. 22:45:08 [DEBUG] tokio_core::reactor: loop poll - 4.924676ms
  964. 22:45:08 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23644, tv_nsec: 834391405 }
  965. 22:45:08 [DEBUG] tokio_core::reactor: loop process, 164.165µs
  966. 22:45:10 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  967. 22:45:10 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  968. 22:45:10 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:35829)
  969. 22:45:10 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local
  970. 22:45:10 [TRACE] mdns::fsm: [<unknown>: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) }) }
  971. 22:45:10 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(192.168.3.23:35829)
  972. 22:45:10 [DEBUG] tokio_core::reactor: loop poll - 2.004670743s
  973. 22:45:10 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23646, tv_nsec: 839309072 }
  974. 22:45:10 [DEBUG] tokio_core::reactor: loop process, 188.278µs
  975. 22:45:10 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  976. 22:45:10 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  977. 22:45:10 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  978. 22:45:10 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  979. 22:45:10 [DEBUG] tokio_core::reactor: loop poll - 1.133631ms
  980. 22:45:10 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23646, tv_nsec: 840716397 }
  981. 22:45:10 [DEBUG] tokio_core::reactor: loop process, 173.019µs
  982. 22:45:10 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  983. 22:45:10 [TRACE] mio::poll: [<unknown>:785] registering with poller
  984. 22:45:10 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(62914564)
  985. 22:45:10 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  986. 22:45:10 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  987. 22:45:10 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  988. 22:45:10 [DEBUG] tokio_core::reactor: loop poll - 617.023µs
  989. 22:45:10 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23646, tv_nsec: 841587792 }
  990. 22:45:10 [DEBUG] tokio_core::reactor: loop process, 316.298µs
  991. 22:45:10 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  992. 22:45:10 [DEBUG] hyper::proto::h1::io: read 220 bytes
  993. 22:45:10 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  994. 22:45:10 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  995. 22:45:10 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  996. 22:45:10 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  997. 22:45:10 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  998. 22:45:10 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  999. 22:45:10 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  1000. 22:45:10 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1001. 22:45:10 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  1002. 22:45:10 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  1003. 22:45:10 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  1004. 22:45:10 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  1005. 22:45:10 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  1006. 22:45:10 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  1007. 22:45:10 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1008. 22:45:10 [DEBUG] tokio_core::reactor: loop poll - 1.96435ms
  1009. 22:45:10 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23646, tv_nsec: 843950158 }
  1010. 22:45:10 [DEBUG] tokio_core::reactor: loop process, 153.852µs
  1011. 22:45:10 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(62914564)
  1012. 22:45:10 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1013. 22:45:10 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1014. 22:45:10 [DEBUG] hyper::proto::h1::io: read 0 bytes
  1015. 22:45:10 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  1016. 22:45:10 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  1017. 22:45:10 [DEBUG] hyper::proto::h1::conn: read eof
  1018. 22:45:10 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1019. 22:45:10 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  1020. 22:45:10 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1021. 22:45:10 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  1022. 22:45:10 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  1023. 22:45:10 [DEBUG] tokio_reactor: dropping I/O source: 4
  1024. 22:45:10 [DEBUG] tokio_core::reactor: loop poll - 5.492534ms
  1025. 22:45:10 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23646, tv_nsec: 849675085 }
  1026. 22:45:10 [DEBUG] tokio_core::reactor: loop process, 157.602µs
  1027. 22:45:12 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  1028. 22:45:12 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1029. 22:45:12 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:35829)
  1030. 22:45:12 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local
  1031. 22:45:12 [TRACE] mdns::fsm: [<unknown>: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) }) }
  1032. 22:45:12 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(192.168.3.23:35829)
  1033. 22:45:12 [DEBUG] tokio_core::reactor: loop poll - 1.989680519s
  1034. 22:45:12 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23648, tv_nsec: 839594924 }
  1035. 22:45:12 [DEBUG] tokio_core::reactor: loop process, 181.352µs
  1036. 22:45:12 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  1037. 22:45:12 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1038. 22:45:12 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  1039. 22:45:12 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1040. 22:45:12 [DEBUG] tokio_core::reactor: loop poll - 1.179881ms
  1041. 22:45:12 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23648, tv_nsec: 841057353 }
  1042. 22:45:12 [DEBUG] tokio_core::reactor: loop process, 270.934µs
  1043. 22:45:12 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1044. 22:45:12 [TRACE] mio::poll: [<unknown>:785] registering with poller
  1045. 22:45:12 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  1046. 22:45:12 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1047. 22:45:12 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(67108868)
  1048. 22:45:12 [DEBUG] tokio_core::reactor: loop poll - 489.16µs
  1049. 22:45:12 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23648, tv_nsec: 841897759 }
  1050. 22:45:12 [DEBUG] tokio_core::reactor: loop process, 301.194µs
  1051. 22:45:12 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1052. 22:45:12 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1053. 22:45:12 [DEBUG] hyper::proto::h1::io: read 220 bytes
  1054. 22:45:12 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  1055. 22:45:12 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  1056. 22:45:12 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  1057. 22:45:12 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  1058. 22:45:12 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  1059. 22:45:12 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  1060. 22:45:12 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  1061. 22:45:12 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1062. 22:45:12 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  1063. 22:45:12 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  1064. 22:45:12 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  1065. 22:45:12 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  1066. 22:45:12 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  1067. 22:45:12 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  1068. 22:45:12 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1069. 22:45:12 [DEBUG] tokio_core::reactor: loop poll - 2.067109ms
  1070. 22:45:12 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23648, tv_nsec: 844346790 }
  1071. 22:45:12 [DEBUG] tokio_core::reactor: loop process, 150.884µs
  1072. 22:45:12 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(67108868)
  1073. 22:45:12 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1074. 22:45:12 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1075. 22:45:12 [DEBUG] hyper::proto::h1::io: read 0 bytes
  1076. 22:45:12 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  1077. 22:45:12 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  1078. 22:45:12 [DEBUG] hyper::proto::h1::conn: read eof
  1079. 22:45:12 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1080. 22:45:12 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  1081. 22:45:12 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1082. 22:45:12 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  1083. 22:45:12 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  1084. 22:45:12 [DEBUG] tokio_reactor: dropping I/O source: 4
  1085. 22:45:12 [DEBUG] tokio_core::reactor: loop poll - 6.112734ms
  1086. 22:45:12 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23648, tv_nsec: 850691917 }
  1087. 22:45:12 [DEBUG] tokio_core::reactor: loop process, 171.248µs
  1088. 22:45:14 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  1089. 22:45:14 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1090. 22:45:14 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:35829)
  1091. 22:45:14 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local
  1092. 22:45:14 [TRACE] mdns::fsm: [<unknown>: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) }) }
  1093. 22:45:14 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(192.168.3.23:35829)
  1094. 22:45:14 [DEBUG] tokio_core::reactor: loop poll - 1.989736354s
  1095. 22:45:14 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23650, tv_nsec: 840683528 }
  1096. 22:45:14 [DEBUG] tokio_core::reactor: loop process, 200.987µs
  1097. 22:45:14 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  1098. 22:45:14 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1099. 22:45:14 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  1100. 22:45:14 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1101. 22:45:14 [DEBUG] tokio_core::reactor: loop poll - 1.13509ms
  1102. 22:45:14 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23650, tv_nsec: 842118041 }
  1103. 22:45:14 [DEBUG] tokio_core::reactor: loop process, 188.956µs
  1104. 22:45:14 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1105. 22:45:14 [TRACE] mio::poll: [<unknown>:785] registering with poller
  1106. 22:45:14 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(71303172)
  1107. 22:45:14 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1108. 22:45:14 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  1109. 22:45:14 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1110. 22:45:14 [DEBUG] tokio_core::reactor: loop poll - 744.001µs
  1111. 22:45:14 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23650, tv_nsec: 843133184 }
  1112. 22:45:14 [DEBUG] tokio_core::reactor: loop process, 147.602µs
  1113. 22:45:14 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1114. 22:45:14 [DEBUG] hyper::proto::h1::io: read 220 bytes
  1115. 22:45:14 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  1116. 22:45:14 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  1117. 22:45:14 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  1118. 22:45:14 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  1119. 22:45:14 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  1120. 22:45:14 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  1121. 22:45:14 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  1122. 22:45:14 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1123. 22:45:14 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  1124. 22:45:14 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  1125. 22:45:14 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  1126. 22:45:14 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  1127. 22:45:14 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  1128. 22:45:14 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  1129. 22:45:14 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1130. 22:45:14 [DEBUG] tokio_core::reactor: loop poll - 1.934715ms
  1131. 22:45:14 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23650, tv_nsec: 845288313 }
  1132. 22:45:14 [DEBUG] tokio_core::reactor: loop process, 155.675µs
  1133. 22:45:14 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(71303172)
  1134. 22:45:14 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1135. 22:45:14 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1136. 22:45:14 [DEBUG] hyper::proto::h1::io: read 0 bytes
  1137. 22:45:14 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  1138. 22:45:14 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  1139. 22:45:14 [DEBUG] hyper::proto::h1::conn: read eof
  1140. 22:45:14 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1141. 22:45:14 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  1142. 22:45:14 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1143. 22:45:14 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  1144. 22:45:14 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  1145. 22:45:14 [DEBUG] tokio_reactor: dropping I/O source: 4
  1146. 22:45:14 [DEBUG] tokio_core::reactor: loop poll - 5.630865ms
  1147. 22:45:14 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23650, tv_nsec: 851155633 }
  1148. 22:45:14 [DEBUG] tokio_core::reactor: loop process, 144.894µs
  1149. 22:45:16 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  1150. 22:45:16 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1151. 22:45:16 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:35829)
  1152. 22:45:16 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local
  1153. 22:45:16 [TRACE] mdns::fsm: [<unknown>: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) }) }
  1154. 22:45:16 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(192.168.3.23:35829)
  1155. 22:45:16 [DEBUG] tokio_core::reactor: loop poll - 1.991890285s
  1156. 22:45:16 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23652, tv_nsec: 843273103 }
  1157. 22:45:16 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  1158. 22:45:16 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1159. 22:45:16 [DEBUG] tokio_core::reactor: loop process, 182.498µs
  1160. 22:45:16 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  1161. 22:45:16 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1162. 22:45:16 [DEBUG] tokio_core::reactor: loop poll - 4.901447ms
  1163. 22:45:16 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23652, tv_nsec: 848688867 }
  1164. 22:45:16 [DEBUG] tokio_core::reactor: loop process, 177.706µs
  1165. 22:45:16 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1166. 22:45:16 [TRACE] mio::poll: [<unknown>:785] registering with poller
  1167. 22:45:16 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(75497476)
  1168. 22:45:16 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  1169. 22:45:16 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1170. 22:45:16 [DEBUG] tokio_core::reactor: loop poll - 647.335µs
  1171. 22:45:16 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23652, tv_nsec: 849597345 }
  1172. 22:45:16 [DEBUG] tokio_core::reactor: loop process, 179.842µs
  1173. 22:45:16 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1174. 22:45:16 [DEBUG] hyper::proto::h1::io: read 220 bytes
  1175. 22:45:16 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  1176. 22:45:16 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  1177. 22:45:16 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  1178. 22:45:16 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  1179. 22:45:16 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  1180. 22:45:16 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  1181. 22:45:16 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  1182. 22:45:16 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1183. 22:45:16 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1184. 22:45:16 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  1185. 22:45:16 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  1186. 22:45:16 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  1187. 22:45:16 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  1188. 22:45:16 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  1189. 22:45:16 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  1190. 22:45:16 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1191. 22:45:16 [DEBUG] tokio_core::reactor: loop poll - 2.094869ms
  1192. 22:45:16 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23652, tv_nsec: 851949919 }
  1193. 22:45:16 [DEBUG] tokio_core::reactor: loop process, 166.509µs
  1194. 22:45:16 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(75497476)
  1195. 22:45:16 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1196. 22:45:16 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1197. 22:45:16 [DEBUG] hyper::proto::h1::io: read 0 bytes
  1198. 22:45:16 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  1199. 22:45:16 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  1200. 22:45:16 [DEBUG] hyper::proto::h1::conn: read eof
  1201. 22:45:16 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1202. 22:45:16 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  1203. 22:45:16 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1204. 22:45:16 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  1205. 22:45:16 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  1206. 22:45:16 [DEBUG] tokio_reactor: dropping I/O source: 4
  1207. 22:45:16 [DEBUG] tokio_core::reactor: loop poll - 6.428459ms
  1208. 22:45:16 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23652, tv_nsec: 858626240 }
  1209. 22:45:16 [DEBUG] tokio_core::reactor: loop process, 153.644µs
  1210. 22:45:18 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  1211. 22:45:18 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1212. 22:45:18 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:35829)
  1213. 22:45:18 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local
  1214. 22:45:18 [TRACE] mdns::fsm: [<unknown>: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) }) }
  1215. 22:45:18 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(192.168.3.23:35829)
  1216. 22:45:18 [DEBUG] tokio_core::reactor: loop poll - 1.968184185s
  1217. 22:45:18 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23654, tv_nsec: 827044901 }
  1218. 22:45:18 [DEBUG] tokio_core::reactor: loop process, 189.372µs
  1219. 22:45:18 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  1220. 22:45:18 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1221. 22:45:18 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  1222. 22:45:18 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1223. 22:45:18 [DEBUG] tokio_core::reactor: loop poll - 3.415164ms
  1224. 22:45:18 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23654, tv_nsec: 830809696 }
  1225. 22:45:18 [DEBUG] tokio_core::reactor: loop process, 618.69µs
  1226. 22:45:18 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1227. 22:45:18 [TRACE] mio::poll: [<unknown>:785] registering with poller
  1228. 22:45:18 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  1229. 22:45:18 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1230. 22:45:18 [DEBUG] tokio_core::reactor: loop poll - 494.525µs
  1231. 22:45:18 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23654, tv_nsec: 832027285 }
  1232. 22:45:18 [DEBUG] tokio_core::reactor: loop process, 159.581µs
  1233. 22:45:18 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(79691780)
  1234. 22:45:18 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1235. 22:45:18 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1236. 22:45:18 [DEBUG] hyper::proto::h1::io: read 220 bytes
  1237. 22:45:18 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  1238. 22:45:18 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  1239. 22:45:18 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  1240. 22:45:18 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  1241. 22:45:18 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  1242. 22:45:18 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  1243. 22:45:18 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  1244. 22:45:18 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1245. 22:45:18 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  1246. 22:45:18 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  1247. 22:45:18 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  1248. 22:45:18 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  1249. 22:45:18 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  1250. 22:45:18 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  1251. 22:45:18 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1252. 22:45:18 [DEBUG] tokio_core::reactor: loop poll - 2.221117ms
  1253. 22:45:18 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23654, tv_nsec: 834507409 }
  1254. 22:45:18 [DEBUG] tokio_core::reactor: loop process, 149.998µs
  1255. 22:45:18 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(79691780)
  1256. 22:45:18 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1257. 22:45:18 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1258. 22:45:18 [DEBUG] hyper::proto::h1::io: read 0 bytes
  1259. 22:45:18 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  1260. 22:45:18 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  1261. 22:45:18 [DEBUG] hyper::proto::h1::conn: read eof
  1262. 22:45:18 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1263. 22:45:18 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  1264. 22:45:18 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1265. 22:45:18 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  1266. 22:45:18 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  1267. 22:45:18 [DEBUG] tokio_reactor: dropping I/O source: 4
  1268. 22:45:18 [DEBUG] tokio_core::reactor: loop poll - 6.142474ms
  1269. 22:45:18 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23654, tv_nsec: 840881026 }
  1270. 22:45:18 [DEBUG] tokio_core::reactor: loop process, 164.789µs
  1271. 22:45:20 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  1272. 22:45:20 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1273. 22:45:20 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:5353)
  1274. 22:45:20 [DEBUG] mdns::fsm: received question: IN _CC32E753._sub._googlecast._tcp.local
  1275. 22:45:20 [DEBUG] mdns::fsm: received question: IN _googlecast._tcp.local
  1276. 22:45:20 [DEBUG] tokio_core::reactor: loop poll - 1.819113177s
  1277. 22:45:20 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23656, tv_nsec: 660241022 }
  1278. 22:45:20 [DEBUG] tokio_core::reactor: loop process, 166.977µs
  1279. 22:45:20 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  1280. 22:45:20 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1281. 22:45:20 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:35829)
  1282. 22:45:20 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local
  1283. 22:45:20 [TRACE] mdns::fsm: [<unknown>: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) }) }
  1284. 22:45:20 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(192.168.3.23:35829)
  1285. 22:45:20 [DEBUG] tokio_core::reactor: loop poll - 167.135673ms
  1286. 22:45:20 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23656, tv_nsec: 827625234 }
  1287. 22:45:20 [DEBUG] tokio_core::reactor: loop process, 177.81µs
  1288. 22:45:20 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  1289. 22:45:20 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1290. 22:45:20 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  1291. 22:45:20 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1292. 22:45:20 [DEBUG] tokio_core::reactor: loop poll - 2.656633ms
  1293. 22:45:20 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23656, tv_nsec: 830560405 }
  1294. 22:45:20 [DEBUG] tokio_core::reactor: loop process, 177.185µs
  1295. 22:45:20 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1296. 22:45:20 [TRACE] mio::poll: [<unknown>:785] registering with poller
  1297. 22:45:20 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(83886084)
  1298. 22:45:20 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1299. 22:45:20 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  1300. 22:45:20 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1301. 22:45:20 [DEBUG] tokio_core::reactor: loop poll - 733.323µs
  1302. 22:45:20 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23656, tv_nsec: 831554298 }
  1303. 22:45:20 [DEBUG] tokio_core::reactor: loop process, 148.019µs
  1304. 22:45:20 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(83886084)
  1305. 22:45:20 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1306. 22:45:20 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1307. 22:45:20 [DEBUG] hyper::proto::h1::io: read 220 bytes
  1308. 22:45:20 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  1309. 22:45:20 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  1310. 22:45:20 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  1311. 22:45:20 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  1312. 22:45:20 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  1313. 22:45:20 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  1314. 22:45:20 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  1315. 22:45:20 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1316. 22:45:20 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  1317. 22:45:20 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  1318. 22:45:20 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  1319. 22:45:20 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  1320. 22:45:20 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  1321. 22:45:20 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  1322. 22:45:20 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1323. 22:45:20 [DEBUG] tokio_core::reactor: loop poll - 3.943699ms
  1324. 22:45:20 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23656, tv_nsec: 835720651 }
  1325. 22:45:20 [DEBUG] tokio_core::reactor: loop process, 158.8µs
  1326. 22:45:20 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(83886084)
  1327. 22:45:20 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1328. 22:45:20 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1329. 22:45:20 [DEBUG] hyper::proto::h1::io: read 0 bytes
  1330. 22:45:20 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  1331. 22:45:20 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  1332. 22:45:20 [DEBUG] hyper::proto::h1::conn: read eof
  1333. 22:45:20 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1334. 22:45:20 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  1335. 22:45:20 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1336. 22:45:20 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  1337. 22:45:20 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  1338. 22:45:20 [DEBUG] tokio_reactor: dropping I/O source: 4
  1339. 22:45:20 [DEBUG] tokio_core::reactor: loop poll - 6.177004ms
  1340. 22:45:20 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23656, tv_nsec: 842133746 }
  1341. 22:45:20 [DEBUG] tokio_core::reactor: loop process, 161.717µs
  1342. 22:45:22 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  1343. 22:45:22 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1344. 22:45:22 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.26:5353)
  1345. 22:45:22 [DEBUG] mdns::fsm: received question: IN _D2CA5178._sub._googlecast._tcp.local
  1346. 22:45:22 [DEBUG] mdns::fsm: received question: IN _googlecast._tcp.local
  1347. 22:45:22 [DEBUG] tokio_core::reactor: loop poll - 1.964117728s
  1348. 22:45:22 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23658, tv_nsec: 806494857 }
  1349. 22:45:22 [DEBUG] tokio_core::reactor: loop process, 166.3µs
  1350. 22:45:22 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  1351. 22:45:22 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1352. 22:45:22 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:35829)
  1353. 22:45:22 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local
  1354. 22:45:22 [TRACE] mdns::fsm: [<unknown>: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) }) }
  1355. 22:45:22 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(192.168.3.23:35829)
  1356. 22:45:22 [DEBUG] tokio_core::reactor: loop poll - 21.847064ms
  1357. 22:45:22 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23658, tv_nsec: 828592752 }
  1358. 22:45:22 [DEBUG] tokio_core::reactor: loop process, 193.122µs
  1359. 22:45:22 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  1360. 22:45:22 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1361. 22:45:22 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  1362. 22:45:22 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1363. 22:45:22 [DEBUG] tokio_core::reactor: loop poll - 2.62257ms
  1364. 22:45:22 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23658, tv_nsec: 831508235 }
  1365. 22:45:22 [DEBUG] tokio_core::reactor: loop process, 183.123µs
  1366. 22:45:22 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1367. 22:45:22 [TRACE] mio::poll: [<unknown>:785] registering with poller
  1368. 22:45:22 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(88080388)
  1369. 22:45:22 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1370. 22:45:22 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  1371. 22:45:22 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1372. 22:45:22 [DEBUG] tokio_core::reactor: loop poll - 966.602µs
  1373. 22:45:22 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23658, tv_nsec: 832743844 }
  1374. 22:45:22 [DEBUG] tokio_core::reactor: loop process, 151.405µs
  1375. 22:45:22 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1376. 22:45:22 [DEBUG] hyper::proto::h1::io: read 220 bytes
  1377. 22:45:22 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  1378. 22:45:22 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  1379. 22:45:22 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  1380. 22:45:22 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  1381. 22:45:22 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  1382. 22:45:22 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  1383. 22:45:22 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  1384. 22:45:22 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1385. 22:45:22 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  1386. 22:45:22 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  1387. 22:45:22 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  1388. 22:45:22 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  1389. 22:45:22 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  1390. 22:45:22 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  1391. 22:45:22 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1392. 22:45:22 [DEBUG] tokio_core::reactor: loop poll - 1.997266ms
  1393. 22:45:22 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23658, tv_nsec: 834964597 }
  1394. 22:45:22 [DEBUG] tokio_core::reactor: loop process, 156.352µs
  1395. 22:45:22 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(88080388)
  1396. 22:45:22 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1397. 22:45:22 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1398. 22:45:22 [DEBUG] hyper::proto::h1::io: read 0 bytes
  1399. 22:45:22 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  1400. 22:45:22 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  1401. 22:45:22 [DEBUG] hyper::proto::h1::conn: read eof
  1402. 22:45:22 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1403. 22:45:22 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  1404. 22:45:22 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1405. 22:45:22 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  1406. 22:45:22 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  1407. 22:45:22 [DEBUG] tokio_reactor: dropping I/O source: 4
  1408. 22:45:22 [DEBUG] tokio_core::reactor: loop poll - 5.204413ms
  1409. 22:45:22 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23658, tv_nsec: 840402653 }
  1410. 22:45:22 [DEBUG] tokio_core::reactor: loop process, 155.571µs
  1411. 22:45:24 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  1412. 22:45:24 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1413. 22:45:24 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:35829)
  1414. 22:45:24 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local
  1415. 22:45:24 [TRACE] mdns::fsm: [<unknown>: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) }) }
  1416. 22:45:24 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(192.168.3.23:35829)
  1417. 22:45:24 [DEBUG] tokio_core::reactor: loop poll - 2.00478997s
  1418. 22:45:24 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23660, tv_nsec: 845428401 }
  1419. 22:45:24 [DEBUG] tokio_core::reactor: loop process, 176.56µs
  1420. 22:45:24 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  1421. 22:45:24 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1422. 22:45:24 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  1423. 22:45:24 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1424. 22:45:24 [DEBUG] tokio_core::reactor: loop poll - 1.562115ms
  1425. 22:45:24 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23660, tv_nsec: 847253638 }
  1426. 22:45:24 [DEBUG] tokio_core::reactor: loop process, 167.706µs
  1427. 22:45:24 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1428. 22:45:24 [TRACE] mio::poll: [<unknown>:785] registering with poller
  1429. 22:45:24 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(92274692)
  1430. 22:45:24 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  1431. 22:45:24 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1432. 22:45:24 [DEBUG] tokio_core::reactor: loop poll - 622.127µs
  1433. 22:45:24 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23660, tv_nsec: 848125814 }
  1434. 22:45:24 [DEBUG] tokio_core::reactor: loop process, 175.05µs
  1435. 22:45:24 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1436. 22:45:24 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1437. 22:45:24 [DEBUG] hyper::proto::h1::io: read 220 bytes
  1438. 22:45:24 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  1439. 22:45:24 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  1440. 22:45:24 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  1441. 22:45:24 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  1442. 22:45:24 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  1443. 22:45:24 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  1444. 22:45:24 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  1445. 22:45:24 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1446. 22:45:24 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  1447. 22:45:24 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  1448. 22:45:24 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  1449. 22:45:24 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  1450. 22:45:24 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  1451. 22:45:24 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  1452. 22:45:24 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1453. 22:45:24 [DEBUG] tokio_core::reactor: loop poll - 2.173879ms
  1454. 22:45:24 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23660, tv_nsec: 850564742 }
  1455. 22:45:24 [DEBUG] tokio_core::reactor: loop process, 159.268µs
  1456. 22:45:24 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(92274692)
  1457. 22:45:24 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1458. 22:45:24 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1459. 22:45:24 [DEBUG] hyper::proto::h1::io: read 0 bytes
  1460. 22:45:24 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  1461. 22:45:24 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  1462. 22:45:24 [DEBUG] hyper::proto::h1::conn: read eof
  1463. 22:45:24 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1464. 22:45:24 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  1465. 22:45:24 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1466. 22:45:24 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  1467. 22:45:24 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  1468. 22:45:24 [DEBUG] tokio_reactor: dropping I/O source: 4
  1469. 22:45:24 [DEBUG] tokio_core::reactor: loop poll - 5.971487ms
  1470. 22:45:24 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23660, tv_nsec: 856779298 }
  1471. 22:45:24 [DEBUG] tokio_core::reactor: loop process, 164.737µs
  1472. 22:45:26 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  1473. 22:45:26 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1474. 22:45:26 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:35829)
  1475. 22:45:26 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local
  1476. 22:45:26 [TRACE] mdns::fsm: [<unknown>: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) }) }
  1477. 22:45:26 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(192.168.3.23:35829)
  1478. 22:45:26 [DEBUG] tokio_core::reactor: loop poll - 1.990688694s
  1479. 22:45:26 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23662, tv_nsec: 847715332 }
  1480. 22:45:26 [DEBUG] tokio_core::reactor: loop process, 200.831µs
  1481. 22:45:26 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  1482. 22:45:26 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1483. 22:45:26 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  1484. 22:45:26 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1485. 22:45:26 [DEBUG] tokio_core::reactor: loop poll - 1.556594ms
  1486. 22:45:26 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23662, tv_nsec: 849577391 }
  1487. 22:45:26 [DEBUG] tokio_core::reactor: loop process, 360.204µs
  1488. 22:45:26 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1489. 22:45:26 [TRACE] mio::poll: [<unknown>:785] registering with poller
  1490. 22:45:26 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(96468996)
  1491. 22:45:26 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1492. 22:45:26 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  1493. 22:45:26 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1494. 22:45:26 [DEBUG] tokio_core::reactor: loop poll - 1.831956ms
  1495. 22:45:26 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23662, tv_nsec: 851957986 }
  1496. 22:45:26 [DEBUG] tokio_core::reactor: loop process, 186.195µs
  1497. 22:45:26 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1498. 22:45:26 [DEBUG] hyper::proto::h1::io: read 220 bytes
  1499. 22:45:26 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  1500. 22:45:26 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  1501. 22:45:26 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  1502. 22:45:26 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  1503. 22:45:26 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  1504. 22:45:26 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  1505. 22:45:26 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  1506. 22:45:26 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1507. 22:45:26 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  1508. 22:45:26 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  1509. 22:45:26 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  1510. 22:45:26 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  1511. 22:45:26 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  1512. 22:45:26 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  1513. 22:45:26 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1514. 22:45:26 [DEBUG] tokio_core::reactor: loop poll - 2.24169ms
  1515. 22:45:26 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23662, tv_nsec: 854468787 }
  1516. 22:45:26 [DEBUG] tokio_core::reactor: loop process, 155.415µs
  1517. 22:45:26 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(96468996)
  1518. 22:45:26 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1519. 22:45:26 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1520. 22:45:26 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(96468996)
  1521. 22:45:26 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1522. 22:45:26 [DEBUG] hyper::proto::h1::io: read 0 bytes
  1523. 22:45:26 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  1524. 22:45:26 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  1525. 22:45:26 [DEBUG] hyper::proto::h1::conn: read eof
  1526. 22:45:26 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1527. 22:45:26 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  1528. 22:45:26 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1529. 22:45:26 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  1530. 22:45:26 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  1531. 22:45:26 [DEBUG] tokio_reactor: dropping I/O source: 4
  1532. 22:45:26 [DEBUG] tokio_core::reactor: loop poll - 5.266131ms
  1533. 22:45:26 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23662, tv_nsec: 859974550 }
  1534. 22:45:26 [DEBUG] tokio_core::reactor: loop process, 264.788µs
  1535. 22:45:28 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  1536. 22:45:28 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1537. 22:45:28 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:35829)
  1538. 22:45:28 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local
  1539. 22:45:28 [TRACE] mdns::fsm: [<unknown>: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) }) }
  1540. 22:45:28 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(192.168.3.23:35829)
  1541. 22:45:28 [DEBUG] tokio_core::reactor: loop poll - 1.98857992s
  1542. 22:45:28 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23664, tv_nsec: 848905403 }
  1543. 22:45:28 [DEBUG] tokio_core::reactor: loop process, 198.748µs
  1544. 22:45:28 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  1545. 22:45:28 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1546. 22:45:28 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  1547. 22:45:28 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1548. 22:45:28 [DEBUG] tokio_core::reactor: loop poll - 1.901955ms
  1549. 22:45:28 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23664, tv_nsec: 851104906 }
  1550. 22:45:28 [DEBUG] tokio_core::reactor: loop process, 197.029µs
  1551. 22:45:28 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1552. 22:45:28 [TRACE] mio::poll: [<unknown>:785] registering with poller
  1553. 22:45:28 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  1554. 22:45:28 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1555. 22:45:28 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(100663300)
  1556. 22:45:28 [DEBUG] tokio_core::reactor: loop poll - 548.378µs
  1557. 22:45:28 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23664, tv_nsec: 851944687 }
  1558. 22:45:28 [DEBUG] tokio_core::reactor: loop process, 325.256µs
  1559. 22:45:28 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1560. 22:45:28 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1561. 22:45:28 [DEBUG] hyper::proto::h1::io: read 220 bytes
  1562. 22:45:28 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  1563. 22:45:28 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  1564. 22:45:28 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  1565. 22:45:28 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  1566. 22:45:28 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  1567. 22:45:28 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  1568. 22:45:28 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  1569. 22:45:28 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1570. 22:45:28 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  1571. 22:45:28 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  1572. 22:45:28 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  1573. 22:45:28 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  1574. 22:45:28 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  1575. 22:45:28 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  1576. 22:45:28 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1577. 22:45:28 [DEBUG] tokio_core::reactor: loop poll - 2.151848ms
  1578. 22:45:28 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23664, tv_nsec: 854510644 }
  1579. 22:45:28 [DEBUG] tokio_core::reactor: loop process, 156.769µs
  1580. 22:45:28 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(100663300)
  1581. 22:45:28 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1582. 22:45:28 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(100663300)
  1583. 22:45:28 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1584. 22:45:28 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1585. 22:45:28 [DEBUG] hyper::proto::h1::io: read 0 bytes
  1586. 22:45:28 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  1587. 22:45:28 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  1588. 22:45:28 [DEBUG] hyper::proto::h1::conn: read eof
  1589. 22:45:28 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1590. 22:45:28 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  1591. 22:45:28 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1592. 22:45:28 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  1593. 22:45:28 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  1594. 22:45:28 [DEBUG] tokio_reactor: dropping I/O source: 4
  1595. 22:45:28 [DEBUG] tokio_core::reactor: loop poll - 4.782699ms
  1596. 22:45:28 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23664, tv_nsec: 859533288 }
  1597. 22:45:28 [DEBUG] tokio_core::reactor: loop process, 156.456µs
  1598. 22:45:30 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  1599. 22:45:30 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1600. 22:45:30 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:35829)
  1601. 22:45:30 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local
  1602. 22:45:30 [TRACE] mdns::fsm: [<unknown>: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) }) }
  1603. 22:45:30 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(192.168.3.23:35829)
  1604. 22:45:30 [DEBUG] tokio_core::reactor: loop poll - 1.986608489s
  1605. 22:45:30 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23666, tv_nsec: 846381409 }
  1606. 22:45:30 [DEBUG] tokio_core::reactor: loop process, 199.685µs
  1607. 22:45:30 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  1608. 22:45:30 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1609. 22:45:30 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  1610. 22:45:30 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1611. 22:45:30 [DEBUG] tokio_core::reactor: loop poll - 1.62123ms
  1612. 22:45:30 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23666, tv_nsec: 848308676 }
  1613. 22:45:30 [DEBUG] tokio_core::reactor: loop process, 171.195µs
  1614. 22:45:30 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1615. 22:45:30 [TRACE] mio::poll: [<unknown>:785] registering with poller
  1616. 22:45:30 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(104857604)
  1617. 22:45:30 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1618. 22:45:30 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  1619. 22:45:30 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1620. 22:45:30 [DEBUG] tokio_core::reactor: loop poll - 742.23µs
  1621. 22:45:30 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23666, tv_nsec: 849298663 }
  1622. 22:45:30 [DEBUG] tokio_core::reactor: loop process, 156.977µs
  1623. 22:45:30 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1624. 22:45:30 [DEBUG] hyper::proto::h1::io: read 220 bytes
  1625. 22:45:30 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  1626. 22:45:30 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  1627. 22:45:30 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  1628. 22:45:30 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  1629. 22:45:30 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  1630. 22:45:30 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  1631. 22:45:30 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  1632. 22:45:30 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1633. 22:45:30 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  1634. 22:45:30 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  1635. 22:45:30 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  1636. 22:45:30 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  1637. 22:45:30 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  1638. 22:45:30 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  1639. 22:45:30 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1640. 22:45:30 [DEBUG] tokio_core::reactor: loop poll - 2.123619ms
  1641. 22:45:30 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23666, tv_nsec: 851663737 }
  1642. 22:45:30 [DEBUG] tokio_core::reactor: loop process, 160.206µs
  1643. 22:45:30 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(104857604)
  1644. 22:45:30 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1645. 22:45:30 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1646. 22:45:30 [DEBUG] hyper::proto::h1::io: read 0 bytes
  1647. 22:45:30 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  1648. 22:45:30 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  1649. 22:45:30 [DEBUG] hyper::proto::h1::conn: read eof
  1650. 22:45:30 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1651. 22:45:30 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  1652. 22:45:30 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1653. 22:45:30 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  1654. 22:45:30 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  1655. 22:45:30 [DEBUG] tokio_reactor: dropping I/O source: 4
  1656. 22:45:30 [DEBUG] tokio_core::reactor: loop poll - 6.151536ms
  1657. 22:45:30 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23666, tv_nsec: 858058811 }
  1658. 22:45:30 [DEBUG] tokio_core::reactor: loop process, 152.759µs
  1659. 22:45:32 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  1660. 22:45:32 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1661. 22:45:32 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:35829)
  1662. 22:45:32 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local
  1663. 22:45:32 [TRACE] mdns::fsm: [<unknown>: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) }) }
  1664. 22:45:32 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(192.168.3.23:35829)
  1665. 22:45:32 [DEBUG] tokio_core::reactor: loop poll - 1.992448155s
  1666. 22:45:32 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23668, tv_nsec: 850740661 }
  1667. 22:45:32 [DEBUG] tokio_core::reactor: loop process, 192.55µs
  1668. 22:45:32 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  1669. 22:45:32 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1670. 22:45:32 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  1671. 22:45:32 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1672. 22:45:32 [DEBUG] tokio_core::reactor: loop poll - 1.083111ms
  1673. 22:45:32 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23668, tv_nsec: 852109914 }
  1674. 22:45:32 [DEBUG] tokio_core::reactor: loop process, 179.685µs
  1675. 22:45:32 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1676. 22:45:32 [TRACE] mio::poll: [<unknown>:785] registering with poller
  1677. 22:45:32 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(109051908)
  1678. 22:45:32 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1679. 22:45:32 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  1680. 22:45:32 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1681. 22:45:32 [DEBUG] tokio_core::reactor: loop poll - 807.646µs
  1682. 22:45:32 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23668, tv_nsec: 853181203 }
  1683. 22:45:32 [DEBUG] tokio_core::reactor: loop process, 169.581µs
  1684. 22:45:32 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1685. 22:45:32 [DEBUG] hyper::proto::h1::io: read 220 bytes
  1686. 22:45:32 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  1687. 22:45:32 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  1688. 22:45:32 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  1689. 22:45:32 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  1690. 22:45:32 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  1691. 22:45:32 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  1692. 22:45:32 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  1693. 22:45:32 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1694. 22:45:32 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  1695. 22:45:32 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  1696. 22:45:32 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  1697. 22:45:32 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  1698. 22:45:32 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  1699. 22:45:32 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  1700. 22:45:32 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1701. 22:45:32 [DEBUG] tokio_core::reactor: loop poll - 2.444604ms
  1702. 22:45:32 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23668, tv_nsec: 855881689 }
  1703. 22:45:32 [DEBUG] tokio_core::reactor: loop process, 180.571µs
  1704. 22:45:32 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(109051908)
  1705. 22:45:32 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1706. 22:45:32 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1707. 22:45:32 [DEBUG] hyper::proto::h1::io: read 0 bytes
  1708. 22:45:32 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  1709. 22:45:32 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  1710. 22:45:32 [DEBUG] hyper::proto::h1::conn: read eof
  1711. 22:45:32 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1712. 22:45:32 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  1713. 22:45:32 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1714. 22:45:32 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  1715. 22:45:32 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  1716. 22:45:32 [DEBUG] tokio_reactor: dropping I/O source: 4
  1717. 22:45:32 [DEBUG] tokio_core::reactor: loop poll - 5.238267ms
  1718. 22:45:32 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23668, tv_nsec: 861382296 }
  1719. 22:45:32 [DEBUG] tokio_core::reactor: loop process, 154.581µs
  1720. 22:45:34 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  1721. 22:45:34 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1722. 22:45:34 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:35829)
  1723. 22:45:34 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local
  1724. 22:45:34 [TRACE] mdns::fsm: [<unknown>: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) }) }
  1725. 22:45:34 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(192.168.3.23:35829)
  1726. 22:45:34 [DEBUG] tokio_core::reactor: loop poll - 1.974775569s
  1727. 22:45:34 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23670, tv_nsec: 836389112 }
  1728. 22:45:34 [DEBUG] tokio_core::reactor: loop process, 621.086µs
  1729. 22:45:34 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  1730. 22:45:34 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1731. 22:45:34 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  1732. 22:45:34 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1733. 22:45:34 [DEBUG] tokio_core::reactor: loop poll - 2.783141ms
  1734. 22:45:34 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23670, tv_nsec: 839961775 }
  1735. 22:45:34 [DEBUG] tokio_core::reactor: loop process, 317.548µs
  1736. 22:45:34 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1737. 22:45:34 [TRACE] mio::poll: [<unknown>:785] registering with poller
  1738. 22:45:34 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  1739. 22:45:34 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1740. 22:45:34 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(113246212)
  1741. 22:45:34 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1742. 22:45:34 [DEBUG] tokio_core::reactor: loop poll - 630.773µs
  1743. 22:45:34 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23670, tv_nsec: 841001137 }
  1744. 22:45:34 [DEBUG] tokio_core::reactor: loop process, 499.629µs
  1745. 22:45:34 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1746. 22:45:34 [DEBUG] hyper::proto::h1::io: read 220 bytes
  1747. 22:45:34 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  1748. 22:45:34 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  1749. 22:45:34 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  1750. 22:45:34 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  1751. 22:45:34 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  1752. 22:45:34 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  1753. 22:45:34 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  1754. 22:45:34 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1755. 22:45:34 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  1756. 22:45:34 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  1757. 22:45:34 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  1758. 22:45:34 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  1759. 22:45:34 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  1760. 22:45:34 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  1761. 22:45:34 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1762. 22:45:34 [DEBUG] tokio_core::reactor: loop poll - 3.302978ms
  1763. 22:45:34 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23670, tv_nsec: 844888795 }
  1764. 22:45:34 [DEBUG] tokio_core::reactor: loop process, 201.456µs
  1765. 22:45:34 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(113246212)
  1766. 22:45:34 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1767. 22:45:34 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1768. 22:45:34 [DEBUG] hyper::proto::h1::io: read 0 bytes
  1769. 22:45:34 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  1770. 22:45:34 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  1771. 22:45:34 [DEBUG] hyper::proto::h1::conn: read eof
  1772. 22:45:34 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1773. 22:45:34 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  1774. 22:45:34 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1775. 22:45:34 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  1776. 22:45:34 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  1777. 22:45:34 [DEBUG] tokio_reactor: dropping I/O source: 4
  1778. 22:45:34 [DEBUG] tokio_core::reactor: loop poll - 5.430764ms
  1779. 22:45:34 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23670, tv_nsec: 850630701 }
  1780. 22:45:34 [DEBUG] tokio_core::reactor: loop process, 178.279µs
  1781. 22:45:36 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(4194305)
  1782. 22:45:36 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1783. 22:45:36 [TRACE] mdns::fsm: [<unknown>:77] received packet from V4(192.168.3.23:35829)
  1784. 22:45:36 [DEBUG] mdns::fsm: received question: IN _spotify-connect._tcp.local
  1785. 22:45:36 [TRACE] mdns::fsm: [<unknown>: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) }) }
  1786. 22:45:36 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(192.168.3.23:35829)
  1787. 22:45:36 [DEBUG] tokio_core::reactor: loop poll - 1.985563454s
  1788. 22:45:36 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23672, tv_nsec: 836462589 }
  1789. 22:45:36 [DEBUG] tokio_core::reactor: loop process, 174.477µs
  1790. 22:45:36 [TRACE] tokio_reactor: [<unknown>:368] event Writable Token(4194305)
  1791. 22:45:36 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1792. 22:45:36 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(0)
  1793. 22:45:36 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1794. 22:45:36 [DEBUG] tokio_core::reactor: loop poll - 2.994441ms
  1795. 22:45:36 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23672, tv_nsec: 839719839 }
  1796. 22:45:36 [DEBUG] tokio_core::reactor: loop process, 176.508µs
  1797. 22:45:36 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1798. 22:45:36 [TRACE] mio::poll: [<unknown>:785] registering with poller
  1799. 22:45:36 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(117440516)
  1800. 22:45:36 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Busy, error: None }
  1801. 22:45:36 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1802. 22:45:36 [DEBUG] tokio_core::reactor: loop poll - 714.574µs
  1803. 22:45:36 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23672, tv_nsec: 840695347 }
  1804. 22:45:36 [DEBUG] tokio_core::reactor: loop process, 171.561µs
  1805. 22:45:36 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1806. 22:45:36 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1807. 22:45:36 [DEBUG] hyper::proto::h1::io: read 220 bytes
  1808. 22:45:36 [TRACE] hyper::proto::h1::role: [<unknown>:46] Request.parse([Header; 100], [u8; 220])
  1809. 22:45:36 [TRACE] hyper::proto::h1::role: [<unknown>:50] Request.parse Complete(220)
  1810. 22:45:36 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
  1811. 22:45:36 [DEBUG] hyper::proto::h1::io: parsed 6 headers (220 bytes)
  1812. 22:45:36 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (0 bytes)
  1813. 22:45:36 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
  1814. 22:45:36 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
  1815. 22:45:36 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1816. 22:45:36 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
  1817. 22:45:36 [TRACE] hyper::proto::h1::role: [<unknown>:129] Server::encode has_body=true, method=Some(Get)
  1818. 22:45:36 [TRACE] hyper::proto::h1::encode: [<unknown>:100] encoding chunked 453B
  1819. 22:45:36 [DEBUG] hyper::proto::h1::io: flushed 549 bytes
  1820. 22:45:36 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
  1821. 22:45:36 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
  1822. 22:45:36 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1823. 22:45:36 [DEBUG] tokio_core::reactor: loop poll - 2.066953ms
  1824. 22:45:36 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23672, tv_nsec: 843019328 }
  1825. 22:45:36 [DEBUG] tokio_core::reactor: loop process, 152.29µs
  1826. 22:45:36 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable | Hup Token(117440516)
  1827. 22:45:36 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1828. 22:45:36 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
  1829. 22:45:36 [DEBUG] hyper::proto::h1::io: read 0 bytes
  1830. 22:45:36 [TRACE] hyper::proto::h1::io: [<unknown>:127] parse eof
  1831. 22:45:36 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
  1832. 22:45:36 [DEBUG] hyper::proto::h1::conn: read eof
  1833. 22:45:36 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=true
  1834. 22:45:36 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }
  1835. 22:45:36 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
  1836. 22:45:36 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
  1837. 22:45:36 [TRACE] mio::poll: [<unknown>:905] deregistering handle with poller
  1838. 22:45:36 [DEBUG] tokio_reactor: dropping I/O source: 4
  1839. 22:45:36 [DEBUG] tokio_core::reactor: loop poll - 6.628977ms
  1840. 22:45:36 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23672, tv_nsec: 849882938 }
  1841. 22:45:36 [DEBUG] tokio_core::reactor: loop process, 230.779µs
  1842. 22:45:36 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  1843. 22:45:36 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1844. 22:45:36 [TRACE] tokio_reactor: [<unknown>:368] event Readable | Writable Token(41943045)
  1845. 22:45:36 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1846. 22:45:36 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  1847. 22:45:36 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  1848. 22:45:36 [TRACE] tokio_io::framed_read: [<unknown>:198] frame decoded from buffer
  1849. 22:45:36 [TRACE] tokio_io::framed_read: [<unknown>:195] attempting to decode a frame
  1850. 22:45:36 [TRACE] tokio_io::framed_write: [<unknown>:188] flushing framed transport
  1851. 22:45:36 [TRACE] tokio_io::framed_write: [<unknown>:208] framed transport flushed
  1852. 22:45:36 [DEBUG] tokio_core::reactor: loop poll - 225.374565ms
  1853. 22:45:36 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 23673, tv_nsec: 75579999 }
  1854. 22:45:36 [DEBUG] tokio_core::reactor: loop process, 141.092µs
  1855. 22:45:36 [DEBUG] librespot_connect::spirc: kMessageTypePause "BAH-W09" f4e1aff727d403458a4ff5d3bee0b289d7c6b1fd 3 1545169504148
  1856. 22:45:36 [ERROR] Caught panic with message: called `Result::unwrap()` on an `Err` value: "SendError(..)"
  1857. 22:45:36 [DEBUG] librespot_connect::spirc: drop Spirc[0]
  1858. 22:45:36 [DEBUG] librespot_playback::player: Shutting down player thread ...
  1859. 22:45:36 [ERROR] Player thread panicked!
  1860. 22:45:36 [DEBUG] librespot_core::session: drop Session[0]
  1861. 22:45:36 [DEBUG] librespot::component: drop AudioKeyManager
  1862. 22:45:36 [DEBUG] librespot::component: drop ChannelManager
  1863. 22:45:36 [DEBUG] librespot::component: drop MercuryManager
  1864. 22:45:36 [TRACE] tokio_threadpool::pool: [<unknown>:137] shutdown; state=pool::State { lifecycle: Running, num_futures: 0 }
  1865. 22:45:36 [TRACE] tokio_threadpool::pool: [<unknown>:183] -> transitioned to shutdown
  1866. 22:45:36 [TRACE] tokio_threadpool::pool: [<unknown>:214] -> shutting down workers
  1867. 22:45:36 [TRACE] tokio_reactor: [<unknown>:368] event Readable Token(4194303)
  1868. 22:45:36 [DEBUG] tokio_reactor: loop process - 1 events, 0.000s
  1869. 22:45:36 [DEBUG] tokio_reactor::background: shutting background reactor down NOW
  1870. 22:45:36 [DEBUG] tokio_reactor::background: background reactor has shutdown
  1871. 22:45:36 [DEBUG] librespot_core::session: drop Dispatch
  1872. [alarm@alarmpi ~]$ exit
  1873.  
  1874. Script done on 2018-12-18 22:45:45+01:00 [COMMAND_EXIT_CODE="101"]
Advertisement
Add Comment
Please, Sign In to add comment
Advertisement
Public Pastes
Advertisement
We use cookies for various purposes including analytics. By continuing to use Pastebin, you agree to our use of cookies as described in the Cookies Policy.  OK, I Understand
Not a member of Pastebin yet?
Sign Up, it unlocks many cool features!