ejabberd icon indicating copy to clipboard operation
ejabberd copied to clipboard
verified publisher icon processone

Inconsistent pubsub behavior if `last_item_cache` is enabled

Open di72nn opened this issue 5 years ago • 0 comments

Environment

  • ejabberd version: 20.04
  • Erlang version: Erlang (SMP,ASYNC_THREADS,HIPE) (BEAM) emulator version 11.0
  • OS: Linux (Arch Linux)
  • Installed from: distro package

Configuration:

...
  mod_pubsub:
    db_type: sql
    access_createnode: pubsub_createnode
    ignore_pep_from_offline: false
    last_item_cache: true
    plugins:
      - flat
      - pep
    force_node_config:
      storage:bookmarks:
        access_model: whitelist
...

Errors from error.log/crash.log

No errors

Bug description

Disclaimer: I'm a complete noob in XMPP. The behavior described here may be caused by some mistake in my ejabberd setup - I can't bring myself to set up a new ejabberd instance just to test it.

If last_item_cache is set to true, pubsub seem to use cached value for headlines, but does not update values in DB. Direct queries (as opposed to headline messages) return values from DB (that do not match headlines).

The problem was initially discovered here.

Lengthy details

Value in DB (for the particular PEP node select * from pubsub_item where nodeid = 12;):

itemid publisher creation modification payload
current [email protected]/laptop 001595:328942:525615 001595:329296:110683 <list xmlns='eu.siacs.conversations.axolotl'><device id='542020432'/><device id='820461778'/><device id='578605933'/></list>
  1. Start ejabberd.
  2. Connect using Gajim with XML Console open. Observe the expected message:
<!-- Incoming 2020-07-21T16:06:09 +04 ([email protected]) -->
<message xmlns="jabber:client" to="[email protected]/desktop" from="[email protected]" type="headline">
  <event xmlns="http://jabber.org/protocol/pubsub#event">
    <items node="eu.siacs.conversations.axolotl.devicelist">
      <item id="current">
        <list xmlns="eu.siacs.conversations.axolotl">
          <device id="542020432" />
          <device id="820461778" />
          <device id="578605933" />
</list>
</item>
</items>
</event>
  <addresses xmlns="http://jabber.org/protocol/address">
    <address jid="[email protected]/desktop" type="replyto" />
</addresses>
</message>
  1. Manually send get request and observe the same result:
<!-- Outgoing 2020-07-21T16:07:25 +04 ([email protected]) -->
<iq type="get" to="[email protected]" id="items1" xmlns="jabber:client">
  <pubsub xmlns="http://jabber.org/protocol/pubsub">
    <items node="eu.siacs.conversations.axolotl.devicelist" />
</pubsub>
</iq>

<!-- Incoming 2020-07-21T16:07:25 +04 ([email protected]) -->
<iq xmlns="jabber:client" xml:lang="en" to="[email protected]/desktop" from="[email protected]" type="result" id="items1">
  <pubsub xmlns="http://jabber.org/protocol/pubsub">
    <items node="eu.siacs.conversations.axolotl.devicelist">
      <item id="current">
        <list xmlns="eu.siacs.conversations.axolotl">
          <device id="542020432" />
          <device id="820461778" />
          <device id="578605933" />
</list>
</item>
</items>
</pubsub>
</iq>
  1. Manually publish updated value and observer updated headlines:
<!-- Outgoing 2020-07-21T16:08:38 +04 ([email protected]) -->
<iq type="set" to="[email protected]" id="update1" xmlns="jabber:client">
  <pubsub xmlns="http://jabber.org/protocol/pubsub">
    <publish node="eu.siacs.conversations.axolotl.devicelist">
      <item id="current">
        <list xmlns="eu.siacs.conversations.axolotl">
          <device id="542020432" />
          <device id="578605933" />
</list>
</item>
</publish>
</pubsub>
</iq>

