processone / processone/ejabberd

Inconsistent pubsub behavior if `last_item_cache` is enabled

Open
#3,335 0 comments 1 reaction 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
Erlang
Stars
6.7k
Forks
1.6k
No merged PRs in 30d

Description

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 d@di72nn.com/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 (d@di72nn.com) -->
<message xmlns="jabber:client" to="d@di72nn.com/desktop" from="d@di72nn.com" 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="d@di72nn.com/desktop" type="replyto" />
</addresses>
</message>
  1. Manually send get request and observe the same result:
<!-- Outgoing 2020-07-21T16:07:25 +04 (d@di72nn.com) -->
<iq type="get" to="d@di72nn.com" 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 (d@di72nn.com) -->
<iq xmlns="jabber:client" xml:lang="en" to="d@di72nn.com/desktop" from="d@di72nn.com" 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 (d@di72nn.com) -->
<iq type="set" to="d@di72nn.com" 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 (d@di72nn.com) -->
<message xmlns="jabber:client" to="d@di72nn.com" from="d@di72nn.com" 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="d@di72nn.com/desktop" type="replyto" />
</addresses>
</message>

<!-- Incoming 2020-07-21T16:08:38 +04 (d@di72nn.com) -->
<iq xmlns="jabber:client" xml:lang="en" to="d@di72nn.com/desktop" from="d@di72nn.com" 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 (d@di72nn.com) -->
<message xmlns="jabber:client" to="d@di72nn.com/desktop" from="d@di72nn.com" 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="d@di72nn.com/desktop" type="replyto" />
</addresses>
</message>
  1. Query it again and observe outdated value:
<!-- Outgoing 2020-07-21T16:10:31 +04 (d@di72nn.com) -->
<iq type="get" to="d@di72nn.com" 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 (d@di72nn.com) -->
<iq xmlns="jabber:client" xml:lang="en" to="d@di72nn.com/desktop" from="d@di72nn.com" 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 (d@di72nn.com) -->
<iq xmlns="jabber:client" to="d@di72nn.com" 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 (d@di72nn.com) -->
<message xmlns="jabber:client" to="d@di72nn.com/desktop" from="d@di72nn.com" 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="d@di72nn.com/desktop" type="replyto" />
</addresses>
</message>

<!-- Incoming 2020-07-21T16:13:00 +04 (d@di72nn.com) -->
<iq xmlns="jabber:client" xml:lang="en" to="d@di72nn.com/desktop" from="d@di72nn.com" 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 (d@di72nn.com) -->
<message xmlns="jabber:client" to="d@di72nn.com/desktop" from="d@di72nn.com" 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="d@di72nn.com/desktop" type="replyto" />
</addresses>
</message>
  1. Manually query the value, observe expected result:
<!-- Outgoing 2020-07-21T16:35:15 +04 (d@di72nn.com) -->
<iq type="get" to="d@di72nn.com" 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 (d@di72nn.com) -->
<iq xmlns="jabber:client" xml:lang="en" to="d@di72nn.com/desktop" from="d@di72nn.com" 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 (d@di72nn.com) -->
<iq type="set" to="d@di72nn.com" 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 (d@di72nn.com) -->
<message xmlns="jabber:client" to="d@di72nn.com" from="d@di72nn.com" 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="d@di72nn.com/desktop" type="replyto" />
</addresses>
</message>

<!-- Incoming 2020-07-21T16:36:42 +04 (d@di72nn.com) -->
<iq xmlns="jabber:client" xml:lang="en" to="d@di72nn.com/desktop" from="d@di72nn.com" 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 (d@di72nn.com) -->
<message xmlns="jabber:client" to="d@di72nn.com/desktop" from="d@di72nn.com" 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="d@di72nn.com/desktop" type="replyto" />
</addresses>
</message>
  1. Manually query, observe correct result:
<!-- Outgoing 2020-07-21T16:38:38 +04 (d@di72nn.com) -->
<iq type="get" to="d@di72nn.com" 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 (d@di72nn.com) -->
<iq xmlns="jabber:client" xml:lang="en" to="d@di72nn.com/desktop" from="d@di72nn.com" 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 d@di72nn.com/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 (d@di72nn.com) -->
<message xmlns="jabber:client" to="d@di72nn.com/desktop" from="d@di72nn.com" 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="d@di72nn.com/desktop" type="replyto" />
</addresses>
</message>
  1. Manual query:
<!-- Outgoing 2020-07-21T16:44:10 +04 (d@di72nn.com) -->
<iq xmlns="jabber:client" to="d@di72nn.com" 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 (d@di72nn.com) -->
<iq xmlns="jabber:client" xml:lang="en" to="d@di72nn.com/desktop" from="d@di72nn.com" 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.

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start at the mod_pubsub configuration and trace how last_item_cache handles pubsub item reads, publishes, and SQL persistence. Reproduce the reported sequence with last_item_cache enabled, comparing headline messages, direct queries, and the database. Done means cached and direct results remain consistent and updates persist in the database.

Written by the indexing model from the issue text.

Assessment

Tech stack
erlang, sql
Domain
backend, databases
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.