Reporting trough event-manager, so the played songs will pop up in the listening history

[tobiasguyer]

Before this commit, played songs by cspot weren't displayed in the listening history. Therefore they had no influence on the algorithm, neither got the artist those plays reported.
I've created a Event-Manager that reports at the end of a playback.
I think this commit is quite important

[tobiasguyer]

Sorry, I thought it would be wise to make a pull request for each important commit.
I'll just post in here, if there are any changes, at least until this pull request is merged.
Implemented, but not yet uploaded are following:

• context-resolve, checks if there are any missing tracks, spotify truncates playlists after 80 songs
• autoplay-enabled, resolves the context uri for the radio-apollo
• radio-apollo, get tracks for the autoplay-feature
• VS1053-support, a vorbis codec audio sink, decoding vorbis with 2 tracks is just quite demanding
• ghostTracks, as long as the main reporting happens trough 'hm://remote/', truncate the sent tracks to 2 old ones and 2 future ones, to keep the sent data small next from gets truncated to 2

futher, following things should be implemented

• hm://connect-state has a lot of information, needed for a standalone player (like old tracks, future tracks, even if there's no other client online
• based on librespot-java, their should be a way to further report information without hm://remote who knows, probably the playing track will also be shown in playlists, not only the collection

[feelfreelinux]

Thanks a lot for the changes. I will try to review each PR one-by-one, and merge it into the develop branch. Currently I have the https://github.com/feelfreelinux/cspot/tree/feat/repeat-shuffle branch that's pending merging into main too, so will try to wrap it up together.

[tobiasguyer]

so.. i think i can finally call it a day.. i like the queuedtracks feature.. shuffeling and unshuffeling can be done properly. i'm just scared of unshuffeling if a queued track is playing :) but i'll try that probably soon.
with too big playlists, there's a fail in the read packet of mercury request ( or a fail in a log command). probably a memoryleak because the data gets too big for the task size.
future adjustment could be, to call resolveContext regularly, and just keep a index, the track size and some tracks(copy them after each resolveContext, and call resolveContext for the shuffeling and unshuffeling too.) and copying them in playing order and keeping the alt_index for the resolveContext (for copying tracks if shuffled). could be, that that way, using abnormous big playlists would be possible again. but it could delay the shuffeling/unshuffeling calls for a while in case of huge playlists. anyway.. i think it's finally working :)

[tobiasguyer]

i think enableTimestampLogging should be removed on esp32's main.cpp. i'm not exactly sure if it's because of the timestamplogging, but my esp always breaks down on the same line after some time (could be 6 min, could be 3 hours). (could be that the contextResolve breakdown was because of the same)
i'll try to run it for a time without
the error report would be following:

Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x402076ef  PS      : 0x00060e30  A0      : 0x80206cc0  A1      : 0x3f813b60
0x402076ef: _svfiprintf_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/vfprintf.c:873

A2      : 0x3ffdd9b0  A3      : 0x3f813b70  A4      : 0x3f813ee0  A5      : 0x3f813ec0
A6      : 0x3f813ea0  A7      : 0x0000000c  A8      : 0xff000000  A9      : 0x3f813de0
A10     : 0x3ffdd944  A11     : 0x00001800  A12     : 0x3ffaefb8  A13     : 0x00000001
A14     : 0x00060d23  A15     : 0x3ff0017c  SAR     : 0x0000001d  EXCCAUSE: 0x0000001c
EXCVADDR: 0xff00000c  LBEG    : 0x4008e051  LEND    : 0x4008e061  LCOUNT  : 0xfffffffd
0x4008e051: strcpy at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/machine/xtensa/strcpy.S:188

0x4008e061: strcpy at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/machine/xtensa/strcpy.S:200



