[0.16.51] Crash with specific save

[skub]

Hello,

at approx 90sec into the game, I get a segfault (game crash) with my current save.

It gets triggered regardless of any action the player takes. Always at exact same maptick.
My platform is Linux. I was able to reproduce this segfault on my Desktop Factorio, and on dedicated server in Headless mode.
In Headless mode client and server segfault simultaneously.

I tried following steps:
- removing mod "Upgrade Planner"
- removing mod "Bot Autofill"
- remove all remaining landfill-tile-ghosts still in the map
- different and low graphics modes

Following mods have been installed over the course of this save:
- "Base mod" 0.16.51 (the game initially also started with that version, no upgrade)
- "Upgrade Builder and Planner" 1.5.3
- "Nanobots: Early Bots" 2.0.7 (disabled since many hours)
- "Bot Landfill" 1.0.2 (since recently. <= 2hours)

I captured both crashes, as apparently the Headless version is more verbose during crash than my client.

Crash headless server and client logs:
headless server factorio-current.log:

Code: Select all

   0.000 2019-01-29 23:23:54; Factorio 0.16.51 (build 36654, linux64, headless)
   0.064 Operating system: Linux (Debian 9.5)
   0.064 Program arguments: "./bin/x64/factorio" "--server-settings" "sk2/server-settings.json" "--start-server" "sk2/sk2.zip" 
   0.064 Read data path: /home/factorio/factorio/data
   0.064 Write data path: /home/factorio/factorio [435362/461197MB]
   0.064 Binaries path: /home/factorio/factorio/bin
   0.082 System info: [CPU:        Intel(R) Core(TM) i5-2400S CPU @ 2.50GHz, 4 cores, RAM: 7696 MB]
   0.082 Environment: DISPLAY=<unset>, WAYLAND_DISPLAY=<unset>
   0.082 Running in headless mode
   0.091 Loading mod core 0.0.0 (data.lua)
   0.111 Loading mod base 0.16.51 (data.lua)
   0.271 Loading mod upgrade-planner 1.5.3 (data.lua)
   0.307 Loading mod base 0.16.51 (data-updates.lua)
   0.349 Checksum for core: 840319042
   0.349 Checksum of base: 3323233190
   0.349 Checksum of upgrade-planner: 378958687
   0.466 Info PlayerData.cpp:65: Local player-data.json available, timestamp 1548800486
   0.466 Info PlayerData.cpp:72: Cloud player-data.json unavailable
   0.467 Custom inputs active: 0
   0.467 Factorio initialised
   0.468 Info ServerSynchronizer.cpp:29: nextHeartbeatSequenceNumber(0) initialized Synchronizer nextTickClosureTick(0).
   0.468 Info ServerMultiplayerManager.cpp:699: mapTick(4294967295) changing state from(Ready) to(PreparedToHostGame)
   0.468 Info ServerMultiplayerManager.cpp:699: mapTick(4294967295) changing state from(PreparedToHostGame) to(CreatingGame)
   0.468 Loading map /home/factorio/factorio/sk2/sk2.zip: 39060566 bytes.
   0.485 Loading Level.dat: 84878783 bytes.
   0.493 Info Scenario.cpp:136: Map version 0.16.51-0
   4.053 Loading script.dat: 176 bytes.
   4.058 Checksum for script /home/factorio/factorio/temp/currently-playing/control.lua: 950616531
   4.061 Checksum for script __upgrade-planner__/control.lua: 1007996437
   4.092 Info UDPSocket.cpp:27: Opening socket at (IP ADDR:({0.0.0.0:34197}))
   4.092 Hosting game at IP ADDR:({0.0.0.0:34197})
   4.092 Info ServerMultiplayerManager.cpp:699: mapTick(17874018) changing state from(CreatingGame) to(InGame)
   4.092 Info UDPSocket.cpp:39: Opening socket for broadcast
  90.839 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({192.168.3.32:47306}))
  90.839 Refusing connection for address (IP ADDR:({192.168.3.32:47306})), username (skub). ModsMismatch
  91.745 Warning TransmissionControlHelper.cpp:176: Fragment 0001 failed too many times
 142.091 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({192.168.3.32:44019}))
 142.091 Refusing connection for address (IP ADDR:({192.168.3.32:44019})), username (skub). PasswordMissing
 142.981 Warning TransmissionControlHelper.cpp:176: Fragment 0003 failed too many times
 145.800 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({192.168.3.32:44490}))
 145.800 Info ServerRouter.cpp:409: Replying to connectionRequest for address(IP ADDR:({192.168.3.32:44490})).
 145.800 Info ServerSynchronizer.cpp:557: nextHeartbeatSequenceNumber(4221) adding peer(1)
 145.817 Info ServerMultiplayerManager.cpp:699: mapTick(17874018) changing state from(InGame) to(InGameSavingMap)
 145.834 Info ServerMultiplayerManager.cpp:795: mapTick(17874018) received stateChanged peerID(1) oldState(Ready) newState(ConnectedWaitingForMap)
 148.210 Info ServerMultiplayerManager.cpp:855: MapTick(17874018) Serving map(/home/factorio/factorio/temp/mp-save-0.zip) for peer(1) size(38315896) crc(1236606960)
 148.210 Info ServerMultiplayerManager.cpp:699: mapTick(17874018) changing state from(InGameSavingMap) to(InGame)
 148.277 Info ServerMultiplayerManager.cpp:795: mapTick(17874018) received stateChanged peerID(1) oldState(ConnectedWaitingForMap) newState(ConnectedDownloadingMap)
 152.450 Info ServerMultiplayerManager.cpp:795: mapTick(17874018) received stateChanged peerID(1) oldState(ConnectedDownloadingMap) newState(ConnectedLoadingMap)
 154.646 Info ServerMultiplayerManager.cpp:795: mapTick(17874149) received stateChanged peerID(1) oldState(ConnectedLoadingMap) newState(TryingToCatchUp)
 155.383 Info ServerMultiplayerManager.cpp:795: mapTick(17874193) received stateChanged peerID(1) oldState(TryingToCatchUp) newState(WaitingForCommandToStartSendingTickClosures)
 155.384 Info GameActionHandler.cpp:3476: MapTick (17874193) processed PlayerJoinGame peerID(1) playerIndex(0) mode(connect ) 
 155.449 Info ServerMultiplayerManager.cpp:795: mapTick(17874197) received stateChanged peerID(1) oldState(WaitingForCommandToStartSendingTickClosures) newState(InGame)
 232.924 Error CrashHandler.cpp:522: Received SIGSEGV
