Strange Lag issue

[Anoyomouse]

Hey

I'm running Immersive Portals-0.11 on a Valhelsia2 server, we're a group of 6 players, and on our server the one player said "i'm having a bit of lag", and in the server logs, it was busy spamming the following:

[13:58:02] [Server thread/INFO] [Portal/]: [Portal] request teleport Paper_Kat minecraft:overworld (134 67 -100)->(134 67 -100) [13:58:03] [Server thread/INFO] [Portal/]: [Portal] request teleport Paper_Kat minecraft:overworld (134 67 -100)->(134 67 -100) [14:04:09] [Server thread/INFO] [Portal/]: [Portal] request teleport Paper_Kat minecraft:overworld (129 67 -109)->(129 67 -109) [14:04:14] [Server thread/INFO] [Portal/]: [Portal] request teleport Paper_Kat minecraft:overworld (130 67 -109)->(130 67 -109)

And it was happening over 30 times for another player earlier in the day. I see the log is in "setPlayerLocation", which leads me to think that it's trying to do a teleport if the clientis laggin when they shouldn't be teleporting, causing the lag to get extended and causing jittering.

Any thoughts on if you should maybe break the checks if the position is the same, and not try and do the teleport logic?

Thanks

[Anoyomouse]

Just linking to the source for reference: https://github.com/qouteall/ImmersivePortalsModForForge/blob/0c2915284ec8adfca25d2369af43837e5a67e343/src/main/java/com/qouteall/immersive_portals/mixin/position_sync/MixinServerPlayNetworkHandler.java#L98

[qouteall]

There is a config option called "enable_teleportation_debug". Please enable that option and reproduce the same issue and post the log

[Joegenco]

Same issue, here. Same modpack. It also teleports some people inside walls, floors unrelated even if they are close to a portal or not.

Also in another note same teleporting inside walls happens when some lagged people try to enter a portal.

I started Logging like you requested. Where does it write the log?

[qouteall]

latest.log (sometimes debug.log) After enabling this option it will log a lot of stack trace which is helpful for diagnosing it

[Joegenco]

[Server thread/INFO] [Portal/]: [Portal] request teleport

Keeps happening but teleporting inside walls is rare. In the logs here you can see the issue. I have extracted a shot time-frame where the issue was present and posted the whole days log.

2020-04-09-1.log.gz debug_09Apr2020_12_44.txt

[qouteall]

I need you to go to config/immersive_protals-common.toml and change teleportation_debug to true and reproduce this issue and post the log.

[Joegenco]

