Playback issues with some RAAT zones on OS X

Tobias · April 24, 2016, 12:24am

Having some trouble with playback on my '12 iMac.

RoonServer is running on a mac mini connected via optical to a soundbar. This zone plays back just fine, both local tracks and tidal content.

On the iMac however, for local tracks (ALAC over Gbit from the mini iTunes library) I get a “music_media_slow” and for Tidal tracks a “tidal_network_error”. Nothing plays back in this zone.

I have tried using system output, the built-in output (both of which is working on the mini) and an external usb interface (Audient iD14) with no luck on the iMac. Also tried temporarily closing firewalls on both machines but no luck there either. Both machines are running the latest Roon Version 1.2 (build 128) stable (64 bit) on OS X 10.11.4.

Any thoughts?

Regards,
Tobias

JSE · April 24, 2016, 9:14am

Tobias, I have the same playing on my mac, nothing want to play using the internal speakers or connected DAC. Not the Tidal stream https://community.roonlabs.com/t/alert-tidal-tidal-network-error/9647 nor the personal library.

vova · April 25, 2016, 9:28pm

Hello @Tobias,

Can you tell us specs of your iMac/mac mini, and describe your network topology. Can you also try to do such test - if it is possible:

Create new OSX user on iMac
Install Roon Remote
Disable built-in firewall
Try to reproduce the issue.

Thanks.

Tobias · April 26, 2016, 10:03pm

Hi,

Thanks for responding.

Specs on iMac are 3,2GHz i5, 24GB RAM, 1TB Fusion Drive.
Specs on Mini are 2,4GHz Core2Duo, 8GB RAM, 256GB SSD, 2TB HDD.
Both are connected to the same Airport Extreme (802.11ac version) via wire.

Entire topology is WAN via wire to Airport Extreme which is wired to iMac, Mini and second Airport Extreme (wireless repeater mode) which my wireless devices are connected to. Music is stored locally on an iTunes library in the SSD part of the Mini.

Thing is I can remotely play music in the Mini zone using the iMac, but I can’t play anything when selecting the iMac as output, not from the iMac itself, the Mini or any of my connected iPad/iPhones.

If I only install the Roon Remote on the iMac, this will not let me play music in the iMac zone - correct?

Tobias · April 27, 2016, 6:53pm

I went ahead and made a new OSX user, installed Roon as a remote, disabled both firewalls (iMac/mini) but the issue persists with the same error messages as before.

Niklas_Andreasson · April 27, 2016, 9:03pm

Hi there. Great forum and an interesting tread. I have the same issue from my MacBook using private zones from Roon Remote + the same errormessage occurs when playing from a “roonready” device (Sonicorbiter SE). Discussing this issue with the helpful guys at Sonore/SmallGreenComputer today, I learned that there might be a fix for this (Roon Build 132?) Looking forward to this, especially since I just paid USD119 for a yearly subscription… @vova when can we expect a new release? Is there a betaprogram available where I can test build 132?

mike · April 27, 2016, 9:42pm

Hey @Niklas_Andreasson – our next release is in testing now and shouldn’t be far off, although delays are always possible. As soon as it’s fully tested, it’ll go live.

@Tobias – I’m going to discuss this issue with @vova and the team a little more and come back to you. Your network sounds solid, but the symptoms sound like what I would expect with networking or performance problems. I wonder if it’s worth trying to run the iMac to the Extreme over wifi and see if there’s any difference.

The Core2Duo is a relatively old machine, too. How big is the library?

Getting back to @Niklas_Andreasson - you mention private zones. Are you running the latest versions on all devices? Can you describe all the devices involved, and give me the basics of your setup? I’m sure we can get this working for you, so thanks in advance for your patience.

Tobias · April 27, 2016, 10:14pm

Hi @mike! The library is 58,23GB with 180 albums and 2091 tracks, so not a very large collection.
It is indeed a little dated CPU wise, but I can play the ALAC tracks fine over iTunes Home Sharing and uncompressed 1080p video content at 30-40000kb/s bitrate over afp without any stuttering, so the gigabit connection between the two machines seems solid.
I feel like the wifi would be a step down, but I will give it a shot to aid troubleshooting.

Edit: Just tried wifi on the iMac end but the error messages persist. Both with ALAC tracks from the mini and Tidal content.

Niklas_Andreasson · April 28, 2016, 1:44pm

Hi Mike. Thank you for your swift reply. Here are the basics of my setup:

Roon Core version 1.2 (build 128) 64bit running on a Mac Mini (mid 2011) 2,3GHz Intel Core i5, 8GB RAM and an SSD startupdisk where Applications and Roon Library folder is installed. I control the Mac Mini using Screen sharing and a VNC Viewer.
All my music is stored on a wired NAS, a WDMyCloud 3TB (2014). My switch is a Zyxel GS-108S v2 and CAT5/6 cables are kept short.
Roon Remote 1.2 (build 128) is intalled on my MacBook Air (13-inch, Late 2010), 1,86 GHz Intel Core 2 Duo and 4GB RAM installed
Output is to a wired AppleTV (3) and to a wired SonicorbiterSE with all the current upgrades installed. Both units are connected to a REGAdac (Mark1) using SPDIF. AppleTV is also connected to a TV using HDMI and an optical cable to another input port on the REGA.

