05/26 21:06:09 Info: Starting Roon v2.66 (build 1658) production on macosx
05/26 21:06:09 Info: Local time is 5/26/2026 9:06:09 PM, UTC time is 5/27/2026 1:06:09 AM
05/26 21:06:09 Trace: [roondns] loaded 62 last-known-good entries
05/26 21:06:09 Debug: Init DefaultBackingApi: HttpWebRequest
05/26 21:06:09 Debug: [easyhttp] default backing API HttpClient -> HttpWebRequest. This may cancel all in progress http requests
05/26 21:06:09 Debug: Attempting to load library: /System/Library/Frameworks/Foundation.framework/Foundation
05/26 21:06:09 Info: Library[/System/Library/Frameworks/Foundation.framework/Foundation] Loaded success => True
05/26 21:06:09 Debug: Attempting to load library: /System/Library/Frameworks/AppKit.framework/AppKit
05/26 21:06:09 Info: Library[/System/Library/Frameworks/AppKit.framework/AppKit] Loaded success => True
05/26 21:06:10 Debug: Attempting to load framework: /System/Library/Frameworks/Cocoa.framework
05/26 21:06:10 Info: Framework[/System/Library/Frameworks/Cocoa.framework] Loaded success => True
05/26 21:06:10 Debug: Attempting to load framework: /System/Library/Frameworks/OpenGL.framework
05/26 21:06:10 Info: Framework[/System/Library/Frameworks/OpenGL.framework] Loaded success => True
05/26 21:06:10 Trace: Switching display link to display 1
05/26 21:06:12 Warn: !!!! are we connected to a local broker? False !!!!
05/26 21:06:12 Debug: [Migrate] Skipping, migration process already finished
05/26 21:06:12 Info: get lock file path: /tmp/.rnsem502-
05/26 21:06:12 Info: GetLockFile, fd: 281
05/26 21:06:12 Info: GetLockFile, res: 0
05/26 21:06:12 Info: get lock file path: /var/tmp/.rnsem502-
05/26 21:06:12 Info: GetLockFile, fd: 285
05/26 21:06:12 Info: GetLockFile, res: 0
05/26 21:06:12 Trace: Nope, we are the only one running
05/26 21:06:12 Info: Is 64 bit? True
05/26 21:06:12 Info: Loading broo project: ui.brooxgz
05/26 21:06:12 Debug: BrooLoader.Load
05/26 21:06:12 Debug: Creating OpenGL Device Target
05/26 21:06:12 Debug: OpenGL Version: 4.1 Metal - 90.5
05/26 21:06:12 Debug: OpenGL Vendor: Apple
05/26 21:06:12 Debug: OpenGL Renderer: Apple M3 Max
05/26 21:06:12 Debug: OpenGL Shader Language: 4.10
05/26 21:06:12 Debug: OpenGL extension count: 43
05/26 21:06:12 Debug: OpenGL extension 0: GL_ARB_blend_func_extended
05/26 21:06:12 Debug: OpenGL extension 1: GL_ARB_draw_buffers_blend
05/26 21:06:12 Debug: OpenGL extension 2: GL_ARB_draw_indirect
05/26 21:06:12 Debug: OpenGL extension 3: GL_ARB_ES2_compatibility
05/26 21:06:12 Debug: OpenGL extension 4: GL_ARB_explicit_attrib_location
05/26 21:06:12 Debug: OpenGL extension 5: GL_ARB_gpu_shader_fp64
05/26 21:06:12 Debug: OpenGL extension 6: GL_ARB_gpu_shader5
05/26 21:06:12 Debug: OpenGL extension 7: GL_ARB_instanced_arrays
05/26 21:06:12 Debug: OpenGL extension 8: GL_ARB_internalformat_query
05/26 21:06:12 Debug: OpenGL extension 9: GL_ARB_occlusion_query2
05/26 21:06:12 Debug: OpenGL extension 10: GL_ARB_sample_shading
05/26 21:06:12 Debug: OpenGL extension 11: GL_ARB_sampler_objects
05/26 21:06:12 Debug: OpenGL extension 12: GL_ARB_separate_shader_objects
05/26 21:06:12 Debug: OpenGL extension 13: GL_ARB_shader_bit_encoding
05/26 21:06:12 Debug: OpenGL extension 14: GL_ARB_shader_subroutine
05/26 21:06:12 Debug: OpenGL extension 15: GL_ARB_shading_language_include
05/26 21:06:12 Debug: OpenGL extension 16: GL_ARB_tessellation_shader
05/26 21:06:12 Debug: OpenGL extension 17: GL_ARB_texture_buffer_object_rgb32
05/26 21:06:12 Debug: OpenGL extension 18: GL_ARB_texture_cube_map_array
05/26 21:06:12 Debug: OpenGL extension 19: GL_ARB_texture_gather
05/26 21:06:12 Debug: OpenGL extension 20: GL_ARB_texture_query_lod
05/26 21:06:12 Debug: OpenGL extension 21: GL_ARB_texture_rgb10_a2ui
05/26 21:06:12 Debug: OpenGL extension 22: GL_ARB_texture_storage
05/26 21:06:12 Debug: OpenGL extension 23: GL_ARB_texture_swizzle
05/26 21:06:12 Debug: OpenGL extension 24: GL_ARB_timer_query
05/26 21:06:12 Debug: OpenGL extension 25: GL_ARB_transform_feedback2
05/26 21:06:12 Debug: OpenGL extension 26: GL_ARB_transform_feedback3
05/26 21:06:12 Debug: OpenGL extension 27: GL_ARB_vertex_attrib_64bit
05/26 21:06:12 Debug: OpenGL extension 28: GL_ARB_vertex_type_2_10_10_10_rev
05/26 21:06:12 Debug: OpenGL extension 29: GL_ARB_viewport_array
05/26 21:06:12 Debug: OpenGL extension 30: GL_EXT_debug_label
05/26 21:06:12 Debug: OpenGL extension 31: GL_EXT_debug_marker
05/26 21:06:12 Debug: OpenGL extension 32: GL_EXT_framebuffer_multisample_blit_scaled
05/26 21:06:12 Debug: OpenGL extension 33: GL_EXT_texture_compression_s3tc
05/26 21:06:12 Debug: OpenGL extension 34: GL_EXT_texture_filter_anisotropic
05/26 21:06:12 Debug: OpenGL extension 35: GL_EXT_texture_sRGB_decode
05/26 21:06:12 Debug: OpenGL extension 36: GL_APPLE_client_storage
05/26 21:06:12 Debug: OpenGL extension 37: GL_APPLE_container_object_shareable
05/26 21:06:12 Debug: OpenGL extension 38: GL_APPLE_flush_render
05/26 21:06:12 Debug: OpenGL extension 39: GL_APPLE_rgb_422
05/26 21:06:12 Debug: OpenGL extension 40: GL_APPLE_row_bytes
05/26 21:06:12 Debug: OpenGL extension 41: GL_APPLE_texture_range
05/26 21:06:12 Debug: OpenGL extension 42: GL_NV_texture_barrier
05/26 21:06:12 Debug: OpenGL maximum texture size: 16384
05/26 21:06:12 Debug: OpenGL maximum array texture layers: 2048
05/26 21:06:12 Debug: Framebuffer info : R8G8B8A8, color encoding: 0x2601, depth: 32, stencil: 0
05/26 21:06:12 Debug: Vertex highp int: range (-2^31 to 2^30), precision: 0 bits
05/26 21:06:12 Debug: Vertex mediump int: range (-2^31 to 2^30), precision: 0 bits
05/26 21:06:12 Debug: Vertex lowp int: range (-2^31 to 2^30), precision: 0 bits
05/26 21:06:12 Debug: Vertex highp float: range (-2^127 to 2^127), precision: 23 bits
05/26 21:06:12 Debug: Vertex mediump float: range (-2^127 to 2^127), precision: 23 bits
05/26 21:06:12 Debug: Vertex lowp float: range (-2^127 to 2^127), precision: 23 bits
05/26 21:06:12 Debug: Fragment highp int: range (-2^31 to 2^30), precision: 0 bits
05/26 21:06:12 Debug: Fragment mediump int: range (-2^31 to 2^30), precision: 0 bits
05/26 21:06:12 Debug: Fragment lowp int: range (-2^31 to 2^30), precision: 0 bits
05/26 21:06:12 Debug: Fragment highp float: range (-2^127 to 2^127), precision: 23 bits
05/26 21:06:12 Debug: Fragment mediump float: range (-2^127 to 2^127), precision: 23 bits
05/26 21:06:12 Debug: Fragment lowp float: range (-2^127 to 2^127), precision: 23 bits
05/26 21:06:12 Trace: [realtime] fetching time from NTP server
05/26 21:06:12 Debug: Maximum parallel texture loading jobs: 13
05/26 21:06:12 Debug: Maximum OpenGl texture size is 16384
05/26 21:06:12 Debug: Loading Binding Assembly
05/26 21:06:12 Trace: [ipaddresses] enumerating addresses
05/26 21:06:12 Trace: [ipaddresses]    FOUND   lo0 127.0.0.1
05/26 21:06:12 Trace: [ipaddresses]    SKIPPED gif0: no ipv4
05/26 21:06:12 Trace: [ipaddresses]    SKIPPED stf0: no ipv4
05/26 21:06:12 Trace: [ipaddresses]    SKIPPED anpi0: no ipv4
05/26 21:06:12 Trace: [ipaddresses]    SKIPPED anpi2: no ipv4
05/26 21:06:12 Trace: [ipaddresses]    SKIPPED anpi1: no ipv4
05/26 21:06:12 Trace: [ipaddresses]    SKIPPED en4: no ipv4
05/26 21:06:12 Trace: [ipaddresses]    SKIPPED en5: no ipv4
05/26 21:06:12 Trace: [ipaddresses]    SKIPPED en6: no ipv4
05/26 21:06:12 Trace: [ipaddresses]    SKIPPED en1: no ipv4
05/26 21:06:12 Trace: [ipaddresses]    SKIPPED en2: no ipv4
05/26 21:06:12 Trace: [ipaddresses]    SKIPPED en3: no ipv4
05/26 21:06:12 Trace: [ipaddresses]    SKIPPED bridge0: no ipv4
05/26 21:06:12 Trace: [ipaddresses]    SKIPPED utun0: no ipv4
05/26 21:06:12 Trace: [ipaddresses]    SKIPPED utun1: no ipv4
05/26 21:06:12 Trace: [ipaddresses]    SKIPPED ap1: no ipv4
05/26 21:06:12 Trace: [ipaddresses]    FOUND   en0 192.168.1.119
05/26 21:06:12 Trace: [ipaddresses]    SKIPPED awdl0: no ipv4
05/26 21:06:12 Trace: [ipaddresses]    SKIPPED llw0: no ipv4
05/26 21:06:12 Trace: [ipaddresses]    SKIPPED utun2: no ipv4
05/26 21:06:12 Trace: [ipaddresses]    SKIPPED utun3: no ipv4
05/26 21:06:12 Trace: [ipaddresses]    FOUND   utun4 100.66.118.119
05/26 21:06:12 Warn: [orbit] init failed due to Index and count must refer to a location within the buffer. (Parameter 'bytes'), reiniting
05/26 21:06:12 Debug: Loading Binding Assembly
05/26 21:06:12 Debug: creating Engine
05/26 21:06:12 Debug: Constructing Script Context
05/26 21:06:12 Debug: using FreeType v2.11.0
05/26 21:06:12 Debug: creating LoadContext
05/26 21:06:12 Trace: [brooengine] Loaded atlas list. 12ms
05/26 21:06:12 Trace: [brooengine] Window is running in scale 2
05/26 21:06:12 Trace: [brooengine] Using atlas scale 2
05/26 21:06:12 Trace: [realtime] Got time from NTP: 5/27/2026 1:06:12 AM UTC (3988832772777ms)
05/26 21:06:12 Trace: [realtime] Updated clock skew to -00:00:00.0326620 (-32.662ms)
05/26 21:06:12 Trace: [broo/imagecache] loaded 144487 cache entries from /Users/brianfay2/Library/Roon/Cache/brooimages_1/index.db, current: 512mb / 7084mb
05/26 21:06:12 Trace: [broo/blurredimagecache] loaded 0 entries from /Users/brianfay2/Library/Roon/Cache/brooimages_blur_1/index.db, current: 0mb / 256mb
05/26 21:06:12 Debug: waiting for script context
05/26 21:06:12 Debug: setting up script context
05/26 21:06:12 Debug: render area size initial value: 699x610
05/26 21:06:12 Info: Loaded broo project: ui.brooxgz, atlas: ui
05/26 21:06:12 Info: Kicking off event loop
05/26 21:06:12 Info: Kicking off event loop
05/26 21:06:12 Debug: ui running on thread 1
05/26 21:06:12 Info: Kicking off main
05/26 21:06:12 Info: Creating root
05/26 21:06:13 Debug: [brooengine Loaded atlas texture ui_atlas@2x-1.png in 207ms
05/26 21:06:13 Debug: [brooengine Loaded atlas texture ui_atlas@2x-2.png in 115ms
05/26 21:06:13 Debug: [brooengine Loaded atlas texture ui_atlas@2x-3.png in 93ms
05/26 21:06:13 Trace: [brooengine] Loaded atlas. 219ms (415ms across all threads)
05/26 21:06:13 Warn: AddTopLevel: win_apploading(8)
05/26 21:06:13 Info: [stats] 427430mb Virtual, 503mb Physical, 93mb Managed, 410mb estimated Unmanaged, 2.59% of runtime in GC pauses, 0ms last GC pause duration
05/26 21:06:14 Info: [broker] starting ee94b89a-9bf8-483a-9c68-704fdb6a3ce7
05/26 21:06:14 Info: [remoting/distributedbroker] V2 Protocol Support is enabled
05/26 21:06:14 Debug: initialize backend in 1373ms
05/26 21:06:14 Info: [raatserver] [runner] Start or Connect...
05/26 21:06:14 Info: [raatserver] [runner] Start or Connect... /Applications/Roon.app/Contents/MacOS/RAATServer
05/26 21:06:14 Info: ConnectOrStartAndWaitForExit RAATServer, path: /Applications/Roon.app/Contents/MacOS/RAATServer
05/26 21:06:14 Info: ConnectOrStartAndWaitForExit RAATServer: Try to connect to existing raatserver
05/26 21:06:14 Info: ConnectOrStartAndWaitForExit RAATServer: Failed to connect to existing raatserver, let's start one
05/26 21:06:14 Debug: ev_app_init: showing broker choosing window
05/26 21:06:14 Warn: AddTopLevel: win_choosebroker(46)
05/26 21:06:14 Info: [raatserver] [runner] Status: Started
05/26 21:06:14 Debug: app_init completed
05/26 21:06:14 Debug: [windowpos] get restore pos: mode= , p={X=345, Y=241}, s={Width=1024, Height=768}
05/26 21:06:14 Debug: trigger: appinitwasnotrun
05/26 21:06:14 Debug: trigger: do nothing
05/26 21:06:14 Warn: [ui] [win_main sharelink trigger] sharelink_type:  sharelink_link: 
05/26 21:06:14 Debug: Created new font texture with id: 4
05/26 21:06:14 Debug: render area size changed value: 1024x736
05/26 21:06:14 Info: [remoting] loaded protocol hash 54d9ca3cfb161da582c9a1fb0d0da129f0930c8c from /Applications/Roon.app/Contents/MonoBundle/.xamarin/osx-arm64/Roon.Broker.Api.Remote.dll
05/26 21:06:14 Trace: [remoting/distributedbroker] Enabling remote broker tracking
05/26 21:06:14 Debug: [broker/filebrowser/volumeattached] initial listing found drive mounted at /
05/26 21:06:14 Debug: [broker/filebrowser] getpartitioninfo 1 command: /usr/sbin/diskutil, args: info -plist '/'
05/26 21:06:15 Trace: [roonbridge] [sood] Refreshing device list
05/26 21:06:15 Trace: [remoting/remotebrokerv2] [BFay’s Basement Tapes] [InitConnection id=eeb9 BFay’s Basement Tapes@192.168.1.150:9332] Connected
05/26 21:06:15 Info: [remoting/distributedbroker] FOUND BROKER BFay’s Basement Tapes (7ef47513-e5a8-4295-a205-f8d6a4d88c62)
05/26 21:06:15 Trace: [remoting/remotebrokerv2] [BFay’s Basement Tapes] initializing with InitConnection[BFay’s Basement Tapes@192.168.1.150:9332, state=Idle]
05/26 21:06:15 Trace: [remoting/remotebrokerv2] [BFay’s Basement Tapes] Connecting => Authenticating
05/26 21:06:15 Trace: [remoting/remotingclientv2] SENT REQUEST DistributedBroker.ConnectRequest={ ClientBrokerId=ee94b89a-9bf8-483a-9c68-704fdb6a3ce7 ClientBrokerName='BFAY-MBP' ProtocolVersion='28' ProtocolHash='54d9ca3cfb161da582c9a1fb0d0da129f0930c8c' ClientBranch='production' }
05/26 21:06:15 Trace: [remoting/remotingclientv2] GOT NONFINAL DistributedBroker.ConnectResponse={ BrokerId=7ef47513-e5a8-4295-a205-f8d6a4d88c62 BrokerName='BFay’s Basement Tapes' }
05/26 21:06:15 Trace: [remoting/remotebrokerv2] [BFay’s Basement Tapes] connected to BFay’s Basement Tapes (7ef47513-e5a8-4295-a205-f8d6a4d88c62)
05/26 21:06:15 Trace: [remoting/remotingclientv2] GOT NONFINAL DistributedBroker.UpdatesChangedResponse={ IsSupported=True WasJustUpdated=False Status='UpToDate' HasChangeLog=False CurrentVersion={ MachineValue=206701661 DisplayValue='2.67 (build 1661) production' Branch='production' } }
05/26 21:06:15 Debug: [windowpos] saving pos=345|241|1024|768 because size changed to {Width=1024, Height=768}
05/26 21:06:15 Debug: [broker/filebrowser] getpartitioninfo 2 command: /usr/sbin/diskutil, args: info -plist '/dev/disk3'
05/26 21:06:15 Warn: [remoting] missing property string Sooloos.Broker.Api.Profile::ListenBrainzToken on type Sooloos.Broker.Api.Profile
05/26 21:06:15 Warn: [remoting] missing property bool Sooloos.Broker.Api.Profile::ScrobbleRadioTracksLastFm on type Sooloos.Broker.Api.Profile
05/26 21:06:15 Warn: [remoting] missing property bool Sooloos.Broker.Api.Profile::ScrobbleRadioTracksListenBrainz on type Sooloos.Broker.Api.Profile
05/26 21:06:15 Warn: [remoting] missing property Sooloos.Broker.Api.LoginStatus Sooloos.Broker.Api.Profile::LastFmLoginStatus on type Sooloos.Broker.Api.Profile
05/26 21:06:15 Warn: [remoting] missing property Sooloos.Broker.Api.LoginStatus Sooloos.Broker.Api.Profile::ListenBrainzLoginStatus on type Sooloos.Broker.Api.Profile
05/26 21:06:15 Warn: [remoting] missing property string Sooloos.Broker.Api.Profile::LastFmUsername on type Sooloos.Broker.Api.Profile
05/26 21:06:15 Warn: [remoting] missing property string Sooloos.Broker.Api.Profile::ListenBrainzUsername on type Sooloos.Broker.Api.Profile
05/26 21:06:15 Warn: [remoting] missing property string Sooloos.Broker.Api.Profile::LastFmImageUrl on type Sooloos.Broker.Api.Profile
05/26 21:06:15 Warn: [remoting] missing property string Sooloos.Broker.Api.Profile::ListenBrainzImageUrl on type Sooloos.Broker.Api.Profile
05/26 21:06:15 Debug: [broker/filebrowser/volumeattached] initial listing found drive mounted at /dev
05/26 21:06:15 Debug: [broker/filebrowser/volumeattached] initial listing found drive mounted at /System/Volumes/VM
05/26 21:06:15 Debug: [broker/filebrowser/volumeattached] initial listing found drive mounted at /System/Volumes/Preboot
05/26 21:06:15 Debug: [broker/filebrowser/volumeattached] initial listing found drive mounted at /System/Volumes/Update
05/26 21:06:15 Debug: [broker/filebrowser/volumeattached] initial listing found drive mounted at /System/Volumes/xarts
05/26 21:06:15 Debug: [broker/filebrowser/volumeattached] initial listing found drive mounted at /System/Volumes/iSCPreboot
05/26 21:06:15 Debug: [broker/filebrowser/volumeattached] initial listing found drive mounted at /System/Volumes/Hardware
05/26 21:06:15 Debug: [broker/filebrowser/volumeattached] initial listing found drive mounted at /System/Volumes/Data
05/26 21:06:15 Debug: [broker/filebrowser/volumeattached] initial listing found drive mounted at /System/Volumes/Data/home
05/26 21:06:15 Debug: [broker/filebrowser/volumeattached] initial listing found drive mounted at /System/Volumes/Update/mnt1
05/26 21:06:15 Debug: [broker/filebrowser/volumeattached] initial listing found drive mounted at /Volumes/TimeMachine-Bearstation
05/26 21:06:15 Debug: [broker/filebrowser] getpartitioninfo 1 command: /usr/sbin/diskutil, args: info -plist 'TimeMachine-Bearstation'
05/26 21:06:15 Warn: could not run /usr/sbin/diskutil info -plist 'TimeMachine-Bearstation' -- Exit code was: 1
05/26 21:06:15 Debug: [broker/filebrowser/volumeattached] initial listing found drive mounted at /Volumes/Time Machine
05/26 21:06:15 Debug: [broker/filebrowser] getpartitioninfo 1 command: /usr/sbin/diskutil, args: info -plist 'Time Machine'
05/26 21:06:15 Warn: [remoting] missing property bool Sooloos.Broker.Api.Playlists::SupportsPlaylistInsertionParameters on type Sooloos.Broker.Api.Playlists
05/26 21:06:15 Warn: could not run /usr/sbin/diskutil info -plist 'Time Machine' -- Exit code was: 1
05/26 21:06:15 Debug: [broker/filebrowser/volumeattached] initial listing found drive mounted at /Volumes/DATA
05/26 21:06:15 Debug: [broker/filebrowser] getpartitioninfo 1 command: /usr/sbin/diskutil, args: info -plist 'DATA'
05/26 21:06:15 Trace: [remoting/remotebrokerv2] [BFay’s Basement Tapes] Authenticating => Connected
05/26 21:06:15 Warn: could not run /usr/sbin/diskutil info -plist 'DATA' -- Exit code was: 1
05/26 21:06:15 Debug: [broker/filebrowser/volumeattached] initial listing found drive mounted at /Volumes/time-machine
05/26 21:06:15 Debug: [broker/filebrowser] getpartitioninfo 1 command: /usr/sbin/diskutil, args: info -plist 'time-machine'
05/26 21:06:15 Warn: could not run /usr/sbin/diskutil info -plist 'time-machine' -- Exit code was: 1
05/26 21:06:15 Debug: [broker/filebrowser/volumeattached] initial listing found drive mounted at /Volumes/backups_new
05/26 21:06:15 Debug: [broker/filebrowser] getpartitioninfo 1 command: /usr/sbin/diskutil, args: info -plist 'backups_new'
05/26 21:06:16 Warn: could not run /usr/sbin/diskutil info -plist 'backups_new' -- Exit code was: 1
05/26 21:06:16 Debug: [broker/filebrowser/volumeattached] initial listing found drive mounted at /Volumes/media
05/26 21:06:16 Debug: [broker/filebrowser] getpartitioninfo 1 command: /usr/sbin/diskutil, args: info -plist 'media'
05/26 21:06:16 Warn: could not run /usr/sbin/diskutil info -plist 'media' -- Exit code was: 1
05/26 21:06:16 Debug: [broker/filebrowser/volumeattached] initial listing found drive mounted at /Volumes/usbshare3
05/26 21:06:16 Debug: [broker/filebrowser] getpartitioninfo 1 command: /usr/sbin/diskutil, args: info -plist 'usbshare3'
05/26 21:06:16 Warn: could not run /usr/sbin/diskutil info -plist 'usbshare3' -- Exit code was: 1
05/26 21:06:16 Trace: [volumewatcher] ev_VolumeChanged DidMount: /
05/26 21:06:16 Trace: [volumewatcher] ev_VolumeChanged DidMount: /dev
05/26 21:06:16 Trace: [volumewatcher] ev_VolumeChanged DidMount: /System/Volumes/VM
05/26 21:06:16 Trace: [volumewatcher] ev_VolumeChanged DidMount: /System/Volumes/Preboot
05/26 21:06:16 Trace: [volumewatcher] ev_VolumeChanged DidMount: /System/Volumes/Update
05/26 21:06:16 Trace: [volumewatcher] ev_VolumeChanged DidMount: /System/Volumes/xarts
05/26 21:06:16 Trace: [volumewatcher] ev_VolumeChanged DidMount: /System/Volumes/iSCPreboot
05/26 21:06:16 Trace: [volumewatcher] ev_VolumeChanged DidMount: /System/Volumes/Hardware
05/26 21:06:16 Trace: [volumewatcher] ev_VolumeChanged DidMount: /System/Volumes/Data
05/26 21:06:16 Trace: [volumewatcher] ev_VolumeChanged DidMount: /System/Volumes/Data/home
05/26 21:06:16 Trace: [volumewatcher] ev_VolumeChanged DidMount: /System/Volumes/Update/mnt1
05/26 21:06:16 Trace: [volumewatcher] ev_VolumeChanged DidMount: /Volumes/TimeMachine-Bearstation
05/26 21:06:16 Trace: [volumewatcher] ev_VolumeChanged DidMount: /Volumes/Time Machine
05/26 21:06:16 Trace: [volumewatcher] ev_VolumeChanged DidMount: /Volumes/DATA
05/26 21:06:16 Trace: [volumewatcher] ev_VolumeChanged DidMount: /Volumes/time-machine
05/26 21:06:16 Trace: [volumewatcher] ev_VolumeChanged DidMount: /Volumes/backups_new
05/26 21:06:16 Trace: [volumewatcher] ev_VolumeChanged DidMount: /Volumes/media
05/26 21:06:16 Trace: [volumewatcher] ev_VolumeChanged DidMount: /Volumes/usbshare3
05/26 21:06:16 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /
05/26 21:06:16 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /dev
05/26 21:06:16 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /System/Volumes/VM
05/26 21:06:16 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /System/Volumes/Preboot
05/26 21:06:16 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /System/Volumes/Update
05/26 21:06:16 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /System/Volumes/xarts
05/26 21:06:16 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /System/Volumes/iSCPreboot
05/26 21:06:16 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /System/Volumes/Hardware
05/26 21:06:16 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /System/Volumes/Data
05/26 21:06:16 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /System/Volumes/Data/home
05/26 21:06:16 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /System/Volumes/Update/mnt1
05/26 21:06:16 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /Volumes/TimeMachine-Bearstation
05/26 21:06:16 Debug: [broker/filebrowser] getpartitioninfo 1 command: /usr/sbin/diskutil, args: info -plist 'TimeMachine-Bearstation'
05/26 21:06:16 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /Volumes/Time Machine
05/26 21:06:16 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /Volumes/DATA
05/26 21:06:16 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /Volumes/time-machine
05/26 21:06:16 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /Volumes/backups_new
05/26 21:06:16 Debug: [broker/filebrowser] getpartitioninfo 1 command: /usr/sbin/diskutil, args: info -plist 'Time Machine'
05/26 21:06:16 Debug: [broker/filebrowser] getpartitioninfo 1 command: /usr/sbin/diskutil, args: info -plist 'backups_new'
05/26 21:06:16 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /Volumes/media
05/26 21:06:16 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /Volumes/usbshare3
05/26 21:06:16 Debug: [broker/filebrowser] getpartitioninfo 1 command: /usr/sbin/diskutil, args: info -plist 'time-machine'
05/26 21:06:16 Debug: [broker/filebrowser] getpartitioninfo 1 command: /usr/sbin/diskutil, args: info -plist 'media'
05/26 21:06:16 Debug: [broker/filebrowser] getpartitioninfo 1 command: /usr/sbin/diskutil, args: info -plist 'DATA'
05/26 21:06:17 Debug: [broker/filebrowser] getpartitioninfo 1 command: /usr/sbin/diskutil, args: info -plist 'usbshare3'
05/26 21:06:17 Warn: could not run /usr/sbin/diskutil info -plist 'TimeMachine-Bearstation' -- Exit code was: 1
05/26 21:06:17 Warn: could not run /usr/sbin/diskutil info -plist 'usbshare3' -- Exit code was: 1
05/26 21:06:17 Warn: could not run /usr/sbin/diskutil info -plist 'Time Machine' -- Exit code was: 1
05/26 21:06:17 Warn: could not run /usr/sbin/diskutil info -plist 'backups_new' -- Exit code was: 1
05/26 21:06:17 Warn: could not run /usr/sbin/diskutil info -plist 'DATA' -- Exit code was: 1
05/26 21:06:17 Warn: could not run /usr/sbin/diskutil info -plist 'time-machine' -- Exit code was: 1
05/26 21:06:17 Warn: could not run /usr/sbin/diskutil info -plist 'media' -- Exit code was: 1
05/26 21:06:17 Debug: [easyhttp] [1] POST to https://api.roonlabs.net/discovery/1/query returned after 2475 ms, status code: 502
05/26 21:06:17 Warn: [servicemanager] failed to query for services 'com.roonlabs.roon.broker.http|com.roonlabs.roon.broker.tcp|com.roonlabs.roon.broker.tcpv2' in domains 'addr:__ADDR__': Result[Status=ServiceUnavailable]
05/26 21:06:17 Debug: ev_app_init: found previously chosen broker: [object System.Guid] [is_essentials=0]
05/26 21:06:17 Info: [client/root] Broker changed null => BFay’s Basement Tapes (Remote Broker 7ef47513-e5a8-4295-a205-f8d6a4d88c62)
05/26 21:06:17 Info: [client/root] Client is acting as a remote
05/26 21:06:17 Trace: [servicemanager] using cache for services 'com.roonlabs.roon.broker.http|com.roonlabs.roon.broker.tcp|com.roonlabs.roon.broker.tcpv2' in domains 'addr:__ADDR__'
05/26 21:06:17 Warn: error processing internet discovery device deviceid=broker/7ef47513-e5a8-4295-a205-f8d6a4d88c62 expiration=5/26/2026 10:21:07 AM domains=addr:69.143.8.3 props={"name":"BFay\u2019s Basement Tapes","deviceType":"RoonAppliance","deviceClass":"Appliance","isDev":false,"displayVersion":"2.66 (build 1658) production","osVersion":"RoonOS 2.1 (build 271) production","product":"RoonServer","userId":"915a5462-247d-40c7-9695-fc1a754ed83e","machineId":"bd108bb0-3ce1-4e9f-af88-486eb7d02e1f"}: System.InvalidOperationException: Sequence contains no elements
   at System.Linq.ThrowHelper.ThrowNoElementsException()
   at System.Linq.Enumerable.First[TSource](IEnumerable`1 source)
   at Sooloos.Broker.Distributed.DistributedBroker.ev_internetdevicefound(ServiceInternetDiscoveryQuery query, ServiceInternetDiscoveryDevice device)
05/26 21:06:17 Trace: [platformnowplaying/mac] MPNowPlayingInfoCenter: Connect
05/26 21:06:17 Info: [client/root] Broker ready changed False => True
05/26 21:06:17 Trace: [bits] myinfo: {"pushid":"broker/ee94b89a-9bf8-483a-9c68-704fdb6a3ce7","roon_auth_token":"804f87d9-fc80-4139-b442-6004c38a8d18","os":"Mac OS X 26.3.1","platform":"macosx","machineversion":206601658,"branch":"production","appmodifier":"","appname":"Roon"}
05/26 21:06:17 Debug: ev_app_init: done
05/26 21:06:17 Info: sending local time zone to remote broker:
05/26 21:06:17 Info:    datetime=5/26/2026 9:06:17 PM
05/26 21:06:17 Info:    iso=2026-05-26T21:06:17.4616110-04:00
05/26 21:06:17 Info:    offset from utc minutes=-240.00000205
05/26 21:06:17 Debug: trigger: appinitwasrun
05/26 21:06:17 Debug: trigger: apploaded, restoring nav stack
05/26 21:06:17 Debug: GMS: restoring nav stack
05/26 21:06:17 Info: ScrollDirection
05/26 21:06:17 Info: ScrollDirection
05/26 21:06:17 Info: ScrollDirection
05/26 21:06:17 Info: ScrollDirection
05/26 21:06:17 Info: ScrollDirection
05/26 21:06:17 Debug: GMS: restoring nav stack data: trackbrowser
05/26 21:06:17 Debug: GMS: restoring nav stack data: albumbrowser
05/26 21:06:17 Warn: AddTopLevel: win_main(264)
05/26 21:06:17 Debug: after delayed_start_work
05/26 21:06:17 Debug: threshold_minutes: 10080
05/26 21:06:17 Warn: [ui] [win_main sharelink trigger] sharelink_type:  sharelink_link: 
05/26 21:06:17 Debug: [easyhttp] [3] POST to https://api.roonlabs.net/bits/1/q/roon.base.,roon.internet_discovery.,roon.debug.,roon.client.,roon.broker.,roon.sood.?roon_auth_token=xxxxxx returned after 240 ms, status code: 200, request body size: 239 B
05/26 21:06:17 Debug: GMS: restoring nav stack data: artistbrowser
05/26 21:06:17 Debug: GMS: restoring nav stack data: composerbrowser
05/26 21:06:17 Debug: GMS: restoring nav stack data: workbrowser
05/26 21:06:17 Debug: GMS: restoring nav stack data: tagbrowser
05/26 21:06:17 Debug: GMS: restoring nav stack data: playlistbrowser
05/26 21:06:17 Debug: GMS: restoring nav stack data: playlistdetails
05/26 21:06:17 Info: [ui] playlistdetails: blobversion=2
05/26 21:06:17 Debug: GMS: restoring nav stack data: folderbrowsertoplevel
05/26 21:06:17 Debug: GMS: restoring nav stack data: folderdetaildesktop
05/26 21:06:17 Debug: GMS: restoring nav stack data: folderdetailphone
05/26 21:06:17 Debug: GMS: restoring nav stack data: nowplaying
05/26 21:06:17 Debug: GMS: restoring nav stack data: sidebar
05/26 21:06:17 Debug: GMS: restoring nav stack data: screens
05/26 21:06:17 Debug: UI-FWD: skipping fwd2 due to lazyload: home
05/26 21:06:17 Debug: UI-FWD: skipping fwd2 due to lazyload: playlistbrowser
05/26 21:06:17 Debug: UI-FWD: skipping fwd2 due to lazyload: unifiedsearch
05/26 21:06:17 Debug: UI-FWD: skipping fwd2 due to lazyload: unifiedsearch
05/26 21:06:17 Debug: UI-FWD: skipping fwd2 due to lazyload: unifiedsearch
05/26 21:06:17 Debug: UI-FWD: skipping fwd2 due to lazyload: albumbrowser
05/26 21:06:17 Debug: UI-FWD: skipping fwd2 due to lazyload: playlistbrowser
05/26 21:06:17 Debug: UI-FWD: skipping fwd2 due to lazyload: playlistbrowser
05/26 21:06:17 Debug: UI-FWD: skipping fwd2 due to lazyload: internetradiobrowser
05/26 21:06:17 Debug: UI-FWD: skipping fwd2 due to lazyload: viewall
05/26 21:06:17 Debug: UI-FWD: skipping fwd2 due to lazyload: unifiedsearch
05/26 21:06:17 Debug: UI-FWD: skipping fwd2 due to lazyload: viewall
05/26 21:06:17 Debug: UI-FWD: skipping fwd2 due to lazyload: unifiedsearch
05/26 21:06:17 Debug: UI-FWD: skipping fwd2 due to lazyload: viewall
05/26 21:06:17 Debug: UI-FWD: skipping fwd2 due to lazyload: internetradiodetails
05/26 21:06:17 Debug: UI-FWD: skipping fwd2 due to lazyload: unifiedsearch
05/26 21:06:17 Debug: UI-FWD: skipping fwd2 due to lazyload: unifiedsearch
05/26 21:06:17 Debug: UI-FWD: skipping fwd2 due to lazyload: unifiedsearch
05/26 21:06:17 Debug: UI-FWD: skipping fwd2 due to lazyload: internetradiodetails
05/26 21:06:17 Debug: UI-FWD: skipping fwd2 due to lazyload: nowplaying
05/26 21:06:17 Debug: GMS: found currentscreen in GMS file, going to index 19
05/26 21:06:17 Debug: UI-FORCE-UNLAZY: mode: nowplaying
05/26 21:06:17 Debug: UI-NAV: nowplaying
05/26 21:06:17 Debug: UI-FWD: mode: nowplaying
05/26 21:06:17 Debug: GMS: trying to save nav stack, but nav stack stuff was in progress
05/26 21:06:17 Debug: UI-NAV: nowplaying
05/26 21:06:17 Debug: GMS: done restoring nav stack
05/26 21:06:17 Trace: [bits] updated bits, in 308ms
05/26 21:06:17 Warn: [ui] [win_main sharelink trigger] sharelink_type:  sharelink_link: 
05/26 21:06:17 Debug: [easyhttp] [4] GET to http://192.168.1.150:9330/devicedb/963f6ab7ec4808e1a7b7a00c6974f46deb02e1b4.png returned after 21 ms, status code: 200, request body size: 0 B
05/26 21:06:17 Info:   ==> 200
05/26 21:06:17 Debug: [easyhttp] [5] GET to http://192.168.1.150:9330/image/fhdibaaa.128.jpg returned after 21 ms, status code: 304, request body size: 0 B
05/26 21:06:17 Trace: [broo/images] caching http://192.168.1.150:9330/devicedb/963f6ab7ec4808e1a7b7a00c6974f46deb02e1b4.png etag=7e740fadf635d5295f79b1aa3e67cdc00d2554f4 expiration=
05/26 21:06:19 Warn: frame took 17.38ms! 2.82ms preframe, 0.61ms safe queue, 0.10ms timers, 0.00ms frame calls, 0.46ms update, 17.33ms render
05/26 21:06:22 Debug: [easyhttp] [2] POST to https://api.roonlabs.net/discovery/1/query returned after 7461 ms, status code: 200, request body size: 74 B
05/26 21:06:24 Debug: [easyhttp] [6] GET to https://api.roonlabs.net/push-manager/1/connect returned after 136 ms, status code: 200, request body size: 0 B
05/26 21:06:24 Debug: [push2] push connector url received from push manager: ws://push-connector-v2-0.prd-roonlabs-1.prd.roonlabs.net/
05/26 21:06:24 Trace: [push2] connecting to push2 connector at ws://push-connector-v2-0.prd-roonlabs-1.prd.roonlabs.net/
05/26 21:06:24 Trace: [push2] connected to push2 connector at ws://push-connector-v2-0.prd-roonlabs-1.prd.roonlabs.net/
05/26 21:06:24 Warn: frame took 21.32ms! 9.99ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.87ms update, 21.32ms render
05/26 21:06:27 Debug: [easyhttp] [7] POST to https://api.roonlabs.net/device-map/1/register returned after 164 ms, status code: 200, request body size: 1 KB
05/26 21:06:27 Trace: [devicemap] device map updated
05/26 21:06:28 Info: [stats] 427442mb Virtual, 535mb Physical, 92mb Managed, 443mb estimated Unmanaged, 1.12% of runtime in GC pauses, 7ms last GC pause duration
05/26 21:06:29 Warn: frame took 22.02ms! 9.59ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.46ms update, 22.02ms render
05/26 21:06:33 Warn: frame took 24.06ms! 9.11ms preframe, 4.10ms safe queue, 0.00ms timers, 0.00ms frame calls, 0.16ms update, 24.06ms render
05/26 21:06:33 Debug: UI-FORCE-UNLAZY: mode: internetradiodetails
05/26 21:06:33 Debug: GMS: saving nav stack
05/26 21:06:33 Debug: UI-FWD: mode: internetradiodetails
05/26 21:06:33 Debug: GMS: trying to save nav stack, but nav stack stuff was in progress
05/26 21:06:33 Debug: UI-NAV: radio details
05/26 21:06:33 Debug: UI-BACK: mode: internetradiodetails
05/26 21:06:33 Debug: GMS: trying to save nav stack, but nav stack stuff was in progress
05/26 21:06:33 Warn: [ui] [win_main sharelink trigger] sharelink_type:  sharelink_link: 
05/26 21:06:33 Debug: GMS: done saving nav stack
05/26 21:06:33 Warn: [ui] [win_main sharelink trigger] sharelink_type:  sharelink_link: 
05/26 21:06:37 Trace: DisposeReusableCellCache: menuscroll(1448), 0 disposed from cache.
05/26 21:06:39 Warn: frame took 23.81ms! 14.09ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 5.26ms update, 23.81ms render
05/26 21:06:43 Debug: threshold_minutes: 10080
05/26 21:06:43 Warn: frame took 26.68ms! 9.02ms preframe, 0.00ms safe queue, 0.03ms timers, 0.00ms frame calls, 0.75ms update, 26.68ms render
05/26 21:06:43 Info: [stats] 427370mb Virtual, 459mb Physical, 72mb Managed, 387mb estimated Unmanaged, 0.66% of runtime in GC pauses, 3ms last GC pause duration
05/26 21:06:44 Trace: [appupdater] initial check for updates
05/26 21:06:44 Debug: [base/updater] Checking for updates: https://updates.roonlabs.net/update/?v=2&serial=A3D8E568-4F3D-4BA0-8A22-26716DB567FD&userid=915a5462-247d-40c7-9695-fc1a754ed83e&platform=macosx&product=Roon&branding=roon&curbranch=production&version=206601658&branch=production&coredeviceid=7ef47513-e5a8-4295-a205-f8d6a4d88c62&deviceid=ee94b89a-9bf8-483a-9c68-704fdb6a3ce7&osversion=Mac+OS+X+26.3.1&os64bit=true
05/26 21:06:44 Debug: [easyhttp] [8] GET to https://api.roonlabs.net/updates/update/?v=2&serial=A3D8E568-4F3D-4BA0-8A22-26716DB567FD&userid=915a5462-247d-40c7-9695-fc1a754ed83e&platform=macosx&product=Roon&branding=roon&curbranch=production&version=206601658&branch=production&coredeviceid=7ef47513-e5a8-4295-a205-f8d6a4d88c62&deviceid=ee94b89a-9bf8-483a-9c68-704fdb6a3ce7&osversion=Mac+OS+X+26.3.1&os64bit=true returned after 315 ms, status code: 200, request body size: 0 B
05/26 21:06:44 Debug: [base/updater] Update response: priority=major
05/26 21:06:44 Debug: [base/updater] Update response: updateurl=http://download.roonlabs.net/updates/production/Roon_206701661.dmg
05/26 21:06:44 Debug: [base/updater] Update response: machineversion=206701661
05/26 21:06:44 Debug: [base/updater] Update response: displayversion=2.67 (build 1661) production
05/26 21:06:44 Debug: [base/updater] Update response: branch=production
05/26 21:06:44 Debug: [base/updater] Update response: type=roon
05/26 21:06:44 Debug: [base/updater] Update response: changelog=
05/26 21:06:44 Debug: [appupdater] Update is available: 2.67 (build 1661) production, Major
05/26 21:06:54 Warn: frame took 20.56ms! 9.67ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 0.94ms update, 20.56ms render
05/26 21:06:58 Info: [stats] 427366mb Virtual, 459mb Physical, 76mb Managed, 383mb estimated Unmanaged, 0.66% of runtime in GC pauses, 3ms last GC pause duration
05/26 21:06:59 Warn: frame took 72.92ms! 9.53ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.42ms update, 72.92ms render
05/26 21:07:09 Warn: frame took 24.13ms! 10.81ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.83ms update, 24.13ms render
05/26 21:07:13 Debug: threshold_minutes: 10080
05/26 21:07:13 Warn: frame took 21.00ms! 9.07ms preframe, 0.00ms safe queue, 0.05ms timers, 0.00ms frame calls, 0.72ms update, 21.00ms render
05/26 21:07:13 Info: [stats] 427363mb Virtual, 466mb Physical, 73mb Managed, 393mb estimated Unmanaged, 0.35% of runtime in GC pauses, 12ms last GC pause duration
05/26 21:07:14 Warn: frame took 20.71ms! 9.53ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.42ms update, 20.71ms render
05/26 21:07:19 Warn: frame took 25.61ms! 9.47ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.40ms update, 25.61ms render
05/26 21:07:24 Warn: frame took 24.71ms! 10.15ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.85ms update, 24.70ms render
05/26 21:07:28 Info: [stats] 427365mb Virtual, 466mb Physical, 76mb Managed, 390mb estimated Unmanaged, 0.35% of runtime in GC pauses, 12ms last GC pause duration
05/26 21:07:29 Warn: frame took 25.81ms! 11.29ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 2.59ms update, 25.81ms render
05/26 21:07:34 Warn: frame took 25.73ms! 9.92ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.74ms update, 25.73ms render
05/26 21:07:39 Warn: frame took 25.10ms! 9.89ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.73ms update, 25.09ms render
05/26 21:07:43 Debug: threshold_minutes: 10080
05/26 21:07:43 Warn: frame took 21.06ms! 10.05ms preframe, 0.00ms safe queue, 0.07ms timers, 0.00ms frame calls, 0.81ms update, 21.06ms render
05/26 21:07:43 Info: [stats] 427367mb Virtual, 466mb Physical, 80mb Managed, 386mb estimated Unmanaged, 0.35% of runtime in GC pauses, 12ms last GC pause duration
05/26 21:07:44 Warn: frame took 20.74ms! 9.85ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.66ms update, 20.74ms render
05/26 21:07:49 Warn: frame took 21.95ms! 9.42ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.24ms update, 21.95ms render
05/26 21:07:54 Warn: frame took 23.28ms! 9.54ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.36ms update, 23.28ms render
05/26 21:07:58 Info: [stats] 427367mb Virtual, 467mb Physical, 77mb Managed, 390mb estimated Unmanaged, 0.23% of runtime in GC pauses, 13ms last GC pause duration
05/26 21:08:04 Warn: frame took 26.69ms! 9.75ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.59ms update, 26.69ms render
05/26 21:08:09 Warn: frame took 25.19ms! 10.53ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 2.33ms update, 25.19ms render
05/26 21:08:13 Debug: threshold_minutes: 10080
05/26 21:08:13 Warn: frame took 22.26ms! 10.15ms preframe, 0.00ms safe queue, 0.08ms timers, 0.00ms frame calls, 0.96ms update, 22.26ms render
05/26 21:08:13 Info: [stats] 427363mb Virtual, 467mb Physical, 80mb Managed, 387mb estimated Unmanaged, 0.23% of runtime in GC pauses, 13ms last GC pause duration
05/26 21:08:14 Warn: frame took 23.35ms! 10.47ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 2.21ms update, 23.35ms render
05/26 21:08:19 Warn: frame took 24.90ms! 9.24ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.80ms update, 24.90ms render
05/26 21:08:24 Warn: frame took 19.80ms! 9.55ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.30ms update, 19.80ms render
05/26 21:08:28 Info: [stats] 427365mb Virtual, 467mb Physical, 74mb Managed, 393mb estimated Unmanaged, 0.18% of runtime in GC pauses, 15ms last GC pause duration
05/26 21:08:29 Warn: frame took 23.88ms! 9.73ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.56ms update, 23.88ms render
05/26 21:08:34 Warn: frame took 24.96ms! 9.63ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.83ms update, 24.96ms render
05/26 21:08:39 Warn: frame took 22.83ms! 10.55ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.54ms update, 22.82ms render
05/26 21:08:43 Debug: threshold_minutes: 10080
05/26 21:08:43 Warn: frame took 25.94ms! 9.21ms preframe, 0.00ms safe queue, 0.07ms timers, 0.00ms frame calls, 0.92ms update, 25.94ms render
05/26 21:08:43 Info: [stats] 427365mb Virtual, 467mb Physical, 77mb Managed, 390mb estimated Unmanaged, 0.18% of runtime in GC pauses, 15ms last GC pause duration
05/26 21:08:44 Warn: frame took 21.27ms! 10.53ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.32ms update, 21.27ms render
05/26 21:08:49 Warn: frame took 18.62ms! 9.37ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.15ms update, 18.62ms render
05/26 21:08:54 Warn: frame took 23.53ms! 9.52ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.34ms update, 23.52ms render
05/26 21:08:58 Info: [stats] 427363mb Virtual, 467mb Physical, 81mb Managed, 386mb estimated Unmanaged, 0.18% of runtime in GC pauses, 15ms last GC pause duration
05/26 21:08:59 Warn: frame took 25.46ms! 9.73ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.55ms update, 25.46ms render
05/26 21:09:04 Warn: frame took 21.64ms! 9.33ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.03ms update, 21.64ms render
05/26 21:09:09 Warn: frame took 23.94ms! 9.74ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.59ms update, 23.94ms render
05/26 21:09:13 Debug: threshold_minutes: 10080
05/26 21:09:13 Warn: frame took 19.64ms! 9.22ms preframe, 0.00ms safe queue, 0.06ms timers, 0.00ms frame calls, 0.86ms update, 19.64ms render
05/26 21:09:13 Info: [stats] 427363mb Virtual, 461mb Physical, 77mb Managed, 384mb estimated Unmanaged, 0.14% of runtime in GC pauses, 1ms last GC pause duration
05/26 21:09:14 Warn: frame took 20.42ms! 9.23ms preframe, 0.00ms safe queue, 0.04ms timers, 0.00ms frame calls, 1.07ms update, 20.42ms render
05/26 21:09:24 Warn: frame took 24.86ms! 10.61ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.51ms update, 24.86ms render
05/26 21:09:28 Info: [stats] 427362mb Virtual, 461mb Physical, 81mb Managed, 380mb estimated Unmanaged, 0.14% of runtime in GC pauses, 1ms last GC pause duration
05/26 21:09:29 Warn: frame took 21.65ms! 9.63ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.47ms update, 21.65ms render
05/26 21:09:34 Warn: frame took 19.45ms! 10.05ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.82ms update, 19.45ms render
05/26 21:09:39 Warn: frame took 24.39ms! 9.30ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.24ms update, 24.39ms render
05/26 21:09:43 Debug: threshold_minutes: 10080
05/26 21:09:43 Info: [stats] 427363mb Virtual, 464mb Physical, 84mb Managed, 380mb estimated Unmanaged, 0.14% of runtime in GC pauses, 1ms last GC pause duration
05/26 21:09:44 Warn: frame took 19.78ms! 22.71ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 14.75ms update, 19.78ms render
05/26 21:09:49 Warn: frame took 24.77ms! 9.85ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.79ms update, 24.77ms render
05/26 21:09:52 Trace: DisposeReusableCellCache: menuscroll(1448), 0 disposed from cache.
05/26 21:09:54 Trace: [remoting/remotingclientv2] GOT NONFINAL DistributedBroker.UpdatesChangedResponse={ IsSupported=True WasJustUpdated=False Status='Checking' HasChangeLog=False CurrentVersion={ MachineValue=206701661 DisplayValue='2.67 (build 1661) production' Branch='production' } }
05/26 21:09:54 Trace: [remoting/remotingclientv2] GOT NONFINAL DistributedBroker.UpdatesChangedResponse={ IsSupported=True WasJustUpdated=False Status='UpToDate' HasChangeLog=False CurrentVersion={ MachineValue=206701661 DisplayValue='2.67 (build 1661) production' Branch='production' } }
05/26 21:09:56 Debug: [appupdater] Update download progress: 1
05/26 21:09:56 Debug: [appupdater] Update download progress: 2
05/26 21:09:56 Debug: [appupdater] Update download progress: 3
05/26 21:09:56 Debug: [appupdater] Update download progress: 4
05/26 21:09:56 Debug: [appupdater] Update download progress: 5
05/26 21:09:56 Debug: [appupdater] Update download progress: 6
05/26 21:09:56 Debug: [appupdater] Update download progress: 7
05/26 21:09:56 Debug: [appupdater] Update download progress: 8
05/26 21:09:57 Debug: [appupdater] Update download progress: 9
05/26 21:09:57 Debug: [appupdater] Update download progress: 10
05/26 21:09:57 Debug: [appupdater] Update download progress: 11
05/26 21:09:57 Debug: [appupdater] Update download progress: 12
05/26 21:09:57 Debug: [appupdater] Update download progress: 13
05/26 21:09:57 Debug: [appupdater] Update download progress: 14
05/26 21:09:57 Debug: [appupdater] Update download progress: 15
05/26 21:09:57 Debug: [appupdater] Update download progress: 16
05/26 21:09:57 Debug: [appupdater] Update download progress: 17
05/26 21:09:57 Debug: [appupdater] Update download progress: 18
05/26 21:09:57 Debug: [appupdater] Update download progress: 19
05/26 21:09:57 Debug: [appupdater] Update download progress: 20
05/26 21:09:58 Debug: [appupdater] Update download progress: 21
05/26 21:09:58 Debug: [appupdater] Update download progress: 22
05/26 21:09:58 Debug: [appupdater] Update download progress: 23
05/26 21:09:58 Debug: [appupdater] Update download progress: 24
05/26 21:09:58 Debug: [appupdater] Update download progress: 25
05/26 21:09:58 Debug: [appupdater] Update download progress: 26
05/26 21:09:58 Debug: [appupdater] Update download progress: 27
05/26 21:09:58 Info: [stats] 427375mb Virtual, 466mb Physical, 80mb Managed, 386mb estimated Unmanaged, 0.11% of runtime in GC pauses, 4ms last GC pause duration
05/26 21:09:58 Debug: [appupdater] Update download progress: 28
05/26 21:09:58 Debug: [appupdater] Update download progress: 29
05/26 21:09:59 Debug: [appupdater] Update download progress: 30
05/26 21:09:59 Debug: [appupdater] Update download progress: 31
05/26 21:09:59 Debug: [appupdater] Update download progress: 32
05/26 21:09:59 Debug: [appupdater] Update download progress: 33
05/26 21:09:59 Debug: [appupdater] Update download progress: 34
05/26 21:09:59 Debug: [appupdater] Update download progress: 35
05/26 21:09:59 Debug: [appupdater] Update download progress: 36
05/26 21:09:59 Debug: [appupdater] Update download progress: 37
05/26 21:09:59 Debug: [appupdater] Update download progress: 38
05/26 21:09:59 Debug: [appupdater] Update download progress: 39
05/26 21:09:59 Debug: [appupdater] Update download progress: 40
05/26 21:09:59 Debug: [appupdater] Update download progress: 41
05/26 21:09:59 Debug: [appupdater] Update download progress: 42
05/26 21:09:59 Debug: [appupdater] Update download progress: 43
05/26 21:09:59 Debug: [appupdater] Update download progress: 44
05/26 21:09:59 Debug: [appupdater] Update download progress: 45
05/26 21:09:59 Warn: frame took 24.54ms! 9.73ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 1.54ms update, 24.54ms render
05/26 21:09:59 Debug: [appupdater] Update download progress: 46
05/26 21:09:59 Debug: [appupdater] Update download progress: 47
05/26 21:10:00 Debug: [appupdater] Update download progress: 48
05/26 21:10:00 Debug: [appupdater] Update download progress: 49
05/26 21:10:00 Debug: [appupdater] Update download progress: 50
05/26 21:10:00 Debug: [appupdater] Update download progress: 51
05/26 21:10:00 Debug: [appupdater] Update download progress: 52
05/26 21:10:00 Debug: [appupdater] Update download progress: 53
05/26 21:10:00 Debug: [appupdater] Update download progress: 54
05/26 21:10:00 Debug: [appupdater] Update download progress: 55
05/26 21:10:00 Debug: [appupdater] Update download progress: 56
05/26 21:10:00 Debug: [appupdater] Update download progress: 57
05/26 21:10:00 Debug: [appupdater] Update download progress: 58
05/26 21:10:00 Debug: [appupdater] Update download progress: 59
05/26 21:10:00 Debug: [appupdater] Update download progress: 60
05/26 21:10:00 Debug: [appupdater] Update download progress: 61
05/26 21:10:00 Debug: [appupdater] Update download progress: 62
05/26 21:10:00 Debug: [appupdater] Update download progress: 63
05/26 21:10:00 Debug: [appupdater] Update download progress: 64
05/26 21:10:01 Debug: [appupdater] Update download progress: 65
05/26 21:10:01 Debug: [appupdater] Update download progress: 66
05/26 21:10:01 Debug: [appupdater] Update download progress: 67
05/26 21:10:01 Debug: [appupdater] Update download progress: 68
05/26 21:10:01 Debug: [appupdater] Update download progress: 69
05/26 21:10:01 Debug: [appupdater] Update download progress: 70
05/26 21:10:01 Debug: [appupdater] Update download progress: 71
05/26 21:10:01 Debug: [appupdater] Update download progress: 72
05/26 21:10:01 Debug: [appupdater] Update download progress: 73
05/26 21:10:01 Debug: [appupdater] Update download progress: 74
05/26 21:10:01 Debug: [appupdater] Update download progress: 75
05/26 21:10:01 Debug: [appupdater] Update download progress: 76
05/26 21:10:02 Debug: [appupdater] Update download progress: 77
05/26 21:10:02 Debug: [appupdater] Update download progress: 78
05/26 21:10:02 Debug: [appupdater] Update download progress: 79
05/26 21:10:02 Debug: [appupdater] Update download progress: 80
05/26 21:10:02 Debug: [appupdater] Update download progress: 81
05/26 21:10:02 Debug: [appupdater] Update download progress: 82
05/26 21:10:02 Debug: [appupdater] Update download progress: 83
05/26 21:10:02 Debug: [appupdater] Update download progress: 84
05/26 21:10:02 Debug: [appupdater] Update download progress: 85
05/26 21:10:02 Debug: [appupdater] Update download progress: 86
05/26 21:10:02 Debug: [appupdater] Update download progress: 87
05/26 21:10:02 Debug: [appupdater] Update download progress: 88
05/26 21:10:02 Debug: [appupdater] Update download progress: 89
05/26 21:10:02 Debug: [appupdater] Update download progress: 90
05/26 21:10:02 Debug: [appupdater] Update download progress: 91
05/26 21:10:03 Debug: [appupdater] Update download progress: 92
05/26 21:10:03 Debug: [appupdater] Update download progress: 93
05/26 21:10:03 Debug: [appupdater] Update download progress: 94
05/26 21:10:03 Debug: [appupdater] Update download progress: 95
05/26 21:10:03 Debug: [appupdater] Update download progress: 96
05/26 21:10:03 Debug: [appupdater] Update download progress: 97
05/26 21:10:03 Debug: [appupdater] Update download progress: 98
05/26 21:10:03 Debug: [appupdater] Update download progress: 99
05/26 21:10:03 Debug: [appupdater] Update download progress: 100
05/26 21:10:03 Debug: [appupdater] Update downloaded: 2.67 (build 1661) production /var/folders/cl/76jwdtbx6rz4lp58pl5ldy_80000gp/T/dfdd0483-9087-4a70-aa41-2d517705fe32__Roon_206701661.dmg
05/26 21:10:03 Trace: [base/updater] Checking if another process is already downloading or installing an update
05/26 21:10:03 Info: get lock file path: /var/tmp/.rnsemu502
05/26 21:10:03 Info: GetLockFile, fd: 274
05/26 21:10:03 Info: GetLockFile, res: 0
05/26 21:10:03 Trace: [base/updater] there does not appear to be another download or install in process
05/26 21:10:03 Info: [base/updater] Installing update
05/26 21:10:03 Debug: [base/updater] Installing update: /var/folders/cl/76jwdtbx6rz4lp58pl5ldy_80000gp/T/dfdd0483-9087-4a70-aa41-2d517705fe32__Roon_206701661.dmg
05/26 21:10:03 Debug: [base/updater] bp = /Applications/Roon.app
05/26 21:10:03 Debug: [base/updater] bundlepath = /Applications/Roon.app
05/26 21:10:03 Debug: [base/updater] workdir = /var/folders/cl/76jwdtbx6rz4lp58pl5ldy_80000gp/T
05/26 21:10:03 Debug: [base/updater] prepared update script '/var/folders/cl/76jwdtbx6rz4lp58pl5ldy_80000gp/T/update.sh':
set -x

function cleanup {
  exitcode=$?
  hdiutil eject roonupdate
  rm -r roonupdate
  rm '/var/folders/cl/76jwdtbx6rz4lp58pl5ldy_80000gp/T/dfdd0483-9087-4a70-aa41-2d517705fe32__Roon_206701661.dmg'
  rm $0
  exit $exitcode
}
trap cleanup EXIT

cd '/var/folders/cl/76jwdtbx6rz4lp58pl5ldy_80000gp/T' || exit 1
hdiutil eject roonupdate 2>/dev/null
rm -r roonupdate 2>/dev/null
mkdir roonupdate || exit 2

hdiutil attach -mountpoint roonupdate '/var/folders/cl/76jwdtbx6rz4lp58pl5ldy_80000gp/T/dfdd0483-9087-4a70-aa41-2d517705fe32__Roon_206701661.dmg' || exit 3
ls -l roonupdate
ls -l '/Applications/Roon.app'
rm -fr '/Applications/Roon.app'/update.tmp || exit 4
mkdir '/Applications/Roon.app'/update.tmp || exit 5
cp -a roonupdate/*.app/Contents '/Applications/Roon.app'/update.tmp/ || exit 6
rm -fr '/Applications/Roon.app'/update || exit 7
mv '/Applications/Roon.app'/update.tmp '/Applications/Roon.app'/update || exit 8


05/26 21:10:03 Debug: [base/updater] executing /bin/bash "/var/folders/cl/76jwdtbx6rz4lp58pl5ldy_80000gp/T/update.sh"
05/26 21:10:03 Debug: [base/updater] waiting for update.sh to exit
05/26 21:10:03 Trace: [base/updater stderr] + trap cleanup EXIT
05/26 21:10:03 Trace: [base/updater stderr] + cd /var/folders/cl/76jwdtbx6rz4lp58pl5ldy_80000gp/T
05/26 21:10:03 Trace: [base/updater stderr] + hdiutil eject roonupdate
05/26 21:10:03 Trace: [base/updater stderr] + rm -r roonupdate
05/26 21:10:03 Trace: [base/updater stderr] + mkdir roonupdate
05/26 21:10:03 Trace: [base/updater stderr] + hdiutil attach -mountpoint roonupdate /var/folders/cl/76jwdtbx6rz4lp58pl5ldy_80000gp/T/dfdd0483-9087-4a70-aa41-2d517705fe32__Roon_206701661.dmg
05/26 21:10:03 Trace: [base/updater stdout] Checksumming whole disk (Apple_HFS : 0)…
05/26 21:10:04 Trace: [base/updater stdout]           whole disk (Apple_HFS : 0): verified   CRC32 $C4C890E5
05/26 21:10:04 Trace: [base/updater stdout] verified   CRC32 $E6F6FD58
05/26 21:10:04 Trace: [base/updater stdout] /dev/disk4          	                               	/private/var/folders/cl/76jwdtbx6rz4lp58pl5ldy_80000gp/T/roonupdate
05/26 21:10:04 Trace: [base/updater stderr] + ls -l roonupdate
05/26 21:10:04 Warn: frame took 43.25ms! 8.99ms preframe, 0.00ms safe queue, 0.00ms timers, 0.00ms frame calls, 0.86ms update, 43.25ms render
05/26 21:10:04 Trace: [base/updater stdout] total 608
05/26 21:10:04 Trace: [base/updater stdout] -rw-r--r--@ 1 brianfay2  staff     0 Jun 15  2011 Applications
05/26 21:10:04 Trace: [base/updater stdout] drwxrwxrwx  3 brianfay2  staff   102 May 21 16:21 Roon.app
05/26 21:10:04 Trace: [base/updater stdout] -rw-r--r--@ 1 brianfay2  staff  7057 May 10  2015 background.png
05/26 21:10:04 Trace: [base/updater stderr] + ls -l /Applications/Roon.app
05/26 21:10:04 Trace: [base/updater stdout] total 0
05/26 21:10:04 Trace: [base/updater stdout] drwxr-xr-x@ 10 brianfay2  staff  320 May  1 14:51 Contents
05/26 21:10:04 Trace: [base/updater stderr] + rm -fr /Applications/Roon.app/update.tmp
05/26 21:10:04 Trace: [base/updater stderr] + mkdir /Applications/Roon.app/update.tmp
05/26 21:10:04 Trace: [base/updater stderr] + cp -a roonupdate/Roon.app/Contents /Applications/Roon.app/update.tmp/
05/26 21:10:06 Trace: [volumewatcher] ev_VolumeChanged DidMount: /private/var/folders/cl/76jwdtbx6rz4lp58pl5ldy_80000gp/T/roonupdate
05/26 21:10:06 Debug: [broker/filebrowser/volumeattached] found newly mounted drive at /private/var/folders/cl/76jwdtbx6rz4lp58pl5ldy_80000gp/T/roonupdate
05/26 21:10:08 Trace: [base/updater stderr] + rm -fr /Applications/Roon.app/update
05/26 21:10:08 Trace: [base/updater stderr] + mv /Applications/Roon.app/update.tmp /Applications/Roon.app/update
05/26 21:10:08 Trace: [base/updater stderr] + cleanup
05/26 21:10:08 Trace: [base/updater stderr] + exitcode=0
05/26 21:10:08 Trace: [base/updater stderr] + hdiutil eject roonupdate
05/26 21:10:09 Trace: [base/updater stdout] "disk4" ejected.
05/26 21:10:09 Trace: [base/updater stderr] + rm -r roonupdate
05/26 21:10:09 Trace: [base/updater stderr] + rm /var/folders/cl/76jwdtbx6rz4lp58pl5ldy_80000gp/T/dfdd0483-9087-4a70-aa41-2d517705fe32__Roon_206701661.dmg
05/26 21:10:09 Trace: [base/updater stderr] + rm /var/folders/cl/76jwdtbx6rz4lp58pl5ldy_80000gp/T/update.sh
05/26 21:10:09 Trace: [base/updater stderr] + exit 0
05/26 21:10:09 Debug: [base/updater] update.sh exited with 0
05/26 21:10:09 Debug: [appupdater] Update installed: 2.67 (build 1661) production