<!-- Incoming 2020-07-21T16:08:38 +04 ([email protected]) -->
<message xmlns="jabber:client" to="[email protected]" from="[email protected]" type="headline">
  <event xmlns="http://jabber.org/protocol/pubsub#event">
    <items node="eu.siacs.conversations.axolotl.devicelist">
      <item id="current">
        <list xmlns="eu.siacs.conversations.axolotl">
          <device id="542020432" />
          <device id="578605933" />
</list>
</item>
</items>
</event>
  <addresses xmlns="http://jabber.org/protocol/address">
    <address jid="[email protected]/desktop" type="replyto" />
</addresses>
</message>

<!-- Incoming 2020-07-21T16:08:38 +04 ([email protected]) -->
<iq xmlns="jabber:client" xml:lang="en" to="[email protected]/desktop" from="[email protected]" type="result" id="update1">
  <pubsub xmlns="http://jabber.org/protocol/pubsub">
    <publish node="eu.siacs.conversations.axolotl.devicelist">
      <item id="current" />
</publish>
</pubsub>
</iq>

<!-- Incoming 2020-07-21T16:08:38 +04 ([email protected]) -->
<message xmlns="jabber:client" to="[email protected]/desktop" from="[email protected]" type="headline">
  <event xmlns="http://jabber.org/protocol/pubsub#event">
    <items node="eu.siacs.conversations.axolotl.devicelist">
      <item id="current">
        <list xmlns="eu.siacs.conversations.axolotl">
          <device id="542020432" />
          <device id="578605933" />
</list>
</item>
</items>
</event>
  <addresses xmlns="http://jabber.org/protocol/address">
    <address jid="[email protected]/desktop" type="replyto" />
</addresses>
</message>
  1. Query it again and observe outdated value:
<!-- Outgoing 2020-07-21T16:10:31 +04 ([email protected]) -->
<iq type="get" to="[email protected]" id="items1" xmlns="jabber:client">
  <pubsub xmlns="http://jabber.org/protocol/pubsub">
    <items node="eu.siacs.conversations.axolotl.devicelist" />
</pubsub>
</iq>

<!-- Incoming 2020-07-21T16:10:32 +04 ([email protected]) -->
<iq xmlns="jabber:client" xml:lang="en" to="[email protected]/desktop" from="[email protected]" type="result" id="items1">
  <pubsub xmlns="http://jabber.org/protocol/pubsub">
    <items node="eu.siacs.conversations.axolotl.devicelist">
      <item id="current">
        <list xmlns="eu.siacs.conversations.axolotl">
          <device id="542020432" />
          <device id="820461778" />
          <device id="578605933" />
</list>
</item>
</items>
</pubsub>
</iq>
  1. Restart Gajim and connect, observe inconsistent results:
<!-- Outgoing 2020-07-21T16:13:00 +04 ([email protected]) -->
<iq xmlns="jabber:client" to="[email protected]" type="get" id="7a8611de-bb3d-4637-a61c-ea55a390fd3b">
  <pubsub xmlns="http://jabber.org/protocol/pubsub">
    <items node="eu.siacs.conversations.axolotl.devicelist" max_items="1" />
  </pubsub>
</iq>

<!-- Incoming 2020-07-21T16:13:00 +04 ([email protected]) -->
<message xmlns="jabber:client" to="[email protected]/desktop" from="[email protected]" type="headline">
  <event xmlns="http://jabber.org/protocol/pubsub#event">
    <items node="eu.siacs.conversations.axolotl.devicelist">
      <item id="current">
        <list xmlns="eu.siacs.conversations.axolotl">
          <device id="542020432" />
          <device id="578605933" />
</list>
</item>
</items>
</event>
  <addresses xmlns="http://jabber.org/protocol/address">
    <address jid="[email protected]/desktop" type="replyto" />
</addresses>
</message>

<!-- Incoming 2020-07-21T16:13:00 +04 ([email protected]) -->
<iq xmlns="jabber:client" xml:lang="en" to="[email protected]/desktop" from="[email protected]" type="result" id="7a8611de-bb3d-4637-a61c-ea55a390fd3b">
  <pubsub xmlns="http://jabber.org/protocol/pubsub">
    <set xmlns="http://jabber.org/protocol/rsm">
      <count>1</count>
      <first index="0">2020-07-21T10:55:42.525615Z</first>
      <last>2020-07-21T10:55:42.525615Z</last>