`[09Apr2020 15:54:56.738] [Server thread/INFO] [Portal/]: [Portal] request teleport Kartofche minecraft:overworld (-1313 70 28)->(-1313 70 28)

[09Apr2020 15:54:56.738] [Server thread/INFO] [STDERR/]: [net.minecraft.network.play.ServerPlayNetHandler:func_175089_a:1478]: at net.minecraft.network.play.ServerPlayNetHandler.func_175089_a(ServerPlayNetHandler.java:1478) [09Apr2020 15:54:56.738] [Server thread/INFO] [STDERR/]: [net.minecraft.network.play.ServerPlayNetHandler:func_175089_a:1478]: at net.minecraft.network.play.ServerPlayNetHandler.func_147364_a(ServerPlayNetHandler.java:782) [09Apr2020 15:54:56.738] [Server thread/INFO] [STDERR/]: [net.minecraft.network.play.ServerPlayNetHandler:func_175089_a:1478]: at net.minecraft.network.play.ServerPlayNetHandler.func_147347_a(ServerPlayNetHandler.java:758) [09Apr2020 15:54:56.739] [Server thread/INFO] [STDERR/]: [net.minecraft.network.play.ServerPlayNetHandler:func_175089_a:1478]: at net.minecraft.network.play.client.CPlayerPacket.func_148833_a(SourceFile:122) [09Apr2020 15:54:56.739] [Server thread/INFO] [STDERR/]: [net.minecraft.network.play.ServerPlayNetHandler:func_175089_a:1478]: at net.minecraft.network.play.client.CPlayerPacket$PositionPacket.func_148833_a(SourceFile:56) [09Apr2020 15:54:56.739] [Server thread/INFO] [STDERR/]: [net.minecraft.network.play.ServerPlayNetHandler:func_175089_a:1478]: at net.minecraft.network.PacketThreadUtil.func_225383_a(SourceFile:21) [09Apr2020 15:54:56.739] [Server thread/INFO] [STDERR/]: [net.minecraft.network.play.ServerPlayNetHandler:func_175089_a:1478]: at net.minecraft.util.concurrent.TickDelayedTask.run(SourceFile:18) [09Apr2020 15:54:56.739] [Server thread/INFO] [STDERR/]: [net.minecraft.network.play.ServerPlayNetHandler:func_175089_a:1478]: at net.minecraft.util.concurrent.ThreadTaskExecutor.func_213166_h(SourceFile:144) [09Apr2020 15:54:56.739] [Server thread/INFO] [STDERR/]: [net.minecraft.network.play.ServerPlayNetHandler:func_175089_a:1478]: at net.minecraft.util.concurrent.RecursiveEventLoop.func_213166_h(SourceFile:23) [09Apr2020 15:54:56.739] [Server thread/INFO] [STDERR/]: [net.minecraft.network.play.ServerPlayNetHandler:func_175089_a:1478]: at net.minecraft.server.MinecraftServer.func_213166_h(MinecraftServer.java:731) [09Apr2020 15:54:56.739] [Server thread/INFO] [STDERR/]: [net.minecraft.network.play.ServerPlayNetHandler:func_175089_a:1478]: at net.minecraft.server.MinecraftServer.func_213166_h(MinecraftServer.java:141) [09Apr2020 15:54:56.739] [Server thread/INFO] [STDERR/]: [net.minecraft.network.play.ServerPlayNetHandler:func_175089_a:1478]: at net.minecraft.util.concurrent.ThreadTaskExecutor.func_213168_p(SourceFile:118) [09Apr2020 15:54:56.739] [Server thread/INFO] [STDERR/]: [net.minecraft.network.play.ServerPlayNetHandler:func_175089_a:1478]: at net.minecraft.server.MinecraftServer.func_213205_aW(MinecraftServer.java:714) [09Apr2020 15:54:56.739] [Server thread/INFO] [STDERR/]: [net.minecraft.network.play.ServerPlayNetHandler:func_175089_a:1478]: at net.minecraft.server.MinecraftServer.func_213168_p(MinecraftServer.java:708) [09Apr2020 15:54:56.739] [Server thread/INFO] [STDERR/]: [net.minecraft.network.play.ServerPlayNetHandler:func_175089_a:1478]: at net.minecraft.util.concurrent.ThreadTaskExecutor.func_213161_c(SourceFile:127) [09Apr2020 15:54:56.739] [Server thread/INFO] [STDERR/]: [net.minecraft.network.play.ServerPlayNetHandler:func_175089_a:1478]: at net.minecraft.server.MinecraftServer.func_213202_o(MinecraftServer.java:694) [09Apr2020 15:54:56.739] [Server thread/INFO] [STDERR/]: [net.minecraft.network.play.ServerPlayNetHandler:func_175089_a:1478]: at net.minecraft.server.MinecraftServer.run(MinecraftServer.java:641) [09Apr2020 15:54:56.739] [Server thread/INFO] [STDERR/]: [net.minecraft.network.play.ServerPlayNetHandler:func_175089_a:1478]: at java.lang.Thread.run(Unknown Source)`

Here it is, now it reports this right after the laggy teleportation. Please excuse my illiteracy on debugging, is this what you need?

[qouteall]

@Anoyomouse What does the player mean "lag"? One possibility is that the player moves forward and then teleport back. This also happens in vanilla when the network condition is not good. But vanilla will not log this. Does the "lag" recover after a period of time?

[qouteall]

@Fastfingered When the other side world is not loaded, going through the portal will cause the player to drop in the void and then stuck inside the floor. When does the player get teleported into the wall? Does it happen when the player is standing still or moving quickly?

[qouteall]

The log shows that client side sends position packet and the server thinks that the player movement is illegal (moving too fast or move through wall) and then ask the client to teleport to a legal position. Maybe it's caused by network lag.

[qouteall]

But network lag will not make the player teleport into wall. That's werid

[Joegenco]

The teleportation in to walls generally happens when the player moves quickly while they have minor lag.

What do you mean by the other side not being loaded. In terms of the server or the client? Is there a way to ease the restriction on the "illegal moves" so people with mild lag don't come across random teleports? At this point im aware that this question doesn't relate to Immersive Portals.

[qouteall]

When player is in overworld other side means nether. I am going to make that if the other side is not loaded then player will freeze when touching portal until it loads. I am going to create an option for avoid teleporting player when the player is inside wall in server side so that this issue happens more rarely

