[1.1.0] Error on headless server: Child 53 was terminated by signal 9, saving process crashed

[luketyleruk]

last of the script.

762.660 Info AsyncScenarioSaver.cpp:144: Saving process PID: 53
790.036 Error ChildProcessAgent.cpp:62: Child 53 was terminated by signal 9
790.047 Error Util.cpp:83: Attempting to create notice box in headless mode. Message: 'Saving process crashed.'
793.464 Info ServerMultiplayerManager.cpp:113: Disconnecting multiplayer connection.
793.464 Info ServerMultiplayerManager.cpp:780: updateTick(4294967295) changing state from(InGame) to(DisconnectingScheduled)
793.690 Info ServerMultiplayerManager.cpp:140: Quitting multiplayer connection.
793.690 Info ServerMultiplayerManager.cpp:780: updateTick(4294967295) changing state from(DisconnectingScheduled) to(Closed)
793.690 Info HttpSharedState.cpp:54: Downloading https://multiplayer.factorio.com/remove-game/8647461
794.010 Info UDPSocket.cpp:218: Closing socket
794.010 Info UDPSocket.cpp:248: Socket closed
794.010 Info UDPSocket.cpp:218: Closing socket
794.124 Info UDPSocket.cpp:218: Closing socket
794.124 Info UDPSocket.cpp:248: Socket closed
794.128 Goodbye

[Loewchen]

Post the complete log.

[luketyleruk]

Code: Select all

