-- Logs begin at Thu 2019-02-14 19:11:59 JST, end at Fri 2026-08-28 22:37:37 JST. -- Aug 28 22:36:45 southzi go-librespot[1279]: time="2026-08-28T22:36:45+09:00" level=debug msg="obtained new client token: AAH+I7oEPnZFKZp/8CJ047yWc5fCYCkmTmSwMKgKmIUtWueGOQ111sq1rWXf8zkj/kDRFwfZ7/ykR1Wuw17kclI18yDaTorsC03EZU3/aCRIMCfU210QhkaI0Th3LSPzIuIZW9jiWzyEikXBqeIOEy21OnV9COshCetxHEejS+gnW4h9X1LZzGgpLb8WDjq6AMLxlCMLYrNoimQajHLrwo4Ymis6dM21Ftr7KyBAZhWcs850YHe99Q6C" Aug 28 22:36:45 southzi go-librespot[1279]: time="2026-08-28T22:36:45+09:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 28 22:36:45 southzi go-librespot[1279]: time="2026-08-28T22:36:45+09:00" level=debug msg="completed keyexchange" Aug 28 22:36:45 southzi go-librespot[1279]: time="2026-08-28T22:36:45+09:00" level=debug msg="completed challenge" Aug 28 22:36:45 southzi go-librespot[1279]: time="2026-08-28T22:36:45+09:00" level=info msg="authenticated AP" username="wd*********************j2" Aug 28 22:36:45 southzi go-librespot[1279]: time="2026-08-28T22:36:45+09:00" level=info msg="authenticated Login5" username="wd*********************j2" Aug 28 22:36:45 southzi go-librespot[1279]: time="2026-08-28T22:36:45+09:00" level=info msg="accepted zeroconf from Tanaka MBA15" username="wd*********************j2" Aug 28 22:36:45 southzi go-librespot[1279]: time="2026-08-28T22:36:45+09:00" level=debug msg="dealer connection opened" Aug 28 22:36:45 southzi go-librespot[1279]: time="2026-08-28T22:36:45+09:00" level=trace msg="starting accesspoint recv loop" Aug 28 22:36:45 southzi go-librespot[1279]: time="2026-08-28T22:36:45+09:00" level=trace msg="starting dealer recv loop" Aug 28 22:36:45 southzi go-librespot[1279]: time="2026-08-28T22:36:45+09:00" level=trace msg="received accesspoint ping" Aug 28 22:36:45 southzi go-librespot[1279]: time="2026-08-28T22:36:45+09:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Aug 28 22:36:45 southzi go-librespot[1279]: time="2026-08-28T22:36:45+09:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Aug 28 22:36:45 southzi go-librespot[1279]: time="2026-08-28T22:36:45+09:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Aug 28 22:36:45 southzi go-librespot[1279]: time="2026-08-28T22:36:45+09:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Aug 28 22:36:45 southzi go-librespot[1279]: time="2026-08-28T22:36:45+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Aug 28 22:36:45 southzi go-librespot[1279]: time="2026-08-28T22:36:45+09:00" level=debug msg="received connection id: YjkyYTQ1NDgtNWI2...OEM0N0Q1OEYyQw==" Aug 28 22:36:46 southzi go-librespot[1279]: time="2026-08-28T22:36:46+09:00" level=trace msg="received accesspoint pong ack" Aug 28 22:36:46 southzi go-librespot[1279]: time="2026-08-28T22:36:46+09:00" level=debug msg="put connect state because NEW_DEVICE" Aug 28 22:36:46 southzi go-librespot[1279]: time="2026-08-28T22:36:46+09:00" level=debug msg="update volume requested to 43142/65535" Aug 28 22:36:46 southzi go-librespot[1279]: time="2026-08-28T22:36:46+09:00" level=debug msg="handling transfer player command from 5e2dd2043c2b7f9ec09f5000c8b72dd5b85b60de" Aug 28 22:36:46 southzi go-librespot[1279]: time="2026-08-28T22:36:46+09:00" level=warning msg="failed handling dealer request" error="failed creating track list: failed initializing context resolver: failed resolving context spotify:playlist:37i9dQZF1EYkqdzj48dyYq: invalid status code from context resolve: 404" Aug 28 22:36:46 southzi go-librespot[1279]: time="2026-08-28T22:36:46+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 28 22:36:46 southzi go-librespot[1279]: time="2026-08-28T22:36:46+09:00" level=trace msg="emitting websocket event: volume" Aug 28 22:36:46 southzi volumio[977]: info: Setting Volumio Volume from Spotify: 66 Aug 28 22:36:46 southzi volumio[977]: info: VolumeController::SetAlsaVolume66 Aug 28 22:36:46 southzi volumio[977]: info: CoreStateMachine::pushState Aug 28 22:36:46 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:36:46 southzi volumio[977]: info: CoreCommandRouter::volumioPushState Aug 28 22:36:49 southzi go-librespot[1279]: time="2026-08-28T22:36:49+09:00" level=debug msg="handling transfer player command from 5e2dd2043c2b7f9ec09f5000c8b72dd5b85b60de" Aug 28 22:36:49 southzi go-librespot[1279]: time="2026-08-28T22:36:49+09:00" level=warning msg="failed handling dealer request" error="failed creating track list: failed initializing context resolver: failed resolving context spotify:playlist:37i9dQZF1EYkqdzj48dyYq: invalid status code from context resolve: 404" Aug 28 22:36:54 southzi go-librespot[1279]: time="2026-08-28T22:36:54+09:00" level=debug msg="handling transfer player command from 5e2dd2043c2b7f9ec09f5000c8b72dd5b85b60de" Aug 28 22:36:54 southzi go-librespot[1279]: time="2026-08-28T22:36:54+09:00" level=warning msg="failed handling dealer request" error="failed creating track list: failed initializing context resolver: failed resolving context spotify:playlist:37i9dQZF1EYkqdzj48dyYq: invalid status code from context resolve: 404" Aug 28 22:36:57 southzi go-librespot[1279]: time="2026-08-28T22:36:57+09:00" level=debug msg="handling transfer player command from 5e2dd2043c2b7f9ec09f5000c8b72dd5b85b60de" Aug 28 22:36:57 southzi go-librespot[1279]: time="2026-08-28T22:36:57+09:00" level=warning msg="failed handling dealer request" error="failed creating track list: failed initializing context resolver: failed resolving context spotify:playlist:37i9dQZF1EYkqdzj48dyYq: invalid status code from context resolve: 404" Aug 28 22:37:13 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:13.556+09:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.1.179:57696 Aug 28 22:37:14 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 22:37:14 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 22:37:14 southzi volumio[977]: info: Discovery: Getting this device information Aug 28 22:37:14 southzi volumio[977]: info: CoreCommandRouter::volumioGetState Aug 28 22:37:14 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:14 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 22:37:14 southzi volumio[977]: verbose: New Socket.io Connection to 192.168.1.34:3000 from 192.168.1.179 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 9 Aug 28 22:37:14 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 28 22:37:14 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.233+09:00 level=INFO msg="app ready event" component=server event=CLIENT_EVENT_TYPE_APP_READY peer="192.168.1.179:57696 @ 0x2c127b0" latency=4.353928ms platform=PLATFORM_IOS version=6.260807.0 Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.236+09:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.1.179:57696 @ 0x2c127b0" latency=6.017314ms timeout=20s Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.236+09:00 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.1.179:57696 @ 0x2c127b0" Aug 28 22:37:15 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 28 22:37:15 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 28 22:37:15 southzi volumio[977]: info: Received Get System Info Aug 28 22:37:15 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 22:37:15 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 22:37:15 southzi volumio[977]: info: Discovery: Getting this device information Aug 28 22:37:15 southzi volumio[977]: info: CoreCommandRouter::volumioGetState Aug 28 22:37:15 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:15 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.245+09:00 level=INFO msg="emitting device name changed event" component=server peer="192.168.1.179:57696 @ 0x2c127b0" name=SouthZi Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.262+09:00 level=INFO msg="emitting device language changed event" component=server peer="192.168.1.179:57696 @ 0x2c127b0" language=ja Aug 28 22:37:15 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.267+09:00 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.1.179:57696 @ 0x2c127b0" timezone=Asia/Tokyo Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.269+09:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.1.179:57696 @ 0x2c127b0" available=true connected=false macAddress= ip4Address= ip6Address= Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.272+09:00 level=INFO msg="emitting wifi info changed event" component=server peer="192.168.1.179:57696 @ 0x2c127b0" available=true connected=true macAddress=b8:27:eb:a2:43:91 ip4Address=192.168.1.34/24 ip6Address= ssid="Apple Network 1972" Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.273+09:00 level=INFO msg="emitting device setup status changed event" component=server peer="192.168.1.179:57696 @ 0x2c127b0" setupComplete=true Aug 28 22:37:15 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Aug 28 22:37:15 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Aug 28 22:37:15 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 22:37:15 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 28 22:37:15 southzi volumio[977]: amixer -c 2 info | grep "snd_rpi_hifiberry_dacplus" Aug 28 22:37:15 southzi volumio[977]: Card hw:2 'sndrpihifiberry'/'snd_rpi_hifiberry_dacplus' Aug 28 22:37:15 southzi volumio[977]: amixer -c 0 info | grep "bcm2835 ALSA" Aug 28 22:37:15 southzi volumio[977]: amixer -c 1 info | grep "bcm2835 Headphones" Aug 28 22:37:15 southzi volumio[977]: Card hw:1 'Headphones'/'bcm2835 Headphones' Aug 28 22:37:15 southzi volumio[977]: amixer -c 2 info | grep "snd_rpi_hifiberry_dacplus" Aug 28 22:37:15 southzi volumio[977]: Card hw:2 'sndrpihifiberry'/'snd_rpi_hifiberry_dacplus' Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.529+09:00 level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.1.179:57696 @ 0x2c127b0" selectedOutputId=2 Aug 28 22:37:15 southzi volumio[977]: info: Received Get System Info Aug 28 22:37:15 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 22:37:15 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 22:37:15 southzi volumio[977]: info: Discovery: Getting this device information Aug 28 22:37:15 southzi volumio[977]: info: CoreCommandRouter::volumioGetState Aug 28 22:37:15 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:15 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.562+09:00 level=INFO msg="emitting software info changed event" component=server peer="192.168.1.179:57696 @ 0x2c127b0" currentVersion=3.912 latestVersion=3.912 Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.562+09:00 level=INFO msg="emitting software update progress event" component=server peer="192.168.1.179:57696 @ 0x2c127b0" status=UPDATE_STATUS_NONE progress=0 Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.563+09:00 level=INFO msg="emitting user changed event" component=server peer="192.168.1.179:57696 @ 0x2c127b0" userId=aWP60z1YuJMf4Zbi0VNcIsrufMr2 Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.564+09:00 level=INFO msg="emitting music providers changed event" component=server peer="192.168.1.179:57696 @ 0x2c127b0" providers=9 Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.564+09:00 level=INFO msg="emitting plugins changed event" component=server peer="192.168.1.179:57696 @ 0x2c127b0" plugins=54 Aug 28 22:37:15 southzi volumio[977]: info: CoreCommandRouter::volumioGetState Aug 28 22:37:15 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.572+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.179:57696 @ 0x2c127b0" state=STATUS_STOPPED positionMs=0 volume=100 Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.573+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.179:57696 @ 0x2c127b0" id= title= Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.592+09:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.1.179:57696 @ 0x2c127b0" latency=3.497748ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.619+09:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.179:57696 @ 0x2c127b0" latency=3.042917ms timeout=10s Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.778+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.179:57696 @ 0x2c127b0" latency=3.042917ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=158.778702ms Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.847+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.179:57696 @ 0x2c127b0" latency=3.042917ms timeout=10s endpoint=https://www.googleapis.com duration=228.048205ms Aug 28 22:37:15 southzi go-librespot[1279]: time="2026-08-28T22:37:15+09:00" level=trace msg="sent dealer ping" Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.973+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.179:57696 @ 0x2c127b0" latency=3.042917ms timeout=10s endpoint=https://google.com duration=354.217729ms Aug 28 22:37:15 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:15.975+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.179:57696 @ 0x2c127b0" latency=3.042917ms timeout=10s endpoint=https://securetoken.googleapis.com duration=353.970281ms Aug 28 22:37:15 southzi go-librespot[1279]: time="2026-08-28T22:37:15+09:00" level=trace msg="received dealer pong" Aug 28 22:37:16 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:16.039+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.179:57696 @ 0x2c127b0" latency=3.042917ms timeout=10s endpoint=https://database.volumio.cloud duration=418.686449ms Aug 28 22:37:16 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:16.091+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.179:57696 @ 0x2c127b0" latency=3.042917ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=471.822353ms Aug 28 22:37:16 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:16.104+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.179:57696 @ 0x2c127b0" latency=3.042917ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=479.719231ms Aug 28 22:37:16 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:16.143+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.179:57696 @ 0x2c127b0" latency=3.042917ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=523.62685ms Aug 28 22:37:16 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:16.197+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.179:57696 @ 0x2c127b0" latency=3.042917ms timeout=10s endpoint=http://pushupdates.volumio.org duration=577.832651ms Aug 28 22:37:16 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:16.203+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.179:57696 @ 0x2c127b0" latency=3.042917ms timeout=10s endpoint=http://plugins.volumio.org duration=584.221924ms Aug 28 22:37:16 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:16.551+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.179:57696 @ 0x2c127b0" latency=3.042917ms timeout=10s endpoint=https://functions.volumio.cloud duration=931.802983ms Aug 28 22:37:16 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:16.553+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.179:57696 @ 0x2c127b0" latency=3.042917ms timeout=10s endpoint=https://functions.volumio.cloud duration=930.337826ms Aug 28 22:37:16 southzi sudo[2540]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 22:37:16 southzi sudo[2538]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 22:37:16 southzi sudo[2540]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 28 22:37:16 southzi sudo[2538]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 28 22:37:16 southzi sudo[2540]: pam_unix(sudo:session): session closed for user root Aug 28 22:37:16 southzi sudo[2538]: pam_unix(sudo:session): session closed for user root Aug 28 22:37:16 southzi volumio[977]: verbose: New Socket.io Connection to 192.168.1.34 from 192.168.1.179 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 9 Aug 28 22:37:16 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 28 22:37:16 southzi volumio[977]: info: CoreCommandRouter::volumioGetVisibleSources Aug 28 22:37:16 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::volumioGetState Aug 28 22:37:17 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 28 22:37:17 southzi volumio[977]: info: Received Get System Info Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 22:37:17 southzi volumio[977]: info: Discovery: Getting this device information Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::volumioGetState Aug 28 22:37:17 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::volumioGetState Aug 28 22:37:17 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:17 southzi volumio[977]: info: Listing playlists Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 28 22:37:17 southzi sudo[2545]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 22:37:17 southzi sudo[2545]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 28 22:37:17 southzi sudo[2545]: pam_unix(sudo:session): session closed for user root Aug 28 22:37:17 southzi sudo[2547]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 22:37:17 southzi sudo[2547]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 28 22:37:17 southzi sudo[2547]: pam_unix(sudo:session): session closed for user root Aug 28 22:37:17 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:17.256+09:00 level=INFO msg="new address was allocated" component=ble/conn old=1 new=2 Aug 28 22:37:17 southzi volumio[977]: verbose: New Socket.io Connection to 192.168.1.34 from 192.168.1.179 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 9 Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::volumioGetVisibleSources Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::volumioGetState Aug 28 22:37:17 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 28 22:37:17 southzi volumio[977]: info: Received Get System Info Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 22:37:17 southzi volumio[977]: info: Discovery: Getting this device information Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::volumioGetState Aug 28 22:37:17 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::volumioGetState Aug 28 22:37:17 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:17 southzi volumio[977]: info: Listing playlists Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 28 22:37:17 southzi dbus-daemon[600]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.30" (uid=0 pid=1714 comm="/usr/bin/volumio5-onboarding ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.4" (uid=0 pid=747 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn") Aug 28 22:37:17 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 28 22:37:17 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:17.813+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.179:57696 @ 0x2c127b0" latency=3.042917ms timeout=10s endpoint=http://cddb.volumio.org duration=2.191931913s Aug 28 22:37:18 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 28 22:37:19 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 28 22:37:19 southzi volumio[977]: info: Received Get System Info Aug 28 22:37:19 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 22:37:19 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 22:37:19 southzi volumio[977]: info: Discovery: Getting this device information Aug 28 22:37:19 southzi volumio[977]: info: CoreCommandRouter::volumioGetState Aug 28 22:37:19 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:19 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 22:37:20 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 28 22:37:20 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 28 22:37:20 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 28 22:37:20 southzi volumio[977]: info: Received Get System Info Aug 28 22:37:20 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 22:37:20 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 22:37:20 southzi volumio[977]: info: Discovery: Getting this device information Aug 28 22:37:20 southzi volumio[977]: info: CoreCommandRouter::volumioGetState Aug 28 22:37:20 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:20 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 22:37:24 southzi go-librespot[1279]: time="2026-08-28T22:37:24+09:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Aug 28 22:37:24 southzi volumio[977]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify Aug 28 22:37:24 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 22:37:24 southzi sudo[2599]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop go-librespot-daemon.service Aug 28 22:37:24 southzi sudo[2599]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 28 22:37:24 southzi volumio[977]: info: Disabling plugin spop Aug 28 22:37:24 southzi volumio[977]: info: Done. Aug 28 22:37:24 southzi systemd[1]: Stopping go-librespot Daemon... Aug 28 22:37:24 southzi volumio[977]: info: Connection to go-librespot Websocket closed Aug 28 22:37:24 southzi systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Aug 28 22:37:24 southzi systemd[1]: go-librespot-daemon.service: Succeeded. Aug 28 22:37:24 southzi systemd[1]: Stopped go-librespot Daemon. Aug 28 22:37:24 southzi sudo[2599]: pam_unix(sudo:session): session closed for user root Aug 28 22:37:26 southzi volumio[977]: info: Enabling plugin spotify-connect Aug 28 22:37:26 southzi volumio[977]: info: Loading plugin "spotify-connect"... Aug 28 22:37:26 southzi volumio[977]: info: Preparing to generate the ALSA configuration file Aug 28 22:37:26 southzi volumio[977]: info: Asound.conf file unchanged, so no further update is needed Aug 28 22:37:26 southzi volumio[977]: info: Output device has changed, restarting MPD Aug 28 22:37:26 southzi sudo[2612]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 28 22:37:26 southzi volumio[977]: info: Output device has changed, restarting Shairport Sync Aug 28 22:37:26 southzi sudo[2612]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 28 22:37:26 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 22:37:26 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 22:37:26 southzi sudo[2612]: pam_unix(sudo:session): session closed for user root Aug 28 22:37:26 southzi sudo[2614]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 28 22:37:26 southzi sudo[2614]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 28 22:37:26 southzi systemd[1]: Stopping Music Player Daemon... Aug 28 22:37:26 southzi volumio[977]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 22:37:26 southzi volumio[977]: info: PLUGIN START: spotify-connect Aug 28 22:37:26 southzi volumio[977]: info: MPD Permissions set Aug 28 22:37:26 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 22:37:26 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 22:37:26 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 22:37:26 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 22:37:26 southzi volumio[977]: info: Starting Shairport Sync Aug 28 22:37:26 southzi sudo[2628]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 22:37:26 southzi sudo[2628]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 28 22:37:26 southzi systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Aug 28 22:37:26 southzi systemd[1]: shairport-sync.service: Succeeded. Aug 28 22:37:26 southzi systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Aug 28 22:37:26 southzi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Aug 28 22:37:26 southzi sudo[2628]: pam_unix(sudo:session): session closed for user root Aug 28 22:37:26 southzi volumio[977]: info: Shairport-Sync Started Aug 28 22:37:27 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Aug 28 22:37:27 southzi systemd[1]: mpd.service: Succeeded. Aug 28 22:37:27 southzi systemd[1]: Stopped Music Player Daemon. Aug 28 22:37:27 southzi systemd[1]: Starting Music Player Daemon... Aug 28 22:37:27 southzi volumio[977]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 28 22:37:27 southzi sudo[2639]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 28 22:37:27 southzi sudo[2639]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 28 22:37:27 southzi sudo[2639]: pam_unix(sudo:session): session closed for user root Aug 28 22:37:27 southzi volumio[977]: info: [go-librespot] time="2026-08-28T22:37:27+09:00" level=info msg="running go-librespot 0.8.0" Aug 28 22:37:27 southzi volumio[977]: info: [go-librespot] time="2026-08-28T22:37:27+09:00" level=info msg="api server listening on 127.0.0.1:9878" Aug 28 22:37:27 southzi volumio[977]: info: Done. Aug 28 22:37:27 southzi volumio[977]: info: [SpotifyConnect] event stream CONNECTED (ws://localhost:9878/events) Aug 28 22:37:27 southzi volumio[977]: info: [go-librespot] time="2026-08-28T22:37:27+09:00" level=info msg="zeroconf server listening on port 44071" Aug 28 22:37:27 southzi volumio[977]: info: [go-librespot] time="2026-08-28T22:37:27+09:00" level=info msg="using avahi-daemon avahi 0.7 for mDNS service registration" Aug 28 22:37:27 southzi volumio[977]: info: [go-librespot] time="2026-08-28T22:37:27+09:00" level=info msg="loading previously persisted zeroconf credentials" username="wd*********************j2" Aug 28 22:37:28 southzi volumio[977]: info: [go-librespot] time="2026-08-28T22:37:28+09:00" level=info msg="authenticated AP" username="wd*********************j2" Aug 28 22:37:28 southzi volumio[977]: info: [go-librespot] time="2026-08-28T22:37:28+09:00" level=info msg="authenticated Login5" username="wd*********************j2" Aug 28 22:37:28 southzi volumio[977]: info: CoreCommandRouter::servicePushState Aug 28 22:37:28 southzi volumio[977]: info: CoreStateMachine::pushState Aug 28 22:37:28 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:28 southzi volumio[977]: info: CoreCommandRouter::volumioPushState Aug 28 22:37:28 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:28 southzi volumio[977]: verbose: STATE SERVICE {"status":"stop","service":"spotify-connect","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2} Aug 28 22:37:28 southzi volumio[977]: verbose: CURRENT POSITION 0 Aug 28 22:37:28 southzi volumio[977]: info: CoreStateMachine::syncState stateService stop Aug 28 22:37:28 southzi volumio[977]: info: CoreStateMachine::syncState currentStatus stop Aug 28 22:37:28 southzi volumio[977]: info: CoreStateMachine::pushState Aug 28 22:37:28 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:28 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 22:37:28 southzi volumio[977]: info: CoreCommandRouter::volumioPushState Aug 28 22:37:28 southzi volumio[977]: info: No code Aug 28 22:37:28 southzi volumio[977]: info: CoreStateMachine::pushState Aug 28 22:37:28 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:28 southzi volumio[977]: info: CoreCommandRouter::volumioPushState Aug 28 22:37:28 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:28.741+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" state=STATUS_STOPPED positionMs=0 volume=100 Aug 28 22:37:28 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:28.743+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" id= title= Aug 28 22:37:28 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:28.746+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" state=STATUS_STOPPED positionMs=0 volume=100 Aug 28 22:37:28 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:28.747+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" state=STATUS_STOPPED positionMs=0 volume=100 Aug 28 22:37:28 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:28.749+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" id= title= Aug 28 22:37:28 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:28.751+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" id= title= Aug 28 22:37:28 southzi volumio[977]: info: [SpotifyConnect] event: playback_ready Aug 28 22:37:28 southzi volumio[977]: info: [SpotifyConnect] event: volume Aug 28 22:37:28 southzi volumio[977]: info: VolumeController::SetAlsaVolume100 Aug 28 22:37:28 southzi volumio[977]: info: CoreStateMachine::pushState Aug 28 22:37:28 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:28 southzi volumio[977]: info: CoreCommandRouter::volumioPushState Aug 28 22:37:29 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:29.018+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" state=STATUS_STOPPED positionMs=0 volume=100 Aug 28 22:37:29 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:29.019+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" id= title= Aug 28 22:37:29 southzi mpd[2641]: Aug 28 22:37 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 28 22:37:29 southzi systemd[1]: Started Music Player Daemon. Aug 28 22:37:29 southzi sudo[2614]: pam_unix(sudo:session): session closed for user root Aug 28 22:37:29 southzi volumio[977]: error: updateQueue error: null Aug 28 22:37:33 southzi volumio[977]: info: CALLMETHOD: music_service spotify-connect saveSettings [object Object] Aug 28 22:37:33 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: spotify-connect , saveSettings Aug 28 22:37:34 southzi volumio[977]: info: [go-librespot] time="2026-08-28T22:37:34+09:00" level=error msg="websocket connection errored" error="failed to get reader: received close frame: status = StatusNoStatusRcvd and reason = \"\"" Aug 28 22:37:34 southzi volumio[977]: warn: [SpotifyConnect] event stream closed, retrying… Aug 28 22:37:34 southzi volumio[977]: warn: [SpotifyConnect] daemon exited (0) Aug 28 22:37:34 southzi volumio[977]: info: [go-librespot] time="2026-08-28T22:37:34+09:00" level=info msg="running go-librespot 0.8.0" Aug 28 22:37:34 southzi volumio[977]: info: [go-librespot] time="2026-08-28T22:37:34+09:00" level=info msg="api server listening on 127.0.0.1:9878" Aug 28 22:37:34 southzi volumio[977]: info: [go-librespot] time="2026-08-28T22:37:34+09:00" level=info msg="zeroconf server listening on port 39929" Aug 28 22:37:34 southzi volumio[977]: info: [go-librespot] time="2026-08-28T22:37:34+09:00" level=info msg="using avahi-daemon avahi 0.7 for mDNS service registration" Aug 28 22:37:34 southzi volumio[977]: info: [go-librespot] time="2026-08-28T22:37:34+09:00" level=info msg="loading previously persisted zeroconf credentials" username="wd*********************j2" Aug 28 22:37:34 southzi volumio[977]: info: [go-librespot] time="2026-08-28T22:37:34+09:00" level=info msg="authenticated AP" username="wd*********************j2" Aug 28 22:37:34 southzi volumio[977]: info: [go-librespot] time="2026-08-28T22:37:34+09:00" level=info msg="authenticated Login5" username="wd*********************j2" Aug 28 22:37:35 southzi volumio[977]: info: [SpotifyConnect] event stream CONNECTED (ws://localhost:9878/events) Aug 28 22:37:35 southzi volumio[977]: info: CoreCommandRouter::servicePushState Aug 28 22:37:35 southzi volumio[977]: info: CoreStateMachine::pushState Aug 28 22:37:35 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:35 southzi volumio[977]: info: CoreCommandRouter::volumioPushState Aug 28 22:37:35 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:35 southzi volumio[977]: verbose: STATE SERVICE {"status":"stop","service":"spotify-connect","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2} Aug 28 22:37:35 southzi volumio[977]: verbose: CURRENT POSITION 0 Aug 28 22:37:35 southzi volumio[977]: info: CoreStateMachine::syncState stateService stop Aug 28 22:37:35 southzi volumio[977]: info: CoreStateMachine::syncState currentStatus stop Aug 28 22:37:35 southzi volumio[977]: info: CoreStateMachine::pushState Aug 28 22:37:35 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:35 southzi volumio[977]: info: CoreCommandRouter::volumioPushState Aug 28 22:37:35 southzi volumio[977]: info: No code Aug 28 22:37:35 southzi volumio[977]: info: CoreStateMachine::pushState Aug 28 22:37:35 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:35 southzi volumio[977]: info: CoreCommandRouter::volumioPushState Aug 28 22:37:35 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:35.118+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" state=STATUS_STOPPED positionMs=0 volume=100 Aug 28 22:37:35 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:35.121+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" id= title= Aug 28 22:37:35 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:35.121+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" state=STATUS_STOPPED positionMs=0 volume=100 Aug 28 22:37:35 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:35.122+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" id= title= Aug 28 22:37:35 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:35.125+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" state=STATUS_STOPPED positionMs=0 volume=100 Aug 28 22:37:35 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:35.127+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" id= title= Aug 28 22:37:35 southzi volumio[977]: info: [SpotifyConnect] event: volume Aug 28 22:37:35 southzi volumio[977]: info: VolumeController::SetAlsaVolume100 Aug 28 22:37:35 southzi volumio[977]: info: CoreStateMachine::pushState Aug 28 22:37:35 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:35 southzi volumio[977]: info: CoreCommandRouter::volumioPushState Aug 28 22:37:35 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:35.245+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" state=STATUS_STOPPED positionMs=0 volume=100 Aug 28 22:37:35 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:35.245+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" id= title= Aug 28 22:37:36 southzi volumio[977]: info: [SpotifyConnect] event stream CONNECTED (ws://localhost:9878/events) Aug 28 22:37:36 southzi volumio[977]: info: CoreCommandRouter::servicePushState Aug 28 22:37:36 southzi volumio[977]: info: CoreStateMachine::pushState Aug 28 22:37:36 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:36 southzi volumio[977]: info: CoreCommandRouter::volumioPushState Aug 28 22:37:36 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:36 southzi volumio[977]: verbose: STATE SERVICE {"status":"stop","service":"spotify-connect","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2} Aug 28 22:37:36 southzi volumio[977]: verbose: CURRENT POSITION 0 Aug 28 22:37:36 southzi volumio[977]: info: CoreStateMachine::syncState stateService stop Aug 28 22:37:36 southzi volumio[977]: info: CoreStateMachine::syncState currentStatus stop Aug 28 22:37:36 southzi volumio[977]: info: CoreStateMachine::pushState Aug 28 22:37:36 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:36 southzi volumio[977]: info: CoreCommandRouter::volumioPushState Aug 28 22:37:36 southzi volumio[977]: info: No code Aug 28 22:37:36 southzi volumio[977]: info: CoreStateMachine::pushState Aug 28 22:37:36 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:36 southzi volumio[977]: info: CoreCommandRouter::volumioPushState Aug 28 22:37:36 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:36.076+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" state=STATUS_STOPPED positionMs=0 volume=100 Aug 28 22:37:36 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:36.078+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" id= title= Aug 28 22:37:36 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:36.080+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" state=STATUS_STOPPED positionMs=0 volume=100 Aug 28 22:37:36 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:36.081+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" id= title= Aug 28 22:37:36 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:36.087+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" state=STATUS_STOPPED positionMs=0 volume=100 Aug 28 22:37:36 southzi volumio5-onboarding[1714]: time=2026-08-28T22:37:36.087+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.179:57696,00:00:00:00:00:00%01 @ 0x2c127b0" id= title= Aug 28 22:37:36 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 28 22:37:36 southzi volumio[977]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Aug 28 22:37:36 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Aug 28 22:37:36 southzi volumio[977]: info: Received Get System Version Aug 28 22:37:36 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 22:37:36 southzi volumio[977]: info: Received Get System Info Aug 28 22:37:36 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 22:37:36 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 22:37:36 southzi volumio[977]: info: Discovery: Getting this device information Aug 28 22:37:36 southzi volumio[977]: info: CoreCommandRouter::volumioGetState Aug 28 22:37:36 southzi volumio[977]: info: CorePlayQueue::getTrack 0 Aug 28 22:37:36 southzi volumio[977]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 22:37:37 southzi volumio[977]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 22:37:37 southzi volumio[977]: Error: Unable to resolve or reject the same promise twice Aug 28 22:37:37 southzi volumio[977]: at Promise.resolve (/data/plugins/music_service/spotify-connect/node_modules/kew/kew.js:140:43) Aug 28 22:37:37 southzi volumio[977]: at Timeout._onTimeout (/data/plugins/music_service/spotify-connect/index.js:162:13) Aug 28 22:37:37 southzi volumio[977]: at listOnTimeout (internal/timers.js:554:17) Aug 28 22:37:37 southzi volumio[977]: at processTimers (internal/timers.js:497:7) Aug 28 22:37:37 southzi volumio[977]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 22:37:37 southzi sudo[2688]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-08-28 22:36 Aug 28 22:37:37 southzi sudo[2688]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="e9612ec5034fb2e958508aaefbca2962fd6f6654" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="464fc672d77d3df6ee72b331d36cdf1fa936e1ec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 27 Feb 2026 10:59:40 AM CET" VOLUMIO_VERSION="3.912" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="37c6ab864cb114e1344d540995c69f86"