Redisearch: Faulty replication; some changes slaved, some not; mem usage increasing but "on hold"

[tw-bert]

We had an outage on our live slave systems last week which seems to have been caused by RediSearch (we use a pre-release of RediSearch against Redis 4.0.2, and have protected ourselves enough to minimize enduser impact, and we were able to contain the situation).

Our live system uses RediSearch branch aof_fixes on master as well as slaves.

So not the latest version of RediSearch, and we fully understand we have to upgrade, but we will have to wait a few days until we can update the master (planning, free timeslot, dependencies).

For now, all we are interested in is: "Is it probable that this is fixed in RC 0.99.0?"

What I did just now, is create a new redis slave on a test system, with RediSearch 0.99.0, with slaveof to a live master Redis instance, which still uses version aof_fixes.

The result is similar to what we saw in live slaves a few days back.
Here are the symptoms:

• A simple set hello world does replicate (Note: we did not test this at crisis time on live)
• A complex update from a Lua script (but not hitting any RediSearch commands) does not replicate
• The master is 100% okay (redis contents are daily diffed to origin), also RediSearch data seems accurate (but not daily diffed yet)
• We disabled snapshotting, and rdb_changes_since_last_save only rises when doing set hello world examples
• The used_memory_dataset does reflect all changes coming in (so data is recieved from the master, and is put somewhere in memory, but the Lua initiated changes never make it to the keyspace as far as we can tell)
• We consistently get master_link_status:up, master_last_io_seconds_ago:0 and master_sync_in_progress:0
• The logs do not show anything out of the ordinary
• On the day of the live issue, there was a partial sync at around 02:00AM, which went fine. We scanned the AOF of the master (not rewritten), and the first command of that day (!!!!!) that was able to trigger a RediSearch index write (from a Lua script, SAFEADD) was at 11:43AM. Our two slaves stopped replicating at 11:43AM, both at the same time. After that, memory usage kept climbing on both of the slaves, but the data was stale, and rdb_changes_since_last_save stopped rising (and snapshotting is disabled in the config, so no rdb saves are ever done, except for service stop or client request).

Here are some Graphs of the live issue.
From: 2017-11-16 11:00:00
To: 2017-11-16 12:00:00

Master (shows derivative of rdb_changes_since_last_save):

Slave 1 (shows derivative of rdb_changes_since_last_save, notice the flatliner after 11:43):

Slave 2 (shows derivative of rdb_changes_since_last_save, notice the flatliner after 11:43):

Graphs below are of Slave 1, notice the mem usage after 11:43:

At this point, could you provide hints on more data to gather, which could be useful at a later stage (after upgrading RediSearch for example)? I still have the 0.99.0 slave running on a test system with the faulty behaviour, and I'll try to keep it running today.

Hope you can help, cheers, TW

[dvirsky]

@mnunberg I'd like you to handle this please. First of all could you diff 0.99 and aof_fixes and see the diffs in that respect? I believe we found a couple of problems involving safe add after that branch was pushed.

It can also be a problem outside of redisearch, something with the integration of lua and modules, some gil issue.

@tw-bert the most help of course would be if you could create a contained test case that recreates this behavior. We're not testing redisearch with Lua at the moment, but I can't say for sure that's the case. Also, I'd try this stuff with redis unstable and not 4.0.2, the major problem with Lua and blocking commands was solved since but not released as redis 4.0.3 yet.

[mnunberg]

I can't think of anything immediately obvious wrt replication, but SAFEADD has some limitations. I wouldn't ever execute SAFEADD on a master when it might be run concurrently together with other ADD commands.

[dvirsky]

@tw-bert also, you can run MONITOR to see what's going on, it shows commans received from the master and commands run by lua scripts.

I have a suspicion it's just a bug in replication, but it's not enough data I guess.

[dvirsky]

also, I do believe aof_fixes is deleted so I can't diff it directly.

[mnunberg]

I just restored it and am already diffing it.

[mnunberg]

I don't see any relevant changes between aof_fixes and master. There were some fixes in respect to attempting to add duplicate documents, and there was also a fix in the indexer queue, but SAFEADD bypasses the indexer queue anyway, so it shouldn't be affected by those changes.

[dvirsky]