0.002 2020-11-24 15:00:44; Factorio 1.1.0 (build 56997, linux64, headless)
   0.070 Operating system: Linux (Debian 10)
   0.071 Program arguments: "./bin/x64/factorio" "--port" "34197" "--server-settings" "data/server-settings.json" "--start-server" "mega.zip" 
   0.071 Read data path: /home/container/data
   0.071 Write data path: /home/container [16875/40007MB]
   0.071 Binaries path: /home/container/bin
   0.076 System info: [CPU: QEMU Virtual CPU version 2.5+, 4 cores, RAM: 11981 MB]
   0.076 Environment: DISPLAY=<unset> WAYLAND_DISPLAY=<unset> DESKTOP_SESSION=<unset> XDG_SESSION_DESKTOP=<unset> XDG_CURRENT_DESKTOP=<unset> __GL_FSAA_MODE=<unset> __GL_LOG_MAX_ANISO=<unset> __GL_SYNC_TO_VBLANK=<unset> __GL_SORT_FBCONFIGS=<unset> __GL_YIELD=<unset>
   0.076 Running in headless mode
   0.119 Loading mod core 0.0.0 (data.lua)
   0.164 Loading mod base 1.1.0 (data.lua)
   0.395 Loading mod base 1.1.0 (data-updates.lua)
   0.503 Checksum for core: 1359792165
   0.503 Checksum of base: 2334436397
   0.652 Prototype list checksum: 1154245852
   0.686 Info PlayerData.cpp:70: Local player-data.json available, timestamp 1606230042
   0.686 Info PlayerData.cpp:77: Cloud player-data.json unavailable
   0.689 Factorio initialised
   0.690 Info ServerSynchronizer.cpp:29: nextHeartbeatSequenceNumber(0) initialized Synchronizer nextTickClosureTick(0).
   0.690 Info ServerMultiplayerManager.cpp:780: updateTick(4294967295) changing state from(Ready) to(PreparedToHostGame)
   0.690 Info ServerMultiplayerManager.cpp:780: updateTick(4294967295) changing state from(PreparedToHostGame) to(CreatingGame)
   0.690 Loading map /home/container/mega.zip: 278226999 bytes.
   0.701 Loading level.dat: 678435850 bytes.
   0.705 Info Scenario.cpp:199: Map version 1.1.0-40
  15.147 Loading script.dat: 425 bytes.
  15.150 Checksum for script /home/container/temp/currently-playing/control.lua: 2384004003
  15.298 Info UDPSocket.cpp:27: Opening socket at (IP ADDR:({0.0.0.0:34197}))
  15.298 Hosting game at IP ADDR:({0.0.0.0:34197})
  15.298 Info HttpSharedState.cpp:54: Downloading https://auth.factorio.com/generate-server-padlock-2?api_version=4
  15.687 Info AuthServerConnector.cpp:68: Obtained serverPadlock for serverHash (9ZMM5Gwuo1KmweJWtNCEvel9jVPs6ky8) from the auth server.
  15.687 Info ServerMultiplayerManager.cpp:780: updateTick(27513066) changing state from(CreatingGame) to(InGame)
  15.784 Info ServerRouter.cpp:636: Asking pingpong servers (pingpong1.factorio.com:34197, pingpong2.factorio.com:34197, pingpong3.factorio.com:34197, pingpong4.factorio.com:34197) for own address
  15.785 Info UDPSocket.cpp:39: Opening socket for broadcast
  15.785 Info CommandLineMultiplayer.cpp:278: Maximum segment size = 100; minimum segment size = 25; maximum-segment-size peer count = 10; minimum-segment-size peer count = 20
  15.870 Info ServerRouter.cpp:519: Own address is IP ADDR:({51.77.226.83:34197}) (confirmed by pingpong1)
  15.887 Info ServerRouter.cpp:519: Own address is IP ADDR:({51.77.226.83:34197}) (confirmed by pingpong3)
  16.038 Info ServerRouter.cpp:519: Own address is IP ADDR:({51.77.226.83:34197}) (confirmed by pingpong4)
  16.279 Info MatchingServer.cpp:114: Matching server game `8647461` has been created.
  16.291 Info ServerMultiplayerManager.cpp:712: Matching server connection resumed
  27.907 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({213.104.125.23:2094}))
  27.907 Info ServerRouter.cpp:602: Generated hmac(dAtxadx7ezOvHsPfLEgoUQ==) and serverKey(xkcvXViSFKZZ1mIyVCOunw==) for username(ColonelWill) differ. Generated from message(ColonelWill_uyeNI1maSCtpaxnNKk1D97czogZHbEBXHDQbh8mZgdk=_201124145121).
  27.907 Refusing connection for address (IP ADDR:({213.104.125.23:2094})), username (ColonelWill). UserVerificationMismatch
  28.662 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({213.104.125.23:2098}))
  28.662 Info ServerRouter.cpp:453: Replying to connectionRequest for address(IP ADDR:({213.104.125.23:2098})).
  28.662 Info ServerSynchronizer.cpp:600: nextHeartbeatSequenceNumber(383) adding peer(1)
  28.679 Warning WriteFileGuard.cpp:96: Couldn't chown /home/container/player-data.tmp.json: Operation not permitted
  28.680 Info ServerMultiplayerManager.cpp:780: updateTick(27513066) changing state from(InGame) to(InGameSavingMap)
  28.748 Info ServerMultiplayerManager.cpp:930: updateTick(27513066) received stateChanged peerID(1) oldState(Ready) newState(ConnectedWaitingForMap)
  35.111 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({217.137.42.72:1403}))
  35.111 Info ServerRouter.cpp:602: Generated hmac(cW9Wuz9RhknDO+c7kBZFqg==) and serverKey(g7IB7udPhrOIBmqagnrHIQ==) for username(studix2002) differ. Generated from message(studix2002_uyeNI1maSCtpaxnNKk1D97czogZHbEBXHDQbh8mZgdk=_201124145128).
  35.111 Refusing connection for address (IP ADDR:({217.137.42.72:1403})), username (studix2002). UserVerificationMismatch
  36.173 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({217.137.42.72:1406}))
  36.173 Info ServerRouter.cpp:453: Replying to connectionRequest for address(IP ADDR:({217.137.42.72:1406})).
  36.173 Info ServerSynchronizer.cpp:600: nextHeartbeatSequenceNumber(606) adding peer(2)
  36.275 Info ServerMultiplayerManager.cpp:930: updateTick(27513066) received stateChanged peerID(2) oldState(Ready) newState(ConnectedWaitingForMap)
  37.568 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({82.11.248.109:57122}))
  37.568 Info ServerRouter.cpp:602: Generated hmac(+qZ+Lx31Ia3C12zGax2UcQ==) and serverKey(+OXcWLKnLm/o+eK5XsrZ2g==) for username(lukus) differ. Generated from message(lukus_uyeNI1maSCtpaxnNKk1D97czogZHbEBXHDQbh8mZgdk=_201124144739).
  37.568 Refusing connection for address (IP ADDR:({82.11.248.109:57122})), username (lukus). UserVerificationMismatch
  38.105 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({82.11.248.109:59264}))
  38.105 Info ServerRouter.cpp:453: Replying to connectionRequest for address(IP ADDR:({82.11.248.109:59264})).
  38.105 Info ServerSynchronizer.cpp:600: nextHeartbeatSequenceNumber(664) adding peer(3)
  38.155 Info ServerMultiplayerManager.cpp:930: updateTick(27513066) received stateChanged peerID(3) oldState(Ready) newState(ConnectedWaitingForMap)
  40.447 Info ServerMultiplayerManager.cpp:997: UpdateTick(27513066) Serving map(/home/container/temp/mp-save-0.zip) for peer(1) size(277641637) crc(2030808986)
  40.447 Info ServerMultiplayerManager.cpp:997: UpdateTick(27513066) Serving map(/home/container/temp/mp-save-0.zip) for peer(2) size(277641637) crc(2030808986)
  40.447 Info ServerMultiplayerManager.cpp:997: UpdateTick(27513066) Serving map(/home/container/temp/mp-save-0.zip) for peer(3) size(277641637) crc(2030808986)
  40.447 Info ServerMultiplayerManager.cpp:780: updateTick(27513066) changing state from(InGameSavingMap) to(InGame)
  40.564 Info ServerMultiplayerManager.cpp:930: updateTick(27513066) received stateChanged peerID(3) oldState(ConnectedWaitingForMap) newState(ConnectedDownloadingMap)
  40.615 Info ServerMultiplayerManager.cpp:930: updateTick(27513066) received stateChanged peerID(1) oldState(ConnectedWaitingForMap) newState(ConnectedDownloadingMap)
  40.682 Info ServerMultiplayerManager.cpp:930: updateTick(27513066) received stateChanged peerID(2) oldState(ConnectedWaitingForMap) newState(ConnectedDownloadingMap)
  41.643 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({81.140.239.206:50204}))
  41.643 Info ServerRouter.cpp:602: Generated hmac(rOoHPgHse/XlD0XewYsWJg==) and serverKey(x1Afi5pQVj77kBez22BxuQ==) for username(Higiey) differ. Generated from message(Higiey_uyeNI1maSCtpaxnNKk1D97czogZHbEBXHDQbh8mZgdk=_201124145615).
  41.644 Refusing connection for address (IP ADDR:({81.140.239.206:50204})), username (Higiey). UserVerificationMismatch
  42.287 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({81.140.239.206:58614}))
  42.287 Info ServerRouter.cpp:453: Replying to connectionRequest for address(IP ADDR:({81.140.239.206:58614})).
  42.287 Info ServerSynchronizer.cpp:600: nextHeartbeatSequenceNumber(780) adding peer(4)
  42.305 Info ServerMultiplayerManager.cpp:780: updateTick(27513066) changing state from(InGame) to(InGameSavingMap)
  42.461 Info ServerMultiplayerManager.cpp:930: updateTick(27513066) received stateChanged peerID(4) oldState(Ready) newState(ConnectedWaitingForMap)
  54.197 Info ServerMultiplayerManager.cpp:997: UpdateTick(27513066) Serving map(/home/container/temp/mp-save-1.zip) for peer(4) size(277641637) crc(1592605191)
  54.197 Info ServerMultiplayerManager.cpp:780: updateTick(27513066) changing state from(InGameSavingMap) to(InGame)
  54.424 Info ServerMultiplayerManager.cpp:930: updateTick(27513066) received stateChanged peerID(4) oldState(ConnectedWaitingForMap) newState(ConnectedDownloadingMap)
 113.311 Info ServerMultiplayerManager.cpp:930: updateTick(27513066) received stateChanged peerID(3) oldState(ConnectedDownloadingMap) newState(ConnectedLoadingMap)
 120.791 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({5.146.195.184:52859}))
 120.791 Refusing connection for address (IP ADDR:({5.146.195.184:52859})), username (posteule). UserVerificationMissing
 121.641 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({5.146.195.184:52939}))
 121.641 Refusing connection for address (IP ADDR:({5.146.195.184:52939})), username (posteule). PasswordMissing
 128.374 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({5.146.195.184:52991}))
 128.374 Info ServerRouter.cpp:453: Replying to connectionRequest for address(IP ADDR:({5.146.195.184:52991})).
 128.374 Info ServerSynchronizer.cpp:600: nextHeartbeatSequenceNumber(3378) adding peer(5)
 128.391 Info ServerMultiplayerManager.cpp:780: updateTick(27513970) changing state from(InGame) to(InGameSavingMap)
 128.437 Info ServerMultiplayerManager.cpp:930: updateTick(27513970) received stateChanged peerID(5) oldState(Ready) newState(ConnectedWaitingForMap)
 128.808 Info ServerMultiplayerManager.cpp:930: updateTick(27513970) received stateChanged peerID(4) oldState(ConnectedDownloadingMap) newState(ConnectedLoadingMap)
 137.745 Info ServerMultiplayerManager.cpp:930: updateTick(27513970) received stateChanged peerID(3) oldState(ConnectedLoadingMap) newState(TryingToCatchUp)
 140.242 Info ServerMultiplayerManager.cpp:997: UpdateTick(27513970) Serving map(/home/container/temp/mp-save-2.zip) for peer(5) size(277591974) crc(3012265541)
 140.242 Info ServerMultiplayerManager.cpp:780: updateTick(27513970) changing state from(InGameSavingMap) to(InGame)
 140.421 Info ServerMultiplayerManager.cpp:930: updateTick(27513984) received stateChanged peerID(5) oldState(ConnectedWaitingForMap) newState(ConnectedDownloadingMap)
 147.080 Info ServerMultiplayerManager.cpp:930: updateTick(27514384) received stateChanged peerID(4) oldState(ConnectedLoadingMap) newState(TryingToCatchUp)
 147.815 Info ServerMultiplayerManager.cpp:930: updateTick(27514428) received stateChanged peerID(1) oldState(ConnectedDownloadingMap) newState(ConnectedLoadingMap)
 155.692 Info ServerMultiplayerManager.cpp:930: updateTick(27514901) received stateChanged peerID(3) oldState(TryingToCatchUp) newState(WaitingForCommandToStartSendingTickClosures)
 155.694 Info GameActionHandler.cpp:4976: UpdateTick (27514901) processed PlayerJoinGame peerID(3) playerIndex(10) mode(connect) 
 155.798 Info ServerMultiplayerManager.cpp:930: updateTick(27514907) received stateChanged peerID(3) oldState(WaitingForCommandToStartSendingTickClosures) newState(InGame)
 166.777 Info ServerMultiplayerManager.cpp:930: updateTick(27515326) received stateChanged peerID(1) oldState(ConnectedLoadingMap) newState(TryingToCatchUp)
 173.219 Info ServerMultiplayerManager.cpp:930: updateTick(27515326) received stateChanged peerID(4) oldState(TryingToCatchUp) newState(WaitingForCommandToStartSendingTickClosures)
 173.287 Info ServerMultiplayerManager.cpp:930: updateTick(27515326) received stateChanged peerID(4) oldState(WaitingForCommandToStartSendingTickClosures) newState(InGame)
 175.250 Info ServerMultiplayerManager.cpp:930: updateTick(27515326) received stateChanged peerID(5) oldState(ConnectedDownloadingMap) newState(ConnectedLoadingMap)
 189.063 Info ServerMultiplayerManager.cpp:930: updateTick(27515326) received stateChanged peerID(1) oldState(TryingToCatchUp) newState(WaitingForCommandToStartSendingTickClosures)
 189.198 Info ServerMultiplayerManager.cpp:930: updateTick(27515326) received stateChanged peerID(1) oldState(WaitingForCommandToStartSendingTickClosures) newState(InGame)
 195.219 Info GameActionHandler.cpp:4976: UpdateTick (27515326) processed PlayerJoinGame peerID(1) playerIndex(0) mode(connect) 
 195.219 Info GameActionHandler.cpp:4976: UpdateTick (27515326) processed PlayerJoinGame peerID(4) playerIndex(33) mode(connect) 
 210.254 Info ServerMultiplayerManager.cpp:930: updateTick(27516229) received stateChanged peerID(5) oldState(ConnectedLoadingMap) newState(TryingToCatchUp)
 307.029 Info ServerMultiplayerManager.cpp:930: updateTick(27522014) received stateChanged peerID(5) oldState(TryingToCatchUp) newState(WaitingForCommandToStartSendingTickClosures)
 307.030 Info GameActionHandler.cpp:4976: UpdateTick (27522014) processed PlayerJoinGame peerID(5) playerIndex(41) mode(connect) 
 307.119 Info ServerMultiplayerManager.cpp:930: updateTick(27522020) received stateChanged peerID(5) oldState(WaitingForCommandToStartSendingTickClosures) newState(InGame)
 436.657 Info ServerMultiplayerManager.cpp:930: updateTick(27529787) received stateChanged peerID(2) oldState(ConnectedDownloadingMap) newState(ConnectedLoadingMap)
 466.526 Info ServerMultiplayerManager.cpp:930: updateTick(27531579) received stateChanged peerID(2) oldState(ConnectedLoadingMap) newState(TryingToCatchUp)
 743.681 Info ServerMultiplayerManager.cpp:930: updateTick(27539658) received stateChanged peerID(2) oldState(TryingToCatchUp) newState(WaitingForCommandToStartSendingTickClosures)
 743.766 Info ServerMultiplayerManager.cpp:930: updateTick(27539658) received stateChanged peerID(2) oldState(WaitingForCommandToStartSendingTickClosures) newState(InGame)
 756.914 Info GameActionHandler.cpp:4976: UpdateTick (27539658) processed PlayerJoinGame peerID(2) playerIndex(3) mode(connect) 
 762.618 Info AppManager.cpp:285: Saving to _autosave5 (non-blocking).
 762.660 Info AsyncScenarioSaver.cpp:144: Saving process PID: 53
 790.036 Error ChildProcessAgent.cpp:62: Child 53 was terminated by signal 9
 790.047 Error Util.cpp:83: Attempting to create notice box in headless mode. Message: 'Saving process crashed.'
 793.464 Info ServerMultiplayerManager.cpp:113: Disconnecting multiplayer connection.
 793.464 Info ServerMultiplayerManager.cpp:780: updateTick(4294967295) changing state from(InGame) to(DisconnectingScheduled)
 793.690 Info ServerMultiplayerManager.cpp:140: Quitting multiplayer connection.
 793.690 Info ServerMultiplayerManager.cpp:780: updateTick(4294967295) changing state from(DisconnectingScheduled) to(Closed)
 793.690 Info HttpSharedState.cpp:54: Downloading https://multiplayer.factorio.com/remove-game/8647461
 794.010 Info UDPSocket.cpp:218: Closing socket
 794.010 Info UDPSocket.cpp:248: Socket closed
 794.010 Info UDPSocket.cpp:218: Closing socket
 794.124 Info UDPSocket.cpp:218: Closing socket
 794.124 Info UDPSocket.cpp:248: Socket closed
 794.128 Goodbye

