Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Combined trains break apart after server restarting #486

Open
BiDuang opened this issue Nov 9, 2023 · 42 comments
Open

Combined trains break apart after server restarting #486

BiDuang opened this issue Nov 9, 2023 · 42 comments

Comments

@BiDuang
Copy link

BiDuang commented Nov 9, 2023

English is not my native language; please excuse typing errors.

Info

Please provide the following information:

  • BkCommonLib Version (/train version): 1.20.2-v1 (build: 1464)
  • TrainCarts Version (/train version): v1.20.2-v1 (build: 1634)
  • Server Type and Version (/version): git-Paper-280 (MC: 1.20.2)

Bug

Description

Combination trains running on loop lines will malfunction after a server restart. For example, carts will disconnect from each other and became a new train.

Before restart:
2023-11-09_10 25 49

After restart:
2023-11-09_11 01 33

You can see that some train got new children.

Steps to reproduce

Just restart the server and do nothing.

@bergerkiller
Copy link
Member

Where the trains revert, is that near to the spawn area of the server, and is the spawn kept loaded? Do the trains have keepchunksloaded on?

@BiDuang
Copy link
Author

BiDuang commented Nov 9, 2023

Where the trains revert, is that near to the spawn area of the server, and is the spawn kept loaded? Do the trains have keepchunksloaded on?

Some of them near the spawn area, but not very close(maybe about 100-200 blocks away?)

And yes, each train has enabled keepchunksloaded to ensure it can running on a circle line.

@bergerkiller
Copy link
Member

bergerkiller commented Nov 9, 2023

And /train startuplog doesnt show any errors at startup when this happens? Its going to be difficult to figure out when/what causes it. Not easy to reproduce on my end anyways

@BiDuang
Copy link
Author

BiDuang commented Nov 10, 2023

And /train startuplog doesnt show any errors at startup when this happens? Its going to be difficult to figure out when/what causes it. Not easy to reproduce on my end anyways

Yes, nothing goes wrong in the log:

====================================================
Date: Friday, November 10, 2023 GMT+8
Server: git-Paper-280 (MC: 1.20.2) (JDK 17.0.6+9-LTS-190)
Relevant plugins:
  - BKCommonLib 1.20.2-v1 (build: 1634) (jar: BKCommonLib-1.20.2-v1-1634.jar)
  - Train_Carts 1.20.2-v1 (build: 1464) (jar: TrainCarts-1.20.2-v1-1464.jar)
====================================================

---- Plugin logs ----
[10:26:13] [INFO] [BKCommonLib] Loading server plugin BKCommonLib v1.20.2-v1
[10:26:23] [INFO] [Train_Carts] 0 detector rail regions loaded covering 0 blocks
[10:26:25] [INFO] [BKCommonLib] Enabling BKCommonLib v1.20.2-v1
[10:26:26] [INFO] [BKCommonLib] BKCommonLib is running on Paper (git-Paper-280) : v1_20_R2 (Minecraft 1.20.2)
[10:26:26] [INFO] [BKCommonLib.Network] Now using the ProtocolLib library to provide Packet Listener and Monitor support
[10:26:26] [INFO] [BKCommonLib] Supplier supplying suppliers for your lazy needs!
[10:26:26] [INFO] [BKCommonLib] BKCommonLib version 1.20.2-v1 (build: 1634) enabled! (0.871s)
[10:26:28] [INFO] [BKCommonLib] [RegionChangeTracker] Region block changes will be notified from WorldEdit (>= v7.0.0)
[10:26:29] [INFO] [BKCommonLib] ViaVersion detected, will use it to detect player game versions
[10:26:29] [INFO] [Train_Carts] Enabling Train_Carts v1.20.2-v1
[10:26:33] [INFO] [Train_Carts] [Resource Pack Models] Loading resource pack item model lists
[10:26:33] [INFO] [Train_Carts] SignLink detected, support for arrival signs added!
[10:26:34] [INFO] [Train_Carts] 12 Trains have been loaded in 1 world. (240 Minecarts)
[10:26:34] [INFO] [Train_Carts] Restoring trains and loading nearby chunks...
[10:26:43] [INFO] [Train_Carts] Train_Carts version 1.20.2-v1 (build: 1464) enabled! (13.178s)
[10:26:43] [INFO] [Train_Carts] SignLink detected, support for arrival signs added!

---- Miscellaneous server logs ----
[10:26:24] [INFO] [Minecraft] Server permissions file permissions.yml is empty, ignoring it
[10:26:44] [INFO] [Minecraft] [CoreProtect] 使用 SQLite 用于数据存储。
[10:26:44] [INFO] [Minecraft] --------------------
[10:26:44] [INFO] [Minecraft] [CoreProtect] 对 CoreProtect 感到满意吗?请加入我们的 Discord 频道!
[10:26:44] [INFO] [Minecraft] [CoreProtect] Discord: www.coreprotect.net/discord/
[10:26:44] [INFO] [Minecraft] --------------------
[...]
[10:26:44] [INFO] [Minecraft] [CoreProtect] 与 WorldEdit 的交互已成功初始化。
[10:26:45] [INFO] [Minecraft] Timings Reset

This issue occurs every time the server starts. I have updated all plugins and server core but the problem is not resolved.

@BiDuang
Copy link
Author

BiDuang commented Nov 14, 2023

I suspect this error occurs during the save or restore phase. Because if you don't reboot the server, then everything will be fine.

@bergerkiller
Copy link
Member

Can you stop the server and upload the latest.log generated at that point? Its possible the server did not properly shut down (and save). So it should show the plugins disabling and worlds saving before the server shuts off.

@BiDuang
Copy link
Author

BiDuang commented Nov 14, 2023

Can you stop the server and upload the latest.log generated at that point? Its possible the server did not properly shut down (and save). So it should show the plugins disabling and worlds saving before the server shuts off.

Sure, there's the log:

[16:37:46 INFO]: There are 11 trains on this server (of which 8
[16:37:46 INFO]:  are moving)
[16:37:46 INFO]: There are 336 minecart entities
[16:37:46 INFO]: The following trains exist on this server:
[16:37:46 INFO]: L1-1 / L1-2 / L1-3 / L2-1 / L2-2 / L2-3 / L2-4 / L2-5
[16:37:46 INFO]: L2-6 / L2-7 / woolfact
[16:37:52 INFO]: Stopping the server
[16:37:52 INFO]: Stopping server
[16:37:52 INFO]: [AntiPopup] Disabling AntiPopup v7
[16:37:52 INFO]: [AntiPopup] Disabled PacketEvents.
[16:37:52 INFO]: [Chunky] Disabling Chunky v1.3.92
[16:37:52 INFO]: [CoreProtect] Disabling CoreProtect v22.2
[16:37:52 INFO]: [CoreProtect] 正在完成数据记录,请稍等...
[16:37:53 INFO]: [CoreProtect] 禁用 CoreProtect v22.2 成功!
[16:37:53 INFO]: [GravityControl] Disabling GravityControl v2.0.0
[16:37:53 INFO]: [Images] Disabling Images v2.3.1
[16:37:53 INFO]: [ResourcePack-Plugin] Disabling ResourcePack-Plugin v1.7.3
[16:37:53 INFO]: [ResourcePack-Plugin] ResourcePack-plugin has been disabled!
[16:37:53 INFO]: [SeeMore] Disabling SeeMore v1.0.2
[16:37:53 INFO]: [TabTPS] Disabling TabTPS v1.3.21
[16:37:53 INFO]: [Train_Carts] Disabling Train_Carts v1.20.2-v1
[16:37:54 INFO]: [Train_Carts] Train_Carts disabled!
[16:37:54 INFO]: [ViaBackwards] Disabling ViaBackwards v4.8.1
[16:37:54 INFO]: [BlueMap] Disabling BlueMap v3.17
[16:37:54 INFO]: [BlueMap] Stopping...
[16:37:54 INFO]: [BlueMap] Saved and stopped!
[16:37:54 INFO]: [WorldEdit] Disabling WorldEdit v7.2.17+6544-56d0383
[16:37:54 INFO]: [BKCommonLib] [RegionChangeTracker] Region block changes will no longer be notified from WorldEdit (>= v7.0.0)
[16:37:54 INFO]: Unregistering com.sk89q.worldedit.bukkit.BukkitServerInterface from WorldEdit
[16:37:54 INFO]: [SignLink] Disabling SignLink v1.20.2-v1
[16:37:54 INFO]: [SignLink] SignLink disabled!
[16:37:54 INFO]: [Vault] Disabling Vault v1.7.3-b131
[16:37:54 INFO]: [BKCommonLib] Disabling BKCommonLib v1.20.2-v1
[16:37:54 INFO]: [PlaceholderAPI] Disabling PlaceholderAPI v2.11.5
[16:37:54 INFO]: [LuckPerms] Disabling LuckPerms v5.4.82
[16:37:54 INFO]: [LuckPerms] Starting shutdown process...
[16:37:54 INFO]: [LuckPerms] Closing storage...
[16:37:54 INFO]: [LuckPerms] Goodbye!
[16:37:54 INFO]: [ProtocolLib] Disabling ProtocolLib v5.1.1-SNAPSHOT-673
[16:37:54 INFO]: [ViaVersion] Disabling ViaVersion v4.8.1
[16:37:54 INFO]: [ViaVersion] ViaVersion is disabling, if this is a reload and you experience issues consider rebooting.
[16:37:54 INFO]: Saving players
[16:37:54 INFO]: Saving worlds
[16:37:54 INFO]: Saving chunks for level 'ServerLevel[world]'/minecraft:overworld
[16:37:54 INFO]: [ChunkHolderManager] Waiting 60s for chunk system to halt for world 'world'
[16:37:54 INFO]: [ChunkHolderManager] Halted chunk system for world 'world'
[16:37:54 INFO]: [ChunkHolderManager] Saving all chunkholders for world 'world'
[16:37:55 INFO]: [ChunkHolderManager] Saved 330 block chunks, 774 entity chunks, 0 poi chunks in world 'world' in 0.62s
[16:37:55 INFO]: ThreadedAnvilChunkStorage (world): All chunks are saved
[16:37:55 INFO]: Saving chunks for level 'ServerLevel[world_nether]'/minecraft:the_nether
[16:37:55 INFO]: [ChunkHolderManager] Waiting 60s for chunk system to halt for world 'world_nether'
[16:37:55 INFO]: [ChunkHolderManager] Halted chunk system for world 'world_nether'
[16:37:55 INFO]: [ChunkHolderManager] Saving all chunkholders for world 'world_nether'
[16:37:55 INFO]: [ChunkHolderManager] Saved 400 block chunks, 160 entity chunks, 0 poi chunks in world 'world_nether' in 0.45s
[16:37:55 INFO]: ThreadedAnvilChunkStorage (DIM-1): All chunks are saved
[16:37:55 INFO]: Saving chunks for level 'ServerLevel[world_the_end]'/minecraft:the_end
[16:37:55 INFO]: [ChunkHolderManager] Waiting 60s for chunk system to halt for world 'world_the_end'
[16:37:55 INFO]: [ChunkHolderManager] Halted chunk system for world 'world_the_end'
[16:37:55 INFO]: [ChunkHolderManager] Saving all chunkholders for world 'world_the_end'
[16:37:55 INFO]: [ChunkHolderManager] Saved 1 block chunks, 5 entity chunks, 0 poi chunks in world 'world_the_end' in 0.02s
[16:37:55 INFO]: ThreadedAnvilChunkStorage (DIM1): All chunks are saved
[16:37:55 INFO]: ThreadedAnvilChunkStorage: All dimensions are saved
[16:37:55 INFO]: Flushing Chunk IO
[16:37:55 INFO]: Closing Thread Pool
2023-11-14 16:37:55,868 Log4j2-AsyncAppenderEventDispatcher-1-Async WARN Advanced terminal features are not available in this environment
[16:37:55 INFO]: Closing Server