in any case, none of these will cause a deadlock or anything, at worst a race condition leading to some data corruption, and that shouldn't happen as well.
and related to lua? I dunno...

[dvirsky]

@tw-bert are you replicating the lua scripts or their effects? See https://redis.io/commands/eval#replicating-commands-instead-of-scripts

If you're replicating the script and it's calling redisearch - bad stuff can certainly happen since redisearch explicitly replicates effects of lua calling it, whether lua chooses to replicate commands or scripts.

So that's the first suspicious thing to look at... Now @mnunberg imagine a scenario where this happens (i.e. the whole script runs on master and slave, and the effects on the master are replicated on top of the script, so things happen twice) - can this cause a deadlock?

[mnunberg]

Yeah, I've just scanned the code again and don't see a code path where something like this could happen.

@tw-bert In addition to trying what Dvir suggested, do you think you can provide us with a version of the lua script or something that might help us better understand what's going on (or better yet - can reliably reproduce it)? From what I can tell, the relationship to RS is for now purely coincidental, especially where SAFEADD is concerned, since SAFEADD shouldn't affect the replication state.

[dvirsky]

@yossigo just opened this issue https://github.com/antirez/redis/pull/4463

Yossi, do you think it might be able to cause something like what we're seeing here? (basically slaves stopping processing commands all of the sudden)

[tw-bert]

Thank you for all your quick responses.

dvrisky: the most help of course would be if you could create a contained test case that recreates this behavior.

Yes, I would prefer that as well, and I'm definitely trying to create a reproducable scenario. The problem is, the issue is hard to reproduce. It happened two times in 10 days, after gigabytes of data and millions of transactions. We have been running this system to great success for years (downtime was almost zero, and always explainable _-> read: our own doing_). Note: RediSearch is a godsend to us, so some startup hickups like these are fine, and were to be expected.

dvrisky: Also, I'd try this stuff with redis unstable and not 4.0.2

Tempting, but we do not want to use a core Redis unstable on a live production system. A module is one thing, and a calculated risk. We kept the scope of RediSearch pre-release module usage very small. So far, we haven't been able to reproduce this issue other than in the live system.

mnunberg: I wouldn't ever execute SAFEADD on a master when it might be run concurrently together with other ADD commands.

We were just following your advice. FT.ADD was not working from Lua at all. If there is another way, please inform me.

That said, write concurrency is very very low on the master. Almost all redis writes come from a replicating daemon, which is one single threaded process. Regarding FT.ADD there is currently zero chance of that happening concurrently at this time. Only FT.SAFEADD, only from Lua, only one writer.

dvrisky: also, you can run MONITOR to see what's going on

I ran MONITOR on the slave. It does show the Lua initiated transactions. Too much to paste here; we have a busy system (50-10000 tps at the moment). However, memory usage is climbing, and the resulting data is not there (for example a ZRANGEBYLEX on a specific key, thus nothing to do with RediSearch in itself, shows stale data).

dvirsky: replicating the lua scripts or their effects?

Script replication. We (my team) could consider switching to replicated effects (this is relatively new functionality in redis, not available when the Lua script was written), as a workaround, if it is likely to work around this issue. Requires some testing on our side though.

mnunberg: do you think you can provide us with a version of the lua script or something that might help us better understand what's going on

Yes sure, here is a gist (I had to anonymize it, I left the relevant parts):

tInput      = cmsgpack.unpack(KEYS[1])
tInputTrans = tInput[1]
tInputData  = tInput[2]

for iIter = 1, #tInputTrans, 1 do

  -- Input data: Two arrays of equal length. Both contains slices.
  -- 
  -- "-transid.d" slices: 
  -- ====================
  --  [:snip:]
  -- cSliceTransPre (fxbi transaction-id, subtransaction-id, and crud type) is used to determine the crud type cr/up/rm
  -- cSliceTransKey is the second entry.
  -- "data" slices:
  -- ==============
  -- Complete data slice with the actual record data, for 'up' (update) slices.
  -- 'rm' slices contain only the prefix, no data.
  --

--[[:snip:]]

  cSliceTransKey  = cSliceTransKey:match('(.-)%z\128%z')