Playback from core/library Mac Mini works like a charm and so does the airplay playback using the connected ATV. Playback on MacBookAir stops after 2-3 seconds (no sound) and skips to the next track(s) displaying the errormessage:
I have tried running the MBA rebote both wired (USB to Cat5) and on the WiFi Network. In Roon Remote on MBA I have activated both system output and built-in output on the MBA and fiddled with all kinds og combos of settings and disabling either etc, including Private Zone settings.

Playback to the SOSE using RoonReady mode gives exact same errormessage. Note that playback from the SOSE using the Airplay SOSE-app works fine (even though my SOSE unit powers down occationally and will be replaced by SmallGreenComputer shortly - great customer service

)

Edit: Both Macs are running El Capitain 10.11.4. My library is 113830 Tracks (15945 “Albums”). I’m using an iTunes library with the xml in the standard location. No music folders are being watched. I have a Tidal HiFi subscription set up in Roon.

mike · April 30, 2016, 9:18pm

Hey guys – we’ve been looking into this and trying to reproduce the issue.

First off, we do have some changes coming in our next release which were designed to help RAAT be a bit more stable when moving really large media files around the network. We think this should help with the error you’re receiving here, and that should be live soon.

One thing that would be helpful to know here is whether the zone disappears when this happens, or if playback simply stops when the error occurs. I believe it’s the latter, but let me know if you’re seeing otherwise.

@Tobias @Niklas_Andreasson – can you both try again when the next version goes live, and if you’re still having issues here, let me know and we’ll take another look and do some further analysis on your logs.

Thanks and sorry for the trouble guys!

Niklas_Andreasson · April 30, 2016, 10:02pm

Hi Mike. The zones are still there. Playback starts for 2 seconds but there is no sound. Please let me know: 1) did you manage to reproduce this error? 2) is the upcoming fix app 2,4 or 8 days away? 3) I’d be happy to join your beta-testing, is that possible? @mike It’s been 14 days since I flagged a problem. Still no solution and no response on when the next release can be expected!? Please give me something here…?

Niklas_Andreasson · May 12, 2016, 7:37am

Hello again. Updated (build 142) yesterday and the problem with local output on my MacBookAir is still there, I’m afraid. Also - output to my RoonReady SonicorbiterSE still does not work when setting the SOSE in “Roon-mode”. Please PM me for details and logs!

mike · May 13, 2016, 5:53pm

Sorry for the trouble here @Niklas_Andreasson – I just sent you some information about getting us logs in a PM. Let me know when you’ve sent them, and we’ll figure this out.

Moving on,

Can you try going to Apps -> Software Manager -> Update, and confirming you’re running the latest version of their software?

Niklas_Andreasson · May 13, 2016, 10:42pm

@mike The SOSE was and is now updated for the 2nd time today. It should be running the latest version of the software (2.1-23?) Here’s the log:

SOSE is updated:

Upgrade in progress…

05/13/2016 18:11:02 - Starting upgrade. (This can take a long time…)

05/13/2016 18:11:02 - Updating sonicorbiter packages…
Last metadata expiration check performed 0:00:01 ago on Fri May 13 18:11:05 2016.
Dependencies resolved.
Nothing to do.
Complete!
05/13/2016 18:11:23 - Updating OS packages…
Last metadata expiration check performed 0:00:07 ago on Fri May 13 18:11:17 2016.
Dependencies resolved.
Nothing to do.
Complete!
05/13/2016 18:11:25 - Upgrade complete. Please reboot
Back to main menu

mike · May 16, 2016, 7:31pm

Thanks @Niklas_Andreasson – we’ve got the logs and we’ll be analyzing them over the next day or two.

One thing I’d like to confirm is that this isn’t a firewall issue. Can you try turning off the firewall on both the Mac Mini and the Air, and let me know if there’s any change in behavior?

We’ll be in touch once we’ve looked at the logs, so thanks for your patience!

Niklas_Andreasson · May 16, 2016, 8:14pm

Both Macs have been running with firewalls set to “turned off” since I set up the mac mini as a Roon server/core. Looking forward to hearing from you. /N

mike · May 16, 2016, 10:29pm

Ok, one other thing I’d like to try is to take iTunes and network storage out of the equation here. I can’t think of a good reason why that would be causing issues on some outputs, but you are running a reasonably big library for our iTunes integration.

Would you mind take a few files from your NAS and copying them somewhere local on the Core machine? Then add this folder as a Watched Folder, and confirm whether the same playback issues occur. I’d be particularly interested to confirm this still happens without iTunes or network storage involved:

We’re going to take another look at your logs @Niklas_Andreasson, but let me know when you’ve had a chance to run that test and we’ll go from there.

Appreciate your patience here!

Niklas_Andreasson · May 17, 2016, 8:11pm

Hi. Screenshot showing the same errormessage playing mp3 320 from same SSD om mac mini as core/library

