[kovarex] [0.17.8] Crash of headless loading save: "this->handPosition == NO_ITEM_STACK_INDEX was not true"

[Xertez]

First, I updated the server to 0.17.8 from 0.17.7 using the following commands:

Code: Select all

systemctl stop factorio

systemctl disable factorio

wget -O factorio.tar.xz https://www.factorio.com/get-download/latest/headless/linux64

unxz factorio.tar.xz

tar -C .. -xvf factorio.tar

rm factorio.tar

systemctl enable factorio

systemctl start factorio

Now, When i realized the server was not coming up, I typed the following commands:

Code: Select all

systemctl stop factorio

/home/gamemaster/factorio/bin/x64/factorio --server-settings /home/gamemaster/factorio/data/server-settings.json --start-server-load-latest --console-log /home/gamemaster/Factorio.log

When those commands were run, The server crashed on startup with the output going into the log. Attached is a copy of the log. I have been able to revert the server to 17.7 using the same commands, but replacing the url in the "wget" command with the 0.17.7 url, and the server starts without issue. Let me know if any more information is needed.

Edit: Also happens in 0.17.9
Edit: Also happens in 0.17.10
Edit: Also happens in 0.17.11

[Loewchen]

Code: Select all

   0.000 2019-03-07 20:15:21; Factorio 0.17.8 (build 43440, linux64, headless)
   0.027 Operating system: Linux (Ubuntu 18.10)
   0.027 Program arguments: "/home/gamemaster/factorio/bin/x64/factorio" "--server-settings" "/home/gamemaster/factorio/data/server-settings.json" "--start-server-load-latest" "--console-log" "/home/gamemaster/Factorio.log" 
   0.027 Read data path: /home/gamemaster/factorio/data
   0.027 Write data path: /home/gamemaster/factorio [873886/937529MB]
   0.027 Binaries path: /home/gamemaster/factorio/bin
   0.032 System info: [CPU: Intel(R) Core(TM) i5-6600K CPU @ 3.50GHz, 4 cores, RAM: 15927 MB]
   0.032 Environment: DISPLAY=<unset>, WAYLAND_DISPLAY=<unset>
   0.032 Running in headless mode
   0.034 Loading mod core 0.0.0 (data.lua)
   0.062 Loading mod base 0.17.8 (data.lua)
   0.182 Loading mod base 0.17.8 (data-updates.lua)
   0.237 Checksum for core: 2736929835
   0.237 Checksum of base: 3541142062
   0.576 Info PlayerData.cpp:67: Local player-data.json available, timestamp 1552007494
   0.576 Info PlayerData.cpp:74: Cloud player-data.json unavailable
   0.576 Custom inputs active: 0
   0.577 Factorio initialised
   0.579 Info ServerSynchronizer.cpp:29: nextHeartbeatSequenceNumber(0) initialized Synchronizer nextTickClosureTick(0).
   0.579 Info ServerMultiplayerManager.cpp:714: updateTick(4294967295) changing state from(Ready) to(PreparedToHostGame)
   0.579 Info ServerMultiplayerManager.cpp:714: updateTick(4294967295) changing state from(PreparedToHostGame) to(CreatingGame)
   0.579 Loading map /home/gamemaster/factorio/saves/_autosave310.zip: 21918469 bytes.
   0.591 Loading Level.dat: 61534675 bytes.
   0.598 Info Scenario.cpp:147: Map version 0.17.7-2
Factorio crashed. Generating symbolized stacktrace, please wait ...
Raw stacktrace: 0xaf730b, 0xc5b68d, 0x9e36c8, 0xa0549f, 0xc507d3, 0xc50261, 0xe9082f, 0xed0750, 0xed1a4c, 0x17dc61f, 0x8164, 0
   6.801 Warning Logger.cpp:542: Symbols.size() == 19, usedSize == 11
