Most of achievements not syncing

[wwMRd]

Achievements are not syncing for most of games. In my case only couple of games syncing. I'm not familiar with Python but I gave it an hour and tried to investigate a bit. It seems that games stats update times out after 10 minutes (predefined value) and function which supposed to update achievements is getting empty objects for almost all games. Games and game times seems to be up to date.

All unlocked achievements should be syncing properly.

I'm not attaching logs as I don't want to spend time to clean the information I wouldn't like to share publicly. Here are some entries from steam log:

2023-05-22 07:47:05,421 - galaxy.api.plugin - INFO - Creating plugin for platform steam, version 1.0.4
2023-05-22 07:47:12,145 - galaxy.api.jsonrpc - INFO - Handling request: id=11, method=start_achievements_import, params=
2023-05-22 07:57:12,163 - steam_network.cache_proto - INFO - Timed out waiting for games cache to get ready
2023-05-22 07:57:12,163 - backend_steam_network - INFO - Finished achievements context prepare
2023-05-22 07:57:12,163 - galaxy.task_manager - DEBUG - Task manager plugin external: creating task 16 (achievements import)
2023-05-22 07:57:12,163 - galaxy.task_manager - DEBUG - Task manager plugin external: finished task 9 (start_achievements_import)
2023-05-22 07:57:12,165 - root - DEBUG - Sending data: {"jsonrpc": "2.0", "id": "11", "result": null}
2023-05-22 07:57:12,165 - galaxy.task_manager - DEBUG - Task manager jsonrpc server: finished task 7 (start_achievements_import)
2023-05-22 07:57:12,165 - backend_steam_network - INFO - Asked for achievs for 43110
2023-05-22 07:57:12,165 - galaxy.api.jsonrpc - INFO - Sending notification: method=game_achievements_import_success, params={'game_id': '43110', 'unlocked_achievements': [Achievement(unlock_time=1355737994, achievement_id=None, achievement_name='First blood')]}
2023-05-22 07:57:12,166 - backend_steam_network - INFO - Asked for achievs for 35700
2023-05-22 07:57:12,166 - galaxy.api.jsonrpc - INFO - Sending notification: method=game_achievements_import_success, params={'game_id': '35700', 'unlocked_achievements': []}

[Amarinth]

Exact same messages here (on the last alpha build), and seems to happen every time it tries to sync achievements. Always comes up with Timed out waiting for games cache to get ready exactly 10 minutes after method=start_achievements_import, and then it imports some achievements in the last 1 second, before saying it's finished.

That would explain why some achievements do turn up eventually, but it seems to be utterly random as to when.

I can post a more complete log later, once I've had time to install the beta and leave that running for a while.

[ABaumher]

Don't have a ton of time to look into it this week, but if it's an issue of timing out after 10 minutes, i don't think there's much i can do. I have basically two options: optimize how quickly we process information to make it take less time to write to the cache, or tell gog to wait for us to finish. The latter would involve better documentation from GOG which doesn't exist, and the former is likely necessary, but also incredibly difficult/time-consuming.

As i understand it (i didn't write any of the sync logic and haven't debugged it at all, so take with a massive grain of salt.), when we "prepare to retrieve achievements" we start getting that info and writing it to a cache. when we finish, we return somehow, and then gog calls "retrieve achievements." What's happening is gog is getting impatient and after 10 minutes, cancels the "prepare" and immediately calls "retrieve". so we give them what we have. When GOG calls tick, we update again, so it gets what we wrote to the cache since then. But it seems to call tick randomly.

[ABaumher]

i'd need to read a long log to see if we keep adding to the cache after gog finishes the prepare statement, and possibly have people with larger libraries manipulate the gog python plugin code so it logs stuff for us. unfortunately this would involve some copy-pasta. Either way, it's probably going to have to wait until the weekend.

[Amarinth]

Here's my log from last night, which looks like it has a decent number of these events in it.

Just let me know if you need me to tweak any files to improve the logging.

In the meantime I'm going to keep an eye on my Steam achievements, because the import process does seem to be unusually slow. To give you an idea of how slow, I've got ~150 Steam games with significant playtime & achievements, but Galaxy has only processed ~25 of them so far. I deleted the cache file when I installed the beta, so this the progress after 2 days of leaving Galaxy running in the background for most of the day.