Backtrace: 0x402076ec:0x3f813b60 0x40206cbd:0x3f813e20 0x4008ebe1:0x3f813ee0 0x4008ed5d:0x3f813f50 0x401f4b37:0x3f813f70 0x401e2f29:0x3f813fa0 0x401e1c5f:0x3f814060 0x40143def:0x3f8140c0 0x401443df:0x3f814120 0x400fdf05:0x3f8141e0 0x400fe74d:0x3f8149d0 0x400e15b5:0x3f814ab0 0x400dc2c2:0x3f814c40 0x40095445:0x3f814c60
0x402076ec: _svfiprintf_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/vfprintf.c:661

0x40206cbd: sniprintf at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/sniprintf.c:80 (discriminator 4)

0x4008ebe1: __strftime at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/time/strftime.c:1328

0x4008ed5d: strftime at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/time/strftime.c:1445

0x401f4b37: std::__timepunct<char>::_M_put(char*, unsigned int, char const*, tm const*) const at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/build/build-cc-gcc-final/xtensa-esp32-elf/esp32-psram/no-rtti/libstdc++-v3/src/c++98/time_members.cc:51

0x401e2f29: std::time_put<char, std::ostreambuf_iterator<char, std::char_traits<char> > >::do_put(std::ostreambuf_iterator<char, std::char_traits<char> >, std::ios_base&, char, tm const*, char, char) const at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/build/build-cc-gcc-final/xtensa-esp32-elf/esp32-psram/no-rtti/libstdc++-v3/include/bits/locale_facets_nonio.tcc:1340

0x401e1c5f: std::time_put<char, std::ostreambuf_iterator<char, std::char_traits<char> > >::put(std::ostreambuf_iterator<char, std::char_traits<char> >, std::ios_base&, char, tm const*, char const*, char const*) const at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/build/build-cc-gcc-final/xtensa-esp32-elf/esp32-psram/no-rtti/libstdc++-v3/include/bits/locale_facets_nonio.tcc:1299

0x40143def: std::basic_ostream<char, std::char_traits<char> >& std::operator<< <char, std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&, std::_Put_time<char>) at c:\espressif\tools\xtensa-esp32-elf\esp-2021r2-patch5-8.4.0\xtensa-esp32-elf\xtensa-esp32-elf\include\c++\8.4.0/iomanip:379

0x401443df: bell::BellLogger::printTimestamp() at C:/esp32/github_commits/cspot/cspot/bell/main/utilities/include/BellLogger.h:107
 (inlined by) bell::BellLogger::debug(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, int, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, char const*, ...) at C:/esp32/github_commits/cspot/cspot/bell/main/utilities/include/BellLogger.h:33

0x400fdf05: cspot::MercurySession::decodeResponse(std::vector<unsigned char, std::allocator<unsigned char> > const&) at C:/esp32/github_commits/cspot/cspot/src/MercurySession.cpp:249 (discriminator 4)

0x400fe74d: cspot::MercurySession::handlePacket() at C:/esp32/github_commits/cspot/cspot/src/MercurySession.cpp:177

0x400e15b5: CSpotTask::runTask() at C:/esp32/github_commits/cspot/targets/esp32/main/main.cpp:224

0x400dc2c2: bell::Task::taskEntryFuncPSRAM(void*) at C:/esp32/github_commits/cspot/cspot/bell/main/utilities/include/BellTask.h:95

0x40095445: vPortTaskWrapper at C:/Espressif/frameworks/esp-idf-v4.4.3/components/freertos/port/xtensa/port.c:131

[feelfreelinux]

Hm, it might be that the timestamp error is caused by an memory corruption or heap overflow elsewhere - I'll take a look into it.
Tried the codebase today, and it works pretty well :) One thing though - I'll have to refactor the way the trackmetrics is reported. Currently, it assumes that the TrackPlayer is never in the future - Aka, it reports that a song has finished playing, even if its only buffered up. This causes some problems when used with large buffers, holding multiple songs. I assume that the song start / end metric is supposed to be only sent when the actual playback happens