#0  0x0000000000c5b68d in std::__uniq_ptr_impl<LoggerFileWriteStream, std::default_delete<LoggerFileWriteStream> >::_M_ptr() const at /usr/include/c++/8/bits/unique_ptr.h:150
#1  0x00000000009e36c8 in std::unique_ptr<LoggerFileWriteStream, std::default_delete<LoggerFileWriteStream> >::get() const at /usr/include/c++/8/bits/unique_ptr.h:343
#2  0x0000000000a0549f in std::unique_ptr<LoggerFileWriteStream, std::default_delete<LoggerFileWriteStream> >::operator->() const at /usr/include/c++/8/bits/unique_ptr.h:337
#3  0x0000000000c507d3 in Logger::flush() at /tmp/factorio-build-P4Rxlx/src/Util/Logger.cpp:578
#4  0x0000000000c50261 in Logger::logStacktrace(StackTraceInfo*) at /tmp/factorio-build-P4Rxlx/src/Util/Logger.cpp:566
#5  0x0000000000e9082f in Logging::flush() at /tmp/factorio-build-P4Rxlx/src/Util/Logging.cpp:65
#6  0x0000000000ed0750 in Logging::logAndAbortOrThrow(char const*, unsigned int, LogLevel, std::string const&) at /tmp/factorio-build-P4Rxlx/src/Util/Logging.cpp:90
#7  0x0000000000ed1a4c in Logging::logAndAbortOrThrow(char const*, unsigned int, LogLevel, char const*, ...) at /tmp/factorio-build-P4Rxlx/src/Util/Logging.cpp:83
#8  0x00000000017dc61f in Controller::checkConsistency() const at /tmp/factorio-build-P4Rxlx/src/Controller/Controller.cpp:401
#9  0x0000000000008164 in CharacterController::checkConsistency() const at /tmp/factorio-build-P4Rxlx/src/Controller/CharacterController.cpp:882
#10 (nil) in Map::checkConsistency(ProgressObserver*) at /tmp/factorio-build-P4Rxlx/src/Map/Map.cpp:1961 (discriminator 2)
#11 (nil) in Map::setupEntities(MapDeserialiser*, bool, ProgressObserver*) at /tmp/factorio-build-P4Rxlx/src/Map/Map.cpp:1056
#12 0x40341e6d076e4d4c in TimeUtil::CpuTimer::elapsed() const at /tmp/factorio-build-P4Rxlx/src/Util/TimeUtil.hpp:44
#13 0x406ad56c9cab2c96 in TimeUtil::CpuTimer::getSecondsPassed() const at /tmp/factorio-build-P4Rxlx/src/Util/TimeUtil.hpp:29
#14 0xbf8aab6232c41c72 in Scenario::loadFactory(Filesystem::Path const*, Filesystem::Path const&, LoadType, MapDeserialiser*, InputType, InputHandler*, MultiplayerManagerBase*, bool, ProgressObserver*, bool, InputListener*) at /tmp/factorio-build-P4Rxlx/src/Scenario/Scenario.cpp:226
#15 0x3f6555e8289ce390 in ParallelScenarioLoader::doLoad(ParallelScenarioLoader*, MapDeserialiser*, InputType, InputHandler*, MultiplayerManagerBase*, bool) at /tmp/factorio-build-P4Rxlx/src/Scenario/ParallelScenarioLoader.cpp:155
#16 0xbfc94441f8f7260d in execute_native_thread_routine at tmp9LnEF.fake.c:?
#17 0x000000000141e28b in ?? at ??:0
#18 0x8000000000000000 in ?? at ??:0
Stack trace logging done
  11.006 Warning Logger.cpp:542: Symbols.size() == 14, usedSize == 10
  11.006 Error Controller.cpp:398: mainInventory->getHandPosition() == NO_ITEM_STACK_INDEX was not true
Logger::writeStacktrace skipped.
  11.007 Error Util.cpp:97: Unexpected error occurred. If you're running the latest version of the game you can help us solve the problem by posting the contents of the log file on the Factorio forums.
Please also include the save file(s), any mods you may be using, and any steps you know of to reproduce the crash.
  11.007 Uploading log file

[Xertez]

I was looking further into this issue, because it also occurs on 0.17.9, and ran across this post: viewtopic.php?f=7&t=65676

Could the two possibly be related?

[Loewchen]

Post the save please, best use a hosting service and post the link.