I guess this leaves NAS and iTunes XML out of the equation?! /N

Niklas_Andreasson · May 17, 2016, 8:24pm

A screenshot using the SOSE in Roonmode playing a local file on the roon core mac mini. SOSE Software updated to 2.1-24.

Uploading new roon-logs now. Some SOSE logs below:

Upgrade in progress...

05/17/2016 16:13:57 - Starting upgrade. (This can take a long time...)

05/17/2016 16:13:57 - Updating sonicorbiter packages...
Last metadata expiration check performed 0:00:01 ago on Tue May 17 16:14:03 2016.
Dependencies resolved.
================================================================================
Package Arch Version Repository Size
================================================================================
Upgrading:
sonicorbiter noarch 2.1-24.fc22 sonicorbiter 54 k
sonicorbiter-GUI noarch 2.1-16.fc22 sonicorbiter 933 k

Transaction Summary
================================================================================
Upgrade 2 Packages

Total download size: 987 k
Downloading Packages:
--------------------------------------------------------------------------------
Total 215 kB/s | 987 kB 00:04
Running transaction check
Transaction check succeeded.
Running transaction test
Transaction test succeeded.
Running transaction
Upgrading : sonicorbiter-2.1-24.fc22.noarch 1/4
Upgrading : sonicorbiter-GUI-2.1-16.fc22.noarch 2/4
Cleanup : sonicorbiter-GUI-2.1-15.fc22.noarch 3/4
Cleanup : sonicorbiter-2.1-23.fc22.noarch 4/4
Verifying : sonicorbiter-2.1-24.fc22.noarch 1/4
Verifying : sonicorbiter-GUI-2.1-16.fc22.noarch 2/4
Verifying : sonicorbiter-2.1-23.fc22.noarch 3/4
Verifying : sonicorbiter-GUI-2.1-15.fc22.noarch 4/4

Upgraded:
sonicorbiter.noarch 2.1-24.fc22 sonicorbiter-GUI.noarch 2.1-16.fc22

Complete!

------------

Niklas_Andreasson · May 17, 2016, 8:25pm

	RoonReady Diagnostic information BACK to Menu


05/17/2016 16:22:55 - ------------------------------------------------------------

05/17/2016 16:22:55 - /opt/RoonReady/raatool logdump 53de81c0-345c-439b-8045-4999c27bd5e5

[0000000] 0.005 TRACE [info] initializing info dictionary

[0000001] 0.006 TRACE [info] inserting raat_version -> 1.0.18

[0000002] 0.006 TRACE [info] inserting protocol_version -> 3

[0000003] 0.025 TRACE [ALSA] initializing output uniqueid=hw:0,0

[0000004] 0.025 TRACE [ALSA] preferred buffer duration=0.100000s

[0000005] 0.025 TRACE [ALSA] resync delay=0.100000s

[0000006] 0.025 TRACE [ALSA] max pcm rate=384000

[0000007] 0.025 TRACE [ALSA] max dsd rate=128

[0000008] 0.025 TRACE [ALSA] dsd_mode=none

[0000009] 0.025 TRACE [output/alsa] getting hardware info

[0000010] 0.026 TRACE pcm card id SPDIF

[0000011] 0.026 TRACE pcm card name Integrated SPDIF

[0000012] 0.026 TRACE pcm card longname Integrated SPDIF

[0000013] 0.026 TRACE pcm card mixername

[0000014] 0.026 TRACE pcm card components

[0000015] 0.026 TRACE pcm card driver Integrated_SPDI

[0000016] 0.026 TRACE [output/alsa] probing formats

[0000017] 0.027 TRACE [alsa] [hw:0,0] probing formats

[0000018] 0.027 TRACE [alsa] [hw:0,0]     device supports channels range 2-2

[0000019] 0.027 TRACE [alsa] [hw:0,0] supports PCM format 44100/16/1

[0000020] 0.027 TRACE [alsa] [hw:0,0] supports PCM format 44100/24/1

[0000021] 0.027 TRACE [alsa] [hw:0,0] supports PCM format 48000/16/1

[0000022] 0.027 TRACE [alsa] [hw:0,0] supports PCM format 48000/24/1

[0000023] 0.027 TRACE [alsa] [hw:0,0] supports PCM format 88200/16/1

[0000024] 0.027 TRACE [alsa] [hw:0,0] supports PCM format 88200/24/1

[0000025] 0.027 TRACE [alsa] [hw:0,0] supports PCM format 96000/16/1

[0000026] 0.027 TRACE [alsa] [hw:0,0] supports PCM format 96000/24/1

[0000027] 0.028 TRACE [alsa] [hw:0,0] supports PCM format 176400/16/1

[0000028] 0.028 TRACE [alsa] [hw:0,0] supports PCM format 176400/24/1

[0000029] 0.028 TRACE [alsa] [hw:0,0] supports PCM format 192000/16/1

[0000030] 0.028 TRACE [alsa] [hw:0,0] supports PCM format 192000/24/1

[0000031] 0.028 TRACE [alsa] [hw:0,0] supports PCM format 44100/16/2

