2.8.2 issue with establishing replication

[Marc Gravell]

We're having some big problems getting replication working in 2.8.2; the setup is a little complex involving multi-level replication, and upgrading from a 2.6.13 install. The bridge between our primary and secondary data-centre is showing

# MASTER timeout: no data nor PING received...

and later

[32022] 06 Dec 20:01:46.286 * Trying a partial resynchronization
[32022] 06 Dec 20:01:46.365 * Full resync from master: 

and so it keeps re-syncing; it **seems** to have stabilised now, but it has knocked our confidence in it a bit, so I'm unsure whether to revert!

Context: 20GB database (based on "used"), with high-latency to a secondary data-centre where it takes 10 minutes to do a full sync+load, and during that time we churn about 300MB of transaction data. During our deploy we've tried changing repl_backlog_size to 1GB, but it was still unstable.

At the time of writing, we're keeping our master node on 2.6.13 so we still have a revert story - and unless we can get confidence in the replication I'm going to have to start re-deploying 2.6.13.

Any ideas what we're doing wrong here?

Marc

Log:

[32022] 06 Dec 19:24:56.360 * MASTER <-> SLAVE sync started

[32022] 06 Dec 19:24:56.439 * Non blocking connect for SYNC fired the event.

[32022] 06 Dec 19:24:56.550 # Error reply to PING from master: '-LOADING Redis is loading the dataset in memory'

[32022] 06 Dec 19:24:57.362 * Connecting to MASTER ny-redis01.ds.stackexchange.com:6379

[32022] 06 Dec 19:24:57.363 * MASTER <-> SLAVE sync started

[32022] 06 Dec 19:24:57.442 * Non blocking connect for SYNC fired the event.

[32022] 06 Dec 19:24:57.522 * Master replied to PING, replication can continue...

[32022] 06 Dec 19:24:57.602 * Partial resynchronization not possible (no cached master)

[32022] 06 Dec 19:24:57.682 * Full resync from master: 00682274becb9882c4c9741cfdb583962f4b9fae:181600

[32022] 06 Dec 19:26:32.246 * MASTER <-> SLAVE sync: receiving 6434201052 bytes from master

[32022] 06 Dec 19:32:20.430 * MASTER <-> SLAVE sync: Loading DB in memory

[32022] 06 Dec 19:36:19.497 * MASTER <-> SLAVE sync: Finished with success

[32022] 06 Dec 19:37:20.803 # MASTER timeout: no data nor PING received...

[32022] 06 Dec 19:37:20.803 * Caching the disconnected master state.

[32022] 06 Dec 19:37:20.803 * Connecting to MASTER ny-redis01.ds.stackexchange.com:6379

[32022] 06 Dec 19:37:20.804 * MASTER <-> SLAVE sync started

[32022] 06 Dec 19:37:20.884 * Non blocking connect for SYNC fired the event.

[32022] 06 Dec 19:37:20.963 * Master replied to PING, replication can continue...

[32022] 06 Dec 19:37:21.042 * Trying a partial resynchronization (request 00682274becb9882c4c9741cfdb583962f4b9fae:3670551).

[32022] 06 Dec 19:37:21.121 * Full resync from master: 00682274becb9882c4c9741cfdb583962f4b9fae:652792803

[32022] 06 Dec 19:37:21.121 * Discarding previously cached master state.

[32022] 06 Dec 19:38:56.056 * MASTER <-> SLAVE sync: receiving 6458924765 bytes from master

[32022] 06 Dec 19:44:31.897 * MASTER <-> SLAVE sync: Loading DB in memory

[32022] 06 Dec 19:48:45.907 * MASTER <-> SLAVE sync: Finished with success

[32022] 06 Dec 19:49:47.043 # MASTER timeout: no data nor PING received...

[32022] 06 Dec 19:49:47.043 * Caching the disconnected master state.

[32022] 06 Dec 19:49:47.043 * Connecting to MASTER ny-redis01.ds.stackexchange.com:6379

[32022] 06 Dec 19:49:47.044 * MASTER <-> SLAVE sync started

[32022] 06 Dec 19:49:47.123 * Non blocking connect for SYNC fired the event.

[32022] 06 Dec 19:49:47.202 * Master replied to PING, replication can continue...

[32022] 06 Dec 19:49:47.281 * Trying a partial resynchronization (request 00682274becb9882c4c9741cfdb583962f4b9fae:656844415).

[32022] 06 Dec 19:49:47.360 * Full resync from master: 00682274becb9882c4c9741cfdb583962f4b9fae:1063025761

[32022] 06 Dec 19:49:47.360 * Discarding previously cached master state.

[32022] 06 Dec 19:51:22.405 * MASTER <-> SLAVE sync: receiving 6463872589 bytes from master

[32022] 06 Dec 19:56:31.966 * MASTER <-> SLAVE sync: Loading DB in memory

[32022] 06 Dec 20:00:45.534 * MASTER <-> SLAVE sync: Finished with success

[32022] 06 Dec 20:01:46.048 # MASTER timeout: no data nor PING received...