[Xertez]

Post the save please, best use a hosting service and post the link.

Understood. Here is the link to the autosave via google drive: https://drive.google.com/file/d/1eLKLZp ... sp=sharing

[kovarex]

Hello, this was fixed for 0.17.9

[Bilka]

Hello, this was fixed for 0.17.9

See a few posts above:

I was looking further into this issue, because it also occurs on 0.17.9, and ran across this post: viewtopic.php?f=7&t=65676

Could the two possibly be related?

[Xertez]

Just an add on, as The error occurs in 0.17.10 as well.

Code: Select all

gamemaster@mars:~/factorio$ clear
gamemaster@mars:~/factorio$ cat Launch.sh
/home/gamemaster/factorio/bin/x64/factorio --server-settings /home/gamemaster/factorio/data/server-settings.json --start-server-load-latest --console-log /home/gamemaster/Factorio.log
gamemaster@mars:~/factorio$ ./Launch.sh
   0.000 2019-03-11 17:00:29; Factorio 0.17.10 (build 43567, linux64, headless)
   0.027 Operating system: Linux (Ubuntu 18.10)
   0.027 Program arguments: "/home/gamemaster/factorio/bin/x64/factorio" "--server-settings" "/home/gamemaster/factorio/data/server-settings.json" "--start-server-load-latest" "--console-log" "/home/gamemaster/Factorio.log"
   0.027 Read data path: /home/gamemaster/factorio/data
   0.027 Write data path: /home/gamemaster/factorio [866944/937529MB]
   0.027 Binaries path: /home/gamemaster/factorio/bin
   0.031 System info: [CPU: Intel(R) Core(TM) i5-6600K CPU @ 3.50GHz, 4 cores, RAM: 15927 MB]
   0.031 Environment: DISPLAY=<unset>, WAYLAND_DISPLAY=<unset>
   0.031 Running in headless mode
   0.033 Loading mod core 0.0.0 (data.lua)
   0.060 Loading mod base 0.17.10 (data.lua)
   0.180 Loading mod base 0.17.10 (data-updates.lua)
   0.236 Checksum for core: 4249075453
   0.236 Checksum of base: 46491745
   0.575 Info PlayerData.cpp:67: Local player-data.json available, timestamp 1552337882
   0.575 Info PlayerData.cpp:74: Cloud player-data.json unavailable
   0.576 Custom inputs active: 0
   0.577 Factorio initialised
   0.580 Info ServerSynchronizer.cpp:29: nextHeartbeatSequenceNumber(0) initialized Synchronizer nextTickClosureTick(0).
   0.580 Info ServerMultiplayerManager.cpp:714: updateTick(4294967295) changing state from(Ready) to(PreparedToHostGame)
   0.580 Info ServerMultiplayerManager.cpp:714: updateTick(4294967295) changing state from(PreparedToHostGame) to(CreatingGame)
   0.580 Loading map /home/gamemaster/factorio/saves/_autosave662.zip: 26517941 bytes.
   0.592 Loading Level.dat: 71575775 bytes.
   0.599 Info Scenario.cpp:147: Map version 0.17.7-2
   7.256 Warning Logger.cpp:542: Symbols.size() == 18, usedSize == 11
Factorio crashed. Generating symbolized stacktrace, please wait ...
Raw stacktrace: 0x9e3b25, 0x9e42a8, 0xa05fcf, 0xc5491b, 0xc54381, 0xe95a6f, 0xed4f40, 0xed623c, 0x17e061f, 0x8164, 0
  11.474 Warning Logger.cpp:542: Symbols.size() == 13, usedSize == 10