[Joegenco]

Thank you for the quick responses and feature implementation. Where can I get you a coffee or a beer(Patreon, paypal, etc..)?

[qouteall]

Posting the client log may be helpful

[Jorge-M]

we're seeing that sometimes laggy players will clip through the portal frame and end up below the portal (which, since there's a portal over lava, has lead to some deaths). Is this the same issue? If not, what kind of debug logging should I turn on when we reproduce it?

[qouteall]

@Jorge-M Did the player go through the portal before other side loads?

[Jorge-M]

no, the other side had loaded already (the effect is striking and beautiful, and the chunk loading works really well)

[qouteall]

Can you show a video about this?

[Jorge-M]

I've put out the request for video to some of the people on the server but we haven't gotten footage yet, although someone did end up sinking into the rock on one of the portals recently: they went from the nether side through the floor of the portal and ended up (after mashing buttons) on the other side of the portal, in the nether

[gcaraman]

Here's a video of that happening on my server https://drive.google.com/file/d/1WLFlUylec5zsIPXzsKv9_kEs_OZZXygM/view?usp=sharing

If the person dies or disconects, the server crashes with this log:

        Index: 3
        Listeners:
                0: HIGH
                1: ASM: net.blay09.mods.netherportalfix.NetherPortalFix@2e6eb540 onEntityTravelToDimension(Lnet/minecraftforge/event/entity/EntityTravelToDimensionEvent;)V
                2: NORMAL
                3: ASM: class net.telepathicgrunt.bumblezone.entities.PlayerTeleportationBehavior$ForgeEvents entityTravelToDimensionEvent(Lnet/minecraftforge/event/entity/EntityTravelToDimensionEvent;)V
                4: LOWEST
                5: ASM: class com.minecolonies.coremod.event.EventHandler onEntityTravelToDimensionEvent(Lnet/minecraftforge/event/entity/EntityTravelToDimensionEvent;)V
java.lang.RuntimeException
        at net.minecraftforge.common.util.LazyOptional.orElseThrow(LazyOptional.java:261)
        at net.telepathicgrunt.bumblezone.entities.PlayerTeleportationBehavior$ForgeEvents.entityTravelToDimensionEvent(PlayerTeleportationBehavior.java:217)        at net.minecraftforge.eventbus.ASMEventHandler_147_ForgeEvents_entityTravelToDimensionEvent_EntityTravelToDimensionEvent.invoke(.dynamic)
        at net.minecraftforge.eventbus.ASMEventHandler.invoke(ASMEventHandler.java:80)
        at net.minecraftforge.eventbus.EventBus.post(EventBus.java:258)
        at net.minecraftforge.common.ForgeHooks.onTravelToDimension(ForgeHooks.java:736)
        at com.legacy.goodnightsleep.world.GNSTeleportationUtil.changeDimension(GNSTeleportationUtil.java:32)
        at com.legacy.goodnightsleep.world.nightmare.NightmareDimension.func_76563_a(NightmareDimension.java:152)
        at net.minecraft.world.IWorld.func_72826_c(IWorld.java:33)
        at net.minecraft.world.World.func_72966_v(World.java:776)
        at net.minecraft.world.server.ServerWorld.func_72835_b(ServerWorld.java:310)
        at net.minecraft.server.MinecraftServer.func_71190_q(MinecraftServer.java:849)
        at net.minecraft.server.dedicated.DedicatedServer.func_71190_q(DedicatedServer.java:330)
        at net.minecraft.server.MinecraftServer.func_71217_p(MinecraftServer.java:784)
        at net.minecraft.server.MinecraftServer.run(MinecraftServer.java:637)
        at java.lang.Thread.run(Unknown Source)

