Opaque containers can become stuck in inventory

[ssalevan]

Description Sometimes opaque containers can become 'stuck' in an Avatar's inventory, unable to be removed into their hands.

Reproducer

1. Buy a bag from the Vendo in the test-vendo region
2. Open the bag, close the bag, then place it in your inventory again
3. Buy another bag from the Vendo
4. Put that bag in your inventory
5. Attempt to retrieve the first bag from your inventory

Results Error beep sounds and no bag is produced. Bag remains in inventory.

Expected Results Bag is produced.

[frandallfarmer]

Did this problem remain if you changed regions?

[ssalevan]

This problem does not seem to persist between region changes.

[ssalevan]

I've found a similar case that may be easier to reproduce and exists across region changes:

Reproducer

1. Buy the blue cross-hatched bag from the Vendo
2. Buy another
3. Pick up the first and put it in your inventory
4. Pick up the second and put it in your inventory

Results Error bell sounds and second bag is not added to inventory

Expected Results Bag is added to inventory

Logs

==> /neohabitat/bridge.log <==
debug: server (3:Steve) -> {"type":"reply","noid":17,"filler":0,"x":108,"y":150,"how":0}
debug: [85,238,17,0,108,150,0] -> client (3:Steve)
debug: client (3:Steve) ->  [noid:9 request:4 ... []]
debug: {"to":"item-vendo.front","op":"VEND"} -> server (3:Steve)

==> /neohabitat/elko_server.log <==
- 2017/04/23 23:05:26.600 MSG comm-cli : TCP(1) -> {"to":"item-vendo.front","op":"VEND"}
- 2017/04/23 23:05:26.601 MSG comm-cli : TCP(1) <- {"type":"reply", "noid":9, "filler":0, "success":1, "item_price_lo":5, "item_price_hi":0, "object":{"type":"item", "ref":"i-2421147802771958087", "name":"bag", "mods":[{"type":"Bag", "noid":18, "style":0, "x":68, "y":152, "orientation":56, "gr_state":0, "open_flags":2}]}}

==> /neohabitat/bridge.log <==
debug: server (3:Steve) -> {"type":"reply","noid":9,"filler":0,"success":1,"item_price_lo":5,"item_price_hi":0,"object":{"type":"item","ref":"i-2421147802771958087","name":"bag","mods":[{"type":"Bag","noid":18,"style":0,"x":68,"y":152,"orientation":56,"gr_state":0,"open_flags":2}]}}
debug: [85,239,9,0,1,5,0,18,6,0,0,68,152,56,0,0,2,0,0,0] -> client (3:Steve)
debug: client (3:Steve) ->  [noid:17 request:6 ... [254]]
debug: {"to":"user-steve-4592146128420754946","op":"POSTURE","pose":254} -> server (3:Steve)

==> /neohabitat/elko_server.log <==
- 2017/04/23 23:05:30.988 MSG comm-cli : TCP(1) -> {"to":"user-steve-4592146128420754946","op":"POSTURE","pose":254}

==> /neohabitat/bridge.log <==
debug: client (3:Steve) ->  [noid:9 request:4 ... []]
debug: {"to":"item-vendo.front","op":"VEND"} -> server (3:Steve)

==> /neohabitat/elko_server.log <==
- 2017/04/23 23:05:32.901 MSG comm-cli : TCP(1) -> {"to":"item-vendo.front","op":"VEND"}
- 2017/04/23 23:05:32.902 MSG comm-cli : TCP(1) <- {"type":"reply", "noid":9, "filler":0, "success":1, "item_price_lo":5, "item_price_hi":0, "object":{"type":"item", "ref":"i-1234075890420152994", "name":"bag", "mods":[{"type":"Bag", "noid":19, "style":0, "x":68, "y":152, "orientation":56, "gr_state":0, "open_flags":2}]}}

==> /neohabitat/bridge.log <==
debug: server (3:Steve) -> {"type":"reply","noid":9,"filler":0,"success":1,"item_price_lo":5,"item_price_hi":0,"object":{"type":"item","ref":"i-1234075890420152994","name":"bag","mods":[{"type":"Bag","noid":19,"style":0,"x":68,"y":152,"orientation":56,"gr_state":0,"open_flags":2}]}}
debug: [85,225,9,0,1,5,0,19,6,0,0,68,152,56,0,0,2,0,0,0] -> client (3:Steve)
debug: client (3:Steve) ->  [noid:17 request:6 ... [254]]
debug: {"to":"user-steve-4592146128420754946","op":"POSTURE","pose":254} -> server (3:Steve)

