[1.1.74] failing to load player-data after save (infrequent)

[dalindes]

When launching factorio recently, after some single-player-mode play in my prior session, I was greeted with this error:

Window title: Data error
Text content: Failed to load the player data file. Campaign progress might be lost.
(screenshot attached.)

There's also this error in the factorio-current.log (full log also attached):

Code: Select all

   0.988 Error PlayerData.cpp:230: Failed to load player data: Unterminated string at /home/lindes/Downloads/factorio/git-based/player-data.json:529

This was a surprise, as I hadn't modified that file from what Factorio had last saved. I expected it to load up normally, and have the default action be to continue the save I'd most recently saved. Instead, I had this error screen, and then also the release notes screen. Strangely, after dismissing both of these, the default action was, still, to load the most recent save prior to that. (Or perhaps that's not so strange -- it seems to select the most-recently-modified-file in the saves/ folder, which is, of course, the save I'd last saved.)

Luckily, I happen to keep my player-data.json and other things in git, so I was able to revert to the previous file to investigate why it failed. Took me a while to narrow it down, but I eventually discovered that the culprit was the "last-played" section, and in particular the "save-name" field. I suspect that the problem may be that some code is rejecting one of the following things that stood out to me as potentially suspicious in the save-name data:

1. the data had a "slash" ('/') in it (and the save was not in a subdirectory or anything);
2. it also had a "backtick" ('`') in it.

Of course, it could be something else that causes that string to be interpreted as "unterminated" (though it passes other JSON parsers (e.g. jq) just fine.)

Here's the offending line, and the command I used to get it (with my prompt listed as ': $; '):

Code: Select all

: $; grep -a save-name player-data.json
    "save-name": "�lK\u0006\u0000\u0000\u0000\u0000a��/�H�`O-1c"

And, in case that doesn't come through properly what with the 8-bit data in that, here's a hexdump:

Code: Select all

: $; grep -a save-name player-data.json | ot -tx1c
0000000  20  20  20  20  22  73  61  76  65  2d  6e  61  6d  65  22  3a
                          "   s   a   v   e   -   n   a   m   e   "   :
0000020  20  22  b6  6c  4b  5c  75  30  30  30  36  5c  75  30  30  30
              " 266   l   K   \   u   0   0   0   6   \   u   0   0   0
0000040  30  5c  75  30  30  30  30  5c  75  30  30  30  30  5c  75  30
          0   \   u   0   0   0   0   \   u   0   0   0   0   \   u   0
0000060  30  30  30  61  bb  e5  2f  82  48  ff  60  4f  2d  31  63  22
          0   0   0   a 273 345   / 202   H 377   `   O   -   1   c   "
0000100  0a
         \n
0000101

I'm 100% certain that that's the offending line, as if I delete that one line (and the comma from the previous line, for JSON syntax reasons), it loads up without error. (Though when it does so, it goes ahead and deletes the whole "last-played" section after exiting without playing.)

I don't wish to share the exact save name (it contains some vaguely personal information), but it's very similar to:

Code: Select all

redactd-2-01-SOLO-1c.zip

("redactd" is the same number of characters as the information I redacted.)

I tried loading that save and re-saving to the same name a few times, and was unable to reproduce the problem. Here's a log of a few attempts (the same grep after launch-load-save-quit cycles, each appended to a file):

Code: Select all

: $; cat save-names.log 
    "save-name": "�lK\u0006\u0000\u0000\u0000\u0000a��/�H�`O-1c"
    "save-name": "�\u0003�\u0006\u0000\u0000\u0000\u0000�HR�\u001a��oO-1c"
    "save-name": "�\n�\u0005\u0000\u0000\u0000\u0000��]����FO-1c"
    "save-name": "N��\u0004\u0000\u0000\u0000\u0000��r�2��O-1c"
    "save-name": "\u0015P8\u0007\u0000\u0000\u0000\u00008��?,\u001c�O-1c"
    "save-name": "�%�\u0003\u0000\u0000\u0000\u0000�'O�!\u001e��O-1c"

This invites a question I've long wondered about: why are these names mangled, anyway? If I save to a nice short filename (like "a"), it gets reflected in the file accordingly:

Code: Select all

    "save-name": "a"

I presume this is somehow related to filename mangling that... some system or other that you're attempting to maintain compatibility with uses? If so, couldn't you do that mangling when reading this back in? And/or if you're needing to encode some information in here, do so using something more standard like base64 or url-encoding or something? (Side note: a fix for this might also allow this request to be accomodated.)

