-- Logs begin at Thu 2019-02-14 15:41:59 IST, end at Sat 2025-04-12 21:39:51 IST. -- Apr 12 21:38:03 misti volumio[974]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 12 21:38:03 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Apr 12 21:38:03 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 21:38:03 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Apr 12 21:38:03 misti volumio[974]: info: Getting Alsa Cards List without I2S DAC Apr 12 21:38:03 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SNumber Apr 12 21:38:03 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 21:38:03 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 12 21:38:03 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 12 21:38:03 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 12 21:38:03 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 12 21:38:03 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 12 21:38:03 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 12 21:38:03 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 12 21:38:03 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Apr 12 21:38:03 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Apr 12 21:38:08 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 12 21:38:08 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 12 21:38:08 misti volumio[974]: info: Discovery: Getting this device information Apr 12 21:38:08 misti volumio[974]: info: CoreCommandRouter::volumioGetState Apr 12 21:38:08 misti volumio[974]: info: CorePlayQueue::getTrack 3 Apr 12 21:38:08 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 12 21:38:13 misti volumio[974]: info: CALLMETHOD: music_service mpd savePlaybackOptions [object Object] Apr 12 21:38:13 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: mpd , savePlaybackOptions Apr 12 21:38:13 misti sudo[6494]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 12 21:38:13 misti sudo[6494]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 21:38:13 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 21:38:13 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 21:38:13 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 21:38:13 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 21:38:13 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 21:38:13 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 21:38:13 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 21:38:13 misti sudo[6494]: pam_unix(sudo:session): session closed for user root Apr 12 21:38:13 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 21:38:13 misti sudo[6496]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 12 21:38:13 misti sudo[6496]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 21:38:13 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 21:38:13 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 21:38:13 misti volumio[974]: info: MPD Permissions set Apr 12 21:38:13 misti systemd[1]: Stopping Music Player Daemon... Apr 12 21:38:13 misti systemd[1]: mpd.service: Succeeded. Apr 12 21:38:13 misti systemd[1]: Stopped Music Player Daemon. Apr 12 21:38:13 misti systemd[1]: Starting Music Player Daemon... Apr 12 21:38:13 misti sudo[6503]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Apr 12 21:38:13 misti sudo[6503]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 21:38:13 misti sudo[6503]: pam_unix(sudo:session): session closed for user root Apr 12 21:38:13 misti volumio[974]: error: Upnp client error: Error: This socket has been ended by the other party Apr 12 21:38:14 misti mpd[6508]: Apr 12 21:38 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Apr 12 21:38:14 misti systemd[1]: Started Music Player Daemon. Apr 12 21:38:14 misti sudo[6496]: pam_unix(sudo:session): session closed for user root Apr 12 21:38:14 misti volumio[974]: error: updateQueue error: null Apr 12 21:38:14 misti volumio[974]: info: CALLMETHOD: music_service mpd savePlaybackOptions [object Object] Apr 12 21:38:14 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: mpd , savePlaybackOptions Apr 12 21:38:14 misti sudo[6514]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 12 21:38:14 misti sudo[6514]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 21:38:14 misti sudo[6514]: pam_unix(sudo:session): session closed for user root Apr 12 21:38:14 misti volumio[974]: info: MPD Permissions set Apr 12 21:38:14 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 21:38:14 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 21:38:14 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 21:38:14 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 21:38:14 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 21:38:14 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 21:38:14 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 21:38:14 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 21:38:14 misti sudo[6517]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 12 21:38:14 misti sudo[6517]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 21:38:15 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 21:38:15 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 21:38:15 misti systemd[1]: Stopping Music Player Daemon... Apr 12 21:38:15 misti systemd[1]: mpd.service: Succeeded. Apr 12 21:38:15 misti systemd[1]: Stopped Music Player Daemon. Apr 12 21:38:15 misti systemd[1]: Starting Music Player Daemon... Apr 12 21:38:15 misti sudo[6523]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Apr 12 21:38:15 misti sudo[6523]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 21:38:15 misti sudo[6523]: pam_unix(sudo:session): session closed for user root Apr 12 21:38:16 misti mpd[6525]: Apr 12 21:38 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Apr 12 21:38:16 misti systemd[1]: Started Music Player Daemon. Apr 12 21:38:16 misti sudo[6517]: pam_unix(sudo:session): session closed for user root Apr 12 21:38:16 misti volumio[974]: error: updateQueue error: null Apr 12 21:38:24 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 12 21:38:24 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Apr 12 21:38:38 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 12 21:38:38 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 12 21:38:38 misti volumio[974]: info: Discovery: Getting this device information Apr 12 21:38:38 misti volumio[974]: info: CoreCommandRouter::volumioGetState Apr 12 21:38:38 misti volumio[974]: info: CorePlayQueue::getTrack 3 Apr 12 21:38:38 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 12 21:38:46 misti volumio[974]: info: Enabling plugin ytmusic Apr 12 21:38:46 misti volumio[974]: info: Loading plugin "ytmusic"... Apr 12 21:38:50 misti volumio[974]: info: PLUGIN START: ytmusic Apr 12 21:38:50 misti volumio[974]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 12 21:38:50 misti volumio[974]: info: [1744474130767] CoreMusicLibrary::Adding element YouTube Music Apr 12 21:38:50 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 12 21:38:50 misti volumio[974]: Cannot find translation for source YouTube Music Apr 12 21:38:50 misti volumio[974]: info: Done. Apr 12 21:38:50 misti volumio[974]: Upnp client error: Error: This socket has been ended by the other party Apr 12 21:38:57 misti volumio[974]: info: Enabling plugin spop Apr 12 21:38:57 misti volumio[974]: info: Loading plugin "spop"... Apr 12 21:38:58 misti volumio[974]: info: PLUGIN START: spop Apr 12 21:38:58 misti volumio[974]: info: Creating Spotify config file Apr 12 21:38:58 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 21:38:58 misti volumio[974]: info: Done. Apr 12 21:38:58 misti volumio[974]: info: Spotify config file written Apr 12 21:38:58 misti sudo[6707]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 12 21:38:58 misti sudo[6707]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 21:38:58 misti systemd[1]: Started go-librespot Daemon. Apr 12 21:38:58 misti go-librespot[6709]: Librespot-go daemon starting... Apr 12 21:38:58 misti sudo[6707]: pam_unix(sudo:session): session closed for user root Apr 12 21:38:59 misti volumio[974]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Apr 12 21:38:59 misti volumio[974]: SPOTIFY: BQBAlbm1NJu2A_Fe7K5i0-z8hcbLHfz_nLmDiOQLs6a1XadR2sCmcZcybrGOj2iUCrlT5RyLmtDyTEWqLiIt9CRgacw7LBTyDJAbJ-oZX2k1FbdeuSdS9tDFI4_zwPPcK3mYBzxWhcNiEC9zBs88K-sKwZBCYC0GpEXDDP8tvCKNW9ZvEN0HOViSlpZcleUv5Pp6G5R1SZzcdl7KQWSxn3mjPxcjJCPIEzs9s_SE0hlCBkoBT2jXkdlzfh4_LtUUZCQnoPMbug_ZBJtmv-TwY9LESNT4wq51q8REIBbFnRvNQJs8XmxKbaBoRXQf1eGrUof30aAglAIXAA Apr 12 21:38:59 misti volumio[974]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Apr 12 21:38:59 misti volumio[974]: info: New Spotify access token = BQBAlbm1NJu2A_Fe7K5i0-z8hcbLHfz_nLmDiOQLs6a1XadR2sCmcZcybrGOj2iUCrlT5RyLmtDyTEWqLiIt9CRgacw7LBTyDJAbJ-oZX2k1FbdeuSdS9tDFI4_zwPPcK3mYBzxWhcNiEC9zBs88K-sKwZBCYC0GpEXDDP8tvCKNW9ZvEN0HOViSlpZcleUv5Pp6G5R1SZzcdl7KQWSxn3mjPxcjJCPIEzs9s_SE0hlCBkoBT2jXkdlzfh4_LtUUZCQnoPMbug_ZBJtmv-TwY9LESNT4wq51q8REIBbFnRvNQJs8XmxKbaBoRXQf1eGrUof30aAglAIXAA Apr 12 21:38:59 misti volumio[974]: info: Spotify credentials grant success - running version from March 24, 2019 Apr 12 21:38:59 misti go-librespot[6709]: time="2025-04-12T21:38:59+05:30" level=info msg="generated new device id: 66a7ee889e7f9694f02d4e55d8e3fbcc9f6301b3" Apr 12 21:38:59 misti go-librespot[6709]: time="2025-04-12T21:38:59+05:30" level=debug msg="stored credentials found for 3165qx6grylxtxfghcrn7f7ewj7i" Apr 12 21:38:59 misti volumio[974]: SPOTIFY: User informations: {"country":"IN","display_name":"Samir","email":null,"explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/3165qx6grylxtxfghcrn7f7ewj7i"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/3165qx6grylxtxfghcrn7f7ewj7i","id":"3165qx6grylxtxfghcrn7f7ewj7i","images":[],"product":"premium","type":"user","uri":"spotify:user:3165qx6grylxtxfghcrn7f7ewj7i"} Apr 12 21:38:59 misti volumio[974]: info: Spotify Successfully logged in Apr 12 21:38:59 misti volumio[974]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 12 21:38:59 misti volumio[974]: info: [1744474139469] CoreMusicLibrary::Adding element Spotify Apr 12 21:38:59 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 12 21:38:59 misti volumio[974]: Cannot find translation for source YouTube Music Apr 12 21:38:59 misti volumio[974]: Cannot find translation for source Spotify Apr 12 21:38:59 misti go-librespot[6709]: time="2025-04-12T21:38:59+05:30" level=debug msg="obtained new client token: AACDm9gxboQ0Du7+M0yRyy6dX+KXCdbPRBucq1Bj/E5w0Oi0R0GXhKnWhgNVFgrk1iUvMnK0NSOU3SJqYKdPh7Y0tR0lA7ap2xCHILe/4u36yf1alvWpCf5XILlSpDL0a1ksuz1QcoGQMc5nNaODKt092KAmBq44DXS0q8iZeMdD8znZ+78EJ7Lt+wLnMLd9J5LQurVqB60zakzfqMQc/k4fRI5ze3w7GMlgdWWWeYsEK5sYQg4Cn2H2RJiO7g==" Apr 12 21:39:00 misti go-librespot[6709]: time="2025-04-12T21:39:00+05:30" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 12 21:39:00 misti go-librespot[6709]: time="2025-04-12T21:39:00+05:30" level=debug msg="completed keyexchange" Apr 12 21:39:00 misti volumio[974]: info: Enabling plugin ampswitch Apr 12 21:39:00 misti volumio[974]: info: Loading plugin "ampswitch"... Apr 12 21:39:00 misti go-librespot[6709]: time="2025-04-12T21:39:00+05:30" level=debug msg="completed challenge" Apr 12 21:39:01 misti go-librespot[6709]: time="2025-04-12T21:39:01+05:30" level=debug msg="authenticated as 3165qx6grylxtxfghcrn7f7ewj7i" Apr 12 21:39:01 misti volumio[974]: info: Applying required configuration parameters for plugin ampswitch Apr 12 21:39:01 misti volumio[974]: info: PLUGIN START: ampswitch Apr 12 21:39:01 misti go-librespot[6709]: time="2025-04-12T21:39:01+05:30" level=debug msg="authenticated as 3165qx6grylxtxfghcrn7f7ewj7i" Apr 12 21:39:01 misti volumio[974]: info: Done. Apr 12 21:39:01 misti volumio[974]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Apr 12 21:39:01 misti volumio[974]: info: CoreCommandRouter::volumioGetState Apr 12 21:39:01 misti volumio[974]: info: CorePlayQueue::getTrack 3 Apr 12 21:39:01 misti volumio[974]: info: [ASDebug] CurState: pause PrevState: na Apr 12 21:39:01 misti volumio[974]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Apr 12 21:39:01 misti volumio[974]: info: [ASDebug] CurState: pause PrevState: na Apr 12 21:39:01 misti volumio[974]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Apr 12 21:39:01 misti go-librespot[6709]: time="2025-04-12T21:39:01+05:30" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 12 21:39:01 misti go-librespot[6709]: time="2025-04-12T21:39:01+05:30" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 12 21:39:01 misti volumio[974]: info: go-librespot daemon successfully initialized Apr 12 21:39:01 misti go-librespot[6709]: time="2025-04-12T21:39:01+05:30" level=debug msg="dealer connection opened" Apr 12 21:39:01 misti go-librespot[6709]: time="2025-04-12T21:39:01+05:30" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 12 21:39:01 misti go-librespot[6709]: time="2025-04-12T21:39:01+05:30" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 12 21:39:01 misti go-librespot[6709]: time="2025-04-12T21:39:01+05:30" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 12 21:39:01 misti go-librespot[6709]: time="2025-04-12T21:39:01+05:30" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 12 21:39:01 misti go-librespot[6709]: time="2025-04-12T21:39:01+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Apr 12 21:39:01 misti go-librespot[6709]: time="2025-04-12T21:39:01+05:30" level=debug msg="received connection id: ODQxOWY4MzAtNTZlOS00MGVkLTk4NDctYjU5ZjI4NjZlZGQzK2RlYWxlcit0Y3A6Ly8wYWM5NDllZC5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArNjUwOTgxOTEzMkRENkQ4NDVGNTYzNkJDNUQ2NEM3NThCMzJCQ0FDNkNBMUE0MjgyRTA0QUYxQUVDMTQ1OUEwQQ==" Apr 12 21:39:02 misti volumio[974]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 12 21:39:02 misti volumio[974]: info: [ASDebug] Setting UI defaults Apr 12 21:39:02 misti volumio[974]: info: [ASDebug] Port: 24 Apr 12 21:39:02 misti volumio[974]: info: [ASDebug] Inverted: false Apr 12 21:39:02 misti volumio[974]: info: [ASDebug] Latched: false Apr 12 21:39:02 misti volumio[974]: info: [ASDebug] On pulse width: 500 Apr 12 21:39:02 misti volumio[974]: info: [ASDebug] Off pulse width: 500 Apr 12 21:39:02 misti go-librespot[6709]: time="2025-04-12T21:39:02+05:30" level=debug msg="put connect state because NEW_DEVICE" Apr 12 21:39:02 misti volumio[974]: info: [ASDebug] Togle GPIO: OFF Apr 12 21:39:04 misti volumio[974]: info: Initializing connection to go-librespot Websocket Apr 12 21:39:04 misti go-librespot[6709]: time="2025-04-12T21:39:04+05:30" level=debug msg="new websocket client" Apr 12 21:39:04 misti volumio[974]: info: Connection to go-librespot Websocket established Apr 12 21:39:07 misti volumio[974]: info: Getting Spotify volume Apr 12 21:39:07 misti volumio[974]: info: Spotify volume: 100 Apr 12 21:39:07 misti volumio[974]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Apr 12 21:39:07 misti volumio[974]: info: CoreCommandRouter::volumioGetState Apr 12 21:39:07 misti volumio[974]: info: CorePlayQueue::getTrack 3 Apr 12 21:39:08 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 12 21:39:08 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 12 21:39:08 misti volumio[974]: info: Discovery: Getting this device information Apr 12 21:39:08 misti volumio[974]: info: CoreCommandRouter::volumioGetState Apr 12 21:39:08 misti volumio[974]: info: CorePlayQueue::getTrack 3 Apr 12 21:39:08 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 12 21:39:10 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 12 21:39:10 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Apr 12 21:39:12 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 12 21:39:12 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 12 21:39:12 misti volumio[974]: info: Discovery: Getting this device information Apr 12 21:39:12 misti volumio[974]: info: CoreCommandRouter::volumioGetState Apr 12 21:39:12 misti volumio[974]: info: CorePlayQueue::getTrack 3 Apr 12 21:39:12 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 12 21:39:23 misti volumio[974]: info: [ASDebug] Port: 24 Apr 12 21:39:23 misti volumio[974]: info: [ASDebug] Inverted: false Apr 12 21:39:23 misti volumio[974]: info: [ASDebug] Delay: 720 Apr 12 21:39:29 misti volumio[974]: info: Enabling plugin autostart Apr 12 21:39:29 misti volumio[974]: info: Loading plugin "autostart"... Apr 12 21:39:29 misti volumio[974]: info: Applying required configuration parameters for plugin autostart Apr 12 21:39:29 misti volumio[974]: info: AutoStart - onVolumioStart - read config.json Apr 12 21:39:29 misti volumio[974]: info: PLUGIN START: autostart Apr 12 21:39:29 misti volumio[974]: info: AutoStart - onStart Apr 12 21:39:29 misti volumio[974]: info: Done. Apr 12 21:39:38 misti volumio[974]: info: Enabling plugin backup_restore Apr 12 21:39:38 misti volumio[974]: info: Loading plugin "backup_restore"... Apr 12 21:39:38 misti volumio[974]: info: Applying required configuration parameters for plugin backup_restore Apr 12 21:39:38 misti volumio[974]: info: PLUGIN START: backup_restore Apr 12 21:39:38 misti volumio[974]: info: Done. Apr 12 21:39:38 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 12 21:39:38 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 12 21:39:38 misti volumio[974]: info: Discovery: Getting this device information Apr 12 21:39:38 misti volumio[974]: info: CoreCommandRouter::volumioGetState Apr 12 21:39:38 misti volumio[974]: info: CorePlayQueue::getTrack 3 Apr 12 21:39:38 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 12 21:39:40 misti volumio[974]: info: Enabling plugin gpio-buttons Apr 12 21:39:40 misti volumio[974]: info: Loading plugin "gpio-buttons"... Apr 12 21:39:41 misti volumio[974]: info: GPIO-Buttons initialized Apr 12 21:39:41 misti volumio[974]: info: PLUGIN START: gpio-buttons Apr 12 21:39:41 misti volumio[974]: info: GPIO-Buttons: Reading config and creating triggers... Apr 12 21:39:41 misti volumio[974]: info: GPIO-Buttons started Apr 12 21:39:41 misti volumio[974]: info: Done. Apr 12 21:39:41 misti volumio[974]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Apr 12 21:39:43 misti volumio[974]: info: Enabling plugin gpio_control Apr 12 21:39:43 misti volumio[974]: info: Loading plugin "gpio_control"... Apr 12 21:39:43 misti volumio[974]: gpiox_arm32 V2.1.0 Apr 12 21:39:43 misti volumio[974]: info: Applying required configuration parameters for plugin gpio_control Apr 12 21:39:43 misti volumio[974]: info: PLUGIN START: gpio_control Apr 12 21:39:43 misti volumio[974]: info: [GPIO_Control] Reading config and creating GPIOs Apr 12 21:39:43 misti volumio[974]: info: [GPIO_Control] On systemShutdown will set GPIO 6 to On after 9 Seconds delay Apr 12 21:39:43 misti volumio[974]: info: [GPIO_Control] GPIOs created Apr 12 21:39:43 misti volumio[974]: info: [GPIO_Control] Handling event: systemStartup Apr 12 21:39:43 misti volumio[974]: info: Done. Apr 12 21:39:43 misti volumio[974]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Apr 12 21:39:43 misti volumio[974]: info: CoreCommandRouter::volumioGetState Apr 12 21:39:43 misti volumio[974]: info: CorePlayQueue::getTrack 3 Apr 12 21:39:43 misti volumio[974]: info: [GPIO_Control] Status changed: pause Apr 12 21:39:43 misti volumio[974]: info: [GPIO_Control] Handling event: musicPause Apr 12 21:39:43 misti volumio[974]: info: [GPIO_Control] Handling event: repeatAllOff Apr 12 21:39:43 misti volumio[974]: info: [GPIO_Control] Handling event: repeatOff Apr 12 21:39:43 misti volumio[974]: info: [GPIO_Control] Status changed: pause Apr 12 21:39:45 misti volumio[974]: info: Enabling plugin ir_controller Apr 12 21:39:45 misti volumio[974]: info: Loading plugin "ir_controller"... Apr 12 21:39:45 misti volumio[974]: info: Applying required configuration parameters for plugin ir_controller Apr 12 21:39:45 misti volumio[974]: info: PLUGIN START: ir_controller Apr 12 21:39:45 misti volumio[974]: info: Loading i18n strings for locale en Apr 12 21:39:45 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 12 21:39:45 misti sudo[6947]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod -R a+rwX /etc/lirc/irexec.lircrc /etc/lirc/lirc_options.conf /etc/lirc/lircd.conf /etc/lirc/lircd.conf.d /etc/lirc/lircmd.conf /etc/lirc/lircrc Apr 12 21:39:45 misti sudo[6947]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 21:39:45 misti sudo[6947]: pam_unix(sudo:session): session closed for user root Apr 12 21:39:45 misti volumio[974]: info: ir_controller: File permissions successfully set on /etc/lirc/*. Apr 12 21:39:45 misti volumio[974]: info: ir_controller: LIRC correctly updated. Apr 12 21:39:45 misti volumio[974]: info: ir_controller: HAT did not load /proc/device-tree/ir_receiver! Apr 12 21:39:45 misti volumio[974]: info: Done. Apr 12 21:39:45 misti volumio[974]: info: ir_controller: Raspberry Pi revision code: a020d4 Apr 12 21:39:45 misti sudo[6954]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -r -1 Apr 12 21:39:45 misti sudo[6954]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 21:39:45 misti sudo[6954]: pam_unix(sudo:session): session closed for user root Apr 12 21:39:45 misti sudo[6963]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay gpio-ir gpio_pin=12 gpio_pull=down Apr 12 21:39:45 misti sudo[6963]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 21:39:45 misti sudo[6963]: pam_unix(sudo:session): session closed for user root Apr 12 21:39:45 misti volumio[974]: info: ir_controller: Overlay gpio-ir gpio_pin=12 gpio_pull=down loaded. Apr 12 21:39:45 misti kernel: Registered IR keymap rc-rc6-mce Apr 12 21:39:45 misti kernel: IR RC6 protocol handler initialized Apr 12 21:39:45 misti sudo[6975]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart lircd.service Apr 12 21:39:45 misti sudo[6975]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 21:39:45 misti kernel: rc rc0: gpio_ir_recv as /devices/platform/ir-receiver@c/rc/rc0 Apr 12 21:39:45 misti kernel: rc rc0: lirc_dev: driver gpio_ir_recv registered at minor = 0, raw IR receiver, no transmitter Apr 12 21:39:45 misti kernel: input: gpio_ir_recv as /devices/platform/ir-receiver@c/rc/rc0/input0 Apr 12 21:39:45 misti systemd[1]: Starting lircd(8) initialization helper tool... Apr 12 21:39:46 misti systemd-udevd[6978]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1. Apr 12 21:39:46 misti systemd-logind[606]: Watching system buttons on /dev/input/event0 (gpio_ir_recv) Apr 12 21:39:46 misti lircd-setup[6979]: /usr/sbin/lircd-setup:37: DeprecationWarning: The SafeConfigParser class has been renamed to ConfigParser in Python 3.2. This alias will be removed in future versions. Use ConfigParser directly instead. Apr 12 21:39:46 misti lircd-setup[6979]: parser = configparser.SafeConfigParser() Apr 12 21:39:46 misti systemd[1]: lircd-setup.service: Succeeded. Apr 12 21:39:46 misti systemd[1]: Started lircd(8) initialization helper tool. Apr 12 21:39:46 misti systemd[1]: Starting Flexible IR remote input/output application support... Apr 12 21:39:46 misti lircd-0.10.1[6982]: Info: lircd: Opening log, level: Info Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Version: lircd 0.10.1 Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: System info: Linux misti 6.6.62-v7+ #1816 SMP Mon Nov 18 15:30:49 GMT 2024 armv7l GNU/Linux Apr 12 21:39:46 misti lircd-0.10.1[6982]: Info: Initial device: /dev/lirc0 Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: 'lirc' written to protocols file /sys/class/rc/rc0/protocols Apr 12 21:39:46 misti lircd-0.10.1[6982]: Info: Initial device: /dev/lirc0 Apr 12 21:39:46 misti lircd-0.10.1[6982]: Info: [lirc] protocol is enabled Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Options: driver: default Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Options: output: /var/run/lirc/lircd Apr 12 21:39:46 misti lircd[6982]: lircd-0.10.1[6982]: Info: lircd: Opening log, level: Info Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Options: nodaemon: 1 Apr 12 21:39:46 misti lircd[6982]: lircd-0.10.1[6982]: Notice: Using systemd fd Apr 12 21:39:46 misti lircd[6982]: lircd-0.10.1[6982]: Warning: Running as root Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Options: plugindir: /usr/lib/arm-linux-gnueabihf/lirc/plugins Apr 12 21:39:46 misti lircd[6982]: lircd-0.10.1[6982]: Info: Using remote: /etc/lirc/lircd-custom.conf. Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Options: logfile: syslog Apr 12 21:39:46 misti lircd[6982]: lircd-0.10.1[6982]: Notice: lircd(default) ready, using /var/run/lirc/lircd Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Options: immediate-init: 0 Apr 12 21:39:46 misti systemd[1]: Started Flexible IR remote input/output application support. Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Options: permission: 666 Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Options: driver-options: Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Options: pidfile: /var/run/lirc/lircd.pid Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Options: listen: 0 Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Options: connect: (null) Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Options: userelease: 0 Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Options: effective_user: (null) Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Options: release_suffix: _EVUP Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Options: allow_simulate: 0 Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Options: repeat_max: 600 Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Options: configfile: /etc/lirc/lircd.conf Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Options: dynamic_codes: (null) Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Current driver: default Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Driver API version: 3 Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Driver version: 0.10.0 Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Driver info: See file:///usr/share/doc/lirc/plugindocs/default.html Apr 12 21:39:46 misti lircd-0.10.1[6982]: Info: lircd: Opening log, level: Info Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: Using systemd fd Apr 12 21:39:46 misti lircd-0.10.1[6982]: Warning: Running as root Apr 12 21:39:46 misti lircd-0.10.1[6982]: Info: Using remote: /etc/lirc/lircd-custom.conf. Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: lircd(default) ready, using /var/run/lirc/lircd Apr 12 21:39:46 misti sudo[6975]: pam_unix(sudo:session): session closed for user root Apr 12 21:39:46 misti volumio[974]: info: ir_controller: systemctl restart lircd.service succeeded. Apr 12 21:39:46 misti sudo[6986]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart lircd.service Apr 12 21:39:46 misti sudo[6986]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 21:39:46 misti lircd[6982]: lircd-0.10.1[6982]: Notice: caught signal Apr 12 21:39:46 misti lircd-0.10.1[6982]: Notice: caught signal Apr 12 21:39:46 misti systemd[1]: Stopping Flexible IR remote input/output application support... Apr 12 21:39:46 misti sudo[6989]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart irexec.service Apr 12 21:39:46 misti systemd[1]: lircd.service: Main process exited, code=killed, status=15/TERM Apr 12 21:39:46 misti systemd[1]: lircd.service: Succeeded. Apr 12 21:39:46 misti sudo[6989]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 21:39:46 misti systemd[1]: Stopped Flexible IR remote input/output application support. Apr 12 21:39:46 misti systemd[1]: Starting lircd(8) initialization helper tool... Apr 12 21:39:46 misti systemd[1]: Started Handle events from IR remotes decoded by lircd(8). Apr 12 21:39:46 misti sudo[6989]: pam_unix(sudo:session): session closed for user root Apr 12 21:39:46 misti volumio[974]: info: ir_controller: systemctl restart irexec.service succeeded. Apr 12 21:39:46 misti lircd-setup[6991]: /usr/sbin/lircd-setup:37: DeprecationWarning: The SafeConfigParser class has been renamed to ConfigParser in Python 3.2. This alias will be removed in future versions. Use ConfigParser directly instead. Apr 12 21:39:46 misti lircd-setup[6991]: parser = configparser.SafeConfigParser() Apr 12 21:39:46 misti systemd[1]: lircd-setup.service: Succeeded. Apr 12 21:39:46 misti systemd[1]: Started lircd(8) initialization helper tool. Apr 12 21:39:46 misti systemd[1]: Starting Flexible IR remote input/output application support... Apr 12 21:39:46 misti lircd-0.10.1[6996]: Info: lircd: Opening log, level: Info Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Version: lircd 0.10.1 Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: System info: Linux misti 6.6.62-v7+ #1816 SMP Mon Nov 18 15:30:49 GMT 2024 armv7l GNU/Linux Apr 12 21:39:46 misti lircd-0.10.1[6996]: Info: Initial device: /dev/lirc0 Apr 12 21:39:46 misti lircd-0.10.1[6996]: Info: [lirc] protocol is enabled Apr 12 21:39:46 misti lircd-0.10.1[6996]: Info: Initial device: /dev/lirc0 Apr 12 21:39:46 misti lircd-0.10.1[6996]: Info: [lirc] protocol is enabled Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Options: driver: default Apr 12 21:39:46 misti systemd[1]: Started Flexible IR remote input/output application support. Apr 12 21:39:46 misti lircd[6996]: lircd-0.10.1[6996]: Info: lircd: Opening log, level: Info Apr 12 21:39:46 misti lircd[6996]: lircd-0.10.1[6996]: Notice: Using systemd fd Apr 12 21:39:46 misti lircd[6996]: lircd-0.10.1[6996]: Warning: Running as root Apr 12 21:39:46 misti lircd[6996]: lircd-0.10.1[6996]: Info: Using remote: /etc/lirc/lircd-custom.conf. Apr 12 21:39:46 misti lircd[6996]: lircd-0.10.1[6996]: Notice: lircd(default) ready, using /var/run/lirc/lircd Apr 12 21:39:46 misti lircd[6996]: lircd-0.10.1[6996]: Notice: accepted new client on /var/run/lirc/lircd Apr 12 21:39:46 misti lircd[6996]: lircd-0.10.1[6996]: Info: [lirc] protocol is enabled Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Options: output: /var/run/lirc/lircd Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Options: nodaemon: 1 Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Options: plugindir: /usr/lib/arm-linux-gnueabihf/lirc/plugins Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Options: logfile: syslog Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Options: immediate-init: 0 Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Options: permission: 666 Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Options: driver-options: Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Options: pidfile: /var/run/lirc/lircd.pid Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Options: listen: 0 Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Options: connect: (null) Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Options: userelease: 0 Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Options: effective_user: (null) Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Options: release_suffix: _EVUP Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Options: allow_simulate: 0 Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Options: repeat_max: 600 Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Options: configfile: /etc/lirc/lircd.conf Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Options: dynamic_codes: (null) Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Current driver: default Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Driver API version: 3 Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Driver version: 0.10.0 Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Driver info: See file:///usr/share/doc/lirc/plugindocs/default.html Apr 12 21:39:46 misti lircd-0.10.1[6996]: Info: lircd: Opening log, level: Info Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: Using systemd fd Apr 12 21:39:46 misti lircd-0.10.1[6996]: Warning: Running as root Apr 12 21:39:46 misti lircd-0.10.1[6996]: Info: Using remote: /etc/lirc/lircd-custom.conf. Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: lircd(default) ready, using /var/run/lirc/lircd Apr 12 21:39:46 misti lircd-0.10.1[6996]: Notice: accepted new client on /var/run/lirc/lircd Apr 12 21:39:46 misti lircd-0.10.1[6996]: Info: [lirc] protocol is enabled Apr 12 21:39:46 misti sudo[6986]: pam_unix(sudo:session): session closed for user root Apr 12 21:39:46 misti volumio[974]: info: ir_controller: systemctl restart lircd.service succeeded. Apr 12 21:39:47 misti sudo[7000]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart irexec.service Apr 12 21:39:47 misti sudo[7000]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 21:39:47 misti lircd-0.10.1[6996]: Info: removed client Apr 12 21:39:47 misti lircd[6996]: lircd-0.10.1[6996]: Info: removed client Apr 12 21:39:47 misti systemd[1]: Stopping Handle events from IR remotes decoded by lircd(8)... Apr 12 21:39:47 misti systemd[1]: irexec.service: Main process exited, code=killed, status=15/TERM Apr 12 21:39:47 misti systemd[1]: irexec.service: Succeeded. Apr 12 21:39:47 misti systemd[1]: Stopped Handle events from IR remotes decoded by lircd(8). Apr 12 21:39:47 misti systemd[1]: Started Handle events from IR remotes decoded by lircd(8). Apr 12 21:39:47 misti lircd[6996]: lircd-0.10.1[6996]: Notice: accepted new client on /var/run/lirc/lircd Apr 12 21:39:47 misti lircd[6996]: lircd-0.10.1[6996]: Info: [lirc] protocol is enabled Apr 12 21:39:47 misti lircd-0.10.1[6996]: Notice: accepted new client on /var/run/lirc/lircd Apr 12 21:39:47 misti lircd-0.10.1[6996]: Info: [lirc] protocol is enabled Apr 12 21:39:47 misti sudo[7000]: pam_unix(sudo:session): session closed for user root Apr 12 21:39:47 misti volumio[974]: info: ir_controller: systemctl restart irexec.service succeeded. Apr 12 21:39:48 misti volumio[974]: info: Enabling plugin rotaryencoder2 Apr 12 21:39:48 misti volumio[974]: info: Loading plugin "rotaryencoder2"... Apr 12 21:39:48 misti volumio[974]: info: PLUGIN START: rotaryencoder2 Apr 12 21:39:48 misti volumio[974]: info: Done. Apr 12 21:39:48 misti volumio[974]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Apr 12 21:39:48 misti volumio[974]: info: CoreCommandRouter::volumioGetState Apr 12 21:39:48 misti volumio[974]: info: CorePlayQueue::getTrack 3 Apr 12 21:39:48 misti volumio[974]: info: Disabling plugin rotaryencoder2 Apr 12 21:39:48 misti volumio[974]: info: Done. Apr 12 21:39:49 misti volumio[974]: info: AutoStart - Plugin is starting Apr 12 21:39:49 misti volumio[974]: info: CoreCommandRouter::volumioGetQueue Apr 12 21:39:49 misti volumio[974]: info: CoreStateMachine::getQueue Apr 12 21:39:49 misti volumio[974]: info: CorePlayQueue::getQueue Apr 12 21:39:49 misti volumio[974]: info: AutoStart - start playing Apr 12 21:39:49 misti volumio[974]: info: AutoStart - start playing with no specific position Apr 12 21:39:49 misti volumio[974]: info: CoreCommandRouter::volumioPlay Apr 12 21:39:49 misti volumio[974]: info: CoreStateMachine::play index 0 Apr 12 21:39:49 misti volumio[974]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 12 21:39:50 misti volumio[974]: info: CoreStateMachine::stop Apr 12 21:39:50 misti volumio[974]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 12 21:39:50 misti volumio[974]: info: CoreStateMachine::updateTrackBlock Apr 12 21:39:50 misti volumio[974]: info: CorePlayQueue::getTrackBlock Apr 12 21:39:50 misti volumio[974]: info: CoreStateMachine::stPlaybackTimer Apr 12 21:39:50 misti volumio[974]: info: CoreStateMachine::pushState Apr 12 21:39:50 misti volumio[974]: info: CorePlayQueue::getTrack 3 Apr 12 21:39:50 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 12 21:39:50 misti volumio[974]: info: CoreCommandRouter::volumioPushState Apr 12 21:39:50 misti volumio[974]: info: CoreStateMachine::serviceStop Apr 12 21:39:50 misti volumio[974]: info: CorePlayQueue::getTrack 3 Apr 12 21:39:50 misti volumio[974]: info: CoreCommandRouter::serviceStop Apr 12 21:39:50 misti volumio[974]: info: ControllerMpd::stop Apr 12 21:39:50 misti volumio[974]: verbose: ControllerMpd::sendMpdCommand stop Apr 12 21:39:50 misti volumio[974]: info: [ASDebug] CurState: stop PrevState: pause Apr 12 21:39:50 misti volumio[974]: info: [GPIO_Control] Status changed: stop Apr 12 21:39:50 misti volumio[974]: info: [GPIO_Control] Handling event: musicStop Apr 12 21:39:50 misti volumio[974]: info: sendMpdCommand stop took 28 milliseconds Apr 12 21:39:50 misti volumio[974]: info: CoreStateMachine::play index undefined Apr 12 21:39:50 misti volumio[974]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 12 21:39:50 misti volumio[974]: info: CorePlayQueue::getTrack 0 Apr 12 21:39:50 misti volumio[974]: info: CoreStateMachine::startPlaybackTimer Apr 12 21:39:50 misti volumio[974]: info: CorePlayQueue::getTrack 0 Apr 12 21:39:50 misti volumio[974]: verbose: ControllerMpd::clearAddPlayTracks USB/AHERIYA/MUSIC/Abhimaan - Aandhi - Anand/01 Tere Mere Milan Ki Yeh Raina.wav Apr 12 21:39:50 misti volumio[974]: verbose: ControllerMpd::sendMpdCommand stop Apr 12 21:39:50 misti volumio[974]: info: sendMpdCommand stop took 1 milliseconds Apr 12 21:39:50 misti volumio[974]: verbose: ControllerMpd::sendMpdCommand clear Apr 12 21:39:50 misti volumio[974]: info: Apr 12 21:39:50 misti volumio[974]: ---------------------------- MPD announces system playlist update Apr 12 21:39:50 misti volumio[974]: info: Ignoring MPD Status Update Apr 12 21:39:50 misti volumio[974]: info: sendMpdCommand clear took 2 milliseconds Apr 12 21:39:50 misti volumio[974]: verbose: ControllerMpd::sendMpdCommand add "USB/AHERIYA/MUSIC/Abhimaan - Aandhi - Anand/01 Tere Mere Milan Ki Yeh Raina.wav" Apr 12 21:39:50 misti volumio[974]: error: updateQueue error: null Apr 12 21:39:50 misti volumio[974]: info: Apr 12 21:39:50 misti volumio[974]: ---------------------------- MPD announces system playlist update Apr 12 21:39:50 misti volumio[974]: info: Ignoring MPD Status Update Apr 12 21:39:50 misti volumio[974]: info: ------------------------------ 7ms Apr 12 21:39:50 misti volumio[974]: info: sendMpdCommand add "USB/AHERIYA/MUSIC/Abhimaan - Aandhi - Anand/01 Tere Mere Milan Ki Yeh Raina.wav" took 4 milliseconds Apr 12 21:39:50 misti volumio[974]: verbose: ControllerMpd::sendMpdCommand play Apr 12 21:39:50 misti volumio[974]: info: ------------------------------ 4ms Apr 12 21:39:50 misti volumio[974]: info: sendMpdCommand play took 3 milliseconds Apr 12 21:39:50 misti volumio[974]: info: Apr 12 21:39:50 misti volumio[974]: ---------------------------- MPD announces state update: player Apr 12 21:39:50 misti volumio[974]: info: ControllerMpd::getState Apr 12 21:39:50 misti volumio[974]: verbose: ControllerMpd::sendMpdCommand status Apr 12 21:39:50 misti volumio[974]: info: sendMpdCommand status took 2 milliseconds Apr 12 21:39:50 misti volumio[974]: verbose: ControllerMpd::parseState Apr 12 21:39:50 misti volumio[974]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 12 21:39:50 misti volumio[974]: info: Apr 12 21:39:50 misti volumio[974]: ---------------------------- MPD announces state update: player Apr 12 21:39:50 misti volumio[974]: info: ControllerMpd::getState Apr 12 21:39:50 misti volumio[974]: verbose: ControllerMpd::sendMpdCommand status Apr 12 21:39:50 misti volumio[974]: info: sendMpdCommand playlistinfo took 3 milliseconds Apr 12 21:39:50 misti volumio[974]: verbose: ControllerMpd::parseTrackInfo Apr 12 21:39:50 misti volumio[974]: info: ControllerMpd::pushState Apr 12 21:39:50 misti volumio[974]: info: CoreCommandRouter::servicePushState Apr 12 21:39:50 misti volumio[974]: info: CorePlayQueue::getTrack 0 Apr 12 21:39:50 misti volumio[974]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":295,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Tere Mere Milan Ki Yeh Raina","artist":"Kishore Kumar & Lata Mangeshkar","album":"Abhimaan - Aandhi - Anand","uri":"USB/AHERIYA/MUSIC/Abhimaan - Aandhi - Anand/01 Tere Mere Milan Ki Yeh Raina.wav","trackType":"wav"} Apr 12 21:39:50 misti volumio[974]: verbose: CURRENT POSITION 0 Apr 12 21:39:50 misti volumio[974]: info: CoreStateMachine::syncState stateService play Apr 12 21:39:50 misti volumio[974]: info: CoreStateMachine::syncState currentStatus stop Apr 12 21:39:50 misti volumio[974]: info: ------------------------------ 17ms Apr 12 21:39:50 misti volumio[974]: info: sendMpdCommand status took 9 milliseconds Apr 12 21:39:50 misti volumio[974]: verbose: ControllerMpd::parseState Apr 12 21:39:50 misti volumio[974]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 12 21:39:50 misti volumio[974]: info: sendMpdCommand playlistinfo took 1 milliseconds Apr 12 21:39:50 misti volumio[974]: verbose: ControllerMpd::parseTrackInfo Apr 12 21:39:50 misti volumio[974]: info: ControllerMpd::pushState Apr 12 21:39:50 misti volumio[974]: info: CoreCommandRouter::servicePushState Apr 12 21:39:50 misti volumio[974]: info: CorePlayQueue::getTrack 0 Apr 12 21:39:50 misti volumio[974]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":295,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Tere Mere Milan Ki Yeh Raina","artist":"Kishore Kumar & Lata Mangeshkar","album":"Abhimaan - Aandhi - Anand","uri":"USB/AHERIYA/MUSIC/Abhimaan - Aandhi - Anand/01 Tere Mere Milan Ki Yeh Raina.wav","trackType":"wav"} Apr 12 21:39:50 misti volumio[974]: verbose: CURRENT POSITION 0 Apr 12 21:39:50 misti volumio[974]: info: CoreStateMachine::syncState stateService play Apr 12 21:39:50 misti volumio[974]: info: CoreStateMachine::syncState currentStatus play Apr 12 21:39:50 misti volumio[974]: info: Received an update from plugin. extracting info from payload Apr 12 21:39:50 misti volumio[974]: info: CoreStateMachine::pushState Apr 12 21:39:50 misti volumio[974]: info: CorePlayQueue::getTrack 0 Apr 12 21:39:50 misti volumio[974]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 12 21:39:50 misti volumio[974]: info: CoreCommandRouter::volumioPushState Apr 12 21:39:50 misti volumio[974]: info: CoreStateMachine::pushState Apr 12 21:39:50 misti volumio[974]: info: CorePlayQueue::getTrack 0 Apr 12 21:39:50 misti volumio[974]: info: CoreCommandRouter::volumioPushState Apr 12 21:39:50 misti volumio[974]: info: ------------------------------ 44ms Apr 12 21:39:50 misti volumio[974]: info: [ASDebug] CurState: play PrevState: pause Apr 12 21:39:50 misti volumio[974]: info: [ASDebug] Togle GPIO: ON Apr 12 21:39:50 misti volumio[974]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 12 21:39:50 misti volumio[974]: Error: ESPIPE: invalid seek, write Apr 12 21:39:50 misti volumio[974]: at Object.writeSync (fs.js:711:3) Apr 12 21:39:50 misti volumio[974]: at Gpio.writeSync (/data/plugins/system_controller/ampswitch/node_modules/onoff/onoff.js:243:8) Apr 12 21:39:50 misti volumio[974]: at AmpSwitchController.on (/data/plugins/system_controller/ampswitch/index.js:207:23) Apr 12 21:39:50 misti volumio[974]: at AmpSwitchController.parseStatus (/data/plugins/system_controller/ampswitch/index.js:190:86) Apr 12 21:39:50 misti volumio[974]: at Socket.Emitter.emit (/data/plugins/system_controller/ampswitch/node_modules/component-emitter/index.js:145:20) Apr 12 21:39:50 misti volumio[974]: at Socket.onevent (/data/plugins/system_controller/ampswitch/node_modules/socket.io-client/lib/socket.js:278:10) Apr 12 21:39:50 misti volumio[974]: at Socket.onpacket (/data/plugins/system_controller/ampswitch/node_modules/socket.io-client/lib/socket.js:236:12) Apr 12 21:39:50 misti volumio[974]: at Manager. (/data/plugins/system_controller/ampswitch/node_modules/component-bind/index.js:21:15) Apr 12 21:39:50 misti volumio[974]: at Manager.Emitter.emit (/data/plugins/system_controller/ampswitch/node_modules/component-emitter/index.js:145:20) Apr 12 21:39:50 misti volumio[974]: at Manager.ondecoded (/data/plugins/system_controller/ampswitch/node_modules/socket.io-client/lib/manager.js:349:8) Apr 12 21:39:50 misti volumio[974]: at Decoder. (/data/plugins/system_controller/ampswitch/node_modules/component-bind/index.js:21:15) Apr 12 21:39:50 misti volumio[974]: at Decoder.Emitter.emit (/data/plugins/system_controller/ampswitch/node_modules/component-emitter/index.js:145:20) Apr 12 21:39:50 misti volumio[974]: at Decoder.add (/data/plugins/system_controller/ampswitch/node_modules/socket.io-parser/index.js:254:12) Apr 12 21:39:50 misti volumio[974]: at Manager.ondata (/data/plugins/system_controller/ampswitch/node_modules/socket.io-client/lib/manager.js:339:16) Apr 12 21:39:50 misti volumio[974]: at Socket. (/data/plugins/system_controller/ampswitch/node_modules/component-bind/index.js:21:15) Apr 12 21:39:50 misti volumio[974]: at Socket.Emitter.emit (/data/plugins/system_controller/ampswitch/node_modules/component-emitter/index.js:145:20) { Apr 12 21:39:50 misti volumio[974]: errno: -29, Apr 12 21:39:50 misti volumio[974]: syscall: 'write', Apr 12 21:39:50 misti volumio[974]: code: 'ESPIPE' Apr 12 21:39:50 misti volumio[974]: } Apr 12 21:39:50 misti volumio[974]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 12 21:39:51 misti sudo[7022]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-04-12 21:38 Apr 12 21:39:51 misti sudo[7022]: 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="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="e32c2c71ae78852844c70357816bdd871c155ab8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 31 Mar 2025 06:54:47 PM CEST" VOLUMIO_VERSION="3.799" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="436f3f84f6d0b4ffc344f0bc132a32e8"