==> /neohabitat/elko_server.log <==
- 2017/04/23 23:05:37.813 MSG comm-cli : TCP(1) -> {"to":"user-steve-4592146128420754946","op":"POSTURE","pose":254}

==> /neohabitat/bridge.log <==
debug: client (3:Steve) ->  [noid:13 request:2 ... [17,106,183,1]]
debug: {"to":"item-steve.tokens-4592146128420754946","op":"PUT","containerNoid":17,"x":106,"y":183,"orientation":1} -> server (3:Steve)

==> /neohabitat/elko_server.log <==
- 2017/04/23 23:05:38.730 MSG comm-cli : TCP(1) -> {"to":"item-steve.tokens-4592146128420754946","op":"PUT","containerNoid":17,"x":106,"y":183,"orientation":1}
- 2017/04/23 23:05:38.731 MSG comm-cli : TCP(1) <- {"type":"reply", "noid":13, "filler":0, "err":1, "pos":3}

==> /neohabitat/bridge.log <==
debug: server (3:Steve) -> {"type":"reply","noid":13,"filler":0,"err":1,"pos":3}
debug: [85,227,13,0,1,3] -> client (3:Steve)
debug: client (3:Steve) ->  [noid:17 request:6 ... [254]]
debug: {"to":"user-steve-4592146128420754946","op":"POSTURE","pose":254} -> server (3:Steve)

==> /neohabitat/elko_server.log <==
- 2017/04/23 23:05:43.996 MSG comm-cli : TCP(1) -> {"to":"user-steve-4592146128420754946","op":"POSTURE","pose":254}

==> /neohabitat/bridge.log <==
debug: client (3:Steve) ->  [noid:17 request:6 ... [254]]
debug: {"to":"user-steve-4592146128420754946","op":"POSTURE","pose":254} -> server (3:Steve)

==> /neohabitat/elko_server.log <==
- 2017/04/23 23:05:46.666 MSG comm-cli : TCP(1) -> {"to":"user-steve-4592146128420754946","op":"POSTURE","pose":254}

==> /neohabitat/bridge.log <==
debug: client (3:Steve) ->  [noid:17 request:6 ... [254]]
debug: {"to":"user-steve-4592146128420754946","op":"POSTURE","pose":254} -> server (3:Steve)

==> /neohabitat/elko_server.log <==
- 2017/04/23 23:05:48.066 MSG comm-cli : TCP(1) -> {"to":"user-steve-4592146128420754946","op":"POSTURE","pose":254}

==> /neohabitat/bridge.log <==
debug: client (3:Steve) ->  [noid:17 request:8 ... [88,151,0]]
debug: {"to":"user-steve-4592146128420754946","op":"WALK","x":88,"y":151,"how":0} -> server (3:Steve)

==> /neohabitat/elko_server.log <==
- 2017/04/23 23:05:48.156 MSG comm-cli : TCP(1) -> {"to":"user-steve-4592146128420754946","op":"WALK","x":88,"y":151,"how":0}
- 2017/04/23 23:05:48.157 MSG comm-cli : TCP(1) <- {"type":"reply", "noid":17, "filler":0, "x":88, "y":151, "how":0}

==> /neohabitat/bridge.log <==
debug: server (3:Steve) -> {"type":"reply","noid":17,"filler":0,"x":88,"y":151,"how":0}
debug: [85,231,17,0,88,151,0] -> client (3:Steve)
debug: client (3:Steve) ->  [noid:19 request:1 ... []]
debug: {"to":"i-1234075890420152994","op":"GET"} -> server (3:Steve)

==> /neohabitat/elko_server.log <==
- 2017/04/23 23:05:50.200 MSG comm-cli : TCP(1) -> {"to":"i-1234075890420152994","op":"GET"}
- 2017/04/23 23:05:50.200 MSG comm-cli : TCP(1) <- {"type":"reply", "noid":19, "filler":1, "err":1}

==> /neohabitat/bridge.log <==
debug: server (3:Steve) -> {"type":"reply","noid":19,"filler":1,"err":1}
debug: [85,232,19,1,1] -> client (3:Steve)
debug: client (3:Steve) ->  [noid:17 request:6 ... [254]]
debug: {"to":"user-steve-4592146128420754946","op":"POSTURE","pose":254} -> server (3:Steve)