Factorio crashed. Generating symbolized stacktrace, please wait ...
Raw stacktrace: 0x9594f8, 0xa7bdad, 0x9a16f1, 0x9a1b48, 0x9a1b99, 0x138b878, 0x110c0, 0x84ad26, 0x86d5a2, 0x929a1e, 0x92ac21, 0x92ae37, 0x58f698, 0x938a34, 0x947272, 0x54326d, 0x77800e, 0xba21e8, 0xc58f7d, 0xc59562, 0xc599cc, 0xc6c059, 0xc712a0, 0xc715a3, 0xc71b5b, 0x4206f6, 0, 0x426aef
 236.816 Warning Logger.cpp:494: Symbols.size() == 38, usedSize == 27
#0  0x0000000000a7bdad in std::__uniq_ptr_impl<LoggerFileWriteStream, std::default_delete<LoggerFileWriteStream> >::_M_ptr() const at /usr/include/c++/7/bits/unique_ptr.h:147
#1  0x00000000009a16f1 in std::unique_ptr<LoggerFileWriteStream, std::default_delete<LoggerFileWriteStream> >::get() const at /usr/include/c++/7/bits/unique_ptr.h:337
#2  0x00000000009a1b48 in std::unique_ptr<LoggerFileWriteStream, std::default_delete<LoggerFileWriteStream> >::operator->() const at /usr/include/c++/7/bits/unique_ptr.h:331
#3  0x00000000009a1b99 in Logger::flush() at /tmp/factorio-build-ZMjCBB/src/Util/Logger.cpp:533
#4  0x000000000138b878 in Logger::logStacktrace(StackTraceInfo*) at /tmp/factorio-build-ZMjCBB/src/Util/Logger.cpp:521
#5  0x00000000000110c0 in CrashHandler::writeStackTrace(CrashHandler::CrashReason) at /tmp/factorio-build-ZMjCBB/src/Util/CrashHandler.cpp:173
#6  0x000000000084ad26 in CrashHandler::commonSignalHandler(int) at /tmp/factorio-build-ZMjCBB/src/Util/CrashHandler.cpp:525
#7  0x000000000086d5a2 in CrashHandler::firstChanceHandler(int, void*, void*) at /tmp/factorio-build-ZMjCBB/src/Util/CrashHandler.cpp:604
#8  0x0000000000929a1e in google_breakpad::ExceptionHandler::SignalHandler(int, siginfo_t*, void*) at ??:?
#9  0x000000000092ac21 in ?? at ??:0
#10 0x000000000092ae37 in Chunk::removeActiveNeighbourForce(ForceID) at /tmp/factorio-build-ZMjCBB/src/Surface/Chunk.cpp:755
#11 0x000000000058f698 in EntityWithForce::checkNearbyForcesUnRegistration(ChunkPosition const&) at /tmp/factorio-build-ZMjCBB/src/Entity/EntityWithForce.cpp:104
#12 0x0000000000938a34 in EntityWithForce::forceUnRegistration() at /tmp/factorio-build-ZMjCBB/src/Entity/EntityWithForce.cpp:45
#13 0x0000000000947272 in ChunkPosition::ChunkPosition(MapPosition const&) at /tmp/factorio-build-ZMjCBB/src/Util/ChunkPosition.cpp:34
#14 0x000000000054326d in EntityWithForce::forceReRegistration() at /tmp/factorio-build-ZMjCBB/src/Entity/EntityWithForce.cpp:35
#15 0x000000000077800e in AdvancedTilePosition::AdvancedTilePosition(MapPosition const&) at /tmp/factorio-build-ZMjCBB/src/Util/AdvancedTilePosition.hpp:14
#16 0x0000000000ba21e8 in Entity::changePosition(Vector const&) at /tmp/factorio-build-ZMjCBB/src/Entity/Entity.cpp:544
#17 0x0000000000c58f7d in Unit::changePosition(Vector const&) at /tmp/factorio-build-ZMjCBB/src/Entity/Unit.cpp:143
#18 0x0000000000c59562 in non-virtual thunk to Unit::moveSmooth(Vector const&, double) at /tmp/factorio-build-ZMjCBB/src/Entity/Unit.cpp:129
#19 0x0000000000c599cc in GotoBehavior::execute() at /tmp/factorio-build-ZMjCBB/src/AI/GotoBehavior.cpp:710 (discriminator 4)
#20 0x0000000000c6c059 in Commandable::runBehavior() at /tmp/factorio-build-ZMjCBB/src/AI/Commandable.cpp:183
#21 0x0000000000c712a0 in Unit::update() at /tmp/factorio-build-ZMjCBB/src/Entity/Unit.cpp:256
#22 0x0000000000c715a3 in IntrusiveListIterator<UpdatableEntity, void, false>::operator!=(IntrusiveListIterator<UpdatableEntity, void, false> const&) const at /tmp/factorio-build-ZMjCBB/src/Util/Container/IntrusiveList.hpp:434
#23 0x0000000000c71b5b in Chunk::updateActiveEntities(IntrusiveList<UpdatableEntity, void, false>&) at /tmp/factorio-build-ZMjCBB/src/Surface/Chunk.cpp:575
#24 0x00000000004206f6 in Chunk::isConditionallyActive(unsigned int) const at /tmp/factorio-build-ZMjCBB/src/Surface/Chunk.cpp:893
#25 (nil) in Chunk::updateEntities(unsigned int) at /tmp/factorio-build-ZMjCBB/src/Surface/Chunk.cpp:624
#26 0x0000000000426aef in Surface::update() at /tmp/factorio-build-ZMjCBB/src/Surface/Surface.cpp:1191
#27 (nil) in Map::update() at /tmp/factorio-build-ZMjCBB/src/Map/Map.cpp:1362
#28 (nil) in Game::update() at /tmp/factorio-build-ZMjCBB/src/Game.cpp:163
#29 (nil) in Scenario::update() at /tmp/factorio-build-ZMjCBB/src/Scenario/Scenario.cpp:883
#30 (nil) in Scenario::updateStep() at /tmp/factorio-build-ZMjCBB/src/Scenario/Scenario.cpp:789
#31 (nil) in MainLoop::gameUpdateStep(MultiplayerManagerBase*, Scenario*, AppManager*, MainLoop::HeavyMode) at /tmp/factorio-build-ZMjCBB/src/MainLoop.cpp:1007
#32 (nil) in MainLoop::gameUpdateLoop(MainLoop::HeavyMode) at /tmp/factorio-build-ZMjCBB/src/MainLoop.cpp:874
#33 (nil) in MainLoop::mainLoopStepHeadless(MainLoop::HeavyMode) at /tmp/factorio-build-ZMjCBB/src/MainLoop.cpp:482
#34 (nil) in MainLoop::run(Filesystem::Path const&, Filesystem::Path const&, bool, bool, std::function<void ()>, Filesystem::Path const&, MainLoop::HeavyMode) at /tmp/factorio-build-ZMjCBB/src/MainLoop.cpp:333
#35 (nil) in main at /tmp/factorio-build-ZMjCBB/src/Main.cpp:772 (discriminator 4)
#36 (nil) in ?? at ??:0
#37 (nil) in _start at ??:?
Stack trace logging done
 240.487 Warning Logger.cpp:494: Symbols.size() == 33, usedSize == 26
 240.487 Error CrashHandler.cpp:174: Map tick at moment of crash: 17878845
 240.487 Error Util.cpp:67: 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.
 240.487 Uploading log file
 240.535 Info CrashHandler.cpp:617: Wrote minidump to /home/factorio/factorio/factorio-dump-current.dmp