</set>
    <items node="eu.siacs.conversations.axolotl.devicelist">
      <item id="current">
        <list xmlns="eu.siacs.conversations.axolotl">
          <device id="542020432" />
          <device id="820461778" />
          <device id="578605933" />
</list>
</item>
</items>
</pubsub>
</iq>
  1. Stop ejabberd. The value in the DB is not updated.
  2. Set last_item_cache to false, start ejabberd.
  3. Connect using Gajim, observe old value in headline:
<!-- Incoming 2020-07-21T16:33:56 +04 ([email protected]) -->
<message xmlns="jabber:client" to="[email protected]/desktop" from="[email protected]" type="headline">
  <event xmlns="http://jabber.org/protocol/pubsub#event">
    <items node="eu.siacs.conversations.axolotl.devicelist">
      <item id="current">
        <list xmlns="eu.siacs.conversations.axolotl">
          <device id="542020432" />
          <device id="820461778" />
          <device id="578605933" />
</list>
</item>
</items>
</event>
  <addresses xmlns="http://jabber.org/protocol/address">
    <address jid="[email protected]/desktop" type="replyto" />
</addresses>
</message>
  1. Manually query the value, observe expected result:
<!-- Outgoing 2020-07-21T16:35:15 +04 ([email protected]) -->
<iq type="get" to="[email protected]" id="items1" xmlns="jabber:client">
  <pubsub xmlns="http://jabber.org/protocol/pubsub">
    <items node="eu.siacs.conversations.axolotl.devicelist" />
</pubsub>
</iq>

<!-- Incoming 2020-07-21T16:35:15 +04 ([email protected]) -->
<iq xmlns="jabber:client" xml:lang="en" to="[email protected]/desktop" from="[email protected]" type="result" id="items1">
  <pubsub xmlns="http://jabber.org/protocol/pubsub">
    <items node="eu.siacs.conversations.axolotl.devicelist">
      <item id="current">
        <list xmlns="eu.siacs.conversations.axolotl">
          <device id="542020432" />
          <device id="820461778" />
          <device id="578605933" />
</list>
</item>
</items>
</pubsub>
</iq>
  1. Manually update the value, observe correct result:
<!-- Outgoing 2020-07-21T16:36:42 +04 ([email protected]) -->
<iq type="set" to="[email protected]" id="update1" xmlns="jabber:client">
  <pubsub xmlns="http://jabber.org/protocol/pubsub">
    <publish node="eu.siacs.conversations.axolotl.devicelist">
      <item id="current">
        <list xmlns="eu.siacs.conversations.axolotl">
          <device id="542020432" />
          <device id="578605933" />
</list>
</item>
</publish>
</pubsub>
</iq>

<!-- Incoming 2020-07-21T16:36:42 +04 ([email protected]) -->
<message xmlns="jabber:client" to="[email protected]" from="[email protected]" type="headline">
  <event xmlns="http://jabber.org/protocol/pubsub#event">
    <items node="eu.siacs.conversations.axolotl.devicelist">
      <item id="current">
        <list xmlns="eu.siacs.conversations.axolotl">
          <device id="542020432" />
          <device id="578605933" />
</list>
</item>
</items>
</event>
  <addresses xmlns="http://jabber.org/protocol/address">
    <address jid="[email protected]/desktop" type="replyto" />
</addresses>
</message>

<!-- Incoming 2020-07-21T16:36:42 +04 ([email protected]) -->
<iq xmlns="jabber:client" xml:lang="en" to="[email protected]/desktop" from="[email protected]" type="result" id="update1">
  <pubsub xmlns="http://jabber.org/protocol/pubsub">
    <publish node="eu.siacs.conversations.axolotl.devicelist">
      <item id="current" />
</publish>
</pubsub>
</iq>

