Forked-DAAPD / HomePod Log

forked-daapd.log

[2019-11-10 17:59:29] [DEBUG]   player: Start playback of '/media/music/Mark Knopfler/Down the Road Wherever (2018) [CD]/14 Every Heart in the Room.m4a' (id=29562, item-id=1667)
[2019-11-10 17:59:29] [DEBUG]       db: Running query 'SELECT f.* FROM files f WHERE f.id = 29562;'
[2019-11-10 17:59:29] [DEBUG]   player: (Re)opening track: '/media/music/Mark Knopfler/Down the Road Wherever (2018) [CD]/14 Every Heart in the Room.m4a' (id=1667, seek=0)
[2019-11-10 17:59:29] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2019-11-10 17:59:29] [DEBUG]       db: Starting enum 'SELECT * FROM queue f WHERE id = 1667 ORDER BY pos;'
[2019-11-10 17:59:29] [DEBUG]       db: Running query 'END TRANSACTION;'
[2019-11-10 17:59:29] [DEBUG]   player: Setting up input item '/media/music/Mark Knopfler/Down the Road Wherever (2018) [CD]/14 Every Heart in the Room.m4a' (item id 1667)
[2019-11-10 17:59:30] [DEBUG]   ffmpeg: Unhandled or malformed custom metadata of size 64
[2019-11-10 17:59:30] [DEBUG]   ffmpeg: Unhandled or malformed custom metadata of size 68
[2019-11-10 17:59:30] [ WARN]   ffmpeg: stream 0, timescale not set
[2019-11-10 17:59:30] [DEBUG]   ffmpeg: tb:1/44100 samplefmt:s16p samplerate:44100 chlayout:0x3
[2019-11-10 17:59:30] [DEBUG]    xcode: Created 'in' filter: time_base=1/44100:sample_rate=44100:sample_fmt=s16p:channel_layout=0x3
[2019-11-10 17:59:30] [DEBUG]    xcode: Created 'format' filter: sample_fmts=s16:sample_rates=44100:channel_layouts=0x3
[2019-11-10 17:59:30] [DEBUG]   ffmpeg: auto-inserting filter 'auto_resampler_0' between the filter 'in' and the filter 'format'
[2019-11-10 17:59:30] [DEBUG]   ffmpeg: ch:2 chl:stereo fmt:s16p r:44100Hz -> ch:2 chl:stereo fmt:s16 r:44100Hz
[2019-11-10 17:59:30] [DEBUG]   player: Starting input read loop for item '/media/music/Mark Knopfler/Down the Road Wherever (2018) [CD]/14 Every Heart in the Room.m4a' (item id 1667), seek 0
[2019-11-10 17:59:30] [DEBUG]   player: Registered callback to device_restart_cb with id 0 (device 0x5634bfb88dc0, myPod)
[2019-11-10 17:59:30] [DEBUG]   player: Number of active callbacks: 1
[2019-11-10 17:59:30] [DEBUG]   player: Subscription request for quality 44100/16/2 (now 1 subscribers)
[2019-11-10 17:59:30] [DEBUG]     raop: device_start: Sending OPTIONS to 'myPod'
[2019-11-10 17:59:30] [ INFO]   player: Using selected AirPlay device 'myPod'
[2019-11-10 17:59:30] [DEBUG]     raop: startup_options: Sending ANNOUNCE to 'myPod'
[2019-11-10 17:59:30] [DEBUG]     raop: Local address: 192.168.178.10 (LL: no) port 33276
[2019-11-10 17:59:30] [ INFO]     raop: Setting up AirPlay session 3620170260 (192.168.178.10 -> 192.168.178.11)
[2019-11-10 17:59:30] [DEBUG]     raop: startup_announce: Sending SETUP to 'myPod'
[2019-11-10 17:59:30] [DEBUG]     raop: token: unicast
[2019-11-10 17:59:30] [DEBUG]     raop: token: mode
[2019-11-10 17:59:30] [DEBUG]     raop: token: record
[2019-11-10 17:59:30] [DEBUG]     raop: token: server_port
[2019-11-10 17:59:30] [DEBUG]     raop: token: control_port
[2019-11-10 17:59:30] [DEBUG]     raop: token: timing_port
[2019-11-10 17:59:30] [DEBUG]     raop: Negotiated AirTunes v2 UDP streaming session 1; ports s=62720 c=62149 t=0
[2019-11-10 17:59:30] [DEBUG]     raop: startup_setup: Sending RECORD to 'myPod'
[2019-11-10 17:59:30] [DEBUG]     raop: RTP-Info is seq=27975;rtptime=2537217543
[2019-11-10 17:59:30] [DEBUG]     raop: RAOP audio latency is 3600
[2019-11-10 17:59:30] [DEBUG]     raop: volume_internal: Sending SET_PARAMETER to 'myPod'
[2019-11-10 17:59:30] [DEBUG]   player: Callback request received, id is 0
[2019-11-10 17:59:30] [DEBUG]   player: Making deferred callback to device_restart_cb, id was 0
[2019-11-10 17:59:30] [DEBUG]   player: Callback from AirPlay to device_restart_cb (status 2)
[2019-11-10 17:59:30] [DEBUG]   player: Registered callback to device_streaming_cb with id 0 (device 0x5634bfb88dc0, myPod)
[2019-11-10 17:59:30] [DEBUG]   player: Number of active callbacks: 1
[2019-11-10 17:59:30] [DEBUG]     main: Command has 0 pending events
[2019-11-10 17:59:30] [DEBUG]     main: Got worker execute request
[2019-11-10 17:59:30] [DEBUG]      mpd: Asynchronous listener callback called with event type 1.
[2019-11-10 17:59:30] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2019-11-10 17:59:30] [DEBUG]       db: Starting enum 'SELECT * FROM queue f WHERE id = 1667 ORDER BY pos;'
[2019-11-10 17:59:30] [DEBUG]       db: Running query 'END TRANSACTION;'
[2019-11-10 17:59:30] [DEBUG]  artwork: Artwork request for item 29562
[2019-11-10 17:59:30] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 29562;'
[2019-11-10 17:59:30] [DEBUG]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 29562   ;'
[2019-11-10 17:59:30] [DEBUG]    cache: Running query 'SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 2501400360329682155 AND a.max_w = 600 AND a.max_h = 600;'
[2019-11-10 17:59:30] [DEBUG]    cache: Cache hit: SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 2501400360329682155 AND a.max_w = 600 AND a.max_h = 600;
[2019-11-10 17:59:30] [DEBUG]  artwork: Artwork for group 2501400360329682155 found in source 'cache'
[2019-11-10 17:59:30] [DEBUG]   player: 0. Active callback: device_streaming_cb
[2019-11-10 17:59:30] [DEBUG]     raop: Metadata sr=44100, pos_ms=0, len_ms=270586, start=2537217543, display=2537202183, pos=2537217543, end=2549150385, rtptime=2537217543
[2019-11-10 17:59:30] [DEBUG]     raop: send_metadata: Sending SET_PARAMETER to 'myPod'
[2019-11-10 17:59:30] [DEBUG]      mpd: Notify clients waiting for idle results: 1
[2019-11-10 17:59:30] [DEBUG]     raop: send_artwork: Sending SET_PARAMETER to 'myPod'
[2019-11-10 17:59:30] [DEBUG]     raop: send_progress: Sending SET_PARAMETER to 'myPod'
[2019-11-10 17:59:30] [DEBUG]   player: event_read_quality()
[2019-11-10 17:59:30] [DEBUG]   player: New session values (q=44100/16/2, spr=441, bufsize=1764)
[2019-11-10 17:59:30] [DEBUG]   player: Start sync packet sent to 'myPod': cur_pos=2537129343, cur_ts=5775:176169741, now=5775:185782675, rtptime=2537217543,
[2019-11-10 17:59:30] [DEBUG]      web: notify callback reason: 11
[2019-11-10 17:59:30] [DEBUG]      web: JSON api request: '/api/player'
[2019-11-10 17:59:30] [DEBUG]   player: Player status: playing (buffering)
[2019-11-10 17:59:30] [DEBUG]      web: JSON api request: '/api/queue'
[2019-11-10 17:59:30] [DEBUG]       db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';'
[2019-11-10 17:59:30] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM queue;'
[2019-11-10 17:59:30] [DEBUG]   player: Player status: playing (buffering)
[2019-11-10 17:59:30] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2019-11-10 17:59:30] [DEBUG]       db: Starting enum 'SELECT * FROM queue f WHERE 1=1 ORDER BY pos;'
[2019-11-10 17:59:30] [DEBUG]       db: End of queue enum results
[2019-11-10 17:59:30] [DEBUG]       db: Running query 'END TRANSACTION;'
[2019-11-10 17:59:32] [DEBUG]     mdns: Avahi Resolver: resolved service 'D4A33D79B5CE@myPod' type '_raop._tcp' proto 0, host myPod.local, address 192.168.178.11
[2019-11-10 17:59:32] [DEBUG]     mdns: Connection test to 192.168.178.11:7000 completed successfully
[2019-11-10 17:59:32] [DEBUG]     raop: Event for AirPlay device 'myPod' (port 7000, id d4a33d79b5ce)
[2019-11-10 17:59:32] [ INFO]     raop: Adding AirPlay device 'myPod': password: 0, verification: 0, encrypt: 0, authsetup: 0, metadata: 1, type Other, address 192.168.178.11:7000
[2019-11-10 17:59:32] [DEBUG]      mpd: Asynchronous listener callback called with event type 8.
[2019-11-10 17:59:32] [DEBUG]      mpd: Notify clients waiting for idle results: 8
[2019-11-10 17:59:32] [DEBUG]   player: event_play_start()
[2019-11-10 17:59:32] [DEBUG]      mpd: Asynchronous listener callback called with event type 1.
[2019-11-10 17:59:32] [DEBUG]      mpd: Notify clients waiting for idle results: 1
[2019-11-10 17:59:32] [DEBUG]      web: notify callback reason: 11
[2019-11-10 17:59:32] [DEBUG]      web: JSON api request: '/api/player'
[2019-11-10 17:59:32] [DEBUG]   player: Player status: playing
[2019-11-10 17:59:32] [DEBUG]      web: JSON api request: '/api/outputs'
[2019-11-10 18:00:00] [  LOG]     raop: Device 'myPod' closed RTSP connection
[2019-11-10 18:00:00] [DEBUG]     raop: Cleaning up failed session (deferred) on device 'myPod'
[2019-11-10 18:00:00] [DEBUG]   player: Callback request received, id is 0
[2019-11-10 18:00:00] [DEBUG]   player: Unsubscription request for quality 44100/16/2 (now 0 subscribers)
[2019-11-10 18:00:00] [DEBUG]   player: Making deferred callback to device_streaming_cb, id was 0
[2019-11-10 18:00:00] [DEBUG]   player: Callback from AirPlay to device_streaming_cb (status -1)
[2019-11-10 18:00:00] [  LOG]   player: The AirPlay device 'myPod' FAILED