[0000032] 0.028 TRACE [alsa] [hw:0,0] supports PCM format 44100/24/2

[0000033] 0.028 TRACE [alsa] [hw:0,0] supports PCM format 48000/16/2

[0000034] 0.028 TRACE [alsa] [hw:0,0] supports PCM format 48000/24/2

[0000035] 0.028 TRACE [alsa] [hw:0,0] supports PCM format 88200/16/2

[0000036] 0.029 TRACE [alsa] [hw:0,0] supports PCM format 88200/24/2

[0000037] 0.029 TRACE [alsa] [hw:0,0] supports PCM format 96000/16/2

[0000038] 0.029 TRACE [alsa] [hw:0,0] supports PCM format 96000/24/2

[0000039] 0.029 TRACE [alsa] [hw:0,0] supports PCM format 176400/16/2

[0000040] 0.029 TRACE [alsa] [hw:0,0] supports PCM format 176400/24/2

[0000041] 0.029 TRACE [alsa] [hw:0,0] supports PCM format 192000/16/2

[0000042] 0.029 TRACE [alsa] [hw:0,0] supports PCM format 192000/24/2

[0000043] 0.029 TRACE [output/alsa] initialized

[0000044] 0.029 TRACE [volume/software] preferred max attenuation=-100s

[0000045] 0.030 TRACE [volume/software] initialized

[0000046] 0.030 TRACE [watch/alsa] initializing watch device=hw:0 exit_on_lost=1

[0000047] 0.030 TRACE [watch/alsa] initialized

[0000048] 0.030 TRACE [info] inserting unique_id -> 53de81c0-345c-439b-8045-4999c27bd5e5

[0000049] 0.030 TRACE [info] inserting vendor -> Sonore

[0000050] 0.030 TRACE [info] inserting output_name -> SPDIF digital (optical)

[0000051] 0.030 TRACE [info] inserting serial -> 00BCE4

[0000052] 0.030 TRACE [info] inserting config_url -> http://__SELF__/

[0000053] 0.030 TRACE [info] inserting model -> Sonicorbiter SE

[0000054] 0.030 TRACE [info] inserting version -> 1.0.18

[0000055] 0.030 INFO [server] listening on port 45917

[0000056] 0.030 INFO [discovery] unicast socket is bound to 0.0.0.0:40891

[0000057] 0.031 INFO [discovery] multicast socket is bound to 0.0.0.0:11043

[0000058] 0.031 TRACE [device] announcing 
DiscoveryMessage[type=QUERY, 
transactionid=BF3ED89C-EEF9-F982-0CE2-0861EE6AB123, Data={ "unique_id": 
"53de81c0-345c-439b-8045-4999c27bd5e5", "raat_version": "1.0.18", 
"vendor": "Sonore", "protocol_version": "3", "serial": "00BCE4", 
"output_name": "SPDIF digital (optical)", "version": "1.0.18", "model": 
"Sonicorbiter SE", "config_url": "http://__SELF__/", "service_id": 
"5e2042ad-9bc5-4508-be92-ff68f19bdc93", "tcp_port": "45917",  } ]

[0000059] 0.052 TRACE [server] [192.168.0.14:33763] accepted connection

[0000060] 0.068 TRACE [session] [192.168.0.14:33763] starting

[0000061] 0.068 TRACE [session] [192.168.0.14:33763] [internal] executing lua script

[0000062] 0.070 TRACE [session] [192.168.0.14:33763] [internal] executing lua script

[0000063] 0.070 TRACE [session] [192.168.0.14:33763] created

[0000064] 0.101 TRACE [server] [192.168.0.14:33763] GOT[LL] [1] 
{"request":"load_script","sha256":"foo","script":"local base = { 
}\n\nlocal next_subscription_id_gen = 1\n\nfunction 
base.subscribe(table, request, cx) \n    local subscription = 
request.subscription\n    if not subscription then\n        subscription
 = \"__uniq__\" .. next_subscription_id_gen .. \"__uniq__\"\n        
