-- Logs begin at Thu 2019-02-14 11:11:58 CET, end at Sat 2025-01-11 18:04:27 CET. -- Jan 11 18:03:03 volumiobetel wpa_supplicant[1090]: RRM: Ignoring radio measurement request: Not RRM network Jan 11 18:03:06 volumiobetel volumio[1197]: Searching all installed plugins Jan 11 18:03:06 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 18:03:06 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: , search Jan 11 18:03:06 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: mpd , search Jan 11 18:03:06 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , search Jan 11 18:03:06 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Jan 11 18:03:06 volumiobetel volumio[1197]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Jan 11 18:03:06 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: webradio , search Jan 11 18:03:06 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: mixcloud , search Jan 11 18:03:06 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: soundcloud , search Jan 11 18:03:06 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: youtube2 , search Jan 11 18:03:06 volumiobetel volumio[1197]: info: [youtube2] InnertubeLoader: creating Innertube instance... Jan 11 18:03:06 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: ytmusic , search Jan 11 18:03:06 volumiobetel volumio[1197]: info: [ytmusic] InnertubeLoader: creating Innertube instance... Jan 11 18:03:06 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: 80s80s , search Jan 11 18:03:06 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: motherearthradio , search Jan 11 18:03:06 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: personal_radio , search Jan 11 18:03:06 volumiobetel volumio[1197]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin personal_radio Jan 11 18:03:06 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: radio_paradise , search Jan 11 18:03:07 volumiobetel volumio[1197]: (node:1197) UnhandledPromiseRejectionWarning: Error: Start tag expected, '<' not found Jan 11 18:03:07 volumiobetel volumio[1197]: at Object.module.exports.fromXml (/volumio/node_modules/libxmljs/lib/document.js:168:21) Jan 11 18:03:07 volumiobetel volumio[1197]: at /volumio/app/plugins/music_service/webradio/index.js:949:31 Jan 11 18:03:07 volumiobetel volumio[1197]: at runMicrotasks () Jan 11 18:03:07 volumiobetel volumio[1197]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Jan 11 18:03:07 volumiobetel volumio[1197]: (node:1197) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 1) Jan 11 18:03:07 volumiobetel volumio[1197]: (node:1197) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code. Jan 11 18:03:07 volumiobetel volumio[1197]: [YOUTUBEJS][Player]: Failed to extract signature decipher algorithm. Jan 11 18:03:09 volumiobetel volumio[1197]: info: [ytmusic] InnertubeLoader: creating Auth instance... Jan 11 18:03:09 volumiobetel volumio[1197]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 11 18:03:09 volumiobetel volumio[1197]: Searching all installed plugins Jan 11 18:03:09 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 18:03:09 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: , search Jan 11 18:03:09 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: mpd , search Jan 11 18:03:09 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , search Jan 11 18:03:09 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Jan 11 18:03:09 volumiobetel volumio[1197]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Jan 11 18:03:09 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: webradio , search Jan 11 18:03:09 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: mixcloud , search Jan 11 18:03:09 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: soundcloud , search Jan 11 18:03:09 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: youtube2 , search Jan 11 18:03:09 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: ytmusic , search Jan 11 18:03:09 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: 80s80s , search Jan 11 18:03:09 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: motherearthradio , search Jan 11 18:03:09 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: personal_radio , search Jan 11 18:03:09 volumiobetel volumio[1197]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin personal_radio Jan 11 18:03:09 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: radio_paradise , search Jan 11 18:03:09 volumiobetel volumio[1197]: [YOUTUBEJS][Player]: Failed to extract signature decipher algorithm. Jan 11 18:03:10 volumiobetel volumio[1197]: info: [youtube2] InnertubeLoader: creating Auth instance... Jan 11 18:03:10 volumiobetel volumio[1197]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 11 18:03:10 volumiobetel volumio[1197]: Searching all installed plugins Jan 11 18:03:10 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 18:03:10 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: , search Jan 11 18:03:10 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: mpd , search Jan 11 18:03:10 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , search Jan 11 18:03:10 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Jan 11 18:03:10 volumiobetel volumio[1197]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Jan 11 18:03:10 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: webradio , search Jan 11 18:03:10 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: mixcloud , search Jan 11 18:03:10 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: soundcloud , search Jan 11 18:03:10 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: youtube2 , search Jan 11 18:03:10 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: ytmusic , search Jan 11 18:03:10 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: 80s80s , search Jan 11 18:03:10 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: motherearthradio , search Jan 11 18:03:10 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: personal_radio , search Jan 11 18:03:10 volumiobetel volumio[1197]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin personal_radio Jan 11 18:03:10 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: radio_paradise , search Jan 11 18:03:11 volumiobetel volumio[1197]: (node:1197) UnhandledPromiseRejectionWarning: Error: Start tag expected, '<' not found Jan 11 18:03:11 volumiobetel volumio[1197]: at Object.module.exports.fromXml (/volumio/node_modules/libxmljs/lib/document.js:168:21) Jan 11 18:03:11 volumiobetel volumio[1197]: at /volumio/app/plugins/music_service/webradio/index.js:949:31 Jan 11 18:03:11 volumiobetel volumio[1197]: at runMicrotasks () Jan 11 18:03:11 volumiobetel volumio[1197]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Jan 11 18:03:11 volumiobetel volumio[1197]: (node:1197) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 2) Jan 11 18:03:11 volumiobetel volumio[1197]: info: CoreCommandRouter::volumioGetState Jan 11 18:03:11 volumiobetel volumio[1197]: info: CorePlayQueue::getTrack 0 Jan 11 18:03:11 volumiobetel volumio[1197]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 11 18:03:11 volumiobetel volumio[1197]: info: [ytmusic] InnertubeLoader: Auth instance created (status: pending sign-in) Jan 11 18:03:11 volumiobetel volumio[1197]: SearchHeader not found! Jan 11 18:03:11 volumiobetel volumio[1197]: This is a bug, want to help us fix it? Follow the instructions at https://github.com/patrickkfkan/Volumio-YouTube.js/blob/main/docs/updating-the-parser.md or report it at https://github.com/patrickkfkan/Volumio-YouTube.js/issues! Jan 11 18:03:11 volumiobetel volumio[1197]: Introspected and JIT generated this class in the meantime: Jan 11 18:03:11 volumiobetel volumio[1197]: class SearchHeader extends YTNode { Jan 11 18:03:11 volumiobetel volumio[1197]: static type = 'SearchHeader'; Jan 11 18:03:11 volumiobetel volumio[1197]: search_filter_button: YTNodes.Button | null; Jan 11 18:03:11 volumiobetel volumio[1197]: about_these_results_button: YTNodes.Button | null; Jan 11 18:03:11 volumiobetel volumio[1197]: constructor(data: RawNode) { Jan 11 18:03:11 volumiobetel volumio[1197]: super(); Jan 11 18:03:11 volumiobetel volumio[1197]: this.search_filter_button = Parser.parseItem(data.searchFilterButton, [ YTNodes.Button ]); Jan 11 18:03:11 volumiobetel volumio[1197]: this.about_these_results_button = Parser.parseItem(data.aboutTheseResultsButton, [ YTNodes.Button ]); Jan 11 18:03:11 volumiobetel volumio[1197]: } Jan 11 18:03:11 volumiobetel volumio[1197]: } Jan 11 18:03:11 volumiobetel volumio[1197]: error: Search in plugin webradio timed out Jan 11 18:03:11 volumiobetel volumio[1197]: error: Search in plugin soundcloud timed out Jan 11 18:03:11 volumiobetel volumio[1197]: error: Search in plugin youtube2 timed out Jan 11 18:03:11 volumiobetel volumio[1197]: error: Search in plugin ytmusic timed out Jan 11 18:03:11 volumiobetel volumio[1197]: info: All search sources collected, pushing search results Jan 11 18:03:11 volumiobetel volumio[1197]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 11 18:03:11 volumiobetel volumio[1197]: info: [youtube2] InnertubeLoader: Auth instance created (status: pending sign-in) Jan 11 18:03:12 volumiobetel volumio[1197]: error: Failed search in plugin ytmusic: Error: Unable to resolve or reject the same promise twice Jan 11 18:03:12 volumiobetel wpa_supplicant[1090]: RRM: Ignoring radio measurement request: Not RRM network Jan 11 18:03:12 volumiobetel volumio[1197]: error: Failed search in plugin youtube2: Error: Unable to resolve or reject the same promise twice Jan 11 18:03:12 volumiobetel volumio[1197]: ShortsLockupView not found! Jan 11 18:03:12 volumiobetel volumio[1197]: This is a bug, want to help us fix it? Follow the instructions at https://github.com/patrickkfkan/Volumio-YouTube.js/blob/main/docs/updating-the-parser.md or report it at https://github.com/patrickkfkan/Volumio-YouTube.js/issues! Jan 11 18:03:12 volumiobetel volumio[1197]: Introspected and JIT generated this class in the meantime: Jan 11 18:03:12 volumiobetel volumio[1197]: class ShortsLockupView extends YTNode { Jan 11 18:03:12 volumiobetel volumio[1197]: static type = 'ShortsLockupView'; Jan 11 18:03:12 volumiobetel volumio[1197]: entity_id: string; Jan 11 18:03:12 volumiobetel volumio[1197]: accessibility_text: string; Jan 11 18:03:12 volumiobetel volumio[1197]: thumbnail: { Jan 11 18:03:12 volumiobetel volumio[1197]: sources: { Jan 11 18:03:12 volumiobetel volumio[1197]: 0: { Jan 11 18:03:12 volumiobetel volumio[1197]: url: string, Jan 11 18:03:12 volumiobetel volumio[1197]: width: number, Jan 11 18:03:12 volumiobetel volumio[1197]: height: number Jan 11 18:03:12 volumiobetel volumio[1197]: } Jan 11 18:03:12 volumiobetel volumio[1197]: } Jan 11 18:03:12 volumiobetel volumio[1197]: }; Jan 11 18:03:12 volumiobetel volumio[1197]: on_tap: { Jan 11 18:03:12 volumiobetel volumio[1197]: innertube_command: NavigationEndpoint Jan 11 18:03:12 volumiobetel volumio[1197]: }; Jan 11 18:03:12 volumiobetel volumio[1197]: inline_player_data: { Jan 11 18:03:12 volumiobetel volumio[1197]: on_visible: { Jan 11 18:03:12 volumiobetel volumio[1197]: innertube_command: NavigationEndpoint Jan 11 18:03:12 volumiobetel volumio[1197]: } Jan 11 18:03:12 volumiobetel volumio[1197]: }; Jan 11 18:03:12 volumiobetel volumio[1197]: menu_on_tap: { Jan 11 18:03:12 volumiobetel volumio[1197]: innertube_command: NavigationEndpoint Jan 11 18:03:12 volumiobetel volumio[1197]: }; Jan 11 18:03:12 volumiobetel volumio[1197]: index_in_collection: number; Jan 11 18:03:12 volumiobetel volumio[1197]: menu_on_tap_a11y_label: string; Jan 11 18:03:12 volumiobetel volumio[1197]: overlay_metadata: { Jan 11 18:03:12 volumiobetel volumio[1197]: primary_text: { Jan 11 18:03:12 volumiobetel volumio[1197]: content: string Jan 11 18:03:12 volumiobetel volumio[1197]: }, Jan 11 18:03:12 volumiobetel volumio[1197]: secondary_text: { Jan 11 18:03:12 volumiobetel volumio[1197]: content: string Jan 11 18:03:12 volumiobetel volumio[1197]: } Jan 11 18:03:12 volumiobetel volumio[1197]: }; Jan 11 18:03:12 volumiobetel volumio[1197]: logging_directives: { Jan 11 18:03:12 volumiobetel volumio[1197]: tracking_params: string, Jan 11 18:03:12 volumiobetel volumio[1197]: visibility: { Jan 11 18:03:12 volumiobetel volumio[1197]: types: string Jan 11 18:03:12 volumiobetel volumio[1197]: } Jan 11 18:03:12 volumiobetel volumio[1197]: }; Jan 11 18:03:12 volumiobetel volumio[1197]: constructor(data: RawNode) { Jan 11 18:03:12 volumiobetel volumio[1197]: super(); Jan 11 18:03:12 volumiobetel volumio[1197]: this.entity_id = data.entityId; Jan 11 18:03:12 volumiobetel volumio[1197]: this.accessibility_text = data.accessibilityText; Jan 11 18:03:12 volumiobetel volumio[1197]: this.thumbnail = { Jan 11 18:03:12 volumiobetel volumio[1197]: sources: { Jan 11 18:03:12 volumiobetel volumio[1197]: 0: { Jan 11 18:03:12 volumiobetel volumio[1197]: url: data.thumbnail.sources.0.url, Jan 11 18:03:12 volumiobetel volumio[1197]: width: data.thumbnail.sources.0.width, Jan 11 18:03:12 volumiobetel volumio[1197]: height: data.thumbnail.sources.0.height Jan 11 18:03:12 volumiobetel volumio[1197]: } Jan 11 18:03:12 volumiobetel volumio[1197]: } Jan 11 18:03:12 volumiobetel volumio[1197]: }; Jan 11 18:03:12 volumiobetel volumio[1197]: this.on_tap = { Jan 11 18:03:12 volumiobetel volumio[1197]: innertube_command: new NavigationEndpoint(data.onTap.innertubeCommand) Jan 11 18:03:12 volumiobetel volumio[1197]: }; Jan 11 18:03:12 volumiobetel volumio[1197]: this.inline_player_data = { Jan 11 18:03:12 volumiobetel volumio[1197]: on_visible: { Jan 11 18:03:12 volumiobetel volumio[1197]: innertube_command: new NavigationEndpoint(data.inlinePlayerData.onVisible.innertubeCommand) Jan 11 18:03:12 volumiobetel volumio[1197]: } Jan 11 18:03:12 volumiobetel volumio[1197]: }; Jan 11 18:03:12 volumiobetel volumio[1197]: this.menu_on_tap = { Jan 11 18:03:12 volumiobetel volumio[1197]: innertube_command: new NavigationEndpoint(data.menuOnTap.innertubeCommand) Jan 11 18:03:12 volumiobetel volumio[1197]: }; Jan 11 18:03:12 volumiobetel volumio[1197]: this.index_in_collection = data.indexInCollection; Jan 11 18:03:12 volumiobetel volumio[1197]: this.menu_on_tap_a11y_label = data.menuOnTapA11yLabel; Jan 11 18:03:12 volumiobetel volumio[1197]: this.overlay_metadata = { Jan 11 18:03:12 volumiobetel volumio[1197]: primary_text: { Jan 11 18:03:12 volumiobetel volumio[1197]: content: data.overlayMetadata.primaryText.content Jan 11 18:03:12 volumiobetel volumio[1197]: }, Jan 11 18:03:12 volumiobetel volumio[1197]: secondary_text: { Jan 11 18:03:12 volumiobetel volumio[1197]: content: data.overlayMetadata.secondaryText.content Jan 11 18:03:12 volumiobetel volumio[1197]: } Jan 11 18:03:12 volumiobetel volumio[1197]: }; Jan 11 18:03:12 volumiobetel volumio[1197]: this.logging_directives = { Jan 11 18:03:12 volumiobetel volumio[1197]: tracking_params: data.loggingDirectives.trackingParams, Jan 11 18:03:12 volumiobetel volumio[1197]: visibility: { Jan 11 18:03:12 volumiobetel volumio[1197]: types: data.loggingDirectives.visibility.types Jan 11 18:03:12 volumiobetel volumio[1197]: } Jan 11 18:03:12 volumiobetel volumio[1197]: }; Jan 11 18:03:12 volumiobetel volumio[1197]: } Jan 11 18:03:12 volumiobetel volumio[1197]: } Jan 11 18:03:12 volumiobetel volumio[1197]: SearchHeader changed! Jan 11 18:03:12 volumiobetel volumio[1197]: The following keys where altered: chip_bar Jan 11 18:03:12 volumiobetel volumio[1197]: The class has changed to: Jan 11 18:03:12 volumiobetel volumio[1197]: class SearchHeader extends YTNode { Jan 11 18:03:12 volumiobetel volumio[1197]: static type = 'SearchHeader'; Jan 11 18:03:12 volumiobetel volumio[1197]: search_filter_button: YTNodes.Button | null; Jan 11 18:03:12 volumiobetel volumio[1197]: about_these_results_button: YTNodes.Button | null; Jan 11 18:03:12 volumiobetel volumio[1197]: chip_bar?: YTNodes.ChipCloud | null; Jan 11 18:03:12 volumiobetel volumio[1197]: constructor(data: RawNode) { Jan 11 18:03:12 volumiobetel volumio[1197]: super(); Jan 11 18:03:12 volumiobetel volumio[1197]: this.search_filter_button = Parser.parseItem(data.searchFilterButton, [ YTNodes.Button ]); Jan 11 18:03:12 volumiobetel volumio[1197]: this.about_these_results_button = Parser.parseItem(data.aboutTheseResultsButton, [ YTNodes.Button ]); Jan 11 18:03:12 volumiobetel volumio[1197]: this.chip_bar = Reflect.has(data, 'chipBar') ? Parser.parseItem(data.chipBar, [ YTNodes.ChipCloud ]) : undefined; Jan 11 18:03:12 volumiobetel volumio[1197]: } Jan 11 18:03:12 volumiobetel volumio[1197]: } Jan 11 18:03:14 volumiobetel volumio[1197]: error: Failed search in plugin soundcloud: Error: Unable to resolve or reject the same promise twice Jan 11 18:03:14 volumiobetel volumio[1197]: error: Search in plugin soundcloud timed out Jan 11 18:03:14 volumiobetel volumio[1197]: info: All search sources collected, pushing search results Jan 11 18:03:15 volumiobetel volumio[1197]: error: Failed search in plugin soundcloud: Error: Unable to resolve or reject the same promise twice Jan 11 18:03:15 volumiobetel volumio[1197]: error: Search in plugin webradio timed out Jan 11 18:03:15 volumiobetel volumio[1197]: info: All search sources collected, pushing search results Jan 11 18:03:18 volumiobetel wpa_supplicant[1090]: RRM: Ignoring radio measurement request: Not RRM network Jan 11 18:03:27 volumiobetel wpa_supplicant[1090]: RRM: Ignoring radio measurement request: Not RRM network Jan 11 18:03:33 volumiobetel wpa_supplicant[1090]: RRM: Ignoring radio measurement request: Not RRM network Jan 11 18:03:41 volumiobetel wpa_supplicant[1090]: RRM: Ignoring radio measurement request: Not RRM network Jan 11 18:03:48 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:48+01:00" level=debug msg="handling transfer player command from 8c2bba9032d020aaba1a431993d5db3020a8b02c" Jan 11 18:03:48 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:48+01:00" level=debug msg="renewing login5 access token" Jan 11 18:03:49 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:49+01:00" level=debug msg="authenticated as 31kry3352hjmzm66gqd23keoygga" Jan 11 18:03:49 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 11 18:03:49 volumiobetel volumio[1197]: info: Received Get System Info Jan 11 18:03:49 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 11 18:03:49 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 11 18:03:49 volumiobetel volumio[1197]: info: Discovery: Getting this device information Jan 11 18:03:49 volumiobetel volumio[1197]: info: CoreCommandRouter::volumioGetState Jan 11 18:03:49 volumiobetel volumio[1197]: info: CorePlayQueue::getTrack 0 Jan 11 18:03:49 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 11 18:03:49 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:49+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:6FIOAVw5U6eM48JVEA5sqD" Jan 11 18:03:49 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:49+01:00" level=trace msg="fetched new page 0 with 41 items (list: 41)" uri="spotify:playlist:6FIOAVw5U6eM48JVEA5sqD" Jan 11 18:03:49 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:49+01:00" level=debug msg="loading track (paused: true, position: 218902ms)" uri="spotify:track:4T1oZ3UAFKbraSp5JAISWW" Jan 11 18:03:49 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:49+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 11 18:03:49 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:49+01:00" level=trace msg="emitting websocket event: will_play" Jan 11 18:03:49 volumiobetel volumio[1197]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4T1oZ3UAFKbraSp5JAISWW","play_origin":"playlist"}} Jan 11 18:03:49 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:49+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Jan 11 18:03:49 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:49+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1395" Jan 11 18:03:49 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:49+01:00" level=debug msg="selected format OGG_VORBIS_320 (bf9f927f8273759aa9df1973d2cdd6fc0b9ac5db)" uri="spotify:track:4T1oZ3UAFKbraSp5JAISWW" Jan 11 18:03:49 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:49+01:00" level=debug msg="requested aes key for file bf9f927f8273759aa9df1973d2cdd6fc0b9ac5db, gid: 4T1oZ3UAFKbraSp5JAISWW" Jan 11 18:03:49 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:49+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1146" Jan 11 18:03:50 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:50+01:00" level=debug msg="fetched first chunk of 21, total size is 10701660 bytes" uri="spotify:track:4T1oZ3UAFKbraSp5JAISWW" Jan 11 18:03:50 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:50+01:00" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:4T1oZ3UAFKbraSp5JAISWW" Jan 11 18:03:50 volumiobetel wpa_supplicant[1090]: RRM: Ignoring radio measurement request: Not RRM network Jan 11 18:03:51 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:51+01:00" level=debug msg="fetched chunk 20/20, size: 215900" uri="spotify:track:4T1oZ3UAFKbraSp5JAISWW" Jan 11 18:03:51 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:51+01:00" level=debug msg="fetched chunk 17/20, size: 524288" uri="spotify:track:4T1oZ3UAFKbraSp5JAISWW" Jan 11 18:03:51 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:51+01:00" level=debug msg="fetched chunk 18/20, size: 524288" uri="spotify:track:4T1oZ3UAFKbraSp5JAISWW" Jan 11 18:03:51 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:51+01:00" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:4T1oZ3UAFKbraSp5JAISWW" Jan 11 18:03:51 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:51+01:00" level=trace msg="seek to 218902ms (diff: 59ms, samples: 9653578, bytes: 8914784)" uri="spotify:track:4T1oZ3UAFKbraSp5JAISWW" Jan 11 18:03:51 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:51+01:00" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed setting stream for spotify:track:4T1oZ3UAFKbraSp5JAISWW: ALSA error at snd_pcm_open: Device or resource busy" Jan 11 18:03:51 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:51+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jan 11 18:03:51 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:51+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jan 11 18:03:51 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:51+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jan 11 18:03:51 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:51+01:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:4T1oZ3UAFKbraSp5JAISWW" Jan 11 18:03:51 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:51+01:00" level=debug msg="fetched chunk 19/20, size: 524288" uri="spotify:track:4T1oZ3UAFKbraSp5JAISWW" Jan 11 18:03:54 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:54+01:00" level=debug msg="handling resume player command from 8c2bba9032d020aaba1a431993d5db3020a8b02c" Jan 11 18:03:54 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:54+01:00" level=debug msg="resume track at 0ms" Jan 11 18:03:54 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:54+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 11 18:03:54 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:54+01:00" level=trace msg="scheduling prefetch in 235s" Jan 11 18:03:54 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:54+01:00" level=debug msg="sending successful reply for dealer request" Jan 11 18:03:54 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:54+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 11 18:03:54 volumiobetel go-librespot[1651]: time="2025-01-11T18:03:54+01:00" level=trace msg="emitting websocket event: playing" Jan 11 18:03:54 volumiobetel volumio[1197]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4T1oZ3UAFKbraSp5JAISWW","play_origin":"playlist"}} Jan 11 18:03:54 volumiobetel volumio[1197]: info: Spotify is playing in volatile mode Jan 11 18:03:54 volumiobetel volumio[1197]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 11 18:03:54 volumiobetel volumio[1197]: SPOTIFY: UNSET VOLATILE Jan 11 18:03:54 volumiobetel volumio[1197]: SPOTIFY: {"status":"play","position":0,"title":"Rufus and Chaka Khan - Ain't Nobody","artist":"80s80s Real 80s Radio","album":"","albumart":"https://is4-ssl.mzstatic.com/image/thumb/Music114/v4/d8/fa/88/d8fa8867-a677-177a-3f6b-78065860deea/source/600x600bb.jpg","uri":"http://streams.80s80s.de/web/mp3-192/volumio","trackType":"80s80s Radio","seek":0,"duration":"244","samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":true,"repeatSingle":false,"consume":false,"volume":94,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"80s80s Radio","volatile":false,"service":"80s80s"} Jan 11 18:03:54 volumiobetel volumio[1197]: info: Setting Spotify stop after unset volatile call Jan 11 18:03:54 volumiobetel volumio[1197]: SPOTIFY: PUSH STATE SPOTIFY Jan 11 18:03:54 volumiobetel volumio[1197]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 11 18:03:54 volumiobetel volumio[1197]: info: CoreCommandRouter::servicePushState Jan 11 18:03:54 volumiobetel volumio[1197]: info: CoreStateMachine::pushState Jan 11 18:03:54 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 18:03:54 volumiobetel volumio[1197]: info: CoreCommandRouter::volumioPushState Jan 11 18:03:54 volumiobetel volumio[1197]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Jan 11 18:03:54 volumiobetel volumio[1197]: SPOTIFY: PUSH STATE SPOTIFY Jan 11 18:03:54 volumiobetel volumio[1197]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jan 11 18:03:54 volumiobetel volumio[1197]: info: CoreCommandRouter::servicePushState Jan 11 18:03:54 volumiobetel volumio[1197]: info: CoreStateMachine::pushState Jan 11 18:03:54 volumiobetel volumio[1197]: info: CoreCommandRouter::volumioPushState Jan 11 18:03:54 volumiobetel volumio[1197]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Jan 11 18:03:54 volumiobetel volumio[1197]: info: Spotify Stop Jan 11 18:03:54 volumiobetel volumio[1197]: SPOTIFY: SPOTIFY STOP Jan 11 18:03:54 volumiobetel volumio[1197]: SPOTIFY: {"status":"play","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","codec":"ogg","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":94,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true,"service":"spop"} Jan 11 18:03:57 volumiobetel wpa_supplicant[1090]: RRM: Ignoring radio measurement request: Not RRM network Jan 11 18:04:04 volumiobetel wpa_supplicant[1090]: RRM: Ignoring radio measurement request: Not RRM network Jan 11 18:04:06 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:06+01:00" level=debug msg="handling pause player command from 8c2bba9032d020aaba1a431993d5db3020a8b02c" Jan 11 18:04:06 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:06+01:00" level=debug msg="pause track at 0ms" Jan 11 18:04:06 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:06+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 11 18:04:06 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:06+01:00" level=debug msg="sending successful reply for dealer request" Jan 11 18:04:06 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:06+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 11 18:04:06 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:06+01:00" level=trace msg="emitting websocket event: paused" Jan 11 18:04:06 volumiobetel volumio[1197]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:4T1oZ3UAFKbraSp5JAISWW","play_origin":"playlist"}} Jan 11 18:04:06 volumiobetel volumio[1197]: SPOTIFY: PUSH STATE SPOTIFY Jan 11 18:04:06 volumiobetel volumio[1197]: SPOTIFY: {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":11000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jan 11 18:04:06 volumiobetel volumio[1197]: info: CoreCommandRouter::servicePushState Jan 11 18:04:06 volumiobetel volumio[1197]: info: CoreStateMachine::pushState Jan 11 18:04:06 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 18:04:06 volumiobetel volumio[1197]: info: CoreCommandRouter::volumioPushState Jan 11 18:04:06 volumiobetel volumio[1197]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Jan 11 18:04:06 volumiobetel volumio[1197]: info: touch_display: Setting screensaver timeout to 3600 seconds. Jan 11 18:04:07 volumiobetel volumio[1197]: info: CoreCommandRouter::volumioVolatilePlay Jan 11 18:04:07 volumiobetel volumio[1197]: info: CoreStateMachine::volatilePlay Jan 11 18:04:07 volumiobetel volumio[1197]: info: Spotify Play Jan 11 18:04:07 volumiobetel volumio[1197]: info: Sending Spotify command to local API: /player/resume Jan 11 18:04:07 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:07+01:00" level=debug msg="resume track at 0ms" Jan 11 18:04:07 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:07+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 11 18:04:07 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:07+01:00" level=trace msg="scheduling prefetch in 235s" Jan 11 18:04:07 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:07+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 11 18:04:07 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:07+01:00" level=trace msg="emitting websocket event: playing" Jan 11 18:04:07 volumiobetel volumio[1197]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4T1oZ3UAFKbraSp5JAISWW","play_origin":"playlist"}} Jan 11 18:04:07 volumiobetel volumio[1197]: SPOTIFY: PUSH STATE SPOTIFY Jan 11 18:04:07 volumiobetel volumio[1197]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":11000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jan 11 18:04:07 volumiobetel volumio[1197]: info: CoreCommandRouter::servicePushState Jan 11 18:04:07 volumiobetel volumio[1197]: info: CoreStateMachine::pushState Jan 11 18:04:07 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 18:04:07 volumiobetel volumio[1197]: info: CoreCommandRouter::volumioPushState Jan 11 18:04:07 volumiobetel volumio[1197]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Jan 11 18:04:07 volumiobetel volumio[1197]: info: touch_display: Setting screensaver timeout to 0 seconds. Jan 11 18:04:07 volumiobetel volumio[1197]: SPOTIFY: PUSH STATE SPOTIFY Jan 11 18:04:07 volumiobetel volumio[1197]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":11000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jan 11 18:04:07 volumiobetel volumio[1197]: info: CoreCommandRouter::servicePushState Jan 11 18:04:07 volumiobetel volumio[1197]: info: CoreStateMachine::pushState Jan 11 18:04:07 volumiobetel volumio[1197]: info: CoreCommandRouter::volumioPushState Jan 11 18:04:07 volumiobetel volumio[1197]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Jan 11 18:04:08 volumiobetel volumio[1197]: info: CoreCommandRouter::volumioPause Jan 11 18:04:08 volumiobetel volumio[1197]: info: CoreStateMachine::pause Jan 11 18:04:08 volumiobetel volumio[1197]: info: CoreStateMachine::stPlaybackTimer Jan 11 18:04:08 volumiobetel volumio[1197]: info: CoreStateMachine::servicePause Jan 11 18:04:08 volumiobetel volumio[1197]: info: CoreCommandRouter::servicePause Jan 11 18:04:08 volumiobetel volumio[1197]: info: Spotify Received pause Jan 11 18:04:08 volumiobetel volumio[1197]: SPOTIFY: SPOTIFY PAUSE Jan 11 18:04:08 volumiobetel volumio[1197]: SPOTIFY: {"status":"play","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","codec":"ogg","seek":11000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":94,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true,"service":"spop"} Jan 11 18:04:08 volumiobetel volumio[1197]: info: Sending Spotify command to local API: /player/pause Jan 11 18:04:08 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:08+01:00" level=debug msg="pause track at 0ms" Jan 11 18:04:08 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:08+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 11 18:04:08 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:08+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 11 18:04:08 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:08+01:00" level=trace msg="emitting websocket event: paused" Jan 11 18:04:08 volumiobetel volumio[1197]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:4T1oZ3UAFKbraSp5JAISWW","play_origin":"playlist"}} Jan 11 18:04:08 volumiobetel volumio[1197]: SPOTIFY: PUSH STATE SPOTIFY Jan 11 18:04:08 volumiobetel volumio[1197]: SPOTIFY: {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":12000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jan 11 18:04:08 volumiobetel volumio[1197]: info: CoreCommandRouter::servicePushState Jan 11 18:04:08 volumiobetel volumio[1197]: info: CoreStateMachine::pushState Jan 11 18:04:08 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 18:04:08 volumiobetel volumio[1197]: info: CoreCommandRouter::volumioPushState Jan 11 18:04:08 volumiobetel volumio[1197]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Jan 11 18:04:08 volumiobetel volumio[1197]: info: touch_display: Setting screensaver timeout to 3600 seconds. Jan 11 18:04:13 volumiobetel wpa_supplicant[1090]: RRM: Ignoring radio measurement request: Not RRM network Jan 11 18:04:14 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:14+01:00" level=debug msg="handling resume player command from 8c2bba9032d020aaba1a431993d5db3020a8b02c" Jan 11 18:04:14 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:14+01:00" level=debug msg="resume track at 0ms" Jan 11 18:04:14 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:14+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 11 18:04:14 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:14+01:00" level=trace msg="scheduling prefetch in 235s" Jan 11 18:04:14 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:14+01:00" level=debug msg="sending successful reply for dealer request" Jan 11 18:04:14 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:14+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 11 18:04:14 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:14+01:00" level=trace msg="emitting websocket event: playing" Jan 11 18:04:14 volumiobetel volumio[1197]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4T1oZ3UAFKbraSp5JAISWW","play_origin":"playlist"}} Jan 11 18:04:14 volumiobetel volumio[1197]: SPOTIFY: PUSH STATE SPOTIFY Jan 11 18:04:14 volumiobetel volumio[1197]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":12000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jan 11 18:04:14 volumiobetel volumio[1197]: info: CoreCommandRouter::servicePushState Jan 11 18:04:14 volumiobetel volumio[1197]: info: CoreStateMachine::pushState Jan 11 18:04:14 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 18:04:14 volumiobetel volumio[1197]: info: CoreCommandRouter::volumioPushState Jan 11 18:04:14 volumiobetel volumio[1197]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Jan 11 18:04:14 volumiobetel volumio[1197]: info: touch_display: Setting screensaver timeout to 0 seconds. Jan 11 18:04:14 volumiobetel volumio[1197]: SPOTIFY: PUSH STATE SPOTIFY Jan 11 18:04:14 volumiobetel volumio[1197]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":12000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jan 11 18:04:14 volumiobetel volumio[1197]: info: CoreCommandRouter::servicePushState Jan 11 18:04:14 volumiobetel volumio[1197]: info: CoreStateMachine::pushState Jan 11 18:04:14 volumiobetel volumio[1197]: info: CoreCommandRouter::volumioPushState Jan 11 18:04:14 volumiobetel volumio[1197]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Jan 11 18:04:15 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:15+01:00" level=debug msg="handling pause player command from 8c2bba9032d020aaba1a431993d5db3020a8b02c" Jan 11 18:04:15 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:15+01:00" level=debug msg="pause track at 0ms" Jan 11 18:04:15 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:15+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 11 18:04:15 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:15+01:00" level=debug msg="sending successful reply for dealer request" Jan 11 18:04:15 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:15+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 11 18:04:15 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:15+01:00" level=trace msg="emitting websocket event: paused" Jan 11 18:04:15 volumiobetel volumio[1197]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:4T1oZ3UAFKbraSp5JAISWW","play_origin":"playlist"}} Jan 11 18:04:15 volumiobetel volumio[1197]: SPOTIFY: PUSH STATE SPOTIFY Jan 11 18:04:15 volumiobetel volumio[1197]: SPOTIFY: {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":12000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jan 11 18:04:15 volumiobetel volumio[1197]: info: CoreCommandRouter::servicePushState Jan 11 18:04:15 volumiobetel volumio[1197]: info: CoreStateMachine::pushState Jan 11 18:04:15 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 18:04:15 volumiobetel volumio[1197]: info: CoreCommandRouter::volumioPushState Jan 11 18:04:15 volumiobetel volumio[1197]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Jan 11 18:04:15 volumiobetel volumio[1197]: info: touch_display: Setting screensaver timeout to 3600 seconds. Jan 11 18:04:21 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:21+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 344" Jan 11 18:04:21 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:21+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1461" Jan 11 18:04:21 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:21+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jan 11 18:04:21 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:21+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jan 11 18:04:21 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:21+01:00" level=debug msg="put connect state inactive" Jan 11 18:04:21 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:21+01:00" level=trace msg="emitting websocket event: inactive" Jan 11 18:04:21 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:21+01:00" level=trace msg="emitting websocket event: stopped" Jan 11 18:04:21 volumiobetel volumio[1197]: SPOTIFY: received: {"type":"inactive","data":null} Jan 11 18:04:21 volumiobetel volumio[1197]: error: Failed to decode event: inactive Jan 11 18:04:21 volumiobetel volumio[1197]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":""}} Jan 11 18:04:21 volumiobetel volumio[1197]: SPOTIFY: PUSH STATE SPOTIFY Jan 11 18:04:21 volumiobetel volumio[1197]: SPOTIFY: {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":12000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jan 11 18:04:21 volumiobetel volumio[1197]: info: CoreCommandRouter::servicePushState Jan 11 18:04:21 volumiobetel volumio[1197]: info: CoreStateMachine::pushState Jan 11 18:04:21 volumiobetel volumio[1197]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 18:04:21 volumiobetel volumio[1197]: info: CoreCommandRouter::volumioPushState Jan 11 18:04:21 volumiobetel volumio[1197]: info: CorePlayQueue::getTrack 0 Jan 11 18:04:21 volumiobetel volumio[1197]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received spop Jan 11 18:04:21 volumiobetel volumio[1197]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Jan 11 18:04:21 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:21+01:00" level=error msg="failed receiving dealer message" error="failed to get reader: received close frame: status = StatusGoingAway and reason = \"\"" Jan 11 18:04:21 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:21+01:00" level=error msg="failed receiving packet" error="failed reading packet header: read tcp 192.168.1.104:53032->34.158.1.133:4070: use of closed network connection" Jan 11 18:04:21 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:21+01:00" level=debug msg="obtained new client token: AAApcX7/eRfAsG4UFtVLUpD63Fbr20P21Xf91fI4sH+nDYgj4+8+mgpu5u12HMt0kPYTMrqAz55sxRPaSXx9fw+xXzbAwwtGRz3SmPOrXaGYsnaXdttJQOVd1cUJ/rXwifHwBLrYlI42E6BzAGfJQQw2qRMxSQCUiVJ8uanIlRGyYROm/1czxii/9HsV9Q+MfjMoHcz698IBttLSq7ziUAYC+Q1ktghcAUKcXp/F6nqgXO665n13vwF3lmA=" Jan 11 18:04:21 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:21+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 11 18:04:21 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:21+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 11 18:04:21 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:21+01:00" level=debug msg="completed keyexchange" Jan 11 18:04:22 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:22+01:00" level=debug msg="completed challenge" Jan 11 18:04:22 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:22+01:00" level=debug msg="authenticated as 31kry3352hjmzm66gqd23keoygga" Jan 11 18:04:22 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:22+01:00" level=debug msg="authenticated as 31kry3352hjmzm66gqd23keoygga" Jan 11 18:04:22 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:22+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 11 18:04:22 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:22+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 11 18:04:22 volumiobetel wpa_supplicant[1090]: RRM: Ignoring radio measurement request: Not RRM network Jan 11 18:04:22 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:22+01:00" level=debug msg="dealer connection opened" Jan 11 18:04:22 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:22+01:00" level=debug msg="restored session after logout, username: 31kry3352hjmzm66gqd23keoygga" Jan 11 18:04:22 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:22+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jan 11 18:04:22 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:22+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jan 11 18:04:22 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:22+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jan 11 18:04:22 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:22+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jan 11 18:04:22 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:22+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jan 11 18:04:22 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:22+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 344" Jan 11 18:04:22 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:22+01:00" level=debug msg="autoplay enabled: false" Jan 11 18:04:22 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:22+01:00" level=debug msg="received connection id: N2RhMjc5MWItZjgyMS00NjY2LWEyN2UtN2RmZTEzYjIyNDViK2RlYWxlcit0Y3A6Ly8wYWNhNTlkMS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArQkVGQzYyNERCMkU5RTYwNDA1MzU0OEY4N0U0QzFENzIzNjFBNTEzRUI5OTg2MDdGNDIyQUJCQkZBQjgyQzhGMw==" Jan 11 18:04:23 volumiobetel go-librespot[1651]: time="2025-01-11T18:04:23+01:00" level=debug msg="put connect state because NEW_DEVICE" Jan 11 18:04:27 volumiobetel volumio[1197]: info: [1736615067329] [80s80s] Pushing the next song state Michael Jackson - The Way You Make Me Feel and getting next track. Jan 11 18:04:27 volumiobetel volumio[1197]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 18:04:27 volumiobetel volumio[1197]: TypeError: Cannot set property 'name' of undefined Jan 11 18:04:27 volumiobetel volumio[1197]: at Controller80s80s.pushSongState (/data/plugins/music_service/80s80s/index.js:565:20) Jan 11 18:04:27 volumiobetel volumio[1197]: at Controller80s80s.playNextTrack (/data/plugins/music_service/80s80s/index.js:665:34) Jan 11 18:04:27 volumiobetel volumio[1197]: at NanoTimer.setTimeout (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:343:9) Jan 11 18:04:27 volumiobetel volumio[1197]: at Immediate. (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:327:66) Jan 11 18:04:27 volumiobetel volumio[1197]: at processImmediate (internal/timers.js:461:21) Jan 11 18:04:27 volumiobetel volumio[1197]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 18:04:27 volumiobetel sudo[26479]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-01-11 18:03 Jan 11 18:04:27 volumiobetel sudo[26479]: 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="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 06:51:56 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="b9009e0280f50389e80a537357ff3961"