==> /neohabitat/elko_server.log <==
- 2017/04/23 23:05:54.392 MSG comm-cli : TCP(1) -> {"to":"user-steve-4592146128420754946","op":"POSTURE","pose":254}

==> /neohabitat/bridge.log <==
debug: client (3:Steve) ->  [noid:19 request:2 ... [17,88,183,1]]
debug: {"to":"i-1234075890420152994","op":"PUT","containerNoid":17,"x":88,"y":183,"orientation":1} -> server (3:Steve)

==> /neohabitat/elko_server.log <==
- 2017/04/23 23:05:55.206 MSG comm-cli : TCP(1) -> {"to":"i-1234075890420152994","op":"PUT","containerNoid":17,"x":88,"y":183,"orientation":1}
- 2017/04/23 23:05:55.207 MSG comm-cli : TCP(1) <- {"type":"reply", "noid":19, "filler":0, "err":1, "pos":4}

==> /neohabitat/bridge.log <==
debug: server (3:Steve) -> {"type":"reply","noid":19,"filler":0,"err":1,"pos":4}
debug: [85,234,19,0,1,4] -> client (3:Steve)
debug: client (3:Steve) ->  [noid:17 request:6 ... [254]]
debug: {"to":"user-steve-4592146128420754946","op":"POSTURE","pose":254} -> server (3:Steve)

==> /neohabitat/elko_server.log <==
- 2017/04/23 23:05:59.551 MSG comm-cli : TCP(1) -> {"to":"user-steve-4592146128420754946","op":"POSTURE","pose":254}

==> /neohabitat/bridge.log <==
debug: client (3:Steve) ->  [noid:18 request:1 ... []]
debug: {"to":"i-2421147802771958087","op":"GET"} -> server (3:Steve)

==> /neohabitat/elko_server.log <==
- 2017/04/23 23:05:59.734 MSG comm-cli : TCP(1) -> {"to":"i-2421147802771958087","op":"GET"}
- 2017/04/23 23:05:59.735 MSG comm-cli : TCP(1) <- {"type":"reply", "noid":18, "filler":1, "err":1}

==> /neohabitat/bridge.log <==
debug: server (3:Steve) -> {"type":"reply","noid":18,"filler":1,"err":1}
debug: [85,236,18,1,1] -> client (3:Steve)
debug: client (3:Steve) ->  [noid:17 request:6 ... [254]]
debug: {"to":"user-steve-4592146128420754946","op":"POSTURE","pose":254} -> server (3:Steve)

==> /neohabitat/elko_server.log <==
- 2017/04/23 23:06:03.347 MSG comm-cli : TCP(1) -> {"to":"user-steve-4592146128420754946","op":"POSTURE","pose":254}

==> /neohabitat/bridge.log <==
debug: client (3:Steve) ->  [noid:18 request:2 ... [17,86,187,1]]
debug: {"to":"i-2421147802771958087","op":"PUT","containerNoid":17,"x":86,"y":187,"orientation":1} -> server (3:Steve)

==> /neohabitat/elko_server.log <==
- 2017/04/23 23:06:04.170 MSG comm-cli : TCP(1) -> {"to":"i-2421147802771958087","op":"PUT","containerNoid":17,"x":86,"y":187,"orientation":1}
- 2017/04/23 23:06:04.171 MSG comm-cli : TCP(1) <- {"type":"reply", "noid":18, "filler":0, "err":0}

[frandallfarmer]

I don't know if it applies here, but avatars only have 5 slots.

[frandallfarmer]

Looks like the last example may have been a full pocket, I'm not sure.

Whenvever testing problems with containers, if at all possible change regions and capture that contents vector.

Then share logs from region change BEFORE the problem until the region change AFTER (inclusive) of the problem.

Clearly the client and server are getting out of synch and changing regions will "reset" the client to the "correct" state - that and a full log inbetween should allow us to debug the event.

Here's evidence that the simple case doesn't fail for me:

Bought 2 bags and put them in my pocket.

Then GET them both one at a time and put them on the floor.

Based on the descriptions so far, this looks like the same kind of de-synch we're seeing on occasion with heads. I'm betting there's a bug with changing containers that we just need to get a clean log of happening to fix.