related dump file from headless server

related factorio-current.log from client connected to headless server
I had binutils and addr2line installed, but still the client logs are not very verbose about the crash. Not sure how to fix that.
and the related dump file from client side as well.

Crash with "fullclient" appears equally. factorio-current.log & factorio-dump-current.dmp

The savefile is ~40MB

You may want to browse all the files conveniently with this link

Looking for some more ideas to troubleshoot. I hope you will be able to reproduce this segfault also reliably.

Best,
skub

[Rseding91]

Thanks for the report. I can see what's broken in the save file but without knowing how it happened there's not much I can do.

There's a behemoth biter on a chunk that says it should not have any biters on it. As a result it crashes trying to perform the normal biter movement logic as the biter walks around.

Do any of the mods you're using create/destroy biters through attack triggers or entity-created triggers?

[skub]

Awesome, that response was fast!

Do any of the mods you're using create/destroy biters through attack triggers or entity-created triggers?

No not as I am aware. I did listed all mods ever installed on that map, and to my knowledge none of these mods create or destroy biters under any circumstance.
Couple of minutes before the error triggered I cleared out a big section with Artillery trains.
Also I did encountered "Entity Id Missing" Errors many hours before, which could only get mitigated by using an older autosave.

No idea about that behemoth unfortunately.