<!-- Incoming 2020-07-21T16:36:42 +04 ([email protected]) -->
<message xmlns="jabber:client" to="[email protected]/desktop" from="[email protected]" type="headline">
  <event xmlns="http://jabber.org/protocol/pubsub#event">
    <items node="eu.siacs.conversations.axolotl.devicelist">
      <item id="current">
        <list xmlns="eu.siacs.conversations.axolotl">
          <device id="542020432" />
          <device id="578605933" />
</list>
</item>
</items>
</event>
  <addresses xmlns="http://jabber.org/protocol/address">
    <address jid="[email protected]/desktop" type="replyto" />
</addresses>
</message>
  1. Manually query, observe correct result:
<!-- Outgoing 2020-07-21T16:38:38 +04 ([email protected]) -->
<iq type="get" to="[email protected]" id="items1" xmlns="jabber:client">
  <pubsub xmlns="http://jabber.org/protocol/pubsub">
    <items node="eu.siacs.conversations.axolotl.devicelist" />
</pubsub>
</iq>

<!-- Incoming 2020-07-21T16:38:38 +04 ([email protected]) -->
<iq xmlns="jabber:client" xml:lang="en" to="[email protected]/desktop" from="[email protected]" type="result" id="items1">
  <pubsub xmlns="http://jabber.org/protocol/pubsub">
    <items node="eu.siacs.conversations.axolotl.devicelist">
      <item id="current">
        <list xmlns="eu.siacs.conversations.axolotl">
          <device id="542020432" />
          <device id="578605933" />
</list>
</item>
</items>
</pubsub>
</iq>

The DB value is updated too:

itemid publisher creation modification payload
current [email protected]/desktop 001595:328942:525615 001595:335002:831753 <list xmlns='eu.siacs.conversations.axolotl'> <device id='542020432'/> <device id='578605933'/> </list>
  1. Reconnect Gajim, observe correct headline:
<!-- Incoming 2020-07-21T16:42:08 +04 ([email protected]) -->
<message xmlns="jabber:client" to="[email protected]/desktop" from="[email protected]" type="headline">
  <event xmlns="http://jabber.org/protocol/pubsub#event">
    <items node="eu.siacs.conversations.axolotl.devicelist">
      <item id="current">
        <list xmlns="eu.siacs.conversations.axolotl">
          <device id="542020432" />
          <device id="578605933" />
</list>
</item>
</items>
</event>
  <addresses xmlns="http://jabber.org/protocol/address">
    <address jid="[email protected]/desktop" type="replyto" />
</addresses>
</message>
  1. Manual query:
<!-- Outgoing 2020-07-21T16:44:10 +04 ([email protected]) -->
<iq xmlns="jabber:client" to="[email protected]" type="get" id="itemsnew">
  <pubsub xmlns="http://jabber.org/protocol/pubsub">
    <items node="eu.siacs.conversations.axolotl.devicelist" max_items="1" />
</pubsub>
</iq>

<!-- Incoming 2020-07-21T16:44:10 +04 ([email protected]) -->
<iq xmlns="jabber:client" xml:lang="en" to="[email protected]/desktop" from="[email protected]" type="result" id="itemsnew">
  <pubsub xmlns="http://jabber.org/protocol/pubsub">
    <set xmlns="http://jabber.org/protocol/rsm">
      <count>1</count>
      <first index="0">2020-07-21T10:55:42.525615Z</first>
      <last>2020-07-21T10:55:42.525615Z</last>
</set>
    <items node="eu.siacs.conversations.axolotl.devicelist">
      <item id="current">
        <list xmlns="eu.siacs.conversations.axolotl">
          <device id="542020432" />
          <device id="578605933" />
</list>
</item>
</items>
</pubsub>
</iq>

I also noticed that pubsub_node_option.persist_items in the DB is set to false for the particular node, but I don't know whether it is relevant.

Update: possibly was caused by the thing discussed here. I don't have time to retest at the moment.

di72nn avatar Jul 21 '20 12:07 di72nn