I personally don't care much about all of the achievement stuff (just don't break my playtime stats please, lol), so I don't remember how well it worked for me in the past. However I do recall seeing plenty of complaints about this issue on the GOG forums over the years, so I wouldn't be surprised if it's always been this slow and unreliable.

[woj1993]

I have a stupid idea. If we can detect only the games that were played from last time we can only synchronize achievements for them. It needs to have synchronization with steam times but if we have this we can try to synchronize only a subset of games achievements . It won't help with initial load so we must do something like this for it to work correctly: On first run: -sync games -sync times -create a cache for what games we checked achievements. (defaults to need synchronization) -Check achievements - We need to mark any checked game immediately so if we get killed we will know what is list of synchronized games. -normal process so return to gog list of achievements (even if we get killed return what we have) On next runs: -synchronize games -synchronize times (for every game that time played > that in our cache mark it as needing synchronization of achievements) -Check achievements only for games that are marked in cache as needing synchronization (that way we won't check the games that we already have synchronized) Hopefully gog will be opened almost always and we will be able to finally synchronize by making our list of "to sync" games achievements smaller. Extra points if we will prioritize synchronization of games that were last played (their play time will be changed from what we have in cache) so users will see it syncing last played games ASAP. Hiper extra points if we can use the knowledge that game has stopped running and can query for achievements before reporting to gog that game is closed.

[wwMRd]

I investigated a bit today. What I observed (in my case at least) - achievements are synced only for first 100 of games. Everytime same count- I tried many times today, trust me :) So what I did was slicing set of games in 3 parts and run app separatly for every slice: async def run(self): while True: for job in self.job_list[89:180].copy(): Now all my achievements are up to date. @woj1993 idea might be good if possible. Or just somehow split it in smaller subsets and run them one after another - also if possible ofc.

[Amarinth]

Oh, that's interesting. So you're saying it keep re-syncing just the first 100 games unless you force it to sync the subsequent sets manually?

Some quick math tells me that's roughly in line with the numbers I recorded above. I have ~25/150 played games synced, which means on average about 1/6th of my achievements have synced, and I own ~560 games total, so 1/6th of that is not too far off 100.

[ABaumher]

It does seem odd that it takes 10 minutes to grab 100 games worth of achievements.

