Crash when using execution queues

LadyCailinBot commented 10 years ago

CMDHELPER-2875 - Reported by CyaNox

Heavy CH crash when trying to do a little bit of statistics collecting on entities using execution queues.

[16:26:22 ERROR]: Uh oh! You've found an error in CommandHelper. This is an error caused by your code, so you may be able to find a workaround, but is ultimately an error in CommandHelper itself. The line of code that caused the error was this:
ifelse()
on or around /srv/mc/live/survival/plugins/CommandHelper/LocalPackages/shared/MobSpawning/MobSpawning.msa:116.
Please report this error to the developers, and be sure to include the version numbers: Server version: 1.7.2-R0.3-SNAPSHOT; CommandHelper version: 3.3.1-SNAPSHOT:2500-99e92f0,master. Here's the stacktrace:
java.lang.NullPointerException
        at com.laytonsmith.core.constructs.IVariable.ival(IVariable.java:31)
        at com.laytonsmith.core.Script.eval(Script.java:338)
        at com.laytonsmith.core.functions.BasicLogic$ifelse.execs(BasicLogic.java:407)
        at com.laytonsmith.core.Script.eval(Script.java:260)
        at com.laytonsmith.core.Script.eval(Script.java:270)
        at com.laytonsmith.core.functions.BasicLogic$ifelse.execs(BasicLogic.java:407)
        at com.laytonsmith.core.Script.eval(Script.java:260)
        at com.laytonsmith.core.Script.eval(Script.java:270)
        at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1494)
        at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1454)
        at com.laytonsmith.core.constructs.CClosure.execute(CClosure.java:144)
        at com.laytonsmith.core.functions.ExecutionQueue$queue_push$1$1.run(ExecutionQueue.java:72)
        at org.bukkit.craftbukkit.v1_7_R1.scheduler.CraftTask.run(CraftTask.java:58)
        at org.bukkit.craftbukkit.v1_7_R1.scheduler.CraftScheduler.mainThreadHeartbeat(CraftScheduler.java:345)
        at net.minecraft.server.v1_7_R1.MinecraftServer.u(MinecraftServer.java:583)
        at net.minecraft.server.v1_7_R1.DedicatedServer.u(DedicatedServer.java:273)
        at net.minecraft.server.v1_7_R1.MinecraftServer.t(MinecraftServer.java:540)
        at net.minecraft.server.v1_7_R1.MinecraftServer.run(MinecraftServer.java:446)
        at net.minecraft.server.v1_7_R1.ThreadServerApplication.run(SourceFile:617)

[16:26:22 WARN]: [CommandHelper] Task #13683 for CommandHelper v3.3.1-SNAPSHOT:2500-99e92f0,master generated an exception
com.laytonsmith.core.exceptions.CancelCommandException
        at com.laytonsmith.core.Script.eval(Script.java:372) ~[?:?]
        at com.laytonsmith.core.Script.eval(Script.java:270) ~[?:?]
        at com.laytonsmith.core.functions.BasicLogic$ifelse.execs(BasicLogic.java:407) ~[?:?]
        at com.laytonsmith.core.Script.eval(Script.java:260) ~[?:?]
        at com.laytonsmith.core.Script.eval(Script.java:270) ~[?:?]
        at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1494) ~[?:?]
        at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1454) ~[?:?]
        at com.laytonsmith.core.constructs.CClosure.execute(CClosure.java:144) ~[?:?]
        at com.laytonsmith.core.functions.ExecutionQueue$queue_push$1$1.run(ExecutionQueue.java:72) ~[?:?]
        at org.bukkit.craftbukkit.v1_7_R1.scheduler.CraftTask.run(CraftTask.java:58) ~[Spigot.jar:git-Spigot-1235]
        at org.bukkit.craftbukkit.v1_7_R1.scheduler.CraftScheduler.mainThreadHeartbeat(CraftScheduler.java:345) [Spigot.jar:git-Spigot-1235]
        at net.minecraft.server.v1_7_R1.MinecraftServer.u(MinecraftServer.java:583) [Spigot.jar:git-Spigot-1235]
        at net.minecraft.server.v1_7_R1.DedicatedServer.u(DedicatedServer.java:273) [Spigot.jar:git-Spigot-1235]
        at net.minecraft.server.v1_7_R1.MinecraftServer.t(MinecraftServer.java:540) [Spigot.jar:git-Spigot-1235]
        at net.minecraft.server.v1_7_R1.MinecraftServer.run(MinecraftServer.java:446) [Spigot.jar:git-Spigot-1235]
        at net.minecraft.server.v1_7_R1.ThreadServerApplication.run(SourceFile:617) [Spigot.jar:git-Spigot-1235]

This happens in the following code:

/entitystats = >>>
  @s = nano_time()
  @e = all_entities()
  console('All entities (' . array_size(@e) . ') retrieved in ' . sprintf('%.3f', (nano_time() - @s) / 1000000) . 'ms.')
  @s2 = nano_time()
  queue_clear('entitystats')
  export('entitystats.players', array())
  export('entitystats.global', array())
  @c = 0
  @living = array('ZOMBIE', 'VILLAGER')
  foreach(@e, @en){
    @c++
    if (@c > 500){
      break()
    }
    queue_push(closure(
      console('Checking ('.@c.'): ' . @en)
      console('Checking ('.@c.'): ' . @en)
      console('Checking ('.@c.'): ' . @en)
      if (entity_exists(@en)){
        @en_l = entity_loc(@en)
        @en_t = entity_type(@en)
        @en_p = false
        @en_n = ''
        @en_v = null
        @en_r = null
        @en_h = null
        if (array_contains(@living, @en_t)){ #This is line 116
          @en_p = get_entity_persistence(@en)
          @en_n = get_mob_name(@en)
          @en_v = get_entity_vehicle(@en)
          @en_r = get_entity_rider(@en)
          @en_h = get_leashholder(@en)
#          @en_a = get_mob_age(@en)
#          @en_e = get_mob_equipment(@en)
        }
        @np = array()
        foreach(all_players(), @p){
          @ploc = ploc(@p)
          if (@ploc['world'] != @en_l['world']){
            continue()
          }
          if (abs(@ploc['x'] - @en_l['x']) > 128){
            continue()
          }
          if (abs(@ploc['z'] - @en_l['z']) > 128){
            continue()
          }
          if (abs(@ploc['y'] - @en_l['y']) > 128){
            continue()
          }
          @np[] = @p
        }
        if (array_size(@np) > 0){
          @ap = import('entitystats.players')
          foreach(@np, @nnp){
            if (!array_index_exists(@ap, @nnp)){
              @ap[@nnp] = array()
            }
            if (!array_index_exists(@ap[@nnp], @en_t)){
              @ap[@nnp][@en_t] = array(
                'count': 0,
                'persistent': 0,
                'named': 0,
                'invehicle': 0,
                'beingridden': 0,
                'leashed': 0,
              )
            }
            @ap[@nnp][@en_t]['count']++
            if (@en_p){
              @ap[@nnp][@en_t]['persistent']++
            }
            if (@en_n != ''){
              @ap[@nnp][@en_t]['named']++
            }
            if (@en_v != ''){
              @ap[@nnp][@en_t]['invehicle']++
            }
            if (@en_r != ''){
              @ap[@nnp][@en_t]['beingridden']++
            }
            if (@en_h != ''){
              @ap[@nnp][@en_t]['leashed']++
            }
            export('entitystats.players', @ap)
          }
        }else{
          @ap = import('entitystats.global')
          if (!array_index_exists(@ap, @en_t)){
            @ap[@en_t] = array(
              'count': 0,
              'persistent': 0,
              'named': 0,
              'invehicle': 0,
              'beingridden': 0,
              'leashed': 0,
            )
          }
          @ap[@en_t]['count']++
          if (@en_p){
            @ap[@en_t]['persistent']++
          }
          if (@en_n != ''){
            @ap[@en_t]['named']++
          }
          if (@en_v != ''){
            @ap[@en_t]['invehicle']++
          }
          if (@en_r != ''){
            @ap[@en_t]['beingridden']++
          }
          if (@en_h != ''){
            @ap[@en_t]['leashed']++
          }
          export('entitystats.global', @ap)
        }
      }else{
        @ap = import('entitystats.global')
        if (!array_index_exists(@ap, 'de')){
          @ap['de'] = array('spawned': 0)
        }
        @ap['de']['spawned']++
        export('entitystats.global', @ap)
      }
    ), 'entitystats')
    queue_delay(5, 'entitystats')
  }
  @s3 = nano_time()
  queue_push(closure(
    @zp = import('entitystats.players')
    @zg = import('entitystats.global')
    console('Entity stats collected in ' . sprintf('%.3f', (nano_time() - @s3) / 1000000) . 'ms:')
    foreach(@zp, @zpp, @zd){
      console('  ' . @zpp)
      foreach(@zd, @ze, @zs){
        console('    ' . @ze)
        foreach(@zs, @zk, @zv){
          console('      ' . @zk . ': ' . @zv)
        }
      }
    }
    console('  Global: ')
    foreach(@zg, @ze, @zs){
      console('    ' . @ze)
      foreach(@zs, @zk, @zv){
        console('      ' . @zk . ': ' . @zv)
      }
    }
  ), 'entitystats')
  console('Queues initiated in ' . sprintf('%.3f', (nano_time() - @s2) / 1000000) . 'ms.')
<<<

I've not had the ability yet to figure out a smaller code example that produces the same results (Also due to the crash I have not fully tested the rest of the code but it should be mostly valid).

LadyCailinBot commented 10 years ago

Comment by LadyCailin

I've added a new stack trace in a better location to help me identify where the problem actually is. Try the new builds, and post the new stacktrace, please. Thanks!

LadyCailinBot commented 10 years ago

Comment by CyaNox

Looks pretty much the same (Haven't tried a smaller test case to narrow it down).

[14:46:58 ERROR]: Uh oh! You've found an error in CommandHelper. This is an error caused by your code, so you may be able to find a workaround, but is ultimately an error in CommandHelper itself. The line of code that caused the error was this:
@en_r = null
assign(@en_r, java-null)
on or around /srv/mc/live/survival/plugins/CommandHelper/LocalPackages/shared/MobSpawning/MobSpawning.msa:120.
Please report this error to the developers, and be sure to include the version numbers: Server version: 1.7.2-R0.3-SNAPSHOT; CommandHelper version: 3.3.1-SNAPSHOT:2509-ef31d72,master. Here's the stacktrace:
java.lang.NullPointerException
        at com.laytonsmith.core.constructs.IVariable.<init>(IVariable.java:22)
        at com.laytonsmith.core.functions.DataHandling$assign.exec(DataHandling.java:182)
        at com.laytonsmith.core.Script.eval(Script.java:308)
        at com.laytonsmith.core.Script.eval(Script.java:270)
        at com.laytonsmith.core.functions.BasicLogic$ifelse.execs(BasicLogic.java:407)
        at com.laytonsmith.core.Script.eval(Script.java:260)
        at com.laytonsmith.core.Script.eval(Script.java:270)
        at com.laytonsmith.core.functions.BasicLogic$ifelse.execs(BasicLogic.java:407)
        at com.laytonsmith.core.Script.eval(Script.java:260)
        at com.laytonsmith.core.Script.eval(Script.java:270)
        at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1580)
        at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1540)
        at com.laytonsmith.core.constructs.CClosure.execute(CClosure.java:144)
        at com.laytonsmith.core.functions.ExecutionQueue$queue_push$1$1.run(ExecutionQueue.java:72)
        at org.bukkit.craftbukkit.v1_7_R1.scheduler.CraftTask.run(CraftTask.java:58)
        at org.bukkit.craftbukkit.v1_7_R1.scheduler.CraftScheduler.mainThreadHeartbeat(CraftScheduler.java:345)
        at net.minecraft.server.v1_7_R1.MinecraftServer.u(MinecraftServer.java:583)
        at net.minecraft.server.v1_7_R1.DedicatedServer.u(DedicatedServer.java:273)
        at net.minecraft.server.v1_7_R1.MinecraftServer.t(MinecraftServer.java:540)
        at net.minecraft.server.v1_7_R1.MinecraftServer.run(MinecraftServer.java:446)
        at net.minecraft.server.v1_7_R1.ThreadServerApplication.run(SourceFile:617)

[14:46:58 WARN]: [CommandHelper] Task #243 for CommandHelper v3.3.1-SNAPSHOT:2509-ef31d72,master generated an exception
com.laytonsmith.core.exceptions.CancelCommandException
        at com.laytonsmith.core.Script.eval(Script.java:372) ~[?:?]
        at com.laytonsmith.core.Script.eval(Script.java:270) ~[?:?]
        at com.laytonsmith.core.functions.BasicLogic$ifelse.execs(BasicLogic.java:407) ~[?:?]
        at com.laytonsmith.core.Script.eval(Script.java:260) ~[?:?]
        at com.laytonsmith.core.Script.eval(Script.java:270) ~[?:?]
        at com.laytonsmith.core.functions.BasicLogic$ifelse.execs(BasicLogic.java:407) ~[?:?]
        at com.laytonsmith.core.Script.eval(Script.java:260) ~[?:?]
        at com.laytonsmith.core.Script.eval(Script.java:270) ~[?:?]
        at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1580) ~[?:?]
        at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1540) ~[?:?]
        at com.laytonsmith.core.constructs.CClosure.execute(CClosure.java:144) ~[?:?]
        at com.laytonsmith.core.functions.ExecutionQueue$queue_push$1$1.run(ExecutionQueue.java:72) ~[?:?]
        at org.bukkit.craftbukkit.v1_7_R1.scheduler.CraftTask.run(CraftTask.java:58) ~[Spigot.jar:git-Spigot-1235]
        at org.bukkit.craftbukkit.v1_7_R1.scheduler.CraftScheduler.mainThreadHeartbeat(CraftScheduler.java:345) [Spigot.jar:git-Spigot-1235]
        at net.minecraft.server.v1_7_R1.MinecraftServer.u(MinecraftServer.java:583) [Spigot.jar:git-Spigot-1235]
        at net.minecraft.server.v1_7_R1.DedicatedServer.u(DedicatedServer.java:273) [Spigot.jar:git-Spigot-1235]
        at net.minecraft.server.v1_7_R1.MinecraftServer.t(MinecraftServer.java:540) [Spigot.jar:git-Spigot-1235]
        at net.minecraft.server.v1_7_R1.MinecraftServer.run(MinecraftServer.java:446) [Spigot.jar:git-Spigot-1235]
        at net.minecraft.server.v1_7_R1.ThreadServerApplication.run(SourceFile:617) [Spigot.jar:git-Spigot-1235]

LadyCailinBot commented 10 years ago

Comment by CyaNox

Managed to make the test case a whole lot smaller and it seems to be specific to get_entity_rider(). Might still test with the other methods but the code below does reproduce the crash.

/entitystats4 = >>>
  @e = all_entities()
  console('All entities: ' . array_size(@e))
  queue_clear('entitystats')
  @living = array('ZOMBIE', 'VILLAGER')
  foreach(@e, @en){
    queue_push(closure(
      console('Checking: ' . @en)
      try(
        @en_r = get_entity_rider(@en) # Line 314
      ,)
    ), 'entitystats')
    queue_delay(5, 'entitystats')
  }
  queue_push(closure(
    console('Entity stats collected.')
  ), 'entitystats')
  console('Queues initiated.')
<<<

>entitystats4
[15:04:10 INFO]: CommandHelper: All entities: 1118
[15:04:10 INFO]: CommandHelper: Queues initiated.
[15:04:10 INFO]: CommandHelper: Checking: 2
[15:04:10 ERROR]: Uh oh! You've found an error in CommandHelper. This is an error caused by your code, so you may be able to find a workaround, but is ultimately an error in CommandHelper itself. The line of code that caused the error was this:
@en_r = ''
assign(@en_r, java-null)
on or around /srv/mc/live/survival/plugins/CommandHelper/LocalPackages/shared/MobSpawning/MobSpawning.msa:314.
Please report this error to the developers, and be sure to include the version numbers: Server version: 1.7.2-R0.3-SNAPSHOT; CommandHelper version: 3.3.1-SNAPSHOT:2509-ef31d72,master. Here's the stacktrace:
java.lang.NullPointerException
        at com.laytonsmith.core.constructs.IVariable.<init>(IVariable.java:22)
        at com.laytonsmith.core.functions.DataHandling$assign.exec(DataHandling.java:182)
        at com.laytonsmith.core.Script.eval(Script.java:308)
        at com.laytonsmith.core.functions.Exceptions$_try.execs(Exceptions.java:385)
        at com.laytonsmith.core.Script.eval(Script.java:260)
        at com.laytonsmith.core.Script.eval(Script.java:270)
        at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1580)
        at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1540)
        at com.laytonsmith.core.constructs.CClosure.execute(CClosure.java:144)
        at com.laytonsmith.core.functions.ExecutionQueue$queue_push$1$1.run(ExecutionQueue.java:72)
        at org.bukkit.craftbukkit.v1_7_R1.scheduler.CraftTask.run(CraftTask.java:58)
        at org.bukkit.craftbukkit.v1_7_R1.scheduler.CraftScheduler.mainThreadHeartbeat(CraftScheduler.java:345)
        at net.minecraft.server.v1_7_R1.MinecraftServer.u(MinecraftServer.java:583)
        at net.minecraft.server.v1_7_R1.DedicatedServer.u(DedicatedServer.java:273)
        at net.minecraft.server.v1_7_R1.MinecraftServer.t(MinecraftServer.java:540)
        at net.minecraft.server.v1_7_R1.MinecraftServer.run(MinecraftServer.java:446)
        at net.minecraft.server.v1_7_R1.ThreadServerApplication.run(SourceFile:617)

[15:04:10 WARN]: [CommandHelper] Task #33025 for CommandHelper v3.3.1-SNAPSHOT:2509-ef31d72,master generated an exception
com.laytonsmith.core.exceptions.CancelCommandException
        at com.laytonsmith.core.Script.eval(Script.java:372) ~[?:?]
        at com.laytonsmith.core.functions.Exceptions$_try.execs(Exceptions.java:385) ~[?:?]
        at com.laytonsmith.core.Script.eval(Script.java:260) ~[?:?]
        at com.laytonsmith.core.Script.eval(Script.java:270) ~[?:?]
        at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1580) ~[?:?]
        at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1540) ~[?:?]
        at com.laytonsmith.core.constructs.CClosure.execute(CClosure.java:144) ~[?:?]
        at com.laytonsmith.core.functions.ExecutionQueue$queue_push$1$1.run(ExecutionQueue.java:72) ~[?:?]
        at org.bukkit.craftbukkit.v1_7_R1.scheduler.CraftTask.run(CraftTask.java:58) ~[Spigot.jar:git-Spigot-1235]
        at org.bukkit.craftbukkit.v1_7_R1.scheduler.CraftScheduler.mainThreadHeartbeat(CraftScheduler.java:345) [Spigot.jar:git-Spigot-1235]
        at net.minecraft.server.v1_7_R1.MinecraftServer.u(MinecraftServer.java:583) [Spigot.jar:git-Spigot-1235]
        at net.minecraft.server.v1_7_R1.DedicatedServer.u(DedicatedServer.java:273) [Spigot.jar:git-Spigot-1235]
        at net.minecraft.server.v1_7_R1.MinecraftServer.t(MinecraftServer.java:540) [Spigot.jar:git-Spigot-1235]
        at net.minecraft.server.v1_7_R1.MinecraftServer.run(MinecraftServer.java:446) [Spigot.jar:git-Spigot-1235]
        at net.minecraft.server.v1_7_R1.ThreadServerApplication.run(SourceFile:617) [Spigot.jar:git-Spigot-1235]

LadyCailinBot commented 10 years ago

Comment by LadyCailin

This should be fixed in the latest build.

EngineHub / CommandHelper

Crash when using execution queues #876