next_subscription_id_gen = next_subscription_id_gen + 1\n    end\n    
table[subscription] = cx\nend\n\nfunction base.unsubscribe(table, 
request, cx)  \n    if request.subscription and 
table[request.subscription] then\n        table[request.subscription] = 
nil\n        cx:respond({ status = \"Success\" })\n        return\n    
end\n    cx:respond({ status = \"NotFound\" })\nend\n\nfunction 
addr_tostring(addr)\n    return tostring(addr.ip) .. \":\" .. 
tostring(addr.port)\nend\n\nreturn 
base\n","module":"base","name":"raat.dat:base.lua"}

[0000065] 0.102 TRACE [server] new script with name=raat.dat:base.lua module=base

[0000066] 0.115 TRACE [session] [192.168.0.14:33763] pre-loading lua module base

[0000067] 0.129 TRACE [server] [192.168.0.14:33763] GOT[LL] [2] 
{"request":"load_script","sha256":"foo","script":"-- Module 
options:\nlocal always_try_using_lpeg = true\nlocal 
register_global_module_table = false\nlocal global_module_name = 
'json'\n\n--[==[\n\nDavid Kolf's JSON module for Lua 5.1/5.2\n\nVersion 
2.5\n\n\nFor the documentation see the corresponding readme.txt or 
visit\n.\n\nYou
 can contact the author by sending an e-mail to 'david' at the\ndomain 
'dkolf.de'.\n\n\nCopyright (C) 2010-2014 David Heiko Kolf\n\nPermission 
is hereby granted, free of charge, to any person obtaining\na copy of 
this software and associated documentation files (the\n\"Software\"), to
 deal in the Software without restriction, including\nwithout limitation
 the rights to use, copy, modify, merge, publish,\ndistribute, 
sublicense, and/or sell copies of the Software, and to\npermit persons 
to whom the Software is furnished to do so, subject to\nthe following 
conditions:\n\nThe above copyright notice and this p

[0000068] 0.130 TRACE [server] new script with name=raat.dat:dkjson.lua module=dkjson

[0000069] 0.130 TRACE [session] [192.168.0.14:33763] pre-loading lua module dkjson

[0000070] 0.146 TRACE [server] [192.168.0.14:33763] GOT[LL] [3] 
{"request":"load_script","sha256":"foo","script":"local base     = 
require(\"base\")\nlocal json     = require(\"dkjson\")\n\nlocal 
protocol = { }\n\nlocal REQUEST         = 0x00000001\nlocal RESPONSE    
    = 0x00000002\nlocal ARTWORK         = 
0x00000003\n\nprotocol.on_request = function (cx, r) 
end\n\nRequestContext = { }\nRequestContext.__index = 
RequestContext\n\nfunction RequestContext.new(rid,quiet)\n    local self
 = setmetatable({}, RequestContext)\n    self.rid = rid\n    self.quiet =
 quiet\n    self.did_final_response = false\n    return 
self\nend\n\nfunction RequestContext.respond_base(self, response, 
isfinal)\n    local jsonstr = json.encode(response, { indent = false 
})\n    local buf = buffer.new(5 + #jsonstr)\n    buf:set_int32_be(0, 
self.rid)\n    if isfinal then\n        buf:set_uint8(4, 1)\n    else\n 
       buf:set_uint8(4, 0)\n    end\n    buf:set_string(5, jsonstr)\n   
 if not self.quiet then \n        raat.log.trace(\"SENT [\" .. 
tostring(self.r

[0000071] 0.147 TRACE [server] new script with name=raat.dat:protocol.lua module=protocol

[0000072] 0.169 TRACE [session] [192.168.0.14:33763] pre-loading lua module protocol

[0000073] 0.175 TRACE [server] [192.168.0.14:33763] GOT[LL] [4] 
{"request":"load_script","sha256":"foo","script":"local base     = 
require(\"base\")\nlocal protocol = require(\"protocol\")\nlocal json   
  = require(\"dkjson\")\n\nlocal roon = { }\n\nlocal clock_sock\nlocal 
audio_sock\n\nlocal clock_endpoint\nlocal audio_endpoint\nlocal 
controls_subscriptions = { }\nlocal transport_subscriptions = { 
}\n\nlocal IDLE      = \"IDLE\"\nlocal SETUP     = \"SETUP\"\nlocal 
BUFFERING = \"BUFFERING\"\nlocal READY     = \"READY\"\nlocal PLAYING   =
 \"PLAYING\"\nlocal STOPPED   = \"STOPPED\"\n\nlocal 
CLOCK_SYNC_ITERATIONS = 5\n\n-- the current playback info\n-- { \n--    
  stream             = stream\n--      token              = opaque\n--  
    setup_cx           = request context\n--      stream_cx          = 
request context\n--      stream_dropouts    = nsamples\n--      format  
           = { ... }\n--      state              = IDLE | SETUP | 
BUFFERING | PLAYING | STOPPED | READY\n--      nak_port           = 
number\n--      stream_id

[0000074] 0.176 TRACE [server] new script with name=raat.dat:roon.lua module=(null)

[0000075] 0.177 TRACE [session] [192.168.0.14:33763] executing lua script

[0000076] 0.184 TRACE [server] [192.168.0.14:33763] SENT[LL] [1] {"status": "Success"}

[0000077] 0.184 TRACE [server] [192.168.0.14:33763] SENT[LL] [2] {"status": "Success"}

[0000078] 0.184 TRACE [server] [192.168.0.14:33763] SENT[LL] [3] {"status": "Success"}

[0000079] 0.195 WARNING [lua@0xe683c] [192.168.0.14:33763]  failed set recv buffer size: nil

[0000080] 0.195 TRACE [lua@0xe683c] [192.168.0.14:33763]  [roon] clock socket listening on udp 0.0.0.0:59453

[0000081] 0.195 TRACE [lua@0xe683c] [192.168.0.14:33763]  [roon] audio socket listening on udp 0.0.0.0:40738

[0000082] 0.195 TRACE [lua@0xe683c] [192.168.0.14:33763]  [roon] 
output info {"alsa_device": {"id": "SPDIF", "mixername": "", "name": 
"Integrated SPDIF", "longname": "Integrated SPDIF", "components": 
"SPDIF", "driver": "Integrated_SPDI"}}

[0000083] 0.195 TRACE [lua@0xe683c] [192.168.0.14:33763]  [roon] 
volume info {"supports_dsd": false, "requires_external_persistence": 
true}

[0000084] 0.195 TRACE [server] [192.168.0.14:33763] SENT[LL] [4] {"status": "Success"}

[0000085] 0.197 TRACE [lua@0xe683c] [192.168.0.14:33763]  GOT [2] {"request":"info"}

[0000086] 0.206 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [2] 
{"status":"Success","transport":{"is_supported":false,"info":[]},"source_selection":{"is_supported":false,"info":[]},"output":{"supported_formats":[{"bits_per_sample":16,"channels":1,"sample_rate":44100,"sample_type":"pcm"},{"bits_per_sample":24,"channels":1,"sample_rate":44100,"sample_type":"pcm"},{"bits_per_sample":16,"channels":1,"sample_rate":48000,"sample_type":"pcm"},{"bits_per_sample":24,"channels":1,"sample_rate":48000,"sample_type":"pcm"},{"bits_per_sample":16,"channels":1,"sample_rate":88200,"sample_type":"pcm"},{"bits_per_sample":24,"channels":1,"sample_rate":88200,"sample_type":"pcm"},{"bits_per_sample":16,"channels":1,"sample_rate":96000,"sample_type":"pcm"},{"bits_per_sample":24,"channels":1,"sample_rate":96000,"sample_type":"pcm"},{"bits_per_sample":16,"channels":1,"sample_rate":176400,"sample_type":"pcm"},{"bits_per_sample":24,"channels":1,"sample_rate":176400,"sample_type":"pcm"},{"bits_per_sample":16,"channels":1,"sample_rate":192000,"sample_type

[0000087] 0.209 TRACE [lua@0xe683c] [192.168.0.14:33763]  GOT [3] {"request":"subscribe_transport"}

[0000088] 0.210 TRACE [lua@0xe683c] [192.168.0.14:33763]  GOT [4] {"request":"subscribe_controls"}

[0000089] 0.211 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [4] 
{"status":"Success","controls":{"volume":{"step":1.0,"min":-100.0,"value":0,"info":{"requires_external_persistence":true,"supports_dsd":false},"max":0.0,"type":"db","mute":false}},"action":"Changed"}

[0000090] 0.223 TRACE [lua@0xe683c] [192.168.0.14:33763]  GOT [5] {"request":"update_volume","value":-82}

[0000091] 0.223 TRACE [volume/software] volume => -82

[0000092] 0.224 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [5] {"status":"Success"}

[0000093] 0.224 TRACE [lua@0xe683c] [192.168.0.14:33763]  GOT [6] {"request":"update_volume","mute":false}

[0000094] 0.225 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [6] {"status":"Success"}

[0000095] 0.225 TRACE [lua@0xe683c] [192.168.0.14:33763]  got output
 message {"signal_path": [{"is_passthrough": false, "type": 
"digital_volume", "gain": -82.0, "is_muted": false, "quality": "high"}, 
{"quality": "lossless", "type": "output", "method": "digital"}]}

[0000096] 0.226 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [4] 
{"status":"Success","controls":{"volume":{"step":1.0,"min":-100.0,"value":-82,"info":{"requires_external_persistence":true,"supports_dsd":false},"max":0.0,"type":"db","mute":false}},"action":"Changed"}

[0000097] 4.464 TRACE [server] [192.168.0.13:27110] accepted connection

[0000098] 4.470 TRACE [session] [192.168.0.13:27110] starting

[0000099] 4.470 TRACE [session] [192.168.0.13:27110] [internal] executing lua script

[0000100] 4.475 TRACE [session] [192.168.0.13:27110] [internal] executing lua script

[0000101] 4.476 TRACE [session] [192.168.0.13:27110] created

[0000102] 4.516 TRACE [server] [192.168.0.13:27110] read: eof

[0000103] 4.516 TRACE [server] [192.168.0.13:27110] destroying client

[0000104] 4.516 TRACE [session] [192.168.0.13:27110] destroying session

[0000105] 4.516 DEBUG [session] [192.168.0.13:27110] sending async_stop stop cmd

[0000106] 4.517 DEBUG [session] [192.168.0.13:27110] in async_stop stop callback

[0000107] 4.517 DEBUG [session] [192.168.0.13:27110] joining thread

[0000108] 4.517 DEBUG [session] [192.168.0.13:27110] closing loop

[0000109] 5.985 DEBUG [discovery] broadcast op is complete

[0000110] 79.799 TRACE [lua@0xe683c] [192.168.0.14:33763]  GOT [7] 
{"request":"setup","format":{"sample_type":"pcm","sample_rate":96000,"bits_per_sample":24,"channels":2}}

[0000111] 79.799 TRACE alsa output setup: format is pcm 96000/24/2

[0000112] 79.799 TRACE opening [hw:0,0] 96000/24/2

[0000113] 79.801 TRACE prefer larger samples = 1

[0000114] 79.802 TRACE [ALSA] [hw:0,0] using hw pcmformat S24_LE bitspersample 24

[0000115] 79.802 TRACE [ALSA] [hw:0,0] Requesting 9600 frames/period

[0000116] 79.802 TRACE [ALSA] [hw:0,0] Initialized with 4 periods with 8192 frames/period

[0000117] 79.804 TRACE [volume/software] init bitspersample=24

[0000118] 79.804 WARNING sched_setscheduler failed: Operation not permitted

[0000119] 79.804 TRACE samples per buf 8192 ns per buf 85333333 samplerate 96000

[0000120] 79.804 TRACE 8192 samples per buf, 49152 bytes per buf, 65536 bytes per hwbuf

[0000121] 79.804 TRACE [lua@0xe683c] [192.168.0.14:33763]  got 
output message {"signal_path": [{"is_passthrough": false, "type": 
"digital_volume", "gain": -82.0, "is_muted": false, "quality": "high"}, 
{"quality": "lossless", "type": "output", "method": "digital"}]}

[0000122] 79.804 TRACE [output/alsa] [hw:0,0] waiting for device to be ready

[0000123] 79.804 TRACE [output/alsa] [hw:0,0] device is ready

[0000124] 79.809 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [7] 
{"status":"OutputMessage","message":{"signal_path":[{"gain":-82.0,"is_passthrough":false,"quality":"high","type":"digital_volume","is_muted":false},{"method":"digital","type":"output","quality":"lossless"}]}}

[0000125] 79.809 TRACE [lua@0xe683c] [192.168.0.14:33763]  got 
output message {"signal_path": [{"is_passthrough": false, "type": 
"digital_volume", "gain": -82.0, "is_muted": false, "quality": "high"}, 
{"quality": "lossless", "type": "output", "method": "digital"}]}

[0000126] 79.814 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [7] 
{"status":"OutputMessage","message":{"signal_path":[{"gain":-82.0,"is_passthrough":false,"quality":"high","type":"digital_volume","is_muted":false},{"method":"digital","type":"output","quality":"lossless"}]}}

[0000127] 79.827 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [7] {"status":"Success","clock_port":59453,"audio_port":40738}

[0000128] 79.890 TRACE [lua@0xe683c] [192.168.0.14:33763]  GOT [8] 
{"request":"stream","stream_id":1950630812,"first_seq":0,"nak_port":65048}

[0000129] 79.893 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Buffering"}

[0000130] 85.373 TRACE [lua@0xe683c] [192.168.0.14:33763]  GOT [9] {"request":"start","time":5788236500,"stream_sample":0}

[0000131] 85.378 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Playing"}

[0000132] 85.379 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [9] {"status":"Success"}

[0000133] 85.457 TRACE starting playback: now (5802666666ns) + 
ns_per_buf(8568822555787793749ns) = 5887999999ns > 5788236500ns 
streamsample=0

[0000134] 85.457 WARNING dropout of 8192 samples at 1385 [2]

[0000135] 85.518 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000136] 85.542 WARNING dropout of 8192 samples at 9577 [2]

[0000137] 85.619 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000138] 85.627 WARNING dropout of 8192 samples at 17769 [2]

[0000139] 85.712 WARNING dropout of 8192 samples at 25961 [2]

[0000140] 85.720 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":16384}

[0000141] 85.798 WARNING dropout of 8192 samples at 34153 [2]

[0000142] 85.822 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000143] 85.883 WARNING dropout of 8192 samples at 42345 [2]

[0000144] 85.923 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000145] 85.968 WARNING dropout of 8192 samples at 50537 [2]

[0000146] 86.024 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000147] 86.054 WARNING dropout of 8192 samples at 58729 [2]

[0000148] 86.125 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000149] 86.139 WARNING dropout of 8192 samples at 66921 [2]

[0000150] 86.224 WARNING dropout of 8192 samples at 75113 [2]

[0000151] 86.226 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":16384}

[0000152] 86.310 WARNING dropout of 8192 samples at 83305 [2]

[0000153] 86.328 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000154] 86.396 WARNING dropout of 8192 samples at 91497 [2]

[0000155] 86.430 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000156] 86.480 WARNING dropout of 8192 samples at 99689 [2]

[0000157] 86.532 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000158] 86.566 WARNING dropout of 8192 samples at 107881 [2]

[0000159] 86.633 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000160] 86.651 WARNING dropout of 8192 samples at 116073 [2]

[0000161] 86.735 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000162] 86.737 WARNING dropout of 8192 samples at 124265 [2]

[0000163] 86.822 WARNING dropout of 8192 samples at 132457 [2]

[0000164] 86.837 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":16384}

[0000165] 86.907 WARNING dropout of 8192 samples at 140649 [2]

[0000166] 86.938 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000167] 86.993 WARNING dropout of 8192 samples at 148841 [2]

[0000168] 87.040 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000169] 87.078 WARNING dropout of 8192 samples at 157033 [2]

[0000170] 87.142 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000171] 87.163 WARNING dropout of 8192 samples at 165225 [2]

[0000172] 87.244 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000173] 87.248 WARNING dropout of 8192 samples at 173417 [2]

[0000174] 87.334 WARNING dropout of 8192 samples at 181609 [2]

[0000175] 87.346 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":16384}

[0000176] 87.419 WARNING dropout of 8192 samples at 189801 [2]

[0000177] 87.446 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000178] 87.504 WARNING dropout of 8192 samples at 197993 [2]

[0000179] 87.549 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000180] 87.590 WARNING dropout of 8192 samples at 206185 [2]

[0000181] 87.651 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000182] 87.675 WARNING dropout of 8192 samples at 214377 [2]

[0000183] 87.752 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000184] 87.760 WARNING dropout of 8192 samples at 222569 [2]

[0000185] 87.846 WARNING dropout of 8192 samples at 230761 [2]

[0000186] 87.852 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":16384}

[0000187] 87.931 WARNING dropout of 8192 samples at 238953 [2]

[0000188] 87.954 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000189] 88.016 WARNING dropout of 8192 samples at 247145 [2]