Starting org.bukkit.craftbukkit.Main
System Info: Java 17 (Java HotSpot(TM) 64-Bit Server VM 17.0.6+9-LTS-190) Host: Windows 11 10.0 (amd64)
Loading libraries, please wait...
2023-11-14 16:38:56,772 ServerMain WARN Advanced terminal features are not available in this environment
[16:38:59 INFO]: Environment: Environment[accountsHost=https://api.mojang.com, sessionHost=https://sessionserver.mojang.com, servicesHost=https://api.minecraftservices.com, name=PROD]
[16:39:00 INFO]: Loaded 7 recipes
[16:39:00 INFO]: Starting minecraft server version 1.20.2
[16:39:00 INFO]: Loading properties
[16:39:00 INFO]: This server is running Paper version git-Paper-280 (MC: 1.20.2) (Implementing API version 1.20.2-R0.1-SNAPSHOT) (Git: 4675152)
[16:39:01 INFO]: Server Ping Player Sample Count: 12
[16:39:01 INFO]: Using 4 threads for Netty based IO
[16:39:01 WARN]: [!] The timings profiler has been enabled but has been scheduled for removal from Paper in the future.
    We recommend installing the spark profiler as a replacement: https://spark.lucko.me/
    For more information please visit: https://github.com/PaperMC/Paper/issues/8948
[16:39:01 INFO]: [ChunkTaskScheduler] Chunk system is using 1 I/O threads, 5 worker threads, and gen parallelism of 5 threads
[16:39:01 INFO]: Default game type: SURVIVAL
[16:39:01 INFO]: Generating keypair
[16:39:01 INFO]: Starting Minecraft server on *:25565
[16:39:01 INFO]: Using default channel type
[16:39:01 INFO]: Paper: Using Java compression from Velocity.
[16:39:01 INFO]: Paper: Using Java cipher from Velocity.
[16:39:01 INFO]: [SpigotLibraryLoader] [AntiPopup] Loading 1 libraries... please wait
[16:39:01 INFO]: [SpigotLibraryLoader] [AntiPopup] Loaded library D:\MCSManager\daemon\data\InstanceData\19474cdaca8245f4ae1764d280385f04\libraries\dev\dejvokep\boosted-yaml-spigot\1.3\boosted-yaml-spigot-1.3.jar
[16:39:01 INFO]: [ViaVersion] Loading server plugin ViaVersion v4.8.1
[16:39:01 INFO]: [ViaVersion] ViaVersion 4.8.1 is now loaded. Registering protocol transformers and injecting...
[16:39:01 INFO]: [ViaVersion] Loading block connection mappings ...
[16:39:01 INFO]: [ViaVersion] Using FastUtil Long2ObjectOpenHashMap for block connections
[16:39:02 INFO]: [ViaBackwards] Loading translations...
[16:39:02 INFO]: [ViaBackwards] Registering protocols...
[16:39:02 INFO]: [ProtocolLib] Loading server plugin ProtocolLib v5.1.1-SNAPSHOT-673
[16:39:03 INFO]: [LuckPerms] Loading server plugin LuckPerms v5.4.82
[16:39:04 INFO]: [PlaceholderAPI] Loading server plugin PlaceholderAPI v2.11.5
[16:39:04 INFO]: [BKCommonLib] Loading server plugin BKCommonLib v1.20.2-v1
[16:39:09 WARN]: [org.bukkit.craftbukkit.v1_20_R2.legacy.CraftLegacy] Initializing Legacy Material Support. Unless you have legacy plugins and/or data this is a bug!
[16:39:15 INFO]: [Vault] Loading server plugin Vault v1.7.3-b131
[16:39:15 INFO]: [SignLink] Loading server plugin SignLink v1.20.2-v1
[16:39:15 INFO]: [WorldEdit] Loading server plugin WorldEdit v7.2.17+6544-56d0383
[16:39:15 INFO]: Got request to register class com.sk89q.worldedit.bukkit.BukkitServerInterface with WorldEdit [com.sk89q.worldedit.extension.platform.PlatformManager@6b5fb7a4]
[16:39:15 INFO]: [BlueMap] Loading server plugin BlueMap v3.17
[16:39:15 INFO]: [ViaBackwards] Loading server plugin ViaBackwards v4.8.1
[16:39:15 INFO]: [Train_Carts] Loading server plugin Train_Carts v1.20.2-v1
[16:39:16 INFO]: [Train_Carts] 0 detector rail regions loaded covering 0 blocks
[16:39:16 INFO]: [TabTPS] Loading server plugin TabTPS v1.3.21
[16:39:16 INFO]: [SeeMore] Loading server plugin SeeMore v1.0.2
[16:39:16 INFO]: [ResourcePack-Plugin] Loading server plugin ResourcePack-Plugin v1.7.3
[16:39:16 INFO]: [Images] Loading server plugin Images v2.3.1
[16:39:16 INFO]: [GravityControl] Loading server plugin GravityControl v2.0.0
[16:39:16 INFO]: [CoreProtect] Loading server plugin CoreProtect v22.2
[16:39:16 INFO]: [Chunky] Loading server plugin Chunky v1.3.92
[16:39:16 INFO]: [AntiPopup] Loading server plugin AntiPopup v7
[16:39:16 INFO]: [AntiPopup] Loaded PacketEvents.
[16:39:16 INFO]: Server permissions file permissions.yml is empty, ignoring it
[16:39:16 INFO]: [ProtocolLib] Enabling ProtocolLib v5.1.1-SNAPSHOT-673
[16:39:16 INFO]: [LuckPerms] Enabling LuckPerms v5.4.82
[16:39:17 INFO]:         __    
[16:39:17 INFO]:   |    |__)   LuckPerms v5.4.82
[16:39:17 INFO]:   |___ |      Running on Bukkit - Paper
[16:39:17 INFO]: 
[16:39:17 INFO]: [LuckPerms] Loading configuration...
[16:39:17 INFO]: [LuckPerms] Loading storage provider... [H2]
[16:39:18 INFO]: [LuckPerms] Loading internal permission managers...
[16:39:18 INFO]: [LuckPerms] Performing initial data load...
[16:39:18 INFO]: [LuckPerms] Successfully enabled. (took 1652ms)
[16:39:18 INFO]: [BKCommonLib] Enabling BKCommonLib v1.20.2-v1
[16:39:18 INFO]: [BKCommonLib] BKCommonLib is running on Paper (git-Paper-280) : v1_20_R2 (Minecraft 1.20.2)
[16:39:18 INFO]: [BKCommonLib.Network] Now using the ProtocolLib library to provide Packet Listener and Monitor support
[16:39:19 INFO]: [BKCommonLib] Bringing home the bacon since 2011!
[16:39:19 INFO]: [BKCommonLib] BKCommonLib version 1.20.2-v1 (build: 1634) enabled! (1.154s)
[16:39:19 INFO]: [Vault] Enabling Vault v1.7.3-b131
[16:39:19 INFO]: [Vault] [Permission] SuperPermissions loaded as backup permission system.
[16:39:19 INFO]: [Vault] Enabled Version 1.7.3-b131
[16:39:19 INFO]: [LuckPerms] Registered Vault permission & chat hook.
[16:39:19 INFO]: [WorldEdit] Enabling WorldEdit v7.2.17+6544-56d0383
[16:39:19 INFO]: Registering commands with com.sk89q.worldedit.bukkit.BukkitServerInterface
[16:39:20 INFO]: WEPIF: Vault detected! Using Vault for permissions
[16:39:20 INFO]: Using com.sk89q.worldedit.bukkit.adapter.impl.v1_20_R2.PaperweightAdapter as the Bukkit adapter
[16:39:21 INFO]: [BKCommonLib] [RegionChangeTracker] Region block changes will be notified from WorldEdit (>= v7.0.0)
[16:39:21 INFO]: [ResourcePack-Plugin] Enabling ResourcePack-Plugin v1.7.3
[16:39:21 INFO]: [ResourcePack-Plugin]  ===============================================
[16:39:21 INFO]: [ResourcePack-Plugin]           ResourcePack-plugin launched!!
[16:39:21 INFO]: [ResourcePack-Plugin]              By CokeFenya And Fess_
[16:39:21 INFO]: [ResourcePack-Plugin]                   Version: 1.5
[16:39:21 INFO]: [ResourcePack-Plugin]              The plugin was created:
[16:39:21 INFO]: [ResourcePack-Plugin]            https://github.com/CokeFenya
[16:39:21 INFO]: [ResourcePack-Plugin]  ===============================================
[16:39:21 INFO]: Preparing level "world"
[16:39:22 INFO]: Preparing start region for dimension minecraft:overworld
[16:39:23 INFO]: Time elapsed: 528 ms
[16:39:23 INFO]: Preparing start region for dimension minecraft:the_nether
[16:39:23 INFO]: Time elapsed: 40 ms
[16:39:23 INFO]: Preparing start region for dimension minecraft:the_end
[16:39:23 INFO]: Time elapsed: 44 ms
[16:39:23 INFO]: [ViaVersion] Enabling ViaVersion v4.8.1
[16:39:23 INFO]: [ViaVersion] ViaVersion detected server version: 1.20.2 (764)
[16:39:23 INFO]: [BKCommonLib] ViaVersion detected, will use it to detect player game versions
[16:39:23 INFO]: [PlaceholderAPI] Enabling PlaceholderAPI v2.11.5
[16:39:23 INFO]: [PlaceholderAPI] Fetching available expansion information...
[16:39:23 INFO]: [SignLink] Enabling SignLink v1.20.2-v1
[16:39:24 INFO]: [PlaceholderAPI] Successfully registered internal expansion: signlink [1.20.2-v1]
[16:39:24 INFO]: [PlaceholderAPI] Successfully registered internal expansion: sl [1.20.2-v1]
[16:39:24 INFO]: [SignLink] SignLink version 1.20.2-v1 (build: 89) enabled! (0.115s)
[16:39:24 INFO]: [BlueMap] Enabling BlueMap v3.17
[16:39:24 INFO]: [BlueMap] Loading...
[16:39:24 INFO]: [ViaBackwards] Enabling ViaBackwards v4.8.1
[16:39:24 INFO]: [Train_Carts] Enabling Train_Carts v1.20.2-v1
[16:39:24 INFO]: [BlueMap] Loading resources...
[16:39:25 INFO]: [BlueMap] Loading textures...
[16:39:28 INFO]: [Train_Carts] [Resource Pack Models] Loading resource pack item model lists
[16:39:28 INFO]: [Train_Carts] SignLink detected, support for arrival signs added!
[16:39:28 INFO]: [BlueMap] Baking resources...
[16:39:29 INFO]: [BlueMap] Resources loaded.
[16:39:29 INFO]: [BlueMap] Loading world '832ed081-eb04-48a9-b773-3f364ee97064' (D:\MCSManager\daemon\data\InstanceData\19474cdaca8245f4ae1764d280385f04\world)...
[16:39:29 INFO]: [BlueMap] Initializing Storage: 'file' (Type: FILE)
[16:39:29 INFO]: [BlueMap] Loading map 'world'...
[16:39:29 INFO]: [Train_Carts] 11 Trains have been loaded in 1 world. (241 Minecarts)
[16:39:29 INFO]: [Train_Carts] Restoring trains and loading nearby chunks...
[16:39:30 INFO]: [BlueMap] Loading world 'cd544f83-1e1f-444d-84d1-24d47dc3ca5c' (D:\MCSManager\daemon\data\InstanceData\19474cdaca8245f4ae1764d280385f04\world_the_end\DIM1)...
[16:39:30 INFO]: [BlueMap] Loading map 'world_the_end'...
[16:39:32 INFO]: [BlueMap] Loading world '053b4f49-7909-4462-959e-f81d87c42b35' (D:\MCSManager\daemon\data\InstanceData\19474cdaca8245f4ae1764d280385f04\world_nether\DIM-1)...
[16:39:32 INFO]: [BlueMap] Loading map 'world_nether'...
[16:39:33 INFO]: [BlueMap] WebServer bound to all network interfaces on port 8100
[16:39:33 INFO]: [BlueMap] WebServer started.
[16:39:33 INFO]: [BlueMap] Loaded!
[16:39:39 INFO]: [Train_Carts] Train_Carts version 1.20.2-v1 (build: 1464) enabled! (15.132s)
[16:39:39 INFO]: [Train_Carts] SignLink detected, support for arrival signs added!
[16:39:39 INFO]: [TabTPS] Enabling TabTPS v1.3.21
[16:39:39 INFO]: [TabTPS] Successfully registered Mojang Brigadier support for commands.
[16:39:39 INFO]: [TabTPS] Successfully registered asynchronous command completion listener.
[16:39:39 INFO]: [SeeMore] Enabling SeeMore v1.0.2
[16:39:39 INFO]: [Images] Enabling Images v2.3.1
[16:39:39 INFO]: [Images] ProtocolLib detected. Enabling generic packet handling...
[16:39:39 INFO]: [GravityControl] Enabling GravityControl v2.0.0
[16:39:40 INFO]: [CoreProtect] Enabling CoreProtect v22.2
[16:39:40 INFO]: [CoreProtect] CoreProtect 已成功启用! 
[16:39:40 INFO]: [CoreProtect] 使用 SQLite 用于数据存储。
[16:39:40 INFO]: --------------------
[16:39:40 INFO]: [CoreProtect] 对 CoreProtect 感到满意吗?请加入我们的 Discord 频道!
[16:39:40 INFO]: [CoreProtect] Discord: www.coreprotect.net/discord/
[16:39:40 INFO]: --------------------
[16:39:40 INFO]: [Chunky] Enabling Chunky v1.3.92
[16:39:40 INFO]: [AntiPopup] Enabling AntiPopup v7
[16:39:40 INFO]: [AntiPopup] Config enabled.
[16:39:40 INFO]: [AntiPopup] Initiated PacketEvents.
[16:39:40 INFO]: [AntiPopup] Hooked on 1.20.2
[16:39:40 INFO]: [AntiPopup] Commands registered.
[16:39:40 INFO]: [AntiPopup] Logger filter enabled.
[16:39:40 INFO]: [PlaceholderAPI] Placeholder expansion registration initializing...
[16:39:40 INFO]: JMX monitoring enabled
[16:39:40 INFO]: Running delayed init tasks
[16:39:40 INFO]: [CoreProtect] 与 WorldEdit 的交互已成功初始化。
[16:39:40 INFO]: [ViaVersion] Finished mapping loading, shutting down loader executor!
[16:39:40 INFO]: [Vault] Checking for Updates ... 
[16:39:41 INFO]: [Vault] No new version available
[16:39:41 INFO]: [PlaceholderAPI] Successfully registered external expansion: player [2.0.5]
[16:39:41 INFO]: [PlaceholderAPI] Successfully registered external expansion: servertime [3.2]
[16:39:41 INFO]: 2 placeholder hook(s) registered! 1 placeholder hook(s) have an update available.
[16:39:41 INFO]: Done (40.684s)! For help, type "help"
[16:39:41 INFO]: Timings Reset
[16:39:47 WARN]: Can't keep up! Is the server overloaded? Running 5030ms or 100 ticks behind
[16:39:48 INFO]: [Images] Loaded 18 images...
[16:40:13 INFO]: There are 13 trains on this server (of which 8
[16:40:13 INFO]:  are moving)
[16:40:13 INFO]: There are 333 minecart entities
[16:40:13 INFO]: The following trains exist on this server:
[16:40:13 INFO]: L1-1 / L1-2 / L1-3 / L2-1 / L2-2 / L2-3 / L2-4 / L2-5
[16:40:13 INFO]: L2-6 / L2-7 / L2-7~c / L2-7~d / woolfact