#0  0x00000000009e42a8 in Logging::flush() at /tmp/factorio-build-HJFpOf/src/Util/Logging.cpp:65
#1  0x0000000000a05fcf in Logging::logAndAbortOrThrow(char const*, unsigned int, LogLevel, std::string const&) at /tmp/factorio-build-HJFpOf/src/Util/Logging.cpp:90
#2  0x0000000000c5491b in Logging::logAndAbortOrThrow(char const*, unsigned int, LogLevel, char const*, ...) at /tmp/factorio-build-HJFpOf/src/Util/Logging.cpp:83
#3  0x0000000000c54381 in CharacterController::checkConsistency() const at /tmp/factorio-build-HJFpOf/src/Controller/Controller.cpp:401
#4  0x0000000000e95a6f in Map::checkConsistency(ProgressObserver*) at /tmp/factorio-build-HJFpOf/src/Map/Map.cpp:1961 (discriminator 2)
#5  0x0000000000ed4f40 in Map::setupEntities(MapDeserialiser*, bool, ProgressObserver*) at /tmp/factorio-build-HJFpOf/src/Map/Map.cpp:1056
#6  0x0000000000ed623c in TimeUtil::CpuTimer::elapsed() const at /tmp/factorio-build-HJFpOf/src/Util/TimeUtil.hpp:44
#7  0x00000000017e061f in TimeUtil::CpuTimer::getSecondsPassed() const at /tmp/factorio-build-HJFpOf/src/Util/TimeUtil.hpp:29
#8  0x0000000000008164 in Scenario::loadFactory(Filesystem::Path const*, Filesystem::Path const&, LoadType, MapDeserialiser*, InputType, InputHandler*, MultiplayerManagerBase*, bool, ProgressObserver*, bool, InputListener*) at /tmp/factorio-build-HJFpOf/src/Scenario/Scenario.cpp:226
#9  (nil) in ParallelScenarioLoader::doLoad(ParallelScenarioLoader*, MapDeserialiser*, InputType, InputHandler*, MultiplayerManagerBase*, bool) at /tmp/factorio-build-HJFpOf/src/Scenario/ParallelScenarioLoader.cpp:155
#10 (nil) in execute_native_thread_routine at tmpPmHRB.fake.c:?
#11 0x4069e569384ab5a3 in ?? at ??:0
#12 0xbf81170a3ebd706c in ?? at ??:0
Stack trace logging done
  11.474 Error Controller.cpp:401: mainInventory->getHandPosition() == NO_ITEM_STACK_INDEX was not true
Logger::writeStacktrace skipped.
  11.474 Error Util.cpp:97: Unexpected error occurred. If you're running the latest version of the game you can help us solve the problem by posting the contents of the log file on the Factorio forums.
Please also include the save file(s), any mods you may be using, and any steps you know of to reproduce the crash.
  11.474 Uploading log file
gamemaster@mars:~/factorio$

I will provide more info later based on a tip I received.

[kovarex]

The save is 45 bytes so I can't really open it.

[Xertez]

Wanted to give a quick update. On a tip by a friend of mine, I decided to do some troubleshooting. Here was my process:

[1] I logged onto the server from my steam client.
[2] I used the /admin command to open the admin gui.
[3] I pressed "manage", then "delete" on 20 players.
[4] I attempted to update the server via the procedures i outlined in the initial post in this thread.
[5] Each time this failed, I reverted back to 0.17.7.

I repeated the procedures starting at step 1 each time the server ran into the "NO_ITEM_STACK_INDEX" error. Now, a little backstory. The user "Scully_Dog" mentioned that he was unable to play on the server because every time he took something out of his inventory his game crashed. This was also one of the last users I "deleted" from the server before It successfully updated to the current release (at the time of this writing its 0.17.11). Unfortunately I didnt put two and two together until today, but hopefully this info helps you guys (and girls) in some way.

After my server was up and running, i decided to revert back to a backup of the server from before I began troubleshooting, and i used the "/swap-players Scully_Dog" command to swap with him. Sure enough, the moment I pick up anything from the inventory the client crashed, but so did the server. Now The server is headless, and I didn't realize it was crashing until I saw it crash via the console I had open since I SSH into the server to do any management.

Anyways, I'm not sure if the two are related, and I believe I've provided everything necessary to replicate the event (the autosave, the procedures used to troubleshoot, & the procedures to crash the server via Scully_Dog). I hope this helps.

The save is 45 bytes so I can't really open it.

Just a heads up, I just downloaded the autosave and its 186 bytes on my end. If you guys need me to re-upload it, let me know.