[0000190] 88.055 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000191] 88.102 WARNING dropout of 8192 samples at 255337 [2]

[0000192] 88.157 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000193] 88.187 WARNING dropout of 8192 samples at 263529 [2]

[0000194] 88.259 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000195] 88.272 WARNING dropout of 8192 samples at 271721 [2]

[0000196] 88.358 WARNING dropout of 8192 samples at 279913 [2]

[0000197] 88.360 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":16384}

[0000198] 88.443 WARNING dropout of 8192 samples at 288105 [2]

[0000199] 88.461 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Dropout","samples":8192}

[0000200] 88.466 TRACE [lua@0xe683c] [192.168.0.14:33763]  GOT [10] {"request":"end_stream"}

[0000201] 88.467 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [8] {"status":"Ended"}

[0000202] 88.469 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [10] {"status":"Success"}

[0000203] 107.026 TRACE [lua@0xe683c] [192.168.0.14:33763]  GOT [11]
 
{"request":"stream","stream_id":1950630813,"first_seq":724,"nak_port":65048}

[0000204] 107.027 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [11] {"status":"Buffering"}

[0000205] 112.038 TRACE [lua@0xe683c] [192.168.0.14:33763]  GOT [12] {"request":"start","time":32495515967,"stream_sample":0}

[0000206] 112.040 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [11] {"status":"Playing"}

