what is outgoing:undefined in redis

b-sirius-a1v commented 2 years ago

System Information

Aedes: 0.47.0
aedes-persistence-redis: 9.0.0
NodeJS: v16.14.2
OS: MacOS 11.2.2

I'm using a translator

Describe the bug

outgoing:undefined is generated when broker is restarted with client of qos=1 When a client goes offline and back online, the broker no longer provides a buffer for the client

To Reproduce Steps to reproduce the behavior:

Launch Broker
c1 subscribed qos=1
Turn the broker off and on
published by c2 qos=1
outgoing:undefined has been created in redis
disconnect c1
published by c2 qos=1
offlineCount created
connect c1
Buffer is not delivered for c1

robertsLando commented 2 years ago

Does downgrading to 8.0.1 fixes the issue?

b-sirius-a1v commented 2 years ago

@robertsLando

Thank you very much!!! Your help worked for me

I have some questions

Has this been completely resolved by a downgrade?
Can I continue to use this version in a production environment?
maxSessionDelivery appears to be limiting packets to be sent to clients in outgoing, is it correct?
If yes, but maxSessionDelivery was sending packets beyond my expectation

robertsLando commented 2 years ago

@seriousme I think we may have a regression here, maybe introduced by the sanity check on keys?

seriousme commented 2 years ago

It will be some sort of regression if it works on 8.0.1, however encodeURIcomponent is present in NodeJS since version 0.10.

@b-sirius-a1v if you try the following:

node -e "console.log(encodeURIComponent('blah'))"

Where 'blah' is replaced by the real name of C1, do you then get undefined ?

Kind regards, Hans

seriousme commented 2 years ago

I just checked, I can reproduce the problem e.g.:

Running npm test while redis-cli monitor is active gives things like:

1654887375.958952 [0 172.17.0.1:40986] "get" "will:undefined:12345"
1654887375.961158 [0 172.17.0.1:40986] "del" "will:undefined:12345"

1654887376.057816 [0 172.17.0.1:40998] "lrem" "will" "0" "will:undefined:42"
1654887376.058510 [0 172.17.0.1:40998] "get" "will:undefined:42"
1654887376.059604 [0 172.17.0.1:40998] "del" "will:undefined:42"

1654887377.318774 [0 172.17.0.1:41046] "rpush" "outgoing:undefined" "packet:1:42"

However I also see many rpush records containing a correct client ID:

1654887374.027841 [0 172.17.0.1:40842] "rpush" "outgoing:abcde" "packet:broker-42:42"
1654887374.079341 [0 172.17.0.1:40854] "rpush" "outgoing:abcde" "packet:broker-42:42"
1654887374.080908 [0 172.17.0.1:40854] "rpush" "outgoing:fghih" "packet:broker-42:42"
1654887374.208707 [0 172.17.0.1:40866] "rpush" "outgoing:abcde" "packet:broker-42:10"
1654887374.229560 [0 172.17.0.1:40866] "rpush" "outgoing:abcde" "packet:broker-42:50"
1654887374.348288 [0 172.17.0.1:40878] "rpush" "outgoing:abcde" "packet:broker-42:42"
1654887374.400190 [0 172.17.0.1:40890] "rpush" "outgoing:abcde" "packet:broker-42:42"
1654887374.459942 [0 172.17.0.1:40902] "rpush" "outgoing:abcde" "packet:broker-42:42"
1654887374.515436 [0 172.17.0.1:40914] "rpush" "outgoing:abcde" "packet:broker-42:42"
1654887374.542930 [0 172.17.0.1:40914] "rpush" "outgoing:abcde" "packet:broker-42:43"
1654887374.613735 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:1"
1654887374.626464 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:2"
1654887374.631670 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:3"
1654887374.634334 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:4"
1654887374.636782 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:5"
1654887374.643630 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:6"
1654887374.648580 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:7"
1654887374.652527 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:8"
1654887374.662248 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:9"
1654887374.668297 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:10"
1654887374.673134 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:11"
1654887374.676328 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:12"
1654887374.688149 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:13"
1654887374.691820 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:14"
1654887374.694277 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:15"
1654887374.699788 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:16"
1654887374.703262 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:17"
1654887374.706152 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:18"
1654887374.709262 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:19"
1654887374.714574 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:20"
1654887374.717212 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:21"
1654887374.719691 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:22"
1654887374.725906 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:23"
1654887374.730525 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:24"
1654887374.739772 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:25"
1654887374.741978 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:26"
1654887374.743824 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:27"
1654887374.745395 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:28"
1654887374.747189 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:29"
1654887374.749199 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:30"
1654887374.751009 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:31"
1654887374.752954 [0 172.17.0.1:40926] "rpush" "outgoing:abcde" "packet:broker-42:32"
1654887375.377706 [0 172.17.0.1:40938] "rpush" "outgoing:abcde" "packet:broker-42:42"
1654887375.393787 [0 172.17.0.1:40938] "rpush" "outgoing:abcde" "packet:broker-42:50"
1654887375.659640 [0 172.17.0.1:40950] "rpush" "outgoing:abcde" "packet:broker-42:42"
1654887375.683112 [0 172.17.0.1:40950] "rpush" "outgoing:abcde" "outgoing:abcde:broker-42:42"
1654887375.829636 [0 172.17.0.1:40972] "rpush" "will" "will:broker-42:12345"
1654887375.931536 [0 172.17.0.1:40986] "rpush" "will" "will:broker-42:12345"
1654887376.035975 [0 172.17.0.1:40998] "rpush" "will" "will:broker-42:42"
1654887376.044358 [0 172.17.0.1:40998] "rpush" "will" "will:anotherBroker:24"
1654887376.100919 [0 172.17.0.1:41010] "rpush" "will" "will:broker-42:42"
1654887376.175829 [0 172.17.0.1:41034] "rpush" "outgoing:ttlTest" "packet:1:42"

I will check later to see if I can find which test(s) cause the undefined.

Kind regards, Hans

seriousme commented 2 years ago

Ok, there were 7 occurences of undefined in Redis Monitor generated by npm test

The first 3:

1654887375.951618 [0 172.17.0.1:40986] "lrem" "will" "0" "will:undefined:12345"
1654887375.958952 [0 172.17.0.1:40986] "get" "will:undefined:12345"
1654887375.961158 [0 172.17.0.1:40986] "del" "will:undefined:12345"

are caused by: https://github.com/moscajs/aedes-persistence/blob/main/abstract.js#L1483 Where:

brokerId: instance.broker.id,

needs to be added to the client object.

The next 3:

1654887376.057816 [0 172.17.0.1:40998] "lrem" "will" "0" "will:undefined:42"
1654887376.058510 [0 172.17.0.1:40998] "get" "will:undefined:42"
1654887376.059604 [0 172.17.0.1:40998] "del" "will:undefined:42"

are caused by: https://github.com/moscajs/aedes-persistence/blob/main/abstract.js#L1515 Where:

brokerId: instance.broker.id,

needs to be added to the client object. I would then add the same to anotherClient at https://github.com/moscajs/aedes-persistence/blob/main/abstract.js#L1518

The last one is:

1654887377.318774 [0 172.17.0.1:41046] "rpush" "outgoing:undefined" "packet:1:42"

And that is caused by:

https://github.com/moscajs/aedes-persistence-redis/blob/10a9fc8009dbc87e7be1a6c370057f9e9c95a0a3/test.js#L126

Where client.clientId needs to be replaced by client.id

With these fixes in I don't see any undefined anymore in Redis Monitor during npm test.

So the undefined found by @b-sirius-a1v must have another cause. Either the clientID contains an invalid character that can't be encoded by encodeURLComponent or something else goes wrong.

One thing that comes to mind is that brokerId is often used as part of a key, as I understood the brokerId is randomly generated by Aedes at startup and not read from the database. Could that be triggering this behaviour ?