[19:44:22] [Server thread/ERROR] [minecraft/MinecraftServer]: Encountered an unexpected exception
net.minecraft.crash.ReportedException: Exception ticking world
        at net.minecraft.server.MinecraftServer.func_71190_q(MinecraftServer.java:853) ~[?:?] {re:classloading,pl:accesstransformer:B,re:mixin,pl:accesstransformer:B,pl:runtimedistcleaner:A,pl:mixin:A,pl:runtimedistcleaner:A}
        at net.minecraft.server.dedicated.DedicatedServer.func_71190_q(DedicatedServer.java:330) ~[?:?] {re:classloading,pl:accesstransformer:B}
        at net.minecraft.server.MinecraftServer.func_71217_p(MinecraftServer.java:784) ~[?:?] {re:classloading,pl:accesstransformer:B,re:mixin,pl:accesstransformer:B,pl:runtimedistcleaner:A,pl:mixin:A,pl:runtimedistcleaner:A}
        at net.minecraft.server.MinecraftServer.run(MinecraftServer.java:637) [?:?] {re:classloading,pl:accesstransformer:B,re:mixin,pl:accesstransformer:B,pl:runtimedistcleaner:A,pl:mixin:A,pl:runtimedistcleaner:A}
        at java.lang.Thread.run(Unknown Source) [?:1.8.0_221] {}
Caused by: java.lang.RuntimeException
        at net.minecraftforge.common.util.LazyOptional.orElseThrow(LazyOptional.java:261) ~[?:?] {re:classloading}
        at net.telepathicgrunt.bumblezone.entities.PlayerTeleportationBehavior$ForgeEvents.entityTravelToDimensionEvent(PlayerTeleportationBehavior.java:217) ~[?:?] {re:classloading,pl:eventbus:A}
        at net.minecraftforge.eventbus.ASMEventHandler_147_ForgeEvents_entityTravelToDimensionEvent_EntityTravelToDimensionEvent.invoke(.dynamic) ~[?:?] {}
        at net.minecraftforge.eventbus.ASMEventHandler.invoke(ASMEventHandler.java:80) ~[eventbus-2.2.0-service.jar:?] {}
        at net.minecraftforge.eventbus.EventBus.post(EventBus.java:258) ~[eventbus-2.2.0-service.jar:?] {}
        at net.minecraftforge.common.ForgeHooks.onTravelToDimension(ForgeHooks.java:736) ~[?:?] {re:mixin,re:classloading}
        at com.legacy.goodnightsleep.world.GNSTeleportationUtil.changeDimension(GNSTeleportationUtil.java:32) ~[?:1.0.3] {re:classloading}
        at com.legacy.goodnightsleep.world.nightmare.NightmareDimension.func_76563_a(NightmareDimension.java:152) ~[?:1.0.3] {re:classloading,pl:runtimedistcleaner:A}
        at net.minecraft.world.IWorld.func_72826_c(IWorld.java:33) ~[?:?] {re:classloading,pl:runtimedistcleaner:A,re:mixin,pl:runtimedistcleaner:A}
        at net.minecraft.world.World.func_72966_v(World.java:776) ~[?:?] {re:mixin,pl:accesstransformer:B,pl:runtimedistcleaner:A,re:classloading,pl:accesstransformer:B,pl:mixin:APP:assets/immersive_portals/immersive_portals.mixins.json:MixinWorld,pl:mixin:APP:lithium.mixins.json:avoid_allocations.MixinWorld,pl:mixin:APP:performant.mixins.json:world.WorldMixin,pl:mixin:A,pl:runtimedistcleaner:A}
        at net.minecraft.world.server.ServerWorld.func_72835_b(ServerWorld.java:310) ~[?:?] {re:mixin,pl:accesstransformer:B,pl:runtimedistcleaner:A,re:classloading,pl:accesstransformer:B,xf:fml:quark:change-sleeping-player-count,xf:fml:quark:add-rave-hook,xf:fml:immersiveengineering:IE block update callback,pl:mixin:APP:assets/immersive_portals/immersive_portals.mixins.json:MixinServerWorld,pl:mixin:APP:lithium.mixins.json:avoid_allocations.MixinServerWorld,pl:mixin:APP:lithium.mixins.json:fast_tick_scheduler.MixinServerWorld,pl:mixin:A,pl:runtimedistcleaner:A}
        at net.minecraft.server.MinecraftServer.func_71190_q(MinecraftServer.java:849) ~[?:?] {re:classloading,pl:accesstransformer:B,re:mixin,pl:accesstransformer:B,pl:runtimedistcleaner:A,pl:mixin:A,pl:runtimedistcleaner:A}```

Full crash log:
https://drive.google.com/file/d/1COeC7T1JZllV13bku-iPITHFqWxs3wj-/view?usp=sharing

[qouteall]

@gcaraman The crash happens inside bumblezone. Have you tried enabling loose movement check on server?

[gcaraman]

@qouteall But nobody was in bumlezone..

[Xious01]

@qouteall I get 150 FPS, but when I look at mirrors or a portal I drop 100 fps in a heartbeat.