[0000207] 112.041 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [12] {"status":"Success"}

[0000208] 112.080 TRACE starting playback: now (32426666666ns) + 
ns_per_buf(85333333ns) = 32511999999ns > 32495515967ns streamsample=0

[0000209] 112.081 WARNING dropout of 1583 samples at 0 [2]

[0000210] 112.147 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [11] {"status":"Dropout","samples":1583}

[0000211] 112.165 WARNING dropout of 8192 samples at 1583 [2]

[0000212] 112.249 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [11] {"status":"Dropout","samples":8192}

[0000213] 112.250 WARNING dropout of 8192 samples at 9775 [2]

[0000214] 112.336 WARNING dropout of 8192 samples at 17967 [2]

[0000215] 112.350 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [11] {"status":"Dropout","samples":16384}

[0000216] 112.421 WARNING dropout of 8192 samples at 26159 [2]

[0000217] 112.451 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [11] {"status":"Dropout","samples":8192}

[0000218] 112.507 WARNING dropout of 8192 samples at 34351 [2]

[0000219] 112.553 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [11] {"status":"Dropout","samples":8192}

[0000220] 112.592 WARNING dropout of 8192 samples at 42543 [2]

[0000221] 112.654 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [11] {"status":"Dropout","samples":8192}

[0000222] 112.677 WARNING dropout of 8192 samples at 50735 [2]

[0000223] 112.755 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [11] {"status":"Dropout","samples":8192}

[0000224] 112.762 WARNING dropout of 8192 samples at 58927 [2]

[0000225] 112.848 WARNING dropout of 8192 samples at 67119 [2]

[0000226] 112.857 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [11] {"status":"Dropout","samples":16384}

[0000227] 112.933 WARNING dropout of 8192 samples at 75311 [2]

[0000228] 112.959 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [11] {"status":"Dropout","samples":8192}

[0000229] 113.018 WARNING dropout of 8192 samples at 83503 [2]

[0000230] 113.061 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [11] {"status":"Dropout","samples":8192}

[0000231] 113.104 WARNING dropout of 8192 samples at 91695 [2]

[0000232] 113.162 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [11] {"status":"Dropout","samples":8192}

[0000233] 113.189 WARNING dropout of 8192 samples at 99887 [2]

[0000234] 113.264 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [11] {"status":"Dropout","samples":8192}

[0000235] 113.275 WARNING dropout of 8192 samples at 108079 [2]

[0000236] 113.360 WARNING dropout of 8192 samples at 116271 [2]

[0000237] 113.365 TRACE [lua@0xe683c] [192.168.0.14:33763]  SENT [11] {"status":"Dropout","samples":16384}