--[[:snip:]]

  -- Get old 'last one wins' counter for this slice, written by solidifier
  tOldLastOneWins = redis.call(
    'zrangebylex',
    cSliceNoBIKey .. '@lastsolid.d',
    '[' .. cSliceKeyValPrev .. '\000',
    '(' .. cSliceKeyValPrev .. '\001')
  if tOldLastOneWins and (#tOldLastOneWins > 0) then ... end --[[:snip:]]

--[[:snip:]]

  if ... then    redis.call(
      'zremrangebylex',
      cSliceNoBIKey .. '@lastsolid.d',
      '[' .. cSliceKeyValPrev  .. '\000',
      '(' .. cSliceKeyValPrev  .. '\001')

  end

--[[:snip:]]

        iCall = redis.call(
          'zadd',

--[[:snip:]]

      redis.call('publish','qxe@nondisclosed-github, cmsgpack.pack({ ...

--[[:snip:]]

            redis.call('FT.SAFEADD','~ftidx.nondisclosed-github', '~ftdoc.nondisclosed-github@' .. cSliceKeyValNew, 1.0, 'REPLACE', 'FIELDS', 
              'iIDnondisclosed-github', nondisclosed-github_iIDnondisclosed-github or '',
              'cnondisclosed-github,     nondisclosed-github_cnondisclosed-github or '',
             ... )

--[[:snip:]]

        if bDropNew then
          redis.call('FT.DEL','~ftidx.nondisclosed-github', '~ftdoc.nondisclosed-github@' .. cSliceKeyValNew)
          redis.call('DEL','~ftdoc.nondisclosed-github@' .. cSliceKeyValNew) -- Also delete the document. See: https://github.com/RedisLabsModules/RediSearch/issues/78#issuecomment-309682458

--[[:snip:]]

        if bDropPrev then
          redis.call('FT.DEL','~ftidx.nondisclosed-github', '~ftdoc.nondisclosed-github@' .. cSliceKeyValPrev)
          redis.call('DEL','~ftdoc.nondisclosed-github@' .. cSliceKeyValNew) -- Also delete the document. See: https://github.com/RedisLabsModules/RediSearch/issues/78#issuecomment-309682458

--[[:snip:]]

mnunberg: From what I can tell, the relationship to RS is for now purely coincidental

I would agree, but a RS entry at the AOF of the master at the same time (well, exact same second, can't give more precision than that due to fsync config) as the issue is at least very very suspicious.

Appreciating all your help. Anything more I can give you? Maybe memory stats or malloc-stats?

[mnunberg]

If it's indeed related to RS (or commands in general) then simply spawning a new Redis instance with that same AOF should yield the same result, no?

BTW, check your script and see if you don't have any MULTI commands there.

[tw-bert]

We solved the issue (as it seems, only temporarily) by doing a full sync from the master. So alas, no.

[tw-bert]

BTW, check your script and see if you don't have any MULTI commands there.

Nope, no MULTI's

[tw-bert]

Note: I added some more to the Lua snippet above, regarding 'FT.DEL'. I think it shows all possible routes now ( I left out a lot of non related stuff. The script is quite big, hence it's preloaded by our tooling, and only called by using EVALSHA).

[mnunberg]

So I've somewhat managed to replicate it. There's definitely something wonky going on with replication, lua, and FT

[tw-bert]

Awesome that you're seeing something similar. It was no small feat to describe this wonkyness ;)

[mnunberg]

Well, the wonkyness resulted from me not calling redis.replicate_commands() in the lua script. It works fine now?

[tw-bert]

redis.replicate_commands() has never been mandatory to my knowledge. But if we can use it as a workaround, please let me know.

Note: I have to get home from the office now (Netherlands), and am off tomorrow. I'll pop in now and then to see if I can assist somewhere.

[mnunberg]

So it seems that:

for i=0,10
do
    redis.call("FT.SAFEADD", "idx", "newDoc"..tostring(i), "1.0", "FIELDS", "txt", "Hello World"..tostring(i))
    print("Running multi add SEQ: "..tostring(i))
end


--redis.call("SET", "newKey", "IM IN A SCRIPT!!!");

Won't replicate. However, if I uncomment the last line, the entire script replicates. I wonder what's happening here.

[tw-bert]

Good detective work, I can confirm that's a possible flow in our scenario.

[dvirsky]

@tw-bert we've managed to consistently reproduce it and are drilling in now. Not sure yet if it's something in RS or in redis itself.

[tw-bert]

@dvirsky Great news. Good luck, and thanks again for the excellent responses.

[antirez]

Good work @mnunberg, please if you or @dvirsky could open a bug report with minimal example, I'll fix ASAP so we have it in next 4.0.x.

[dvirsky]

See https://github.com/antirez/redis/issues/4466

[mnunberg]

@tw-bert as a workaround, you should be able to use that redis.replicate_command(); OR make a dummy set at the end of your lua script (ensure it gets run), e.g. redis.call("SET", "foo", "bar")).

The reasons why these are necessary for the time being are discussed in the linked-to PR, and will be resolved eventually, but for now, those two workarounds should be enough. Please verify that these indeed work for you, as I've only been able to verify them roughly.

[tw-bert]

@mnunberg thank you, all clear. I was following your work, good to see that it wasn't RS after all.

We will upgrade to RediSearch 0.99.0 soon anyway (within a week or so), and are going to re-populate the master, so that will be a good time to apply replicate_commands() after testing. My guess is, that it will be a performance benifit on the slaves anyway, especially for this Lua script. We will see.

One more question: you mentioned the following:

I wouldn't ever execute SAFEADD on a master when it might be run concurrently together with other ADD commands.

What do you advise in our scenario? Use it for now, but switch to FT.ADD from Lua when Redis 4.0.3 arrives? Or forbid FT.ADD altogether (within or outside of Lua, maybe rename/obfuscate it in redis.conf if possible) and only use FT.SAFEADD?

[mnunberg]

FT.ADD will never be usable from within Lua because it dispatches to a separate thread, which is something that cannot be handled from that context. Now, as to using them together, I’d need to actually look in the code and see if there’s actually an issue. The issue right now is only theoretical, but it’s still something I haven’t tested.

I suppose it’s possible to enforce from within SAFEADD to ensure that it acquires the queue lock (not the GIL), this way, other ADD commands are blocked.

On Nov 22, 2017, at 6:53 PM, tw-bert [e-mail] wrote:

@mnunberg https://github.com/mnunberg thank you, all clear. I was following your work, good to see that it wasn't RS after all.

We will upgrade to RediSearch 0.99.0 soon anyway (within a week or so), and are going to re-populate the master, so that will be a good time to apply replicate_commands() after testing. My guess is, that it will be a performance benifit on the slaves anyway, especially for this Lua script. We will see.

One more question: you mentioned the following:

I wouldn't ever execute SAFEADD on a master when it might be run concurrently together with other ADD commands.

What do you advise in our scenario? Use it for now, but switch to FT.ADD from Lua when Redis 4.0.3 arrives? Or forbid FT.ADD altogether (within or outside of Lua, maybe rename/obfuscate it in redis.conf if possible) and only use FT.SAFEADD?

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub https://github.com/RedisLabsModules/RediSearch/issues/223#issuecomment-346503764, or mute the thread https://github.com/notifications/unsubscribe-auth/AAanUWQ1nYmpM2sEi_-J5ZH_VrsEK5qgks5s5LQBgaJpZM4QnPAG.

[tw-bert]

I understand the technical difficulty. So your advice to us (and anyone else who uses Lua), at the moment, is: "Use FT.SAFEADD everywhere" ? At least until it's tested and checked? We can live with that of course.

[dvirsky]

@tw-bert the next release of redis will add an API to detect running from lua in the module, and will allow us to silently treat lua commands safely, negating the need for SAFEADD. We're pretty sure that it's safe to do both in parallel, but in any case it has nothing to do with the bug you had.

What happens is that the slave receives a MULTI but because of a redis bug(s) never receives the EXEC. So the memory increase you saw is the slave accumulating commands for a transaction that never happens.

[tw-bert]

@dvirsky Great, sounds perfect.

Your explanation on the root cause is also clear, but (to me) does not explain yet why the slave keeps on accumulating all following MULTI/EXECs which have no module commands at all. Is there possibly a unique client-ID involved? Causing all further MULTI/EXECs from that specific client to be put in a queue, until the missing EXEC is recieved, which will never happen?

Just a thought: Would a restart (or disconnect/reconnect) of the main daemon process writing to the master dismiss and clear the queue at the slave? (if this is too hard to answer, please skip)

(Answers to the questions above could help us design our daemon processes better, and solve some live issues within the next few days until we have a free timeslot to do maintenance on the master)

[dvirsky]

I don't think any change on the master would fix that. What we actually found that what "releases" the stuck slave is doing a normal FT.ADD on the master.

There's already a PR from @yossigo that should fix this issue. You could patch 4.0.2 with this PR maybe, or wait a couple of days, I have a sense that this will trigger its release soon (but can't promise anything).

[tw-bert]

Understood. Did I guess right with _"Is there possibly a unique client-ID involved?"_ ?

[dvirsky]

I don't think so. At least the PR is unrelated to client ids. https://github.com/antirez/redis/pull/4467/files

[tw-bert]

Ok. We are quite relieved that the root cause has been identified, a fix is in the pipeline, ánd we have a workaround, so you may close this issue if you prefer. Many thanks from us.

[dvirsky]

Yes, since it's definitely not a RS issue per se, and the discussion has moved to redis, let's close this one. BTW I've just released 0.99.2 with a couple of crash fixes, but none applies to you AFAIK.

[dvirsky]

@tw-bert that PR doesn't solve the issue, so no point in cherry picking it. I'll let you know once it's resolved

[tw-bert]

@dvirsky - we'll wait for 4.0.3

We still have issues after applying one of the suggested workarounds.
We've decided we'll wait for Redis 4.0.3.

What we actually found that what "releases" the stuck slave is doing a normal FT.ADD on the master.

That was of great help, thank you!

More on the workarounds:

We applied the workaround with a normal (not-module-command) redis write command after FT.SAFEADD and FT.DEL (we used a HINCRBY, for easier tracing)

It possibly did not work because we didn't start "fresh". Does not really matter though, we've just disabled all RediSearch commands in our production-environment scripts and will wait for Redis 4.0.3.

---

Note: Hope I'm not diverting too much in the text below, it is more related to this issue's workaround than the issue in itself.

---

The other workaround, using script effect replication via redis.replicate_commands(), could work for this, but it causes other (not bug related) issues for us (at least, I think that is what happens, and we would highly appreciate your thoughts on this, although not related to the issue in itself). Please scrutinize my following statement:

• Replicated effects cause the slave to process multiple updates from one Lua script in a non blocking way. This means that transaction atomicity, if applicable to the master, will be lost on the slave. A client on the slave can read redis data while the transaction is still ongoing, whereas on the master it will be blocked. If this side-effect is not desired, it might be needed to stick to replicated scripts instead of replicated script effects.

The Lua scripts execs on the master are ofcourse short-lived. They are monitored by our tooling (using slowlog data), and rarely exceed 15ms, which is what we want. Still, in those 3~15ms, a lot can happen, like clients running a very speedy script on a slave to fetch for example two related keys. Using replicated effects, I think this might break.

We are very much aware of the advantages of replicated effects, and there are many usecases where we can and will use them. Especially lazy indexing, like letting RediSearch index full documents, is a great candidate for that. In this usecase however, we have some relational integrity which we also would like to use RediSearch for (actually, this use case prompted us to look at RediSearch, since we already use ES for lazy indexing).

[dvirsky]

Replicated effects cause the slave to process multiple updates from one Lua script in a non blocking way. This means that transaction atomicity, if applicable to the master, will be lost on the slave

I'm pretty sure that's why Redis wraps the replicated effects in MULTI/EXEC, which is the mechanism that was broken in redis <=4.0.2. It

this use case prompted us to look at RediSearch, since we already use ES for lazy indexing

I'm glad to see that someone got it :) can you share some more info on your use case? show the app maybe? just curious...

[tw-bert]

Thank you for your feedback. Yes, MULTI/EXEC is non-blocking naturally, so that aligns with my statement. I wonder if Salvatore considered an automated EXPECT in there, but then again, feedback from a slave could reverse its role (and we don't want short-circuiting).

I think you guys made great choices in designing RediSearch, not needing to compete with the big two (Solr+ES) but striving for Redis simplicity in the full-text search market, using Redis as a container and replication engine that is already wide spread.

Some remarks on RediSearch:

• I hope you refrain from using the somewhere suggested "random" flag at redis module registration, since this would render RS unusable for this use case.
• The open issue on verbatim and stemming would be high on my list

The application I'm working on is part of a commercial warehouse logistics application, and can't be disclosed in full. However, I do my best to share generic knowledge with the OSS world, where I feel I have something to add.

What I'm doing in this Lua script isn't very complicated (at least the basics aren't). Just replicating verified transactions from a commercial RDBMS to Redis. We use (at least - actually many more) two redis instances: one for the before-image data (unverified transactions), which never leaves the LAN, and one for the finished and verified transactions, which has a master on our LAN and is replicated to Azure. This simple setup enables us to serve our customers 24/7 in the cloud, even if our own internet connection would be broken, and enables us to do RDBMS and other backend maintenance work offline, without the Azure services even noticing. The Lua script we are talking about here, is called by a daemon backend process which continually transfers before-image data to the master[1:n]azure-slave setup, while checking and verifying database transactions.

We are not trying to replicate the complete RDBMS by the way, but are leveraging an existing data flow to a decoupled, distributed, but private NoSql infrastructure (with the possibility of microservices in mind, if and when the need arises).

We make use of the native sorted set lexicographical index a lot. Some of our keys have several million rows. Next to that, from Lua, we add extra sorted set indexes for secondary views on the same data (which I hope to phase out in the future, replaced by RediSearch - cutting the number of techniques used is always a good thing).

[dvirsky]

Nice to hear this. Interesting, I'm not sure I completely got what you're doing, but I got the main idea. Some comments:

I hope you refrain from using the somewhere suggested "random" flag at redis module registration, since this would render RS unusable for this use case.

Not going to happen, don't worry :)

The open issue on verbatim and stemming would be high on my list

Okay, I'll see what I can do. It's not a very hard one. Basically appending some prefix to stems would fix this.

(which I hope to phase out in the future, replaced by RediSearch - cutting the number of techniques used is always a good thing)

not only that, but from experiments I did RediSearch works much, much faster than sorted sets for that stuff. Although for range scanning it will probably be slower ATM since RS scans the entire range for each query. I do want to add cursors and then it will be very very fast for continuous range scans.

[tw-bert]

Not going to happen, don't worry :)

Great :)

Okay, I'll see what I can do. It's not a very hard one. Basically appending some prefix to stems would fix this.

Sounds good, thank you.

not only that, but from experiments I did RediSearch works much, much faster than sorted sets for that stuff. Although for range scanning it will probably be slower ATM since RS scans the entire range for each query. I do want to add cursors and then it will be very very fast for continuous range scans.

That's helpful insight for me. I dived quite deep into the sorted set implementation, and am still impressed by the performance of the skiplist implementation chosen by antirez. We do use ranges in ~5% of our redis searches. The other 95% percent of our searches are just lookups (0 or 1 returned). So I expect we can benefit greatly from all your efforts, with or without the extra cursors.

[dvirsky]

@tw-bert in case you want to test it, I've implemented the stemming/verbatim thing. check out the stem-prefix branch and/or PR #227

[tw-bert]

Great to see Redis 4.0.3 has been released, we will upgrade within a few days.

[dvirsky]

@tw-bert notice that you now need 4.0.6, and all the bugs in 4.0.3,4,5 were related to replication and Lua, so they're probably not usable for you.

[tw-bert]

@dvirsky Thank you Dvir, I (and the rest of my team) overlooked this. In fact, a team of three put 4.0.5 into production last night...

Well, at least we're on RS 1.0.0 now. And we can postpone our tests (planned later today) now we know they are of no use yet.

Thanks again, I should have payed better attention.

One Q: Do I still have to use SAFEADD from Lua now you can (I think) detect Lua-ness from RS?

[dvirsky]

4.0.5 had crashes so I'd advise upgrading ASAP. See https://groups.google.com/forum/#!topic/redis-db/WgHinhTEujo
And I'd also subscribe to this mailing list just for the announcements. You can also subscribe to releases on github IIRC.

Re SAFEADD: For now I haven't added Lua detection, I'll wait a couple of weeks before assuming people have this version of redis installed. So it's there, and will probably remain there until we can also reliably detect AOF loading as well (a pending PR https://github.com/antirez/redis/pull/4442)

[tw-bert]

Yes, thanks for the advice... at the time of upgrading yesterday, 4.0.5 was the latest and greatest. We are following the google group.

Clear about SAFEADD, thank you for the information.