I honestly think the cache code sucks but it wasn't broken by the new auth so i didn't bother checking. It's also possible that we're getting that info multiple times (I've seen the same game id with achievs multiple times in a few logs), which would be inefficient as all hell. I really don't have time until the weekend to look though

[wwMRd]

No worries, take it easy. You made tremendous work which I really appreciate so I'm just trying to contribute to maybe point you in a good direction. I might find some time today to get into it little more.

[wwMRd]

@Amarinth, can I ask you a favor as you own pretty big steam library? Exchange this file: <steam_plugin_catalog>\steam_network\protocol\protobuf_client.py with the attached one. Run app and wait 10 min - then share your log and check achievements.

protobuf_client.zip

[Amarinth]

That seems to have done the trick, or at least it dramatically improves the efficiency of the achievement import process! 🎉

I could watch it filling out the missing achievement percentages for most of my played games in realtime, and it was quick too (I think if you look in the log it says achievements_import_finished just 1m30s in).

It imported about 4 times as many achievements as it did before, and as far as I can tell they're all accounted for now. I checked the played games that are still at 0% on Steam and I just don't have any achievements for those (I probably played them modded or before achievements got added).

I have a lot of games that are just sat in my backlog, so I'm not the best test case for this. Someone who has a high number of played games with lots of achievements would be ideal to confirm how efficient the process is, but if it took 1m30s for it to process a little over 100 heavily played games for me, then hopefully it should be able to handle at least 5 times as many.

The log entries were split across two files, so I spliced them together: achiev_import.log

PS: I'm not a coder, but looking at the lines you changed, what you did was add a new function that tells it to keep re-running the job until there's nothing left to import?

[ABaumher]

I tried to look on mobile but converting it to a text file and trying to read it is... unpleasant. Technically i should be in a meeting, but they're using the wrong spelling of "board" lol.

If it matters any, i think we do initial import of achievements in the job list array, which is exceedingly stupid. Cleaning that up may also help with making the code run better.

Edit: got diff to work on my phone, that's literally what you changed lol. I'd like to remove job list entirely, and call the functions in there directly instead. We can store the async calls instead of awaiting them immediately, which would otherwise bottleneck our code. I think that's why the code is designed the way it is - to avoid a bottleneck. But the original code design there was dumb af. instead of joblist.append(<action to call the job>) and then in joblist await job() we can do task = job() and listOfAwaitables.append(task) then, in achievements or wherever, wait for all the tasks in listOfAwaitables to finish. Sorry if that's too technical. I actually had that on the discussion for dev ideas, but it was put off (actually, i straight up removed job list and broke all of this, lol).

[ABaumher]

Checking https://github.com/ABaumher/galaxy-integration-steam/blob/master/protobuf_files/proto/steammessages_clientserver_userstats.proto#LL7C9, we may be able to remove an extra call we make by adding a crc_stat. If we can set the value for the play time, we halve the calls we make.

...And it's undocumented. nevermind

[ABaumher]

@Amarinth from what i can tell the change was a little more technical - it tries to prioritize handling packages instead of sending stat requests. In non-code speak, everything we get from Steam is in two parts: a Request (give us the info) and a Response (ok, here's that info). Our old code prioritized sending off the job requests, and never stopped to read the responses until all the requests were sent. This works fine for small libraries, but for big ones it's overwhelmingly bad. In essence, GOG hangs up on us before we can process all the responses we get. In this patch, @wwMRd is only allowing 2 jobs to go through before ensuring we take time to get responses. So even if we don't sync all of them before GOG hangs up, we still get a lot of them. It might be possible to optimize this, as asyncio has 5 active tasks by default (the rest are queued), but we do need to let regular receives for not achievement and stat code run as well.

This is actually a really clever fix, ngl. Job List is still a hack and should be removed, but as far as bandaids on bad code, this is really up there. What i'd really like is to reimplement how we send and receive so we have a "send and wait" helper function that awaits until we get a response. This would fix this issue (and the desync thing @engiefox keeps finding) by only doing one job request at a time. again, this could be optimized by sending a few of them at the same time instead of 1 or 2.

[ABaumher]

@wwMRd there might be side effects (if we receive a message not started via the job list, it'll decrement the count), but you handle the most obvious one on the decrement by not letting it drop below 0. Honestly, i can't see how this could break anything, and it fixes a fundimental design flaw so if you open a PR i'll merge it and update the release to use it so we can hopefully consider the achievement issue solved (for now, until the whole code rework).

For more technical info on how i want to rework it, we can give each request we send a unique "job id" and embed it in the socket message. It's built in to Steam's requests. Currently the code only uses it for any service message calls we make, but there's no reason it can't be used everywhere. It's possible to map this job id to a "future" which we can return to the caller and say "when i get a response, i'll set the value of this future. Wait on the future and you'll get your result". When we receive a message, we retrieve the job id and set the mapped future as complete with the response we got from Steam. Sorry if i'm talking down to you and you know how asyncio already works. It confused the hell out of me for a while.

[engiefox]

just tried that modified file, seems to run much nicer. able to sync ~1500 achievements without issue. plugin-steam-ca27391f-2675-49b1-92c0-896d43afa4f8.log

[wwMRd]

@Amarinth I checked your logs and looks like 580 unique ids were processed - I am pretty confident that's your whole library.

@ABaumher I created this solution as fast temporary fix as I'm pretty occupied at the moment. This is far from perfection but it seems to work so... I'm new to Python so I'm not really sure what can we do and what we can't.

The problem is that we are sending requests for all games (game_stats) at the same time before we start processing responses. As result GOG is cutting most of requests because we are not able to process them in time. After GOG cut the responses we are waiting until 10 min of timeout occurs (game_stats processing basicaly ends in seconds and rest of that time just waiting doing nothing lol). Then achievements retrieval (from game_stats) starts and process them for what we were able to download.

I think requests should run in parallel/background and process their own responses - run and forget, but... no idea if possible.

@ABaumher I can open PR for current solution, just please grant me access to repo.

[woj1993]

It worked for me It started sync on 17:13:58,911 and ended on 17:18:30,858 then it started again on 18:13:45,519 and finished on 18:38:13,976 (i think the second time computer started to sleep because I left it running and found it sleeping. Also I found this error: 2023-05-25 18:38:40,148 - root - ERROR - Fatal read error on pipe transport protocol: <asyncio.sslproto.SSLProtocol object at 0x05258CF0> transport: <_ProactorSocketTransport fd=720> Traceback (most recent call last): File "D:\obj\Windows-Release\37win32_Release\msi_python\zip_win32\proactor_events.py", line 255, in _loop_reading File "D:\obj\Windows-Release\37win32_Release\msi_python\zip_win32\windows_events.py", line 744, in _poll File "D:\obj\Windows-Release\37win32_Release\msi_python\zip_win32\windows_events.py", line 435, in finish_recv OSError: [WinError 121] Przekroczono limit czasu semafora

I have more that 700 games on steam. logs_2.zip

[ABaumher]

@woj1993 if google translate is any use, that error was that an internal variable timed out (a semaphore, actually. A simplified explanation is that it's used to keep stuff thread-safe, but that probably means nothing to you). Which probably happened because your computer went to sleep, so it's not an issue.

@wwMRd i don't have the proper permissions set up to give you write acces - something about protecting master so you can't accidentally write to it, something i really should set up so i don't mess up master myself. I probably can do that this weekend (i'm actually writing this when i should be working and really need to log off, lol). In the meantime, it might be easier for you to fork my repo, overwrite protobuf client, and then do a PR that way. Also, i have about 4 months of python experience so you're not that far behind. We can fire and forget by storing awaitables. whenever you see variable = await <function> we're waiting for <function> to finish it's async nonsense and getting the actual result. Instead, we can say unfinished = <function>, which gets an "awaitable" (technically a coroutine), which we can eventually await to get the result. If we really want fire and forget we can just discard this variable, but the safer thing to do is store all those awaitables somewhere and wait on them before finishing the program. I'm just worried doing so might cause the same issue we had before, albeit in a much cleaner way (we don't have that horrible job list array)

[woj1993]

Actually I have a degree in programming and I'm tester so I know what is a semaphore. :) I guessed that sleeping might caused this but it was worth mentioning anyway.

[ABaumher]

Fair enough, I apologize. I know some of our testers don't have any code knowledge so i try to dumb everything down.

[woj1993]

Don't apologize I should apologize to you. I understand that not everybody has computer knowledge and especially about programing. Also there is no one that knows everything so I could also not known something that you do and is about programing so I shouldn't comment it like that. Sorry. :(

[ReiTung]

not sure if it helps (and I know there is a possible patch on the way), but what I found interesting looking at my logs (I am no coder, but my brain is used to run some logic :)) is that it seems only and always the SAME few games have achievements imported. Looks like the import task is started around every hour, but the logs show that always the same 2 or 3 games are checked (most likely just comparing with the cache which GOG has processed already). Other way round, additional (automatically triggered, did not yet try "sync connections" but would expect it does the same) achievement sync do not touch any other game than the first few done.

[ABaumher]

It's highly possible. We do have what looks to be a really solid fix that's incoming. I never had the achievement issue myself, but that's because my library is small (i have like 25 games on steam, but the ones i do have there i play a LOT of). So I'm not really a good tester. Look for the protobuf_client.py file somewhere on this page if you want to test yourself.

[Krynh]

211 games, nothing syncing on the first go of using the new plugin (waited over 10 minutes). Replaced the one file now and then opened Galaxy again, no achievements showing up so far.

Edit: Never mind, they're now showing as counted, but still missing 300 achievements out of 1419

[wwMRd]

@Krynh could you delete current steam logs, run GOG, wait full 10 minutes and upload fresh log(s)?

Edit: If someone also notice still missing achievements and wants to contribute please do the same Logs catalog: %programdata%\GOG.com\Galaxy\logs

[Krynh]

Where are the logs kept?

On Fri, 26 May 2023, 13:42 wwMRd, @.***> wrote:

@Krynh https://github.com/Krynh could you delete current steam logs, run GOG, wait full 10 minutes and upload fresh log(s)?

— Reply to this email directly, view it on GitHub https://github.com/ABaumher/galaxy-integration-steam/issues/6#issuecomment-1564334768, or unsubscribe https://github.com/notifications/unsubscribe-auth/AEJYYXDOITSIJS6DMJGMOBLXICQLXANCNFSM6AAAAAAYJ5AAQE . You are receiving this because you were mentioned.Message ID: @.***>

[wwMRd]

@Krynh logs catalog %programdata%\GOG.com\Galaxy\logs

[cderoeck]

@ABaumher I just replaced my profobuf_client file with the new one and my achievements issue was fixed. It was broken for something like 2+ years so I'm quite happy! I don't have time to dig deeper and check that all my achievements have been successfully imported, but at least I see the latest ones in my gog client now :)

[ABaumher]

For anyone who tried the new file and found it useful, don't thank me. The credit there is all to @wwMRd. It's an extremely elegant fix and if i can find their wishlist i might buy something for them myself lol.

That bug has existed long before i started working on this. It's been there at least since the initial major release, lol

On Fri, May 26, 2023, 10:42 AM Intox @.***> wrote:

@ABaumher https://github.com/ABaumher I just replaced my profobuf_client file with the new one and my achievements issue was fixed. It was broken for something like 2+ years so I'm quite happy! I don't have time to dig deeper and check that all my achievements have been successfully imported, but at least I see the latest ones in my gog client now :)

— Reply to this email directly, view it on GitHub https://github.com/ABaumher/galaxy-integration-steam/issues/6#issuecomment-1564500066, or unsubscribe https://github.com/notifications/unsubscribe-auth/ASX2DPGGDSAD7A22YLQ37XLXIC6N3ANCNFSM6AAAAAAYJ5AAQE . You are receiving this because you were mentioned.Message ID: @.***>

[Gelean]

~211 games, nothing syncing on the first go of using the new plugin (waited over 10 minutes). Replaced the one file now and then opened Galaxy again, no achievements showing up so far.~

Edit: Never mind, they're now showing as counted, but still missing 300 achievements out of 1419

This was an issue I was running into before the Steam functionality broke as well. There's a roughly 300 achievement difference between what I see in Steam and what GoG reports. Thankfully this fix has at least made the achievement sync possible since it was utterly broken before. My total count shows as 1580 in GoG Galaxy and in Steam it's 1879. There could be other achievements GoG is recording, but the count should be at least 1879. I might dig into this if I get some free time this weekend.

[TheEvilCoder42]

@wwMRd Seems to be working so far, achievements are now synced, huge thanks!

[Krynh]

I suspect the total could be even larger as it's showing xbox live achievements and galaxy ones but on many games it is still missing.

[wwMRd]

GalaxyClient.log Log from first time using new plugin GalaxyClient1.log

@Krynh The correct log name starts with 'plugin-steam-'. Sorry for not being precise. If you refer to total number of achievements on Recent tab, it my not be up to date for some time but achievements might be synced.

[Krynh]

From adding plugin first time: plugin-steam-ca27391f-2675-49b1-92c0-896d43afa4f8.1.log

[Danyelalejandro]

Since the beggining of the integration I never could be able to sync all my huge library of achievements. I hope my logs can help everyone plugin-steam-ca27391f-2675-49b1-92c0-896d43afa4f8.log.zip

[Krynh]

It seems to be stuck on importing now, played a couple of games and unlocked some achievements but nothing's changed.

[ABaumher]

@Danyelalejandro how well is it handling achievements? for your library i'd assume you get almost none, unless you apply that patch above. Try following the instructions here: https://github.com/ABaumher/galaxy-integration-steam/issues/6#issuecomment-1562553410 and see if you get some. I don't think we'll get all of them because it won't sync in 10 minutes but it might

Edit: saw your log. I'll read through that but before i start did you apply the patch or not?

Edit 2: Delete your logs, disconnect, then reconnect so i have a decent starting point. Your logs go back to the beginning of April and i don't feel like digging through all of that lol.

[wwMRd]

From adding plugin first time: plugin-steam-ca27391f-2675-49b1-92c0-896d43afa4f8.1.log

@Krynh This log is for sure from old vesion of protobuf_client.py (without fix). Are you sure you have exchanged the file or maybe this is old log?

[ABaumher]

The beginning is. the later part appears to be my code. It's possible though incredibly unlikely that i missed those error message somehow.

Edit: The message isn't in my repo anywhere. Is it possible you didn't remove all of the old files before pasting in the new stuff?

[ABaumher]

Also, i notice we import all the games before returning an auth of 0. This might be an issue for really big libraries and maybe explains why they crash on first connect but reconnect instantly makes the auth work. I'm going to swap over to the alpha discussion and see if this is what @engiefox has been hitting.

Edit: nope, nevermind.

[ABaumher]

@Danyelalejandro can you find the ID for that one game that's not importing? if you go to steampowered.com and find that game, the url will have the app id in it. I can then search your logs to see if that id is there.

[Danyelalejandro]

@Danyelalejandro can you find the ID for that one game that's not importing? if you go to steampowered.com and find that game, the url will have the app id in it. I can then search your logs to see if that id is there.

Yes, It is 1493750 It is recently launched, one month ago

[Danyelalejandro]

@Danyelalejandro how well is it handling achievements? for your library i'd assume you get almost none, unless you apply that patch above. Try following the instructions here: #6 (comment) and see if you get some. I don't think we'll get all of them because it won't sync in 10 minutes but it might

Edit: saw your log. I'll read through that but before i start did you apply the patch or not?

Edit 2: Delete your logs, disconnect, then reconnect so i have a decent starting point. Your logs go back to the beginning of April and i don't feel like digging through all of that lol.

Done. Applied patch already and instructions done. I will attach logs

[Krynh]

From adding plugin first time: plugin-steam-ca27391f-2675-49b1-92c0-896d43afa4f8.1.log

@Krynh This log is for sure from old vesion of protobuf_client.py (without fix). Are you sure you have exchanged the file or maybe this is old log?

It starts before adding it and then continues on after adding it. plugin-steam-ca27391f-2675-49b1-92c0-896d43afa4f8.log here's the latest log. It's now not importing game time nor achievements restarting fixed the game time, but not the achievements for 221380

[ABaumher]

@Krynh from your logs:

2023-05-26 13:56:02,067 - backend_steam_network - INFO - Asked for achievs for 221380
2023-05-26 13:56:02,067 - galaxy.api.jsonrpc - INFO - Sending notification: method=game_achievements_import_success, params={'game_id': '221380', 'unlocked_achievements': []}

there either aren't any that steam gives us or it's still reading from the cache and the cache is empty. I don't know without looking more but can't atm.

[Krynh]

Steam should be sending it over as I just unlocked them a few hours back or even for halo it should by now have shown them

[wwMRd]

There is a lot of different errors in the log. Some strange behaviours. @Krynh can you restart your PC and delete all steam logs then start GOG for 10 minutes and copy log again? It is really hard to understand what is happennig in there

[Krynh]

plugin-steam-ca27391f-2675-49b1-92c0-896d43afa4f8.log It's now showing in the graph that I've earned two, but they're not showing up in the game yet.

edit:Now showing up on the game page, but historical achievements for other games aren't yet.

[Danyelalejandro]

@Danyelalejandro how well is it handling achievements? for your library i'd assume you get almost none, unless you apply that patch above. Try following the instructions here: #6 (comment) and see if you get some. I don't think we'll get all of them because it won't sync in 10 minutes but it might Edit: saw your log. I'll read through that but before i start did you apply the patch or not? Edit 2: Delete your logs, disconnect, then reconnect so i have a decent starting point. Your logs go back to the beginning of April and i don't feel like digging through all of that lol.

Done. Applied patch already and instructions done. I will attach logs

Finally here. Hope they can help. 0 achievements so far and the game with ID 1493750 only appears in recently played plugin-steam-ca27391f-2675-49b1-92c0-896d43afa4f8.log.zip