-- Logs begin at Thu 2019-02-14 19:11:58 JST, end at Sat 2024-10-26 20:10:11 JST. -- Oct 26 20:09:11 primo go-librespot[3927]: time="2024-10-26T20:09:11+09:00" level=debug msg="fetched chunk 17/22, size: 524288" Oct 26 20:09:16 primo go-librespot[3927]: time="2024-10-26T20:09:16+09:00" level=debug msg="handling skip_next player command from 9aa6a4e8aae481cc1cf21e78104903bd44b4b93b" Oct 26 20:09:16 primo go-librespot[3927]: time="2024-10-26T20:09:16+09:00" level=debug msg="skip next track" Oct 26 20:09:16 primo go-librespot[3927]: time="2024-10-26T20:09:16+09:00" level=debug msg="loading track spotify:track:6tO2KkT2EDjDuI9m32mrkU (paused: false, position: 95ms)" Oct 26 20:09:16 primo kernel: asoc-aml-card auge_sound: tdm playback stop Oct 26 20:09:16 primo kernel: spdif_a is set to disable Oct 26 20:09:16 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Oct 26 20:09:16 primo kernel: aml_dai_tdm_hw_free(), disable mclk for TDM-B Oct 26 20:09:16 primo kernel: tdm playback mute: 1, lane_cnt = 8 Oct 26 20:09:16 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Oct 26 20:09:16 primo go-librespot[3927]: time="2024-10-26T20:09:16+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 20:09:16 primo go-librespot[3927]: time="2024-10-26T20:09:16+09:00" level=trace msg="emitting websocket event: will_play" Oct 26 20:09:16 primo volumio[3376]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6tO2KkT2EDjDuI9m32mrkU","play_origin":"playlist/ondemand"}} Oct 26 20:09:16 primo go-librespot[3927]: time="2024-10-26T20:09:16+09:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:6tO2KkT2EDjDuI9m32mrkU" Oct 26 20:09:16 primo go-librespot[3927]: time="2024-10-26T20:09:16+09:00" level=debug msg="requested aes key for file 4b606055c2894f86c690b0fec6123c7989f8f393, gid: 6tO2KkT2EDjDuI9m32mrkU" Oct 26 20:09:17 primo go-librespot[3927]: time="2024-10-26T20:09:17+09:00" level=debug msg="fetched first chunk of 13, total size is 6304592 bytes" Oct 26 20:09:17 primo go-librespot[3927]: time="2024-10-26T20:09:17+09:00" level=trace msg="seek to 95ms (diff: 95ms, samples: 4189, bytes: 0)" Oct 26 20:09:17 primo kernel: aml_tdm_open Oct 26 20:09:17 primo kernel: Not init audio effects Oct 26 20:09:17 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Oct 26 20:09:17 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Oct 26 20:09:17 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Oct 26 20:09:17 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Oct 26 20:09:17 primo kernel: asoc aml_dai_set_tdm_fmt, 0x4001, ffffffc03d268418, id(1), clksel(1) Oct 26 20:09:17 primo kernel: aml_dai_set_tdm_fmt(), fmt not change Oct 26 20:09:17 primo kernel: dump_pcm_setting(ffffffc03d268418) Oct 26 20:09:17 primo kernel: pcm_mode(1) Oct 26 20:09:17 primo kernel: sysclk(11289600) Oct 26 20:09:17 primo kernel: sysclk_bclk_ratio(4) Oct 26 20:09:17 primo kernel: bclk(2822400) Oct 26 20:09:17 primo kernel: bclk_lrclk_ratio(64) Oct 26 20:09:17 primo kernel: lrclk(44100) Oct 26 20:09:17 primo kernel: tx_mask(0x3) Oct 26 20:09:17 primo kernel: rx_mask(0x3) Oct 26 20:09:17 primo kernel: slots(2) Oct 26 20:09:17 primo kernel: slot_width(32) Oct 26 20:09:17 primo kernel: lane_mask_in(0x2) Oct 26 20:09:17 primo kernel: lane_mask_out(0x1) Oct 26 20:09:17 primo kernel: lane_oe_mask_in(0x0) Oct 26 20:09:17 primo kernel: lane_oe_mask_out(0x0) Oct 26 20:09:17 primo kernel: lane_lb_mask_in(0x0) Oct 26 20:09:17 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Oct 26 20:09:17 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Oct 26 20:09:17 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Oct 26 20:09:17 primo kernel: aml_dai_set_clkdiv, div 4, clksel(1) Oct 26 20:09:17 primo kernel: aml_dai_set_bclk_ratio, select I2S mode Oct 26 20:09:17 primo kernel: aml_dai_tdm_hw_params(), enable mclk for TDM-B Oct 26 20:09:17 primo kernel: aml_tdm_prepare(), reset fddr Oct 26 20:09:17 primo kernel: spdif_a fifo ctrl, frddr:0 type:3, 32 bits, chmask 0x3, swap 0x10 Oct 26 20:09:17 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Oct 26 20:09:17 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Oct 26 20:09:17 primo kernel: tdm playback mute: 0, lane_cnt = 8 Oct 26 20:09:17 primo go-librespot[3927]: time="2024-10-26T20:09:17+09:00" level=info msg="loaded track \"The Dapper Derp\" (uri: spotify:track:6tO2KkT2EDjDuI9m32mrkU, paused: false, position: 95ms, duration: 153280ms)" Oct 26 20:09:17 primo kernel: asoc-aml-card auge_sound: tdm playback enable Oct 26 20:09:17 primo kernel: spdif_a is set to enable Oct 26 20:09:17 primo go-librespot[3927]: time="2024-10-26T20:09:17+09:00" level=debug msg="fetched chunk 2/12, size: 524288" Oct 26 20:09:17 primo go-librespot[3927]: time="2024-10-26T20:09:17+09:00" level=debug msg="fetched chunk 1/12, size: 524288" Oct 26 20:09:17 primo go-librespot[3927]: time="2024-10-26T20:09:17+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 20:09:17 primo go-librespot[3927]: time="2024-10-26T20:09:17+09:00" level=trace msg="emitting websocket event: metadata" Oct 26 20:09:17 primo go-librespot[3927]: time="2024-10-26T20:09:17+09:00" level=debug msg="sending successful reply for delaer request" Oct 26 20:09:17 primo volumio[3376]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6tO2KkT2EDjDuI9m32mrkU","name":"The Dapper Derp","artist_names":["True Loves"],"album_name":"The Dapper Derp","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0283ce4d060320a75b99a978a4","position":95,"duration":153280,"release_date":"year:2020 month:1 day:3","track_number":1,"disc_number":1}} Oct 26 20:09:17 primo go-librespot[3927]: time="2024-10-26T20:09:17+09:00" level=debug msg="fetched chunk 3/12, size: 524288" Oct 26 20:09:17 primo go-librespot[3927]: time="2024-10-26T20:09:17+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 20:09:17 primo go-librespot[3927]: time="2024-10-26T20:09:17+09:00" level=trace msg="emitting websocket event: playing" Oct 26 20:09:17 primo volumio[3376]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6tO2KkT2EDjDuI9m32mrkU","play_origin":"playlist/ondemand"}} Oct 26 20:09:17 primo volumio[3376]: SPOTIFY: PUSH STATE SPOTIFY Oct 26 20:09:17 primo volumio[3376]: SPOTIFY: {"status":"play","service":"spop","title":"The Dapper Derp","artist":"True Loves","album":"The Dapper Derp","albumart":"https://i.scdn.co/image/ab67616d00001e0283ce4d060320a75b99a978a4","uri":"spotify:track:6tO2KkT2EDjDuI9m32mrkU","trackType":"spotify","seek":95,"duration":153,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":true,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 26 20:09:17 primo volumio[3376]: info: CoreCommandRouter::servicePushState Oct 26 20:09:17 primo volumio[3376]: info: CoreStateMachine::pushState Oct 26 20:09:17 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 20:09:17 primo volumio[3376]: info: CoreCommandRouter::volumioPushState Oct 26 20:09:17 primo volumio[3376]: info: Signalling Playback active due to playback status change Oct 26 20:09:17 primo volumio[3376]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 26 20:09:17 primo volumio[3376]: SPOTIFY: PUSH STATE SPOTIFY Oct 26 20:09:17 primo volumio[3376]: SPOTIFY: {"status":"play","service":"spop","title":"The Dapper Derp","artist":"True Loves","album":"The Dapper Derp","albumart":"https://i.scdn.co/image/ab67616d00001e0283ce4d060320a75b99a978a4","uri":"spotify:track:6tO2KkT2EDjDuI9m32mrkU","trackType":"spotify","seek":95,"duration":153,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":true,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 26 20:09:17 primo volumio[3376]: info: CoreCommandRouter::servicePushState Oct 26 20:09:17 primo volumio[3376]: info: CoreStateMachine::pushState Oct 26 20:09:17 primo volumio[3376]: info: CoreCommandRouter::volumioPushState Oct 26 20:09:17 primo volumio[3376]: info: Signalling Playback active due to playback status change Oct 26 20:09:17 primo volumio[3376]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 26 20:09:22 primo go-librespot[3927]: time="2024-10-26T20:09:22+09:00" level=debug msg="handling set_shuffling_context player command from 9aa6a4e8aae481cc1cf21e78104903bd44b4b93b" Oct 26 20:09:22 primo go-librespot[3927]: time="2024-10-26T20:09:22+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 20:09:22 primo go-librespot[3927]: time="2024-10-26T20:09:22+09:00" level=trace msg="emitting websocket event: shuffle_context" Oct 26 20:09:22 primo go-librespot[3927]: time="2024-10-26T20:09:22+09:00" level=debug msg="sending successful reply for delaer request" Oct 26 20:09:22 primo volumio[3376]: SPOTIFY: received: {"type":"shuffle_context","data":{"value":false}} Oct 26 20:09:22 primo volumio[3376]: SPOTIFY: PUSH STATE SPOTIFY Oct 26 20:09:22 primo volumio[3376]: SPOTIFY: {"status":"play","service":"spop","title":"The Dapper Derp","artist":"True Loves","album":"The Dapper Derp","albumart":"https://i.scdn.co/image/ab67616d00001e0283ce4d060320a75b99a978a4","uri":"spotify:track:6tO2KkT2EDjDuI9m32mrkU","trackType":"spotify","seek":5095,"duration":153,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":false,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 26 20:09:22 primo volumio[3376]: info: CoreCommandRouter::servicePushState Oct 26 20:09:22 primo volumio[3376]: info: CoreStateMachine::pushState Oct 26 20:09:22 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 20:09:22 primo volumio[3376]: info: CoreCommandRouter::volumioPushState Oct 26 20:09:22 primo volumio[3376]: info: Signalling Playback active due to playback status change Oct 26 20:09:22 primo volumio[3376]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 26 20:09:23 primo go-librespot[3927]: time="2024-10-26T20:09:23+09:00" level=debug msg="handling set_shuffling_context player command from 9aa6a4e8aae481cc1cf21e78104903bd44b4b93b" Oct 26 20:09:23 primo go-librespot[3927]: time="2024-10-26T20:09:23+09:00" level=debug msg="shuffled context with seed 4407233961789674426 (len: 50, keep: 20)" Oct 26 20:09:23 primo go-librespot[3927]: time="2024-10-26T20:09:23+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 20:09:23 primo go-librespot[3927]: time="2024-10-26T20:09:23+09:00" level=trace msg="emitting websocket event: shuffle_context" Oct 26 20:09:23 primo go-librespot[3927]: time="2024-10-26T20:09:23+09:00" level=debug msg="sending successful reply for delaer request" Oct 26 20:09:23 primo volumio[3376]: SPOTIFY: received: {"type":"shuffle_context","data":{"value":true}} Oct 26 20:09:23 primo volumio[3376]: SPOTIFY: PUSH STATE SPOTIFY Oct 26 20:09:23 primo volumio[3376]: SPOTIFY: {"status":"play","service":"spop","title":"The Dapper Derp","artist":"True Loves","album":"The Dapper Derp","albumart":"https://i.scdn.co/image/ab67616d00001e0283ce4d060320a75b99a978a4","uri":"spotify:track:6tO2KkT2EDjDuI9m32mrkU","trackType":"spotify","seek":6095,"duration":153,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":true,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 26 20:09:23 primo volumio[3376]: info: CoreCommandRouter::servicePushState Oct 26 20:09:23 primo volumio[3376]: info: CoreStateMachine::pushState Oct 26 20:09:23 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 20:09:23 primo volumio[3376]: info: CoreCommandRouter::volumioPushState Oct 26 20:09:23 primo volumio[3376]: info: Signalling Playback active due to playback status change Oct 26 20:09:23 primo volumio[3376]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 26 20:09:25 primo go-librespot[3927]: time="2024-10-26T20:09:25+09:00" level=debug msg="handling seek_to player command from 9aa6a4e8aae481cc1cf21e78104903bd44b4b93b" Oct 26 20:09:25 primo go-librespot[3927]: time="2024-10-26T20:09:25+09:00" level=debug msg="seek track to 0ms" Oct 26 20:09:25 primo go-librespot[3927]: time="2024-10-26T20:09:25+09:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" Oct 26 20:09:25 primo kernel: asoc-aml-card auge_sound: tdm playback stop Oct 26 20:09:25 primo kernel: spdif_a is set to disable Oct 26 20:09:25 primo kernel: aml_tdm_prepare(), reset fddr Oct 26 20:09:25 primo kernel: spdif_a fifo ctrl, frddr:0 type:3, 32 bits, chmask 0x3, swap 0x10 Oct 26 20:09:25 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Oct 26 20:09:25 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Oct 26 20:09:25 primo kernel: tdm playback mute: 0, lane_cnt = 8 Oct 26 20:09:25 primo kernel: asoc-aml-card auge_sound: tdm playback enable Oct 26 20:09:25 primo kernel: spdif_a is set to enable Oct 26 20:09:25 primo go-librespot[3927]: time="2024-10-26T20:09:25+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 20:09:25 primo go-librespot[3927]: time="2024-10-26T20:09:25+09:00" level=trace msg="emitting websocket event: seek" Oct 26 20:09:25 primo go-librespot[3927]: time="2024-10-26T20:09:25+09:00" level=debug msg="sending successful reply for delaer request" Oct 26 20:09:25 primo volumio[3376]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:6tO2KkT2EDjDuI9m32mrkU","position":0,"duration":153280,"play_origin":"playlist/ondemand"}} Oct 26 20:09:25 primo volumio[3376]: SPOTIFY: PUSH STATE SPOTIFY Oct 26 20:09:25 primo volumio[3376]: SPOTIFY: {"status":"play","service":"spop","title":"The Dapper Derp","artist":"True Loves","album":"The Dapper Derp","albumart":"https://i.scdn.co/image/ab67616d00001e0283ce4d060320a75b99a978a4","uri":"spotify:track:6tO2KkT2EDjDuI9m32mrkU","trackType":"spotify","seek":0,"duration":153,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":true,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 26 20:09:25 primo volumio[3376]: info: CoreCommandRouter::servicePushState Oct 26 20:09:25 primo volumio[3376]: info: CoreStateMachine::pushState Oct 26 20:09:25 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 20:09:25 primo volumio[3376]: info: CoreCommandRouter::volumioPushState Oct 26 20:09:25 primo volumio[3376]: info: Signalling Playback active due to playback status change Oct 26 20:09:25 primo volumio[3376]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 26 20:09:25 primo go-librespot[3927]: time="2024-10-26T20:09:25+09:00" level=debug msg="handling seek_to player command from 9aa6a4e8aae481cc1cf21e78104903bd44b4b93b" Oct 26 20:09:25 primo go-librespot[3927]: time="2024-10-26T20:09:25+09:00" level=debug msg="seek track to 0ms" Oct 26 20:09:25 primo go-librespot[3927]: time="2024-10-26T20:09:25+09:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" Oct 26 20:09:26 primo kernel: asoc-aml-card auge_sound: tdm playback stop Oct 26 20:09:26 primo kernel: spdif_a is set to disable Oct 26 20:09:26 primo kernel: aml_tdm_prepare(), reset fddr Oct 26 20:09:26 primo kernel: spdif_a fifo ctrl, frddr:0 type:3, 32 bits, chmask 0x3, swap 0x10 Oct 26 20:09:26 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Oct 26 20:09:26 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Oct 26 20:09:26 primo kernel: tdm playback mute: 0, lane_cnt = 8 Oct 26 20:09:26 primo kernel: asoc-aml-card auge_sound: tdm playback enable Oct 26 20:09:26 primo kernel: spdif_a is set to enable Oct 26 20:09:26 primo go-librespot[3927]: time="2024-10-26T20:09:26+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 20:09:26 primo go-librespot[3927]: time="2024-10-26T20:09:26+09:00" level=trace msg="emitting websocket event: seek" Oct 26 20:09:26 primo go-librespot[3927]: time="2024-10-26T20:09:26+09:00" level=debug msg="sending successful reply for delaer request" Oct 26 20:09:26 primo volumio[3376]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:6tO2KkT2EDjDuI9m32mrkU","position":0,"duration":153280,"play_origin":"playlist/ondemand"}} Oct 26 20:09:26 primo volumio[3376]: SPOTIFY: PUSH STATE SPOTIFY Oct 26 20:09:26 primo volumio[3376]: SPOTIFY: {"status":"play","service":"spop","title":"The Dapper Derp","artist":"True Loves","album":"The Dapper Derp","albumart":"https://i.scdn.co/image/ab67616d00001e0283ce4d060320a75b99a978a4","uri":"spotify:track:6tO2KkT2EDjDuI9m32mrkU","trackType":"spotify","seek":0,"duration":153,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":true,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 26 20:09:26 primo volumio[3376]: info: CoreCommandRouter::servicePushState Oct 26 20:09:26 primo volumio[3376]: info: CoreStateMachine::pushState Oct 26 20:09:26 primo volumio[3376]: info: CoreCommandRouter::volumioPushState Oct 26 20:09:26 primo volumio[3376]: info: Signalling Playback active due to playback status change Oct 26 20:09:26 primo volumio[3376]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 26 20:09:27 primo go-librespot[3927]: time="2024-10-26T20:09:27+09:00" level=debug msg="handling skip_next player command from 9aa6a4e8aae481cc1cf21e78104903bd44b4b93b" Oct 26 20:09:27 primo go-librespot[3927]: time="2024-10-26T20:09:27+09:00" level=debug msg="skip next track" Oct 26 20:09:27 primo go-librespot[3927]: time="2024-10-26T20:09:27+09:00" level=debug msg="loading track spotify:track:6a3Tg3l7s8uXQrLsSNJt4Y (paused: false, position: 89ms)" Oct 26 20:09:27 primo kernel: asoc-aml-card auge_sound: tdm playback stop Oct 26 20:09:27 primo kernel: spdif_a is set to disable Oct 26 20:09:27 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Oct 26 20:09:27 primo kernel: aml_dai_tdm_hw_free(), disable mclk for TDM-B Oct 26 20:09:27 primo kernel: tdm playback mute: 1, lane_cnt = 8 Oct 26 20:09:27 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Oct 26 20:09:27 primo go-librespot[3927]: time="2024-10-26T20:09:27+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 20:09:27 primo go-librespot[3927]: time="2024-10-26T20:09:27+09:00" level=trace msg="emitting websocket event: will_play" Oct 26 20:09:27 primo volumio[3376]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6a3Tg3l7s8uXQrLsSNJt4Y","play_origin":"playlist/ondemand"}} Oct 26 20:09:27 primo go-librespot[3927]: time="2024-10-26T20:09:27+09:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:6a3Tg3l7s8uXQrLsSNJt4Y" Oct 26 20:09:27 primo go-librespot[3927]: time="2024-10-26T20:09:27+09:00" level=debug msg="requested aes key for file feaa1804e0947ee151153e77663cadb9896ad614, gid: 6a3Tg3l7s8uXQrLsSNJt4Y" Oct 26 20:09:27 primo go-librespot[3927]: time="2024-10-26T20:09:27+09:00" level=debug msg="fetched first chunk of 14, total size is 7299156 bytes" Oct 26 20:09:27 primo go-librespot[3927]: time="2024-10-26T20:09:27+09:00" level=trace msg="seek to 89ms (diff: 89ms, samples: 3924, bytes: 0)" Oct 26 20:09:27 primo kernel: aml_tdm_open Oct 26 20:09:27 primo kernel: Not init audio effects Oct 26 20:09:27 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Oct 26 20:09:27 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Oct 26 20:09:27 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Oct 26 20:09:27 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Oct 26 20:09:27 primo kernel: asoc aml_dai_set_tdm_fmt, 0x4001, ffffffc03d268418, id(1), clksel(1) Oct 26 20:09:27 primo kernel: aml_dai_set_tdm_fmt(), fmt not change Oct 26 20:09:27 primo kernel: dump_pcm_setting(ffffffc03d268418) Oct 26 20:09:27 primo kernel: pcm_mode(1) Oct 26 20:09:27 primo kernel: sysclk(11289600) Oct 26 20:09:27 primo kernel: sysclk_bclk_ratio(4) Oct 26 20:09:27 primo kernel: bclk(2822400) Oct 26 20:09:27 primo kernel: bclk_lrclk_ratio(64) Oct 26 20:09:27 primo kernel: lrclk(44100) Oct 26 20:09:27 primo kernel: tx_mask(0x3) Oct 26 20:09:27 primo kernel: rx_mask(0x3) Oct 26 20:09:27 primo kernel: slots(2) Oct 26 20:09:27 primo kernel: slot_width(32) Oct 26 20:09:27 primo kernel: lane_mask_in(0x2) Oct 26 20:09:27 primo kernel: lane_mask_out(0x1) Oct 26 20:09:27 primo kernel: lane_oe_mask_in(0x0) Oct 26 20:09:27 primo kernel: lane_oe_mask_out(0x0) Oct 26 20:09:27 primo kernel: lane_lb_mask_in(0x0) Oct 26 20:09:27 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Oct 26 20:09:27 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Oct 26 20:09:27 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Oct 26 20:09:27 primo kernel: aml_dai_set_clkdiv, div 4, clksel(1) Oct 26 20:09:27 primo kernel: aml_dai_set_bclk_ratio, select I2S mode Oct 26 20:09:27 primo kernel: aml_dai_tdm_hw_params(), enable mclk for TDM-B Oct 26 20:09:27 primo kernel: aml_tdm_prepare(), reset fddr Oct 26 20:09:27 primo kernel: spdif_a fifo ctrl, frddr:0 type:3, 32 bits, chmask 0x3, swap 0x10 Oct 26 20:09:27 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Oct 26 20:09:27 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Oct 26 20:09:27 primo kernel: tdm playback mute: 0, lane_cnt = 8 Oct 26 20:09:27 primo go-librespot[3927]: time="2024-10-26T20:09:27+09:00" level=info msg="loaded track \"Tea Legs\" (uri: spotify:track:6a3Tg3l7s8uXQrLsSNJt4Y, paused: false, position: 89ms, duration: 162933ms)" Oct 26 20:09:28 primo kernel: asoc-aml-card auge_sound: tdm playback enable Oct 26 20:09:28 primo kernel: spdif_a is set to enable Oct 26 20:09:28 primo go-librespot[3927]: time="2024-10-26T20:09:28+09:00" level=debug msg="fetched chunk 3/13, size: 524288" Oct 26 20:09:28 primo go-librespot[3927]: time="2024-10-26T20:09:28+09:00" level=debug msg="fetched chunk 1/13, size: 524288" Oct 26 20:09:28 primo go-librespot[3927]: time="2024-10-26T20:09:28+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 20:09:28 primo go-librespot[3927]: time="2024-10-26T20:09:28+09:00" level=trace msg="emitting websocket event: metadata" Oct 26 20:09:28 primo volumio[3376]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6a3Tg3l7s8uXQrLsSNJt4Y","name":"Tea Legs","artist_names":["The Transatlantics"],"album_name":"The Transatlantics","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02a1ad383411e8ea83a6005b3c","position":89,"duration":162933,"release_date":"year:2010 month:7 day:30","track_number":1,"disc_number":1}} Oct 26 20:09:28 primo go-librespot[3927]: time="2024-10-26T20:09:28+09:00" level=debug msg="sending successful reply for delaer request" Oct 26 20:09:28 primo go-librespot[3927]: time="2024-10-26T20:09:28+09:00" level=debug msg="fetched chunk 2/13, size: 524288" Oct 26 20:09:28 primo go-librespot[3927]: time="2024-10-26T20:09:28+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 20:09:28 primo go-librespot[3927]: time="2024-10-26T20:09:28+09:00" level=trace msg="emitting websocket event: playing" Oct 26 20:09:28 primo volumio[3376]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6a3Tg3l7s8uXQrLsSNJt4Y","play_origin":"playlist/ondemand"}} Oct 26 20:09:28 primo volumio[3376]: SPOTIFY: PUSH STATE SPOTIFY Oct 26 20:09:28 primo volumio[3376]: SPOTIFY: {"status":"play","service":"spop","title":"Tea Legs","artist":"The Transatlantics","album":"The Transatlantics","albumart":"https://i.scdn.co/image/ab67616d00001e02a1ad383411e8ea83a6005b3c","uri":"spotify:track:6a3Tg3l7s8uXQrLsSNJt4Y","trackType":"spotify","seek":1089,"duration":162,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":true,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 26 20:09:28 primo volumio[3376]: info: CoreCommandRouter::servicePushState Oct 26 20:09:28 primo volumio[3376]: info: CoreStateMachine::pushState Oct 26 20:09:28 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 20:09:28 primo volumio[3376]: info: CoreCommandRouter::volumioPushState Oct 26 20:09:28 primo volumio[3376]: info: Signalling Playback active due to playback status change Oct 26 20:09:28 primo volumio[3376]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 26 20:09:28 primo volumio[3376]: SPOTIFY: PUSH STATE SPOTIFY Oct 26 20:09:28 primo volumio[3376]: SPOTIFY: {"status":"play","service":"spop","title":"Tea Legs","artist":"The Transatlantics","album":"The Transatlantics","albumart":"https://i.scdn.co/image/ab67616d00001e02a1ad383411e8ea83a6005b3c","uri":"spotify:track:6a3Tg3l7s8uXQrLsSNJt4Y","trackType":"spotify","seek":1089,"duration":162,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":true,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 26 20:09:28 primo volumio[3376]: info: CoreCommandRouter::servicePushState Oct 26 20:09:28 primo volumio[3376]: info: CoreStateMachine::pushState Oct 26 20:09:28 primo volumio[3376]: info: CoreCommandRouter::volumioPushState Oct 26 20:09:28 primo volumio[3376]: info: Signalling Playback active due to playback status change Oct 26 20:09:28 primo volumio[3376]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 26 20:09:38 primo go-librespot[3927]: time="2024-10-26T20:09:38+09:00" level=debug msg="fetched chunk 4/13, size: 524288" Oct 26 20:09:39 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 26 20:09:39 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 26 20:09:39 primo volumio[3376]: info: Discovery: Getting this device information Oct 26 20:09:39 primo volumio[3376]: info: CoreCommandRouter::volumioGetState Oct 26 20:09:39 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 26 20:09:39 primo volumio[3376]: verbose: New Socket.io Connection to 192.168.1.3:3000 from 192.168.1.2 UA: Dart/3.4 (dart:io) Engine version: 3 Transport: websocket Total Clients: 7 Oct 26 20:09:39 primo volumio[3376]: info: CoreCommandRouter::volumioGetState Oct 26 20:09:39 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 26 20:09:39 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 26 20:09:39 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 26 20:09:39 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 26 20:09:39 primo volumio[3376]: info: Discovery: Getting this device information Oct 26 20:09:39 primo volumio[3376]: info: CoreCommandRouter::volumioGetState Oct 26 20:09:39 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 26 20:09:39 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 26 20:09:39 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 26 20:09:39 primo volumio[3376]: info: Discovery: Getting this device information Oct 26 20:09:39 primo volumio[3376]: info: CoreCommandRouter::volumioGetState Oct 26 20:09:39 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 26 20:09:39 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 26 20:09:39 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 26 20:09:39 primo volumio[3376]: info: Discovery: Getting this device information Oct 26 20:09:39 primo volumio[3376]: info: CoreCommandRouter::volumioGetState Oct 26 20:09:39 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 26 20:09:42 primo sudo[4914]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 26 20:09:42 primo sudo[4914]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 20:09:42 primo sudo[4914]: pam_unix(sudo:session): session closed for user root Oct 26 20:09:42 primo sudo[4916]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 26 20:09:42 primo sudo[4916]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 20:09:42 primo sudo[4916]: pam_unix(sudo:session): session closed for user root Oct 26 20:09:42 primo volumio[3376]: verbose: New Socket.io Connection to 192.168.1.3 from 192.168.1.2 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 17_6_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 8 Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::volumioGetVisibleSources Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::volumioGetState Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 26 20:09:42 primo volumio[3376]: info: Received Get System Info Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 26 20:09:42 primo volumio[3376]: info: Discovery: Getting this device information Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::volumioGetState Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::volumioGetState Oct 26 20:09:42 primo volumio[3376]: info: Listing playlists Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 26 20:09:42 primo sudo[4922]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 26 20:09:42 primo sudo[4922]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 20:09:42 primo sudo[4922]: pam_unix(sudo:session): session closed for user root Oct 26 20:09:42 primo sudo[4924]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 26 20:09:42 primo sudo[4924]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 20:09:42 primo sudo[4924]: pam_unix(sudo:session): session closed for user root Oct 26 20:09:42 primo volumio[3376]: verbose: New Socket.io Connection to 192.168.1.3 from 192.168.1.2 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 17_6_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 8 Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::volumioGetVisibleSources Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::volumioGetState Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 26 20:09:42 primo volumio[3376]: info: Received Get System Info Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 26 20:09:42 primo volumio[3376]: info: Discovery: Getting this device information Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::volumioGetState Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 26 20:09:42 primo volumio[3376]: info: CoreCommandRouter::volumioGetState Oct 26 20:09:43 primo volumio[3376]: info: Listing playlists Oct 26 20:09:43 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 26 20:09:43 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 26 20:09:43 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 26 20:09:44 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Oct 26 20:09:44 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 26 20:09:44 primo volumio[3376]: info: Received Get System Info Oct 26 20:09:44 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 26 20:09:44 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 26 20:09:44 primo volumio[3376]: info: Discovery: Getting this device information Oct 26 20:09:44 primo volumio[3376]: info: CoreCommandRouter::volumioGetState Oct 26 20:09:44 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 26 20:09:44 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Oct 26 20:09:46 primo volumio[3376]: info: CoreCommandRouter::volumioGetQueue Oct 26 20:09:46 primo volumio[3376]: info: CoreStateMachine::getQueue Oct 26 20:09:46 primo volumio[3376]: info: CorePlayQueue::getQueue Oct 26 20:09:47 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 26 20:09:47 primo volumio[3376]: info: Received Get System Info Oct 26 20:09:47 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 26 20:09:47 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 26 20:09:47 primo volumio[3376]: info: Discovery: Getting this device information Oct 26 20:09:47 primo volumio[3376]: info: CoreCommandRouter::volumioGetState Oct 26 20:09:47 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 26 20:09:48 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 26 20:09:48 primo volumio[3376]: info: Received Get System Info Oct 26 20:09:48 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 26 20:09:48 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 26 20:09:48 primo volumio[3376]: info: Discovery: Getting this device information Oct 26 20:09:48 primo volumio[3376]: info: CoreCommandRouter::volumioGetState Oct 26 20:09:48 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 26 20:09:49 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 26 20:09:49 primo volumio[3376]: info: Received Get System Info Oct 26 20:09:49 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 26 20:09:49 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 26 20:09:49 primo volumio[3376]: info: Discovery: Getting this device information Oct 26 20:09:49 primo volumio[3376]: info: CoreCommandRouter::volumioGetState Oct 26 20:09:49 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 26 20:09:49 primo go-librespot[3927]: time="2024-10-26T20:09:49+09:00" level=debug msg="fetched chunk 5/13, size: 524288" Oct 26 20:09:52 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 26 20:09:54 primo volumio[3376]: info: CoreCommandRouter::volumioSeek Oct 26 20:09:54 primo volumio[3376]: info: CoreStateMachine::seek Oct 26 20:09:54 primo volumio[3376]: info: Spotify seek to: 76000 Oct 26 20:09:54 primo volumio[3376]: info: Sending Spotify command with payload to local API: /player/seek Oct 26 20:09:54 primo volumio[3376]: info: CoreStateMachine::startPlaybackTimer Oct 26 20:09:54 primo volumio[3376]: info: CorePlayQueue::getTrack 0 Oct 26 20:09:54 primo volumio[3376]: info: CoreStateMachine::pushState Oct 26 20:09:54 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 20:09:54 primo volumio[3376]: info: CoreCommandRouter::volumioPushState Oct 26 20:09:54 primo volumio[3376]: info: Signalling Playback active due to playback status change Oct 26 20:09:54 primo volumio[3376]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 26 20:09:54 primo go-librespot[3927]: time="2024-10-26T20:09:54+09:00" level=debug msg="seek track to 76000ms" Oct 26 20:09:54 primo go-librespot[3927]: time="2024-10-26T20:09:54+09:00" level=debug msg="fetched chunk 7/13, size: 524288" Oct 26 20:09:54 primo go-librespot[3927]: time="2024-10-26T20:09:54+09:00" level=debug msg="fetched chunk 8/13, size: 524288" Oct 26 20:09:54 primo go-librespot[3927]: time="2024-10-26T20:09:54+09:00" level=debug msg="fetched chunk 9/13, size: 524288" Oct 26 20:09:54 primo go-librespot[3927]: time="2024-10-26T20:09:54+09:00" level=debug msg="fetched chunk 6/13, size: 524288" Oct 26 20:09:54 primo go-librespot[3927]: time="2024-10-26T20:09:54+09:00" level=trace msg="seek to 76000ms (diff: 41ms, samples: 3351600, bytes: 3439489)" Oct 26 20:09:54 primo kernel: asoc-aml-card auge_sound: tdm playback stop Oct 26 20:09:54 primo kernel: spdif_a is set to disable Oct 26 20:09:54 primo kernel: aml_tdm_prepare(), reset fddr Oct 26 20:09:54 primo kernel: spdif_a fifo ctrl, frddr:0 type:3, 32 bits, chmask 0x3, swap 0x10 Oct 26 20:09:54 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Oct 26 20:09:54 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Oct 26 20:09:54 primo kernel: tdm playback mute: 0, lane_cnt = 8 Oct 26 20:09:54 primo kernel: asoc-aml-card auge_sound: tdm playback enable Oct 26 20:09:54 primo kernel: spdif_a is set to enable Oct 26 20:09:54 primo go-librespot[3927]: time="2024-10-26T20:09:54+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 20:09:54 primo go-librespot[3927]: time="2024-10-26T20:09:54+09:00" level=trace msg="emitting websocket event: seek" Oct 26 20:09:54 primo volumio[3376]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:6a3Tg3l7s8uXQrLsSNJt4Y","position":76000,"duration":162933,"play_origin":"playlist/ondemand"}} Oct 26 20:09:54 primo volumio[3376]: SPOTIFY: PUSH STATE SPOTIFY Oct 26 20:09:54 primo volumio[3376]: SPOTIFY: {"status":"play","service":"spop","title":"Tea Legs","artist":"The Transatlantics","album":"The Transatlantics","albumart":"https://i.scdn.co/image/ab67616d00001e02a1ad383411e8ea83a6005b3c","uri":"spotify:track:6a3Tg3l7s8uXQrLsSNJt4Y","trackType":"spotify","seek":76000,"duration":162,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":true,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 26 20:09:54 primo volumio[3376]: info: CoreCommandRouter::servicePushState Oct 26 20:09:54 primo volumio[3376]: info: CoreStateMachine::pushState Oct 26 20:09:54 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 20:09:54 primo volumio[3376]: info: CoreCommandRouter::volumioPushState Oct 26 20:09:54 primo volumio[3376]: info: Signalling Playback active due to playback status change Oct 26 20:09:54 primo volumio[3376]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 26 20:09:55 primo volumio[3376]: info: CoreCommandRouter::volumioSeek Oct 26 20:09:55 primo volumio[3376]: info: CoreStateMachine::seek Oct 26 20:09:55 primo volumio[3376]: info: Spotify seek to: 71000 Oct 26 20:09:55 primo volumio[3376]: info: Sending Spotify command with payload to local API: /player/seek Oct 26 20:09:55 primo volumio[3376]: info: CoreStateMachine::startPlaybackTimer Oct 26 20:09:55 primo volumio[3376]: info: CorePlayQueue::getTrack 0 Oct 26 20:09:55 primo volumio[3376]: info: CoreStateMachine::pushState Oct 26 20:09:55 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 20:09:55 primo volumio[3376]: info: CoreCommandRouter::volumioPushState Oct 26 20:09:55 primo volumio[3376]: info: Signalling Playback active due to playback status change Oct 26 20:09:55 primo volumio[3376]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 26 20:09:55 primo go-librespot[3927]: time="2024-10-26T20:09:55+09:00" level=debug msg="seek track to 71000ms" Oct 26 20:09:55 primo go-librespot[3927]: time="2024-10-26T20:09:55+09:00" level=trace msg="seek to 71000ms (diff: 72ms, samples: 3131100, bytes: 3238675)" Oct 26 20:09:55 primo kernel: asoc-aml-card auge_sound: tdm playback stop Oct 26 20:09:55 primo kernel: spdif_a is set to disable Oct 26 20:09:55 primo kernel: aml_tdm_prepare(), reset fddr Oct 26 20:09:55 primo kernel: spdif_a fifo ctrl, frddr:0 type:3, 32 bits, chmask 0x3, swap 0x10 Oct 26 20:09:55 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Oct 26 20:09:55 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Oct 26 20:09:55 primo kernel: tdm playback mute: 0, lane_cnt = 8 Oct 26 20:09:55 primo kernel: asoc-aml-card auge_sound: tdm playback enable Oct 26 20:09:55 primo kernel: spdif_a is set to enable Oct 26 20:09:55 primo go-librespot[3927]: time="2024-10-26T20:09:55+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 20:09:55 primo go-librespot[3927]: time="2024-10-26T20:09:55+09:00" level=trace msg="emitting websocket event: seek" Oct 26 20:09:55 primo volumio[3376]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:6a3Tg3l7s8uXQrLsSNJt4Y","position":71000,"duration":162933,"play_origin":"playlist/ondemand"}} Oct 26 20:09:55 primo volumio[3376]: SPOTIFY: PUSH STATE SPOTIFY Oct 26 20:09:55 primo volumio[3376]: SPOTIFY: {"status":"play","service":"spop","title":"Tea Legs","artist":"The Transatlantics","album":"The Transatlantics","albumart":"https://i.scdn.co/image/ab67616d00001e02a1ad383411e8ea83a6005b3c","uri":"spotify:track:6a3Tg3l7s8uXQrLsSNJt4Y","trackType":"spotify","seek":71000,"duration":162,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":true,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 26 20:09:55 primo volumio[3376]: info: CoreCommandRouter::servicePushState Oct 26 20:09:55 primo volumio[3376]: info: CoreStateMachine::pushState Oct 26 20:09:55 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 20:09:55 primo volumio[3376]: info: CoreCommandRouter::volumioPushState Oct 26 20:09:55 primo volumio[3376]: info: Signalling Playback active due to playback status change Oct 26 20:09:55 primo volumio[3376]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 26 20:10:02 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 26 20:10:02 primo volumio[3376]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Oct 26 20:10:02 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Oct 26 20:10:02 primo volumio[3376]: info: Received Get System Version Oct 26 20:10:02 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 20:10:02 primo volumio[3376]: info: Received Get System Info Oct 26 20:10:02 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 26 20:10:02 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 26 20:10:02 primo volumio[3376]: info: Discovery: Getting this device information Oct 26 20:10:02 primo volumio[3376]: info: CoreCommandRouter::volumioGetState Oct 26 20:10:02 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 26 20:10:04 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 26 20:10:04 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 26 20:10:04 primo volumio[3376]: info: Discovery: Getting this device information Oct 26 20:10:04 primo volumio[3376]: info: CoreCommandRouter::volumioGetState Oct 26 20:10:04 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 26 20:10:04 primo go-librespot[3927]: time="2024-10-26T20:10:04+09:00" level=debug msg="fetched chunk 10/13, size: 524288" Oct 26 20:10:11 primo volumio[3376]: info: CoreCommandRouter::executeOnPlugin: metavolumio , superSearch Oct 26 20:10:11 primo volumio[3376]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 26 20:10:11 primo volumio[3376]: TypeError: Cannot read property 'then' of undefined Oct 26 20:10:11 primo volumio[3376]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:498:20) Oct 26 20:10:11 primo volumio[3376]: at Socket.emit (events.js:400:28) Oct 26 20:10:11 primo volumio[3376]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Oct 26 20:10:11 primo volumio[3376]: at processTicksAndRejections (internal/process/task_queues.js:77:11) Oct 26 20:10:11 primo volumio[3376]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 26 20:10:11 primo sudo[4982]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-26 20:09 Oct 26 20:10:11 primo sudo[4982]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="primo2rev2" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 06:34:13 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Primo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Primo" VOLUMIO_HASH="4afef88585183bd857d5aee3dd000abc"