I cannot find anything wrong in there, have you got any idea?

@bergerkiller
Copy link
Member

The only thing I find strange is that the bluemap plugin is kicked into action while traincarts is loading trains/chunks. Its a far-off guess, but can you see what happens if you restart without bluemap running? If the same problem still occurs?

If it does its an annoying bug to track down, Ill have to send some custom builds that adds some debugging information

@BiDuang
Copy link
Author

BiDuang commented Nov 14, 2023

The only thing I find strange is that the bluemap plugin is kicked into action while traincarts is loading trains/chunks. Its a far-off guess, but can you see what happens if you restart without bluemap running? If the same problem still occurs?

If it does its an annoying bug to track down, Ill have to send some custom builds that adds some debugging information

Okay, I will try it. Thanks a lot!

@BiDuang
Copy link
Author

BiDuang commented Nov 16, 2023

The only thing I find strange is that the bluemap plugin is kicked into action while traincarts is loading trains/chunks. Its a far-off guess, but can you see what happens if you restart without bluemap running? If the same problem still occurs?

If it does its an annoying bug to track down, Ill have to send some custom builds that adds some debugging information

I disabled the Bluemap, but it didn't work. The train was still torn apart.

@bergerkiller
Copy link
Member

Went over the track walking code again, so I need to narrow down what to look for. Do you know precisely where trains disconnect? If not, I can send a test build that logs the coordinates carts have when they disconnect.