[32022] 06 Dec 20:01:46.048 * Caching the disconnected master state.

[32022] 06 Dec 20:01:46.048 * Connecting to MASTER ny-redis01.ds.stackexchange.com:6379

[32022] 06 Dec 20:01:46.049 * MASTER <-> SLAVE sync started

[32022] 06 Dec 20:01:46.128 * Non blocking connect for SYNC fired the event.

[32022] 06 Dec 20:01:46.207 * Master replied to PING, replication can continue...

[32022] 06 Dec 20:01:46.286 * Trying a partial resynchronization (request 00682274becb9882c4c9741cfdb583962f4b9fae:1066551814).

[32022] 06 Dec 20:01:46.365 * Full resync from master: 00682274becb9882c4c9741cfdb583962f4b9fae:1480454340

[32022] 06 Dec 20:01:46.365 * Discarding previously cached master state.

[Salvatore Sanfilippo]

Hello Marc, more details later, sorry writing from a phone. Is the master in this case 2.6 or 2.8 like the slave?

--
You received this message because you are subscribed to the Google Groups "Redis DB" group.
To unsubscribe from this group and stop receiving emails from it, send an email to redis-db+u...@googlegroups.com.
To post to this group, send email to redi...@googlegroups.com.
Visit this group at http://groups.google.com/group/redis-db.
For more options, visit https://groups.google.com/groups/opt_out.

[Marc Gravell]

Chain:

Primary master 2.6.13

  Slave in same DC 2.8.2

    Slave in second DC 2.8.2

The problem was between the two 2.8.2s

Marc

--
Regards,

Marc

[Salvatore Sanfilippo]

Ok thank you, I'll investigate ASAP. The issue does not appear to be
directly related to partial resynchronization, as the code path is the
one of full sync, but may be related to the changes on this area of
the replication code.

Salvatore

Salvatore 'antirez' Sanfilippo
open source developer - GoPivotal
http://invece.org

We suspect that trading off implementation flexibility for
understandability makes sense for most system designs.
— Diego Ongaro and John Ousterhout (from Raft paper)

[Marc Gravell]

We've reached enough confidence (i.e. seen it stay stable for long enough) that we are proceeding with our full 2.8.2 rollout - so I don't think there is any immediate urgency, but: if nothing else, I felt it was painful enough that you are aware of it.

Thanks,

Marc

[Salvatore Sanfilippo]

On Fri, Dec 6, 2013 at 10:11 PM, Marc Gravell <marc.g...@gmail.com> wrote:
> We've reached enough confidence (i.e. seen it stay stable for long enough)
> that we are proceeding with our full 2.8.2 rollout - so I don't think there
> is any immediate urgency, but: if nothing else, I felt it was painful enough
> that you are aware of it.

Definitely... thank you. I'll do simulations in the next days to
understand what happens. What is surprising is that the problem
happens after the synchronization stage actually terminated, since:

32022] 06 Dec 19:26:32.246 * MASTER <-> SLAVE sync: receiving
6434201052 bytes from master
[32022] 06 Dec 19:32:20.430 * MASTER <-> SLAVE sync: Loading DB in memory
[32022] 06 Dec 19:36:19.497 * MASTER <-> SLAVE sync: Finished with success
[32022] 06 Dec 19:37:20.803 # MASTER timeout: no data nor PING received...

Data loading into memory, and we are waiting for the stream of writes
to arrive, but apparently nothing happens.
So at least there is some specific code path to check carefully.

Cheers,
Salvatore

[Yiftach Shoolman]

Marc, could it be that u reached the master client-output-buffer-limit ? it should be shown in the master log

--
You received this message because you are subscribed to the Google Groups "Redis DB" group.
To unsubscribe from this group and stop receiving emails from it, send an email to redis-db+u...@googlegroups.com.
To post to this group, send email to redi...@googlegroups.com.
Visit this group at http://groups.google.com/group/redis-db.
For more options, visit https://groups.google.com/groups/opt_out.

--

Yiftach Shoolman
+972-54-7634621

[Salvatore Sanfilippo]

I thought at that too Yiftach... in general the master log is very
helpful. However we should see that as a connection closed by the
master (which is not logged. lame!) not as a timeout.

Anyway, good hint, master logs will be helpful maybe :-)

[Marc Gravell]

I'm not at a workstation right now - I will try to obtain them.

Marc

[Marc Gravell]

Here we go; I guess the "# Disconnecting timedout slave" is the important bit

[14076] 06 Dec 19:24:57.640 * Slave asks for synchronization

[14076] 06 Dec 19:24:57.641 * Full resync requested by slave.

[14076] 06 Dec 19:24:57.641 * Starting BGSAVE for SYNC

[14076] 06 Dec 19:24:57.866 * Background saving started by pid 32253

[32253] 06 Dec 19:26:31.605 * DB saved on disk

[32253] 06 Dec 19:26:31.775 * RDB: 3123 MB of memory used by copy-on-write

[14076] 06 Dec 19:26:32.204 * Background saving terminated with success

[14076] 06 Dec 19:32:18.370 * Synchronization with slave succeeded