Kind regards, Hans Ps. I have fixed all 3 items in the PR's mentioned below ;-)

seriousme commented 2 years ago

Small update: I just tried to replicate the issue on aedes-persistence-redis@8.0.1 with the following steps:

- start redis
- start example.js
- mqtt subscribe -i subscriber -t hello -q 1
- mqtt publish -i publisher -t hello -m message1 -q 1

The subscriber now sees message1

- stop the subscriber
- mqtt publish -i publisher -t hello -m message2 -q 1
- mqtt subscribe -i subscriber -t hello -q 1
- mqtt publish -i publisher -t hello -m message3 -q 1

The subscriber only sees message3 and not message2.

So the problem seems to be older than 9.0.0.

Kind regards, Hans

seriousme commented 2 years ago

Ok, my bad :-( The exact scenario is:

- start redis
- start example.js
- mqtt subscribe -i subscriber -t hello -q 1
- stop example.js
- start example.js
- mqtt publish -i publisher -t hello -m message1 -q 1  
- mqtt subscribe -i subscriber -t hello -q 1 --no-clean

This shows message1 on 8.0.1

Now we stop everything, including Redis to clean the cache ! We upgrade to 9.0.0 repeat the procedure and message1 does not show up :-(

The Redis Monitor log shows for 9.0.0:

"info"
"info"
"info"
"psubscribe" "$SYS/sub/*"
"psubscribe" "$SYS/*/heartbeat"
"psubscribe" "$SYS/*/new/clients"
"smembers" "clients"
"hgetall" "client:subscriber"
"hgetall" "client:publisher"
"lrem" "will" "0" "will:undefined:publisher"
"get" "will:undefined:publisher"
"del" "will:undefined:publisher"
"publish" "$SYS/95a09045-b8f0-41ed-9779-76ce4d8ce44e/new/clients" "\x82\xa2id\xb823LNF/awT9GLd5nlXSfb2w/0\xa3msg\x88\xa3cmd\xa7publish\xa8brokerId\xd9$95a09045-b8f0-41ed-9779-76ce4d8ce44e\xadbrokerCounter\x01\xa5topic\xd95$SYS/95a09045-b8f0-41ed-9779-76ce4d8ce44e/new/clients\xa7payload\xc4\tpublisher\xa3qos\x00\xa6retain\xc2\xa3dup\xc2"
"lrange" "outgoing:publisher" "0" "1000"
"mset" "packet:95a09045-b8f0-41ed-9779-76ce4d8ce44e:2" "\x89\xa3cmd\xa7publish\xa8brokerId\xd9$95a09045-b8f0-41ed-9779-76ce4d8ce44e\xadbrokerCounter\x02\xa5topic\xa5hello\xa7payload\xc4\bmessage1\xa3qos\x01\xa6retain\xc2\xa3dup\xc2\xa9messageId\xc0" "packet:95a09045-b8f0-41ed-9779-76ce4d8ce44e:2:offlineCount" "1"
"rpush" "outgoing:undefined" "packet:95a09045-b8f0-41ed-9779-76ce4d8ce44e:2"
"publish" "hello" "\x82\xa2id\xb823LNF/awT9GLd5nlXSfb2w/1\xa3msg\x8a\xa3cmd\xa7publish\xa8brokerId\xd9$95a09045-b8f0-41ed-9779-76ce4d8ce44e\xadbrokerCounter\x02\xa5topic\xa5hello\xa7payload\xc4\bmessage1\xa3qos\x01\xa6retain\xc2\xa3dup\xc2\xa9messageId\xc0\xa8clientId\xa9publisher"
"publish" "$SYS/95a09045-b8f0-41ed-9779-76ce4d8ce44e/disconnect/clients" "\x82\xa2id\xb823LNF/awT9GLd5nlXSfb2w/2\xa3msg\x88\xa3cmd\xa7publish\xa8brokerId\xd9$95a09045-b8f0-41ed-9779-76ce4d8ce44e\xadbrokerCounter\x03\xa5topic\xd9<$SYS/95a09045-b8f0-41ed-9779-76ce4d8ce44e/disconnect/clients\xa7payload\xc4\tpublisher\xa3qos\x00\xa6retain\xc2\xa3dup\xc2"

The Redis Monitor log shows for 8.0.1:

"info"
"info"
"info"
"psubscribe" "$SYS/sub/*"
"psubscribe" "$SYS/*/heartbeat"
"psubscribe" "$SYS/*/new/clients"
"smembers" "clients"
"hgetall" "client:subscriber"
"hgetall" "client:publisher"
"lrem" "will" "0" "will:undefined:publisher"
"get" "will:undefined:publisher"
"del" "will:undefined:publisher"
"publish" "$SYS/931593e9-0ace-44be-86e0-c09b5cec14af/new/clients" "\x82\xa2id\xb8+8tEq2ANRvyKhyTRfMwxbg/0\xa3msg\x88\xa3cmd\xa7publish\xa8brokerId\xd9$931593e9-0ace-44be-86e0-c09b5cec14af\xadbrokerCounter\x01\xa5topic\xd95$SYS/931593e9-0ace-44be-86e0-c09b5cec14af/new/clients\xa7payload\xc4\tpublisher\xa3qos\x00\xa6retain\xc2\xa3dup\xc2"
"lrange" "outgoing:publisher" "0" "1000"
"mset" "packet:931593e9-0ace-44be-86e0-c09b5cec14af:2" "\x89\xa3cmd\xa7publish\xa8brokerId\xd9$931593e9-0ace-44be-86e0-c09b5cec14af\xadbrokerCounter\x02\xa5topic\xa5hello\xa7payload\xc4\bmessage1\xa3qos\x01\xa6retain\xc2\xa3dup\xc2\xa9messageId\xc0" "packet:931593e9-0ace-44be-86e0-c09b5cec14af:2:offlineCount" "1"
"rpush" "outgoing:subscriber" "packet:931593e9-0ace-44be-86e0-c09b5cec14af:2"
"publish" "hello" "\x82\xa2id\xb8+8tEq2ANRvyKhyTRfMwxbg/1\xa3msg\x8a\xa3cmd\xa7publish\xa8brokerId\xd9$931593e9-0ace-44be-86e0-c09b5cec14af\xadbrokerCounter\x02\xa5topic\xa5hello\xa7payload\xc4\bmessage1\xa3qos\x01\xa6retain\xc2\xa3dup\xc2\xa9messageId\xc0\xa8clientId\xa9publisher"
"publish" "$SYS/931593e9-0ace-44be-86e0-c09b5cec14af/disconnect/clients" "\x82\xa2id\xb8+8tEq2ANRvyKhyTRfMwxbg/2\xa3msg\x88\xa3cmd\xa7publish\xa8brokerId\xd9$931593e9-0ace-44be-86e0-c09b5cec14af\xadbrokerCounter\x03\xa5topic\xd9<$SYS/931593e9-0ace-44be-86e0-c09b5cec14af/disconnect/clients\xa7payload\xc4\tpublisher\xa3qos\x00\xa6retain\xc2\xa3dup\xc2"

The major difference being in 9.0.0:

"rpush" "outgoing:undefined" "packet:95a09045-b8f0-41ed-9779-76ce4d8ce44e:2"

instead of in 8.0.1:

"rpush" "outgoing:subscriber" "packet:931593e9-0ace-44be-86e0-c09b5cec14af:2"

Now earlier tests have already shown that rpush gets a clientId in tests. But appearently the tests do not fully match the real life scenario :-(

Kind regards, Hans

seriousme commented 2 years ago

OK, I did some more digging and found the issue :-)

The issue is not with the rpush but with rebuilding the trie on startup, caused by https://github.com/moscajs/aedes-persistence-redis/pull/96/commits/7d517a70948f1fb44d7dd650c491bd382c10e9b4.

Unfortunately in: https://github.com/moscajs/aedes-persistence-redis/blob/10a9fc8009dbc87e7be1a6c370057f9e9c95a0a3/persistence.js#L232

we should have put:

that._db.hgetallBuffer(clientSubKey(clientId), function clientHash (err, hash) {

since we also do: https://github.com/moscajs/aedes-persistence-redis/blob/10a9fc8009dbc87e7be1a6c370057f9e9c95a0a3/persistence.js#L128

An similarly we should use msgpack.decode when processing the result in: https://github.com/moscajs/aedes-persistence-redis/blob/10a9fc8009dbc87e7be1a6c370057f9e9c95a0a3/persistence.js#L565

Fixing those 2 results in correct loading of stored subscriptions on restart.

I will add a PR for this.

Kind regards, Hans

seriousme commented 2 years ago

Btw: having some method of type checking would have helped in avoiding the need for all 3 PR's ;-)

seriousme commented 2 years ago

One more thing:

"lrem" "will" "0" "will:undefined:publisher"
"get" "will:undefined:publisher"
"del" "will:undefined:publisher"

seems to be a bug in Aedes itself, caused by inconsistencies in the interface :-(

The sequence comes from the delWill function.

What seems to be a bit odd is that dellWill gets its brokerId as a parameter from Aedes where getWill and putWill rely on this.broker.id in aedes-persistence-redis which is derived from this.broker.id in Aedes.

Looking at Aedes there are 4 locations that call delWill: 1) the test does not pass a brokerId at all, so it seems to assume that delWill relies on this.broker.id 2) lib/handlers.connect.js does not seem to pass a brokerId either 3) aedes.js seems to explicitly assume that brokerId is already encoded with the will 4) /lib/client.js is the only one that adds `that.broker.id

My suggestion would be to explicitly pass the brokerId tot getWill and putWill as well and remove the implicit dependency on this.broker.id (getWill and putWill are the only functions relying on this.brokerId) and thereby create a consistent interface ;-)

Kind regards, Hans

robertsLando commented 2 years ago

What seems to be a bit odd is that dellWill gets its brokerId as a parameter from Aedes where getWill and putWill rely on this.broker.id in aedes-persistence-redis which is derived from this.broker.id in Aedes.

This makes sense as in a cluster env dellWill should delete any existing will message with that clientId without considering brokerId that could be a different one.

If you see mongodb persistence it uses only the client id to identify a will message.

This is a bug that should be fixed on aedes persistence IMO, the will key should not contain the broker id

friesendrywall commented 2 years ago

Edit: I see that NPM is still on 9.0.0, so following may be somewhat irrelevant.

I think this is still broken.

relevant package dependencies "aedes": "^0.47.0", "aedes-persistence": "^9.1.2", "aedes-persistence-redis": "^9.0.0"

in subscriptionsByTopic, I'm logging as follows:

  subscriptionsByTopic (topic, cb) {
    if (!this.ready) {
      this.once('ready', this.subscriptionsByTopic.bind(this, topic, cb))
      return this
    }
    const result = this._trie.match(topic)
    console.log('subscriptionsByTopic', topic, result);
    cb(null, result)
  }

which yields -

subscriptionsByTopic devices/test [
  {
    clientId: undefined,
    topic: undefined,
    qos: undefined,
    rh: undefined,
    rap: undefined,
    nl: undefined
  }
]

Which of course inserts undefined

Screenshot 2022-07-08 08 37 11

friesendrywall commented 2 years ago

I'm not sure which is the correct place to post, but it would be good to update dependencies to require the correct ones, as well as release redis persistence to npm, otherwise the standard npm install aedes-persistence-redis is going to yield these results.

I think it requires "aedes-persistence": "^9.1.2",

robertsLando commented 2 years ago

It already uses aedes-persistence 9.1.2, it uses aedes-cached-persistence 9 that uses it: https://github.com/moscajs/aedes-cached-persistence/blob/master/package.json

moscajs / aedes-persistence-redis

what is outgoing:undefined in redis #98

Describe the bug