If you do, does this happen while the cart is on a curved piece of vanilla track?

@bergerkiller
Copy link
Member

bergerkiller commented Nov 16, 2023

Ive added a debug mode to hopefully more easily identify why trains split. Update to this build: https://ci.mg-dev.eu/job/TrainCarts/1481/

Boot server with it once, stop again. Then edit config.yml and set logTrainSplitting: true. It will then log all the splits that occur shortly after the server restart, and at normal runtime. Where, why and what cart(s)

@BiDuang
Copy link
Author

BiDuang commented Nov 17, 2023

Cool, it catched!

[16:49:23 INFO]: 2 placeholder hook(s) registered! 1 placeholder hook(s) have an update available.
[16:49:23 WARN]: [Train_Carts] Train 'L1-1' split apart because: Next cart is derailed
[16:49:23 WARN]: [Train_Carts] Search start: {rail={RailTypePowered{powered=true} -203/53/35}, pos={-202.0/53.0625/35.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:23 WARN]: [Train_Carts] Search end: {rail={NONE -204/53/36}, pos={-203.6567/53.0625/36.1567}, mot={-0.7071/0.0/0.7071}, f=SOUTH}
[16:49:23 WARN]: [Train_Carts] Cart that could not be reached: cart #14 of 24 at x=-203.65665663044663 y=53.0625 z=36.15665663044661
[16:49:23 WARN]: [Train_Carts] Train 'L1-1' split apart because: Next cart is derailed
[16:49:23 WARN]: [Train_Carts] Search start: {rail={RailTypePowered{powered=true} -203/53/35}, pos={-202.0/53.0625/35.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:23 WARN]: [Train_Carts] Search end: {rail={NONE -204/53/36}, pos={-203.6567/53.0625/36.1567}, mot={-0.6991/0.0/-0.715}, f=NORTH}
[16:49:23 WARN]: [Train_Carts] Cart that could not be reached: cart #14 of 24 at x=-203.65665663044663 y=53.0625 z=36.15665663044661
[16:49:23 INFO]: [ViaVersion] Finished mapping loading, shutting down loader executor!
[16:49:23 WARN]: [Train_Carts] Train 'L1-1' split apart because: Next cart is derailed
[16:49:23 WARN]: [Train_Carts] Search start: {rail={RailTypePowered{powered=true} -203/53/35}, pos={-202.0/53.0625/35.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:23 WARN]: [Train_Carts] Search end: {rail={NONE -204/53/36}, pos={-203.9196/53.0622/36.3563}, mot={-0.6991/0.0/-0.715}, f=NORTH}
[16:49:23 WARN]: [Train_Carts] Cart that could not be reached: cart #14 of 24 at x=-203.91958714110055 y=53.06223877590793 z=36.356287503865886
[16:49:23 INFO]: [Vault] Checking for Updates ... 
[16:49:23 WARN]: [Train_Carts] Train 'L1-1' split apart because: Next cart is derailed
[16:49:23 WARN]: [Train_Carts] Search start: {rail={RailTypePowered{powered=true} -203/53/35}, pos={-202.0/53.0625/35.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:23 WARN]: [Train_Carts] Search end: {rail={NONE -204/53/36}, pos={-203.9196/53.0622/36.3563}, mot={-0.668/1.0E-4/-0.7441}, f=NORTH}
[16:49:23 WARN]: [Train_Carts] Cart that could not be reached: cart #14 of 24 at x=-203.91958714110055 y=53.06223877590793 z=36.356287503865886
[16:49:23 WARN]: [Train_Carts] Train 'L1-1' split apart because: Next cart is derailed
[16:49:23 WARN]: [Train_Carts] Search start: {rail={RailTypePowered{powered=true} -203/53/35}, pos={-202.0/53.0625/35.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:23 WARN]: [Train_Carts] Search end: {rail={NONE -204/53/36}, pos={-203.9196/53.0622/36.3563}, mot={-0.668/1.0E-4/-0.7441}, f=NORTH}
[16:49:23 WARN]: [Train_Carts] Cart that could not be reached: cart #14 of 24 at x=-203.91958714110055 y=53.06223877590793 z=36.356287503865886
[16:49:23 WARN]: [Train_Carts] Train 'L1-1' split apart because: Next cart is derailed
[16:49:23 WARN]: [Train_Carts] Search start: {rail={RailTypePowered{powered=true} -204/53/35}, pos={-203.0/53.0625/35.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:23 WARN]: [Train_Carts] Search end: {rail={NONE -205/53/36}, pos={-204.1825/53.0617/36.547}, mot={-0.668/1.0E-4/-0.7441}, f=NORTH}
[16:49:23 WARN]: [Train_Carts] Cart that could not be reached: cart #14 of 24 at x=-204.18251968302818 y=53.06171802088557 z=36.54698984905209
[16:49:23 WARN]: [Train_Carts] Train 'L1-1' split apart because: Next cart is derailed
[16:49:23 WARN]: [Train_Carts] Search start: {rail={RailTypePowered{powered=true} -204/53/35}, pos={-203.0/53.0625/35.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:23 WARN]: [Train_Carts] Search end: {rail={NONE -205/53/36}, pos={-204.1825/53.0617/36.547}, mot={-0.6417/3.0E-4/-0.767}, f=NORTH}
[16:49:23 WARN]: [Train_Carts] Cart that could not be reached: cart #14 of 24 at x=-204.18251968302818 y=53.06171802088557 z=36.54698984905209
[16:49:23 WARN]: [Train_Carts] Train 'L1-1' split apart because: Next cart is derailed
[16:49:23 WARN]: [Train_Carts] Search start: {rail={RailTypePowered{powered=true} -204/53/35}, pos={-203.0/53.0625/35.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:23 WARN]: [Train_Carts] Search end: {rail={NONE -205/53/36}, pos={-204.1825/53.0617/36.547}, mot={-0.6417/3.0E-4/-0.767}, f=NORTH}
[16:49:23 WARN]: [Train_Carts] Cart that could not be reached: cart #14 of 24 at x=-204.18251968302818 y=53.06171802088557 z=36.54698984905209
[16:49:23 WARN]: [Train_Carts] Train 'L1-1' split apart because: Next cart is derailed
[16:49:23 WARN]: [Train_Carts] Search start: {rail={RailTypePowered{powered=true} -204/53/35}, pos={-203.0/53.0625/35.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:23 WARN]: [Train_Carts] Search end: {rail={NONE -205/53/36}, pos={-204.4453/53.0609/36.7268}, mot={-0.6417/3.0E-4/-0.767}, f=NORTH}
[16:49:23 WARN]: [Train_Carts] Cart that could not be reached: cart #14 of 24 at x=-204.44533336233116 y=53.06094427654565 z=36.72678569364815
[16:49:24 INFO]: [Vault] No new version available
[16:49:24 INFO]: Done (39.035s)! For help, type "help"
[16:49:24 INFO]: Timings Reset
[16:49:24 WARN]: [Train_Carts] Train 'L1-1' split apart because: Next cart is derailed
[16:49:24 WARN]: [Train_Carts] Search start: {rail={RailTypePowered{powered=true} -204/53/35}, pos={-203.0/53.0625/35.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:24 WARN]: [Train_Carts] Search end: {rail={NONE -205/53/36}, pos={-204.4453/53.0609/36.7268}, mot={-0.6197/5.0E-4/-0.7848}, f=NORTH}
[16:49:24 WARN]: [Train_Carts] Cart that could not be reached: cart #14 of 24 at x=-204.44533336233116 y=53.06094427654565 z=36.72678569364815
[16:49:24 WARN]: [Train_Carts] Train 'L1-1' split apart because: Next cart is derailed
[16:49:24 WARN]: [Train_Carts] Search start: {rail={RailTypePowered{powered=true} -204/53/35}, pos={-203.0/53.0625/35.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:24 WARN]: [Train_Carts] Search end: {rail={NONE -205/53/36}, pos={-204.4453/53.0609/36.7268}, mot={-0.6197/5.0E-4/-0.7848}, f=NORTH}
[16:49:24 WARN]: [Train_Carts] Cart that could not be reached: cart #14 of 24 at x=-204.44533336233116 y=53.06094427654565 z=36.72678569364815
[16:49:24 WARN]: [Train_Carts] Train 'L1-1' split apart because: Next cart is derailed
[16:49:24 WARN]: [Train_Carts] Search start: {rail={RailTypePowered{powered=true} -204/53/35}, pos={-203.0/53.0625/35.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:24 WARN]: [Train_Carts] Search end: {rail={NONE -205/53/36}, pos={-204.7084/53.0599/36.8945}, mot={-0.6197/5.0E-4/-0.7848}, f=NORTH}
[16:49:24 WARN]: [Train_Carts] Cart that could not be reached: cart #14 of 24 at x=-204.70838465243475 y=53.05992799653855 z=36.89453332264862
[16:49:24 WARN]: [Train_Carts] Train 'L1-1' split apart because: Next cart is derailed
[16:49:24 WARN]: [Train_Carts] Search start: {rail={RailTypePowered{powered=true} -204/53/35}, pos={-203.0/53.0625/35.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:24 WARN]: [Train_Carts] Search end: {rail={NONE -205/53/36}, pos={-204.7084/53.0599/36.8945}, mot={-0.6015/9.0E-4/-0.7988}, f=NORTH}
[16:49:24 WARN]: [Train_Carts] Cart that could not be reached: cart #14 of 24 at x=-204.70838465243475 y=53.05992799653855 z=36.89453332264862
[16:49:24 WARN]: [Train_Carts] Train 'L1-1' split apart because: Next cart is derailed
[16:49:24 WARN]: [Train_Carts] Search start: {rail={RailTypePowered{powered=true} -204/53/35}, pos={-203.0/53.0625/35.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:24 WARN]: [Train_Carts] Search end: {rail={NONE -205/53/36}, pos={-204.7084/53.0599/36.8945}, mot={-0.6015/9.0E-4/-0.7988}, f=NORTH}
[16:49:24 WARN]: [Train_Carts] Cart that could not be reached: cart #14 of 24 at x=-204.70838465243475 y=53.05992799653855 z=36.89453332264862
[16:49:24 WARN]: [Train_Carts] Train 'L1-1' split apart because: Next cart is derailed
[16:49:24 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -205/53/35}, pos={-204.0/53.0625/35.5}, mot={-0.7071/0.0/-0.7071}, f=NORTH}
[16:49:24 WARN]: [Train_Carts] Search end: {rail={NONE -205/53/37}, pos={-204.9722/53.0587/37.0498}, mot={-0.6015/9.0E-4/-0.7988}, f=NORTH}
[16:49:24 WARN]: [Train_Carts] Cart that could not be reached: cart #14 of 24 at x=-204.9721673871252 y=53.058681956363635 z=37.04980968820402
[16:49:24 WARN]: [Train_Carts] Train 'L1-1' split apart because: Next cart is derailed
[16:49:24 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -205/53/35}, pos={-204.0/53.0625/35.5}, mot={-0.7071/0.0/-0.7071}, f=NORTH}
[16:49:24 WARN]: [Train_Carts] Search end: {rail={NONE -205/53/37}, pos={-204.9722/53.0587/37.0498}, mot={-0.5866/0.0012/-0.8098}, f=NORTH}
[16:49:24 WARN]: [Train_Carts] Cart that could not be reached: cart #14 of 24 at x=-204.9721673871252 y=53.058681956363635 z=37.04980968820402
[16:49:24 WARN]: [Train_Carts] Train 'L1-1' split apart because: Next cart is derailed
[16:49:24 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -205/53/35}, pos={-204.0/53.0625/35.5}, mot={-0.7071/0.0/-0.7071}, f=NORTH}
[16:49:24 WARN]: [Train_Carts] Search end: {rail={NONE -205/53/37}, pos={-204.9722/53.0587/37.0498}, mot={-0.5866/0.0012/-0.8098}, f=NORTH}
[16:49:24 WARN]: [Train_Carts] Cart that could not be reached: cart #14 of 24 at x=-204.9721673871252 y=53.058681956363635 z=37.04980968820402
[16:49:24 WARN]: [Train_Carts] Train 'L1-1' split apart because: Next cart is derailed
[16:49:24 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -205/53/35}, pos={-204.0/53.0625/35.5}, mot={-0.7071/0.0/-0.7071}, f=NORTH}
[16:49:24 WARN]: [Train_Carts] Search end: {rail={NONE -206/53/37}, pos={-205.2333/53.0572/37.1842}, mot={-0.5866/0.0012/-0.8098}, f=NORTH}
[16:49:24 WARN]: [Train_Carts] Cart that could not be reached: cart #14 of 24 at x=-205.23325795523226 y=53.05723617547564 z=37.18421121634505
[16:49:24 WARN]: [Train_Carts] Train 'L1-1' split apart because: Next cart is derailed
[16:49:24 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -205/53/35}, pos={-204.0/53.0625/35.5}, mot={-0.7071/0.0/-0.7071}, f=NORTH}
[16:49:24 WARN]: [Train_Carts] Search end: {rail={NONE -206/53/37}, pos={-205.2333/53.0572/37.1842}, mot={-0.5562/0.0016/-0.8311}, f=NORTH}
[16:49:24 WARN]: [Train_Carts] Cart that could not be reached: cart #14 of 24 at x=-205.23325795523226 y=53.05723617547564 z=37.18421121634505
[16:49:24 WARN]: [Train_Carts] Train 'L1-1' split apart because: Next cart is derailed
[16:49:24 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -205/53/35}, pos={-204.0/53.0625/35.5}, mot={-0.7071/0.0/-0.7071}, f=NORTH}
[16:49:24 WARN]: [Train_Carts] Search end: {rail={NONE -206/53/37}, pos={-205.2333/53.0572/37.1842}, mot={-0.5562/0.0016/-0.8311}, f=NORTH}
[16:49:24 WARN]: [Train_Carts] Cart that could not be reached: cart #14 of 24 at x=-205.23325795523226 y=53.05723617547564 z=37.18421121634505
[16:49:24 WARN]: [Train_Carts] Train 'L1-1' split apart because: Next cart is derailed
[16:49:24 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -205/53/34}, pos={-204.5/53.0625/35.0}, mot={-0.7071/0.0/-0.7071}, f=NORTH}
[16:49:24 WARN]: [Train_Carts] Search end: {rail={NONE -206/53/37}, pos={-205.4916/53.0556/37.2927}, mot={-0.5562/0.0016/-0.8311}, f=NORTH}
[16:49:24 WARN]: [Train_Carts] Cart that could not be reached: cart #14 of 24 at x=-205.49163055110333 y=53.05561270693594 z=37.292706976306725
[16:49:24 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:24 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -205/53/34}, pos={-204.5/53.0625/35.0}, mot={-0.7071/0.0/-0.7071}, f=NORTH}
[16:49:24 WARN]: [Train_Carts] Search end: {rail={NONE -206/53/37}, pos={-205.4916/53.0556/37.2927}, mot={-0.3748/-0.0023/0.9271}, f=SOUTH}
[16:49:24 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-205.49163055110333 y=53.05561270693594 z=37.292706976306725
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -205/53/34}, pos={-204.5/53.0625/35.0}, mot={-0.7071/0.0/-0.7071}, f=NORTH}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -206/53/37}, pos={-205.4916/53.0556/37.2927}, mot={-0.3428/-0.0027/0.9394}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-205.49163055110333 y=53.05561270693594 z=37.292706976306725
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -205/53/34}, pos={-204.5/53.0625/35.0}, mot={-0.7071/0.0/-0.7071}, f=NORTH}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -206/53/37}, pos={-205.4916/53.0556/37.2927}, mot={-0.3428/-0.0027/0.9394}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-205.49163055110333 y=53.05561270693594 z=37.292706976306725
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -205/53/34}, pos={-204.5/53.0625/35.0}, mot={-0.7071/0.0/-0.7071}, f=NORTH}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -206/53/37}, pos={-205.6755/53.0527/37.4121}, mot={-0.3428/-0.0027/0.9394}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-205.67551907028096 y=53.05266560209267 z=37.41207232763191
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -205/53/34}, pos={-204.5/53.0625/35.0}, mot={-0.7071/0.0/-0.7071}, f=NORTH}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -206/53/37}, pos={-205.6755/53.0527/37.4121}, mot={-0.2933/-0.0034/0.956}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-205.67551907028096 y=53.05266560209267 z=37.41207232763191
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -205/53/34}, pos={-204.5/53.0625/35.0}, mot={-0.7071/0.0/-0.7071}, f=NORTH}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -206/53/37}, pos={-205.6755/53.0527/37.4121}, mot={-0.2933/-0.0034/0.956}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-205.67551907028096 y=53.05266560209267 z=37.41207232763191
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -206/53/34}, pos={-205.0/53.0625/34.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -206/53/37}, pos={-205.8557/53.0487/37.5}, mot={-0.2933/-0.0034/0.956}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-205.85565600263556 y=53.04869715777535 z=37.49997985067477
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -206/53/34}, pos={-205.0/53.0625/34.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -206/53/37}, pos={-205.8557/53.0487/37.5}, mot={-0.2522/-0.0045/0.9677}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-205.85565600263556 y=53.04869715777535 z=37.49997985067477
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -206/53/34}, pos={-205.0/53.0625/34.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -206/53/37}, pos={-205.8557/53.0487/37.5}, mot={-0.2522/-0.0045/0.9677}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-205.85565600263556 y=53.04869715777535 z=37.49997985067477
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -206/53/34}, pos={-205.0/53.0625/34.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -207/53/37}, pos={-206.0357/53.0438/37.5641}, mot={-0.2522/-0.0045/0.9677}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-206.0357413788915 y=53.04376507727941 z=37.5641404873241
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -206/53/34}, pos={-205.0/53.0625/34.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -207/53/37}, pos={-206.0357/53.0438/37.5641}, mot={-0.2067/-0.006/0.9784}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-206.0357413788915 y=53.04376507727941 z=37.5641404873241
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -206/53/34}, pos={-205.0/53.0625/34.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -207/53/37}, pos={-206.2225/53.0379/37.6235}, mot={-0.2067/-0.006/0.9784}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-206.22253023917267 y=53.03791993801431 z=37.623459793667756
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -206/53/34}, pos={-205.0/53.0625/34.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -207/53/37}, pos={-206.2225/53.0379/37.6235}, mot={-0.1641/-0.0078/0.9864}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-206.22253023917267 y=53.03791993801431 z=37.623459793667756
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -206/53/34}, pos={-205.0/53.0625/34.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -207/53/37}, pos={-206.2225/53.0379/37.6235}, mot={-0.1641/-0.0078/0.9864}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-206.22253023917267 y=53.03791993801431 z=37.623459793667756
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -207/53/34}, pos={-206.0/53.0625/34.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -207/53/37}, pos={-206.4158/53.0312/37.678}, mot={-0.1641/-0.0078/0.9864}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-206.415772454419 y=53.031201196083316 z=37.67802242265507
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -207/53/34}, pos={-206.0/53.0625/34.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -207/53/37}, pos={-206.4158/53.0312/37.678}, mot={-0.1244/-0.0098/0.9922}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-206.415772454419 y=53.031201196083316 z=37.67802242265507
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -207/53/34}, pos={-206.0/53.0625/34.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -207/53/37}, pos={-206.4158/53.0312/37.678}, mot={-0.1244/-0.0098/0.9922}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-206.415772454419 y=53.031201196083316 z=37.67802242265507
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -207/53/34}, pos={-206.0/53.0625/34.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -207/53/37}, pos={-206.6152/53.0236/37.728}, mot={-0.1244/-0.0098/0.9922}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-206.61523586055242 y=53.02364436274294 z=37.72796883281758
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -207/53/34}, pos={-206.0/53.0625/34.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -207/53/37}, pos={-206.6152/53.0236/37.728}, mot={-0.0877/-0.012/0.9961}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-206.61523586055242 y=53.02364436274294 z=37.72796883281758
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -207/53/34}, pos={-206.0/53.0625/34.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -207/53/37}, pos={-206.6152/53.0236/37.728}, mot={-0.0877/-0.012/0.9961}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-206.61523586055242 y=53.02364436274294 z=37.72796883281758
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -207/53/34}, pos={-206.0/53.0625/34.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -207/53/37}, pos={-206.8207/53.0153/37.7735}, mot={-0.0877/-0.012/0.9961}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-206.82069075084243 y=53.015281562259474 z=37.77348306988827
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -207/53/34}, pos={-206.0/53.0625/34.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -207/53/37}, pos={-206.8207/53.0153/37.7735}, mot={-0.0537/-0.0144/0.9985}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-206.82069075084243 y=53.015281562259474 z=37.77348306988827
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -207/53/34}, pos={-206.0/53.0625/34.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -207/53/37}, pos={-206.8207/53.0153/37.7735}, mot={-0.0537/-0.0144/0.9985}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-206.82069075084243 y=53.015281562259474 z=37.77348306988827
[16:49:25 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:25 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -207/53/34}, pos={-206.0/53.0625/34.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:25 WARN]: [Train_Carts] Search end: {rail={NONE -208/53/37}, pos={-207.0319/53.0061/37.8148}, mot={-0.0537/-0.0144/0.9985}, f=SOUTH}
[16:49:25 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-207.0319013054925 y=53.006141989328256 z=37.81478185623314
[16:49:26 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:26 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -207/53/34}, pos={-206.0/53.0625/34.5}, mot={-1.0/0.0/0.0}, f=WEST}
[16:49:26 WARN]: [Train_Carts] Search end: {rail={NONE -208/53/37}, pos={-207.0319/53.0061/37.8148}, mot={-0.0225/-0.017/0.9996}, f=SOUTH}
[16:49:26 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-207.0319013054925 y=53.006141989328256 z=37.81478185623314
[16:49:26 WARN]: [Train_Carts] Train 'L1-1~a' split apart because: Next cart is derailed
[16:49:26 WARN]: [Train_Carts] Search start: {rail={RailTypeRegular -208/53/34}, pos={-207.0/53.0625/34.5}, mot={-0.7071/0.0/-0.7071}, f=NORTH}
[16:49:26 WARN]: [Train_Carts] Search end: {rail={NONE -208/52/37}, pos={-207.2486/52.9962/37.8521}, mot={-0.0225/-0.017/0.9996}, f=SOUTH}
[16:49:26 WARN]: [Train_Carts] Cart that could not be reached: cart #1 of 11 at x=-207.24863542394922 y=52.99624838562205 z=37.85210501815752
[16:49:29 WARN]: Can't keep up! Is the server overloaded? Running 5353ms or 107 ticks behind
[16:49:34 INFO]: [Images] Loaded 18 images...
[16:49:46 INFO]: There are 12 trains on this server (of which 8
[16:49:46 INFO]:  are moving)
[16:49:46 INFO]: There are 334 minecart entities
[16:49:46 INFO]: The following trains exist on this server:
[16:49:46 INFO]: L1-1 / L1-1~b / L1-2 / L1-3 / L2-1 / L2-2 / L2-3
[16:49:46 INFO]: L2-4 / L2-5 / L2-6 / L2-7 / woolfact

@bergerkiller
Copy link
Member

bergerkiller commented Nov 17, 2023

Interesting, its derailed. Means for some reason it cannot detect any rails at the position of the cart. Can you check for some of the positions listed, whether its above or inside a rails block?

For example: x=-205.67551907028096 y=53.05266560209267 z=37.41207232763191

If thats above rails then theres a bug at startup reading block data for some reason

@BiDuang
Copy link
Author

BiDuang commented Nov 17, 2023

图片

The block at -205, 53, 37 is a stone, it doesn't make sense.🤔

@bergerkiller
Copy link
Member

bergerkiller commented Nov 17, 2023

Hmmm....its possible that the cart continues moving a short time at startup until all chunks have loaded that the train needs. Is there a linear path from that exact position at a 45 or 90 degree angle to another rail block? Trains move at a 45 degree angle in curves

For example:
image

@bergerkiller
Copy link
Member

bergerkiller commented Nov 17, 2023

Ill probably send a test build later today (in 5 hours or so) that logs all the positions of minecarts when they are first loaded in, and their position every tick until the train loads in, to see if such a drift is occurring.

@BiDuang
Copy link
Author

BiDuang commented Nov 17, 2023

Okay, thanks for your work!

@bergerkiller
Copy link
Member

bergerkiller commented Nov 17, 2023

This build logs the position of all minecarts that are unloaded (pending loading) and when the minecart loads in and is converted to a traincarts minecart.
plugin.zip

You can send the startup log up to and including all split logs, might be pretty spammy

@BiDuang
Copy link
Author

BiDuang commented Nov 17, 2023

I think upload a file can make you read easier?

debug.log

@bergerkiller
Copy link
Member

bergerkiller commented Nov 17, 2023

As I cant see the blocks involved, is there a rails at?:
x=-217.5 y=60.0625 z=-160.92279605257855
For some reason the coordinates have changed, and later on the position is at:
x=-216.81599095859067 y=60.0625 z=-160.68400904140933

@BiDuang
Copy link
Author

BiDuang commented Nov 17, 2023

As I cant see the blocks involved, is there a rails at?: x=-217.5 y=60.0625 z=-160.92279605257855 For some reason the coordinates have changed, and later on the position is at: x=-216.81599095859067 y=60.0625 z=-160.68400904140933

Oh, that's a rail:
图片

@bergerkiller
Copy link
Member

bergerkiller commented Nov 17, 2023

Its kinda difficult to calculate all of this, so its easier if you check. Can you /tp to exactly x=-216.8159 z=-160.684 and look all the way down? Where is this at? I think the initial spawn coordinate is indeed on the rails still, im uncertain about the second after it split off

@BiDuang
Copy link
Author

BiDuang commented Nov 17, 2023

Here it is:
图片

@bergerkiller
Copy link
Member

bergerkiller commented Nov 17, 2023

That does not seem like youre looking all the way down. Pitch angle is only 68 / 90. I need to know exactly where it is at so pixels line up with the coordinates.

@BiDuang
Copy link
Author

BiDuang commented Nov 17, 2023

Okay :
图片

@bergerkiller
Copy link
Member

Not the right coordinates exactly. Use
/tp @p -216.8159 ~ -160.684

@BiDuang
Copy link
Author

BiDuang commented Nov 17, 2023

图片

@bergerkiller
Copy link
Member

It seems some miscalculation happened somewhere in the physics to cause it to move there, because that movement change makes no sense. It was on that straight piece of track, and not much later its off the rails. I'll need to add some more logging to debug this

@BiDuang
Copy link
Author

BiDuang commented Nov 17, 2023

Sure, happy to help.

@bergerkiller
Copy link
Member

plugin.zip
Lot more spammy this time, hopefully it identifies where the position of carts suddenly changes

@BiDuang
Copy link
Author

BiDuang commented Nov 18, 2023

debug.log

@bergerkiller
Copy link
Member

So its part of the physics routine unfortunately, which is a whole lot of code to cover. Ill take out a few likely places and add some logging for it, will be tricky

@bergerkiller
Copy link
Member

plugin.zip

After you send the logging, Ill pick out a single train that had issues, and list a series of coordinates. Youll have to see like previously if they are still above rails or not. So /tp @p x y z to those coordinates, and look all the way down, and verify whether or not its still above the rails or not.

@bergerkiller
Copy link
Member

Ive managed to reproduce the problem by creating a jagged track far away from spawn and having a train go around in circles on it.

@bergerkiller
Copy link
Member

I think I may have found the problem. https://ci.mg-dev.eu/job/TrainCarts/1484/

@BiDuang
Copy link
Author

BiDuang commented Nov 19, 2023

I think I may have found the problem. https://ci.mg-dev.eu/job/TrainCarts/1484/

I've tested it several times and it seems pretty good so far.

@BiDuang BiDuang closed this as completed Nov 19, 2023
@BiDuang BiDuang reopened this Feb 11, 2024
@BiDuang
Copy link
Author

BiDuang commented Feb 11, 2024

Well, looks like it shows again...

@bergerkiller
Copy link
Member

You're running with latest dev snapshot from jenkins of traincarts? There have been a lot of changes

@BiDuang
Copy link
Author

BiDuang commented Feb 13, 2024

No, I'm running with the latest Release version

@bergerkiller
Copy link
Member

Then id start with testing out https://ci.mg-dev.eu/view/all/job/TrainCarts/1542/

It has important changes when it comes to persistence, such as saving and restoring launch actions, active signs and more. Too many changes to really compare it with last release as all of that is basically a rewrite.

Let me know if it still happens, then I can look more deeply into it with the current codebase

@BiDuang
Copy link
Author

BiDuang commented Feb 13, 2024

Okay, thank you. I'll try this new build.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants