sapling never appeared after break-block on tree

[musliner]

I have a no-novelty test run where a sapling didn’t appear after 7 NOPs after a break-block on log/tree (or actually ever, I think)

Our agent is robust to this condition, it reports novelty and replans... but I think that this may represent a sim bug, and our report would be assessed as an FP.
This appears to be somewhat reproducible (at least in my last two runs)...

Note the timestamps reveal we are currently not waiting a second after each NOP, unlike other action commands. Perhaps we need to? The reason I took those delays out is we were running out of time on some of the novelties like 6-3-1-H where you have to grow a lot of trees; if the NOPs each take a second etc, it adds up...

Logs attached in minute...

In our terms, the original plan is:
(BREAK-BLOCK-PLATINUM-BLOCK LOC61_17_51)
(BREAK-BLOCK-DIAMOND-ORE LOC45_17_35)
(BREAK-BLOCK-LOG LOC43_17_42)
(GROW-TREE-FROM-SAPLING LOC56_17_39)
...

So you'll see two break-blocks before the one on the log.

This custom grep pulls from our bridge log the commands sent to the sim and also when we first see mention of sapling
in inventory...
zgrep 'command_ver|sapling' bridge.log.gz |egrep 'command_v|in-inv' |less
... and here's what you get, from the third break-block onwards:
1384:[2021-12-30 13:01:23] command_verb: BREAK_BLOCK
1394:[2021-12-30 13:01:24] command_verb: SENSE_ACTOR_ACTIONS
1407:[2021-12-30 13:01:24] command_verb: SENSE_ALL
1495:[2021-12-30 13:01:24] command_verb: NOP
1505:[2021-12-30 13:01:24] command_verb: NOP
1515:[2021-12-30 13:01:24] command_verb: NOP
1525:[2021-12-30 13:01:24] command_verb: NOP
1535:[2021-12-30 13:01:24] command_verb: NOP
1545:[2021-12-30 13:01:24] command_verb: NOP
1555:[2021-12-30 13:01:24] command_verb: NOP
1565:[2021-12-30 13:01:25] command_verb: SENSE_ACTOR_ACTIONS
1578:[2021-12-30 13:01:25] command_verb: SENSE_ALL
1666:[2021-12-30 13:01:26] command_verb: SENSE_ALL
1754:[2021-12-30 13:01:26] command_verb: SENSE_ALL
1842:[2021-12-30 13:01:26] command_verb: REPORT_NOVELTY
1852:[2021-12-30 13:01:28] command_verb: TP_TO
1862:[2021-12-30 13:01:29] command_verb: SENSE_ACTOR_ACTIONS
1875:[2021-12-30 13:01:29] command_verb: SENSE_ALL
1964:[2021-12-30 13:01:29] command_verb: BREAK_BLOCK
1974:[2021-12-30 13:01:30] command_verb: SENSE_ACTOR_ACTIONS
1987:[2021-12-30 13:01:30] command_verb: SENSE_ALL
2070:[2021-12-30 13:01:30] command_verb: NOP
2080:[2021-12-30 13:01:30] command_verb: NOP
2090:[2021-12-30 13:01:30] command_verb: NOP
2100:[2021-12-30 13:01:30] command_verb: NOP
2110:[2021-12-30 13:01:30] command_verb: NOP
2120:[2021-12-30 13:01:30] command_verb: NOP
2130:[2021-12-30 13:01:30] command_verb: NOP
2140:[2021-12-30 13:01:31] command_verb: SENSE_ACTOR_ACTIONS
2153:[2021-12-30 13:01:31] command_verb: SENSE_ALL
2194:[2021-12-30 13:01:31] prsinterface[24028] send_message: Sending message to openmind: (domain-fact (in-inventory minecraft.sapling 1))

that last line shows when we first see sapling in inventory.

this more verbose grep shows the break-block did succeed...
zgrep 'command_ver|command-response|sapling' bridge.log.gz |egrep 'command|in-inv' |less

[musliner]

pal-tournament.log.gz
bridge.log.gz

the issue occurs in the first (pre-nov) game; later games are 6-3-1-E, ftr.

At SIFT, this is from musliner@openmind0:~/openmind/code/test/results/pal-tournament-v2-shared-6-3-1-E-no-pogoist-2021-12-30-125854-openmind0/