[tobiasguyer]

hmmm.. that's bad, that shouldn't happen. so you're telling me, that each preloaded track executes the runTask, even tough they'd never ghet played?
I'm sorry, because i'm writing it mainly for the vs1053, which includes a direct feed, i don't exactly unterstand, how the track gets processed after the runTask in TrackPlayer.cpp.
AH.. i see, so the problem is, that i've finished the track, when loading all bytes, but for a sink that uses the ogg decoder, to have finished all bytes means only, to have decoded all, but not that all is streamed.
but that should'nt be that big of a problem. can't you just port the two lines of endTrack() and sendEvent() from TrackPlayer.cpp to SpircHandler.cpp?
just add to spircHandler.cpp line 100:

    currentTrack->trackMetrics->endTrack();
    ctx->playbackMetrics->sendEvent(currentTrack);

and remove line 350 - 352 from TrackPlayer.cpp

[tobiasguyer]

and well.. the values wouldn't match perfectly with their intended usecase, but the reporting should happen perfectly fine

[tobiasguyer]

so.. with that commit, i've seperated all the context stuff from trackqueue. that all the radio tracks(spotify smart shuffle) get loaded properly, i had to reduce the preloaded track size to two. but it's running quite smooth for me :) it's, as described with last big commit. it loads some tracks from context, and in case of shuffle, or a depleted tracklist, the context resolver gets called, and decides, if new playlist tracks should be loaded, or the playlist continues with loading new tracks. what hasen't been done is, that tracks in the queuedTracks get deleted after shuffle gets undone. and somehow i cant tell spotify that i'm smart-shuffeling.
neither are tracks loaded in the queuedPlaylist after depletion(i think spotify adds just one track from radio to the playlist after two tracks from the playlist in case of smartshuffle).
but it's running smooth as fuck and hasn't died yet(needed to change the trackplayed feedback in Trackplayer, that it'll skip to the next track in case of missreads)

[tobiasguyer]

nope.. i don't know, wher the mistake is, but preeloadedTracksSize needs to be 3, itherwise, the initial load call doesn't play further than 2 songs.. i'll find out which one is easyer to solve, the preloadedtracksize 3, and a solution to the radio thing, or the preloadedtracksize 2 and the continuos playing

[tobiasguyer]

so.. i think the first stage can finally be called done. all further commits will be comsetics.
i think i'll investigate further how librespot and the computer apps report their tracks.
the hm://remote call somehow overwrites some information (like smart shuffle), that can't be read, or reported trough that call. but it played and reported correctly out of a 700 tracks playlist for eight whole hours, including a start with smartshuffle

[feelfreelinux]

Thanks! I'm slowly testing and fixing up your work a little bit :) Thanks a lot for the huge amount of effort that went into this. I found few minor bugs and a mem leak in Mercury Response struct - will commit my changes soon.

[tobiasguyer]

thanks a lot.. i'll be happy to hear from you. there's one last commit gonna come. there happened some mistakes with the trackloading, should be fixed any minute and then i'm off trying to find out how to properly report. but i've tried already a little and i don't know if ther's anything to come

[tobiasguyer]

i think i know the mainproblem, i've created.
i'm referring to a already deleted track in the endTrack event, beacuse with softwaredecoding, you're playing a track, that's already been completly streamed and decoded, and because of that unreferenced.

[tobiasguyer]

simple solution for that would be to pass a shared_ptr of the preloaded track to espPlayer

[tobiasguyer]

Nope.. that's one of the worst thing i could have suggested.. and i neither think it's the problem. I don't know why it plays so bad with softwaredecode.. mine plays so smooth

[tobiasguyer]

I'm so sorry,. it's gonna take a while, but i think i'll sooner or later post a new pull request with quite a few structural changes.
it's only a concept yet, but i've accomplished more or less a proper way to communicate with spotify, that the songs are displayed, like they should.