[14076] 06 Dec 19:33:19.582 # Disconnecting timedout slave: (ip redacted):6379

[14076] 06 Dec 19:37:21.079 * Slave asks for synchronization

[14076] 06 Dec 19:37:21.079 * Unable to partial resync with the slave for lack of backlog (Slave request was: 3670551).

[14076] 06 Dec 19:37:21.079 * Starting BGSAVE for SYNC

[14076] 06 Dec 19:37:21.363 * Background saving started by pid 5687

[5687] 06 Dec 19:38:55.398 * DB saved on disk

[5687] 06 Dec 19:38:55.609 * RDB: 889 MB of memory used by copy-on-write

[14076] 06 Dec 19:38:56.012 * Background saving terminated with success

[14076] 06 Dec 19:44:29.943 * Synchronization with slave succeeded

[14076] 06 Dec 19:45:30.220 # Disconnecting timedout slave: (ip redacted):6379

[14076] 06 Dec 19:49:47.317 * Slave asks for synchronization

[14076] 06 Dec 19:49:47.317 * Unable to partial resync with the slave for lack of backlog (Slave request was: 656844415).

[14076] 06 Dec 19:49:47.317 * Starting BGSAVE for SYNC

[14076] 06 Dec 19:49:47.615 * Background saving started by pid 13844

[13844] 06 Dec 19:51:21.773 * DB saved on disk

[13844] 06 Dec 19:51:21.987 * RDB: 908 MB of memory used by copy-on-write

[14076] 06 Dec 19:51:22.361 * Background saving terminated with success

[14076] 06 Dec 19:56:29.875 * Synchronization with slave succeeded

[14076] 06 Dec 19:57:30.726 # Disconnecting timedout slave: (ip redacted):6379

[14076] 06 Dec 20:01:46.319 * Slave asks for synchronization

[14076] 06 Dec 20:01:46.319 * Unable to partial resync with the slave for lack of backlog (Slave request was: 1066551814).

[14076] 06 Dec 20:01:46.319 * Starting BGSAVE for SYNC

[14076] 06 Dec 20:01:46.614 * Background saving started by pid 19401

[19401] 06 Dec 20:03:23.654 * DB saved on disk

[19401] 06 Dec 20:03:23.867 * RDB: 1040 MB of memory used by copy-on-write

[14076] 06 Dec 20:03:24.250 * Background saving terminated with success

[14076] 06 Dec 20:09:31.112 * Synchronization with slave succeeded

[14076] 06 Dec 20:10:32.242 # Disconnecting timedout slave: (ip redacted):6379

[14076] 06 Dec 20:13:45.643 * Slave asks for synchronization

[14076] 06 Dec 20:13:45.864 * Partial resynchronization request accepted. Sending 406864227 bytes of backlog starting from offset 1480454341.

[14076] 06 Dec 20:39:21.555 * Caching the disconnected master state.

[14076] 06 Dec 20:39:21.555 * Discarding previously cached master state.

Marc

--
Regards,

Marc

[Yiftach Shoolman]

Looks like repl-timeout exceeded (default 60 and I guess u haven't changed it). It seems to happen when the slave was loading the RDB to it's memory during the full sync process. AFAIK Redis "should" serve clients during that time. I guess it is on Salvatore's court now. But a quick workaround should be to 'config set' this to an higher value

[Marc Gravell]

Interesting. If the repl-timeout is part of the new psync, then it is perhaps unfortunate that it could now create a problem where one didn't exist before. I can try increasing this value.

Marc

[Yiftach Shoolman]

repl-timeout is also in 2.6, but I guess the entire behavior has changed in 2.8. 

[Salvatore Sanfilippo]

That's useful indeed... I'm looking into the issue and reporting here:

https://github.com/antirez/redis/issues/1449

Thanks,
Salvatore

[Alexey Shuksto]

Just a two cents:

In our project we've encounterd this problem too while migrating from 2.6 to 2.8 with database size around 7-10 Gb.

At the end we were able to determine that inssufficient 'repl-timeout' value was cause of that and just increased it to be 'enough' but it was not easy nor apparent.

This is why I would like to vote for second proposed on github approach: acks from slaves on db loading.

понедельник, 9 декабря 2013 г., 14:46:17 UTC+4 пользователь Salvatore Sanfilippo написал:

[Salvatore Sanfilippo]

Hi, thanks for the feedback, I totally agree that's worth to fix, and
I've a patch that I'm testing right now.
The change is a bit of an hack in order to make it simple enough to
back port in 2.8, but the same hack actually is used verbatim already
in Redis in the reverse way, that is, when the master has to signal
its existence while saving the RDB file for full resynchronizations.
The hack consists into sending just "\n" characters that are
interpreted by the other end as a last-time-seen refresh.
Since it is a single character it guarantees to never desynchronize
the protocol and you can send it in odd situations like when no
buffered writes are available, just with a best effort write(2).

Cheers,
Salvatore

[Salvatore Sanfilippo]

Hello,

a patch is available => https://github.com/antirez/redis/issues/1449

Salvatore