Anyway, whatever transformation is happening there is opaque to me, and isn't a pure function based on only the name (and I don't know what other variables may be involved) so I don't know how to reproduce this, though I've tried (as shown).

Hopefully this is enough information to reproduce things on your end, and/or otherwise track down the problem.

Thank y'all for all you do! I know Wube has a track record of fixing even obscure edge cases like this.

And of course, I have a workaround for now. (I'm just glad I was saving the player-data.json file to git, because otherwise a lot of the information above, plus some console history and stuff, would have been lost to me, when it got re-generated.)

Thanks!

[Nidan]

Code: Select all

: $; cat save-names.log 
    "save-name": "�lK\u0006\u0000\u0000\u0000\u0000a��/�H�`O-1c"
    "save-name": "�\u0003�\u0006\u0000\u0000\u0000\u0000�HR�\u001a��oO-1c"
    "save-name": "�\n�\u0005\u0000\u0000\u0000\u0000��]����FO-1c"
    "save-name": "N��\u0004\u0000\u0000\u0000\u0000��r�2��O-1c"
    "save-name": "\u0015P8\u0007\u0000\u0000\u0000\u00008��?,\u001c�O-1c"
    "save-name": "�%�\u0003\u0000\u0000\u0000\u0000�'O�!\u001e��O-1c"

This invites a question I've long wondered about: why are these names mangled, anyway? If I save to a nice short filename (like "a"), it gets reflected in the file accordingly:

Code: Select all

    "save-name": "a"

JSON requires control codes (U+0000 - U+001f) to be escaped, all your "\uXXXX" are the result of that. (Why are you using normally untypeable characters for your save names?)

Your save names have only the final "O-1c" in common with your "redactd-2-01-SOLO-1c.zip" pattern, so any attempt at analyzing might end up at a red herring introduced by your attempt to "sanitize" your data. Please reproduce the issue with names you are happy to share unaltered.

In any case, the value for save-name from the hexdump is invalid UTF-8; I don't know if factorio is prepared to handle that. (File names in general can be arbitrary binary data, which neither UTF-8 nor JSON can represent.) Your list only contains the unicode question mark ("�") rather than the actual bytes, so I can't tell the different between the working(?) list and the non-working one you provided the hexdump for.

[dalindes]

JSON requires control codes (U+0000 - U+001f) to be escaped, all your "\uXXXX" are the result of that.

OK, so that explains _some_ of the encoding (though, I would think one would also want to encode things like the 0xEE that you'll see below (the character before the two characters "4X" (0x34,0x58) in the second save name) as "\u00EE" or something.)

(Why are you using normally untypeable characters for your save names?)

I'm not. I'm only using 7-bit-ASCII-compliant printable characters in my save names. That's why I find it so perplexing that it's being mangled.

That said, I did a little more testing, and have determined that it seems to happen when my nominal save name exceeds 15 characters in length (as far as I can tell, that's the salient factor here, though I suppose it's possible I'm missing something else), which corresponds to a 19-character filename, when including the ".zip" that gets added behind the scenes. If one goes to 16(/20) characters, we start getting weird encoding. At 15(/19), it's fine.

Example testing data follows (unmodified this time). I numbered all the saves sequentially, so the output order in save-names.log should match the output order in the ls -1 output. Including a hexdump in case that's needed. This is trivially easy to reproduce, just try saving as name 0123456789abcdef, and it fails (at least on my system -- though I've had this on multiple OS's, so I think it's unlikely that it's anything peculiar about my system), whereas 0123456789abcde is fine (I don't include these cases below, but I did try them).

Heck, it can even be achieved by saving as a single icon (using the GUI to select it) for an in-game item of sufficient length (e.g. personal laser defense -> "6/�\u0007\u0000\u0000\u0000\u0000rsonal-laser-defense-equipment]", which happily gets the filename of "[item=personal-laser-defense-equipment].zip").

Hopefully you and/or others can reproduce this [edit: the portion of this that mangles the save names with 8-bit data -- the "/" part that's where the real problem is, I haven't found a reliable reproduction for... though presumably the partial repro is enough to track down where this is happening when one has access to the code] as well?

Code: Select all

: $; cat save-names.log 
    "save-name": "save-01-start"
    "save-name": "�4X\u0005\u0000\u0000\u0000\u0000using-a-longer-filename"
    "save-name": "��\b\u0000\u0000\u0000\u0000��>e�>�alonger"
    "save-name": "save-04-using-a"
    "save-name": "!N�\u0007\u0000\u0000\u0000\u0000using-a-bit"
    "save-name": "E=�\u0006\u0000\u0000\u0000\u0000\u0004�����sb"
    "save-name": "�r�\u0004\u0000\u0000\u0000\u0000\u0017�\u0018�;�1�"
    "save-name": "�J]\u0006\u0000\u0000\u0000\u000085\u0016n����"
    "save-name": "save-09-using-2"

Code: Select all

: $; ls -1 saves
save-01-start.zip
save-02-using-a-longer-filename.zip
save-03-using-a-longer.zip
save-04-using-a.zip
save-05-using-a-bit.zip
save-06-using-a-b.zip
save-07-using-a-.zip
save-08-using-ab.zip
save-09-using-2.zip

Code: Select all

: $; xxd save-names.log 
00000000: 2020 2020 2273 6176 652d 6e61 6d65 223a      "save-name":
00000010: 2022 7361 7665 2d30 312d 7374 6172 7422   "save-01-start"
00000020: 0a20 2020 2022 7361 7665 2d6e 616d 6522  .    "save-name"
00000030: 3a20 22ee 3458 5c75 3030 3035 5c75 3030  : ".4X\u0005\u00
00000040: 3030 5c75 3030 3030 5c75 3030 3030 5c75  00\u0000\u0000\u
00000050: 3030 3030 7573 696e 672d 612d 6c6f 6e67  0000using-a-long
00000060: 6572 2d66 696c 656e 616d 6522 0a20 2020  er-filename".   
00000070: 2022 7361 7665 2d6e 616d 6522 3a20 22cd   "save-name": ".
00000080: f4b6 5c62 5c75 3030 3030 5c75 3030 3030  ..\b\u0000\u0000
00000090: 5c75 3030 3030 5c75 3030 3030 9fcf 3e65  \u0000\u0000..>e
000000a0: ea3e ad61 6c6f 6e67 6572 220a 2020 2020  .>.alonger".    
000000b0: 2273 6176 652d 6e61 6d65 223a 2022 7361  "save-name": "sa
000000c0: 7665 2d30 342d 7573 696e 672d 6122 0a20  ve-04-using-a". 
000000d0: 2020 2022 7361 7665 2d6e 616d 6522 3a20     "save-name": 
000000e0: 2221 4e86 5c75 3030 3037 5c75 3030 3030  "!N.\u0007\u0000
000000f0: 5c75 3030 3030 5c75 3030 3030 5c75 3030  \u0000\u0000\u00
00000100: 3030 7573 696e 672d 612d 6269 7422 0a20  00using-a-bit". 
00000110: 2020 2022 7361 7665 2d6e 616d 6522 3a20     "save-name": 
00000120: 2245 3dbe 5c75 3030 3036 5c75 3030 3030  "E=.\u0006\u0000
00000130: 5c75 3030 3030 5c75 3030 3030 5c75 3030  \u0000\u0000\u00
00000140: 3030 5c75 3030 3034 bba4 89ae f28f 7362  00\u0004......sb
00000150: 220a 2020 2020 2273 6176 652d 6e61 6d65  ".    "save-name
00000160: 223a 2022 8272 835c 7530 3030 345c 7530  ": ".r.\u0004\u0
00000170: 3030 305c 7530 3030 305c 7530 3030 305c  000\u0000\u0000\
00000180: 7530 3030 305c 7530 3031 3787 5c75 3030  u0000\u0017.\u00
00000190: 3138 ca3b fb31 a922 0a20 2020 2022 7361  18.;.1.".    "sa
000001a0: 7665 2d6e 616d 6522 3a20 2283 4a5d 5c75  ve-name": ".J]\u
000001b0: 3030 3036 5c75 3030 3030 5c75 3030 3030  0006\u0000\u0000
000001c0: 5c75 3030 3030 5c75 3030 3030 3835 5c75  \u0000\u000085\u
000001d0: 3030 3136 6e9c 99e4 c222 0a20 2020 2022  0016n....".    "
000001e0: 7361 7665 2d6e 616d 6522 3a20 2273 6176  save-name": "sav
000001f0: 652d 3039 2d75 7369 6e67 2d32 220a       e-09-using-2".

[lyvgbfh]

This is trivially easy to reproduce, just try saving as name 0123456789abcdef, and it fails (at least on my system -- though I've had this on multiple OS's, so I think it's unlikely that it's anything peculiar about my system), whereas 0123456789abcde is fine (I don't include these cases below, but I did try them).

Reproduced here as well, on Windows.

[Rseding91]

I'm not able to reproduce it on my machine with that file name; or even a longer one. I tried "0123456789abcdefghijklmnopqrstuvwxyz" and I just get this in the .json file:

Code: Select all

  "last-played": 
  {
    "type": "single-player",
    "save-name": "0123456789abcdefghijklmnopqrstuvwxyz"
  },

So something... is going very weird on your system(s) that I've never seen before. Figuring that out will likely lead to the fix.

[posila]

So something... is going very weird on your system(s) that I've never seen before. Figuring that out will likely lead to the fix.

The corruption in data is weirdly specific. I would expect system/HW problem, that would cause this kind of data corruption, to cause the game crash all the time on many random places. And ... I think difference between 15 character long name and 16 character long name is, that the 15 character one will be small string optimized in std::string. As far as I see it is not use after free, but something weird seems to going on ... as if something in the saving process overwrites beggining of the heap allocated string due to buffer overrun, or something like that.

[DarkShadow44]

Seems to work fine for me. Can you give exact steps to reproduce, preferably creating a new game and saving that?
Also, could that be related to the existing player data? I.e., can you try to reproduce the issue with a clean ".factorio" (Linux) or "%AppData%\Factorio" (Windows) folder?

[Rseding91]

Reproduced here as well, on Windows.

What were you able to reproduce? Could you describe the steps you took to make the error happen?

[lyvgbfh]

Reproduced here as well, on Windows.

What were you able to reproduce? Could you describe the steps you took to make the error happen?

Steps:
Open game
Start new save, all default, confirm
Hit esc, save, paste 0123456789abcdef as the save name and confirm
Exit to desktop
Re-launch game

I'm then greeted by the message about player data being corrupt, with the changelog open in the background.

[DarkShadow44]

Also, could that be related to the existing player data? I.e., can you try to reproduce the issue with a clean ".factorio" (Linux) or "%AppData%\Factorio" (Windows) folder?

Even with a clean factorio folder?

[SoShootMe]

As far as I see it is not use after free, but something weird seems to going on ... as if something in the saving process overwrites beggining of the heap allocated string due to buffer overrun, or something like that.

Sounds like it's time to reach for the rubber duck .

[Rseding91]

I'm then greeted by the message about player data being corrupt, with the changelog open in the background.

Mind if I ask: did you do anything special to have Windows 10 build 20348 installed? Some beta program maybe? Or are you running windows 11 and the log file is just wrong?

[Nidan]

I think I found one piece of the puzzle, at least for some linux users: When using a fresh install, the state of the non-blocking saving option toggles whether the save-name in player-data.json will be clean or garbage.
I don't think this is the actual cause, since non-blocking saving can't explain the report on windows (where the option does nothing) nor any "just using a fresh install" reports, but maybe its enough of a hint.

[Rseding91]

Thanks for the report and the assistance in digging into this. It looks like it is related to the async-saving and should be fixed for the next release thanks to Genhis.

[lyvgbfh]

Mind if I ask: did you do anything special to have Windows 10 build 20348 installed? Some beta program maybe? Or are you running windows 11 and the log file is just wrong?

Nothing special, no. It's what it says on the tin. Worth noting this is 10 LTSC 2021 though.

[dalindes]

Thanks for the report and the assistance in digging into this. It looks like it is related to the async-saving and should be fixed for the next release thanks to Genhis.

Excellent, thanks Rseding!

And indeed, if I set

Code: Select all

non-blocking-saving=false

(or start from a fresh slate where it hasn't ever been set to true), the problem goes away (or fails to show up).

I appreciate it!

[feofeujo32m3r]

I didn't see anything in the patchnotes relating to this, but assume it was simply not mentioned.

However I've had this happen several times in 1.1.76 with non-blocking-saving=true

[Loewchen]

I've had this happen several times in 1.1.76 with non-blocking-saving=true

It's in 1.1.77, the devs refuse to time travel to backport their fixes.

[feofeujo32m3r]

Thanks for letting me know. Was just wondering, because this was said before the release of 1.1.76.

Code: Select all

 It looks like it is related to the async-saving and should be fixed for the next release thanks to Genhis.

Will time travel be implemented some time in the future then?

edit: I was going by the steam announcement https://steamcommunity.com/app/427520/e ... 8969659603 for the release date, guess that was wrong.

[Xorimuth]

Thanks for letting me know. Was just wondering, because this was said before the release of 1.1.76.

I don’t think so - 1.1.76 released on 13 Jan 2023.