carlquistb / FormulaCraft

An SMS-based service for running Minecraft server on AWS.
MIT License
0 stars 1 forks source link

failure in upload world resulted in mineService termination. Child process continued to run. #48

Closed carlquistb closed 4 years ago

carlquistb commented 4 years ago

._uploadWorld() was unable to save two files, and mineService entered a error state. Minecraft continued to run, but the wrapper function did not respond to calls, save or exit.

journalctl -u mineService below:

-- Logs begin at Sat 2020-09-19 20:00:54 UTC, end at Sun 2020-09-20 02:04:19 UTC. --
Sep 19 20:01:52 ip-172-32-4-250.us-west-2.compute.internal systemd[1]: Started MC Server Node Wrapper Service.
Sep 19 20:01:52 ip-172-32-4-250.us-west-2.compute.internal systemd[1]: Starting MC Server Node Wrapper Service...
Sep 19 20:04:20 ip-172-32-4-250.us-west-2.compute.internal node[3092]: okazninja
Sep 19 20:04:40 ip-172-32-4-250.us-west-2.compute.internal node[3092]: okazninja
Sep 19 20:17:00 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [mineShell] Uploading world...
Sep 19 20:19:40 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [ 'okazninja', 'Xenobo' ]
Sep 19 20:32:00 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [mineShell] Uploading world...
Sep 19 20:34:40 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [ 'okazninja', 'Xenobo' ]
Sep 19 20:47:00 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [mineShell] Uploading world...
Sep 19 20:49:40 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [ 'okazninja', 'Xenobo' ]
Sep 19 21:02:00 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [mineShell] Uploading world...
Sep 19 21:04:40 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [ 'okazninja', 'Xenobo' ]
Sep 19 21:17:01 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [mineShell] Uploading world...
Sep 19 21:19:40 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [ 'okazninja', 'Xenobo' ]
Sep 19 21:32:01 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [mineShell] Uploading world...
Sep 19 21:34:40 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [ 'okazninja', 'Xenobo' ]
Sep 19 21:47:01 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [mineShell] Uploading world...
Sep 19 21:49:41 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [ 'okazninja', 'Xenobo' ]
Sep 19 22:02:01 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [mineShell] Uploading world...
Sep 19 22:04:41 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [ 'okazninja', 'Xenobo' ]
Sep 19 22:17:01 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [mineShell] Uploading world...
Sep 19 22:19:41 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [ 'okazninja', 'Xenobo' ]
Sep 19 22:32:01 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [mineShell] Uploading world...
Sep 19 22:34:41 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [ 'okazninja', 'Xenobo' ]
Sep 19 22:47:01 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [mineShell] Uploading world...
Sep 19 22:49:41 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [ 'okazninja', 'Xenobo' ]
Sep 19 23:02:01 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [mineShell] Uploading world...
Sep 19 23:04:41 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [ 'okazninja', 'Xenobo' ]
Sep 19 23:17:01 ip-172-32-4-250.us-west-2.compute.internal node[3092]: [mineShell] Uploading world...
Sep 19 23:17:12 ip-172-32-4-250.us-west-2.compute.internal node[3092]: upload failed: home/ec2-user/mc/world/DIM-1/region/r.0.0.mca to s3://bc-minecraft-repo/worlds/BD79E8C933DCB739D/world/DIM-1/region/r.0.0.mca An error occurred (BadDigest) when calling the PutObject operation (reached max retries: 4): The Content-MD5 you specified did not match what we received.
Sep 19 23:17:12 ip-172-32-4-250.us-west-2.compute.internal node[3092]: upload failed: home/ec2-user/mc/world/DIM-1/region/r.0.-1.mca to s3://bc-minecraft-repo/worlds/BD79E8C933DCB739D/world/DIM-1/region/r.0.-1.mca An error occurred (BadDigest) when calling the PutObject operation (reached max retries: 4): The Content-MD5 you specified did not match what we received.
Sep 19 23:17:12 ip-172-32-4-250.us-west-2.compute.internal node[3092]: child_process.js:669
Sep 19 23:17:12 ip-172-32-4-250.us-west-2.compute.internal node[3092]: throw err;
Sep 19 23:17:12 ip-172-32-4-250.us-west-2.compute.internal node[3092]: ^
Sep 19 23:17:12 ip-172-32-4-250.us-west-2.compute.internal node[3092]: Error: Command failed: aws s3 sync /home/ec2-user/mc/world s3://bc-minecraft-repo/worlds/BD79E8C933DCB739D/world
Sep 19 23:17:12 ip-172-32-4-250.us-west-2.compute.internal node[3092]: upload failed: home/ec2-user/mc/world/DIM-1/region/r.0.0.mca to s3://bc-minecraft-repo/worlds/BD79E8C933DCB739D/world/DIM-1/region/r.0.0.mca An error occurred (BadDigest) when calling the PutObject operation (reached max retries: 4): The Content-MD5 you specified did not match what we received.
Sep 19 23:17:12 ip-172-32-4-250.us-west-2.compute.internal node[3092]: upload failed: home/ec2-user/mc/world/DIM-1/region/r.0.-1.mca to s3://bc-minecraft-repo/worlds/BD79E8C933DCB739D/world/DIM-1/region/r.0.-1.mca An error occurred (BadDigest) when calling the PutObject operation (reached max retries: 4): The Content-MD5 you specified did not match what we received.
Sep 19 23:17:12 ip-172-32-4-250.us-west-2.compute.internal node[3092]: at checkExecSyncError (child_process.js:629:11)
Sep 19 23:17:12 ip-172-32-4-250.us-west-2.compute.internal node[3092]: at execSync (child_process.js:666:13)
Sep 19 23:17:12 ip-172-32-4-250.us-west-2.compute.internal node[3092]: at Object.sync (/home/ec2-user/autostack-scripts/AWS.js:4:2)
Sep 19 23:17:12 ip-172-32-4-250.us-west-2.compute.internal node[3092]: at MineShell._uploadWorld (/home/ec2-user/autostack-scripts/MineShell.js:124:7)
Sep 19 23:17:12 ip-172-32-4-250.us-west-2.compute.internal node[3092]: at Timeout.setInterval [as _onTimeout] (/home/ec2-user/autostack-scripts/MineShell.js:105:25)
Sep 19 23:17:12 ip-172-32-4-250.us-west-2.compute.internal node[3092]: at ontimeout (timers.js:436:11)
Sep 19 23:17:12 ip-172-32-4-250.us-west-2.compute.internal node[3092]: at tryOnTimeout (timers.js:300:5)
Sep 19 23:17:12 ip-172-32-4-250.us-west-2.compute.internal node[3092]: at listOnTimeout (timers.js:263:5)
Sep 19 23:17:12 ip-172-32-4-250.us-west-2.compute.internal node[3092]: at Timer.processTimers (timers.js:223:10)
Sep 19 23:17:12 ip-172-32-4-250.us-west-2.compute.internal systemd[1]: mineService.service: main process exited, code=exited, status=1/FAILURE
Sep 19 23:17:12 ip-172-32-4-250.us-west-2.compute.internal systemd[1]: Unit mineService.service entered failed state.
Sep 19 23:17:12 ip-172-32-4-250.us-west-2.compute.internal systemd[1]: mineService.service failed.

notes:

the error occurred during a save initiated by the 15 minute loop, based on the timing of the error messages at 23:17:12 This was 10 seconds after the upload was initiated.

Based on the error message, I'm thinking this has to do with the file being changed in between the start of the sync and when the file was received by AWS. We could use save-stop and save-start to resolve it.

nlipiarski commented 4 years ago

Closed by #49