Anything else I can do to help you find the bug? Anything I could do to resurrect that save?

Best,
skub

[Rseding91]

The save seems to be lost. If you've had map corruption issues before on the same computer I'd almost suspect hardware issues (bad RAM maybe).

[skub]

The save seems to be lost.

I was able to recover the save. The command: "/c game.forces["enemy"].kill_all_units()" also triggered the Segmentation Fault (crash).
However, "entity.destroy()" seemed to not trigger this bug.
Thank your for the hint that a Behemoth Biter was the cause. Without that insight I would not have found the solution.

I do not consider that crash a sane behaviour. I agree that a corrupt biter happening somewhere else might be the root-cause for that bug, but still a sane implementation of the biter logic would destroy or skip the execution instead of producing a stack trace.

If you've had map corruption issues before on the same computer I'd almost suspect hardware issues (bad RAM maybe).

To be safe, I performed a memtest86+. As this happens on my work horse, I do suspect that its _not_ a hardware issue. IMHO considering hardware issues the cause of a bug in beta software is a blunt statement, my suspicion is a logic issue in either the mods or factorio as the root cause for the corrupt biter. I hope you'd consider modifying the biter logic to act more resilient.

Thank you for your quick response and help!

Best,
skub

[skub]

The save seems to be lost.

I was able to recover the save. [...]
However, "entity.destroy()" seemed to not trigger this bug.

I need to take that back. I made a mistake when applying entity.destroy() not properly catching that corrupt behemoth entity.
Indeed both: entity.destroy() and also surface.delete_chunk() both also trigger that bug. So I may need to consider abandoning that save.

The chunk and region in question was target of artillery fire not long before that issue. This is unfortunately the only hint I can provide to what may have caused that issue.

Best,
skub

[Rseding91]

I do not consider that crash a sane behaviour. I agree that a corrupt biter happening somewhere else might be the root-cause for that bug, but still a sane implementation of the biter logic would destroy or skip the execution instead of producing a stack trace.

I don't consider any crash a sane behavior but when the logic is written to assume some invariant holds true and it magically doesn't it crashes. Like if going to dispatch on_tick to a mod all of a sudden couldn't find the mod. Absolutely everything in the game logic says the mod should always exist if the save is running but it just happens to be gone - that's not an error condition you program into the logic. That's just a corrupt state and it crashes when it tries to use the non-existent mod.

It's the same logic for the biter: it's written to assume that if it exists, it's hooked up to the chunk(s) it sits on/near. In your save it's not - something broke that invariant and now all of the logic around it is broken. Again - that's not an error case you try to account for because everything anyone can see says it should never happen yet it happened.

I do suspect that its _not_ a hardware issue. IMHO considering hardware issues the cause of a bug in beta software is a blunt statement, my suspicion is a logic issue in either the mods or factorio as the root cause for the corrupt biter. I hope you'd consider modifying the biter logic to act more resilient.

You'd be shocked at what percentage of crashes is memory corruption compared to actual game logic issues. We have automated crash reports and a good 10% of them fall into memory corruption land.

Multiple times we've had people give us save files where 1 bit was flipped in some data structure and flipping it back would restore the save to a perfect working condition. If that was a game logic error it would be happening all the time and be causing more than single bit flips. Single bit flips is a tell-tale sine of memory corruption.

Your RAM can be in "perfect working condition" and still have random bits flipped. A lot of the time it doesn't effect anything - maybe a color value changes slightly - or it's unused memory. But in Factorios case it's detrimental to the save file when a bit is flipped.