[luketyleruk]

just found a link about the crash on auto save, just looked at that and i think this is same issue, just testing now

[luketyleruk]

looks like the autosave was killing the server, i turned off autosave and seems stable atm, might have another issue with the Child 53 thing.

[Loewchen]

I think it's a different manifestation of 82786.

[movax20h]

Do you have any mods? I heard sometimes mods might cause asynchronous auto save to crash.

If it is unmodded, if you can share the save, I can test async autosave on my Linux machine. I personally use async autosave for a long time, (vanilla, no mods), and never had a crash, even on hugs bases, and frequent autosaves.

[luketyleruk]

no mods, save file is attached

[Squelch]

I think it's a different manifestation of 82786.

It does seem to be.

looks like the autosave was killing the server, i turned off autosave and seems stable atm, might have another issue with the Child 53 thing.

What's the environment for your headless server? It appears to be virtualised and this might be a factor in the problems encountered with non blocking saves. Can you confirm that you have this set in server settings?

[blahfasel2000]

Signal 9 is SIGKILL. Assuming noone was messing around and manually killing processes on the server the most likely explanation is that the OP's server simply ran out of memory, which caused the OOM killer to kill the autosave process (the OOM killer uses SIGKILL).

OP, if you still have the server's kernel message logs from the time of the crash, please take a look to confirm, there should be a bunch of kernel message about the OOM killer (search for "Out of memory: Kill process").

It doesn't look like those other instances of async autosave crashes/hangs at all to me. Although I would say that in the case of this happening (ie. the child getting SIGKILLed), instead of terminating I think factorio should probably just display an error to players and turn off async saves (odds are that without forking the OOM might not happen again) while continueing to run normally.