Replication master rejected, slave is busy

[Dump Kids 0]

Hello,

I have a case in my server era log like this

2018-12-01 14:05:29 Error: CReplicationModule [Thread 7fded6ffd700]: CStepProcessor: Replication master rejected, slave is busy

what is the cause of the case as above?
does anyone experience like me? if so what is the solution

i use 

mysql : mysql  Ver 14.14 Distrib 5.6.41, for Linux (x86_64) using  EditLine wrapper
os : CentOS Linux 7.5.1804
eraserver : 6.5.417.0
webconsole : 6.5.388.0

my eset agent client +-2000 user & my interval user is default (1 minutes)

this is config from mysql my.cnf

# For advice on how to change settings please see
# hxxp://dev.mysql.com/doc/refman/5.6/en/server-configuration-defaults.html

[mysqld]
# General configuration
innodb_buffer_pool_size = 1024M
join_buffer_size = 16M
sort_buffer_size = 2M

symbolic-links=0
sql_mode=NO_ENGINE_SUBSTITUTION,STRICT_TRANS_TABLES

datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

# Enable big chunks for ESET Remote Administrator
max_allowed_packet=600M

# Enable big statement size for ESET Remote Administrator
innodb_log_files_in_group=2
innodb_log_file_size=200MB

# Enable longer locks timeout for ESET Remote Administrator
innodb_lock_wait_timeout=600

[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

 

 

 

and some log mysql

181201 20:40:38 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended
181201 20:40:40 mysqld_safe Logging to '/var/log/mysqld.log'.
181201 20:40:40 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
2018-12-01 20:40:41 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2018-12-01 20:40:41 0 [Note] /usr/sbin/mysqld (mysqld 5.6.41) starting as process 21788 ...
2018-12-01 20:40:41 21788 [Warning] Buffered warning: Changed limits: max_open_files: 1024 (requested 5000)

2018-12-01 20:40:41 21788 [Warning] Buffered warning: Changed limits: table_open_cache: 431 (requested 2000)

2018-12-01 20:40:41 21788 [Note] Plugin 'FEDERATED' is disabled.
2018-12-01 20:40:41 21788 [Note] InnoDB: Using atomics to ref count buffer pool pages
2018-12-01 20:40:41 21788 [Note] InnoDB: The InnoDB memory heap is disabled
2018-12-01 20:40:41 21788 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-12-01 20:40:41 21788 [Note] InnoDB: Memory barrier is not used
2018-12-01 20:40:41 21788 [Note] InnoDB: Compressed tables use zlib 1.2.3
2018-12-01 20:40:41 21788 [Note] InnoDB: Using Linux native AIO
2018-12-01 20:40:41 21788 [Note] InnoDB: Using CPU crc32 instructions
2018-12-01 20:40:41 21788 [Note] InnoDB: Initializing buffer pool, size = 1.0G
2018-12-01 20:40:41 21788 [Note] InnoDB: Completed initialization of buffer pool
2018-12-01 20:40:41 21788 [Note] InnoDB: Highest supported file format is Barracuda.
2018-12-01 20:40:41 21788 [Note] InnoDB: 128 rollback segment(s) are active.
2018-12-01 20:40:41 21788 [Note] InnoDB: Waiting for purge to start
2018-12-01 20:40:41 21788 [Note] InnoDB: 5.6.41 started; log sequence number 1366794332187
2018-12-01 20:40:41 21788 [Note] Server hostname (bind-address): '*'; port: 3306
2018-12-01 20:40:41 21788 [Note] IPv6 is available.
2018-12-01 20:40:41 21788 [Note]   - '::' resolves to '::';
2018-12-01 20:40:41 21788 [Note] Server socket created on IP: '::'.
2018-12-01 20:40:41 21788 [Note] Event Scheduler: Loaded 0 events
2018-12-01 20:40:41 21788 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.41'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)
2018-12-01 20:43:25 21788 [Note] /usr/sbin/mysqld: Normal shutdown

2018-12-01 20:43:25 21788 [Note] Giving 8 client threads a chance to die gracefully
2018-12-01 20:43:25 21788 [Note] Event Scheduler: Purging the queue. 0 events
2018-12-01 20:43:25 21788 [Note] Shutting down slave threads
2018-12-01 20:43:27 21788 [Note] Forcefully disconnecting 0 remaining clients
2018-12-01 20:43:27 21788 [Note] Binlog end
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'partition'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'PERFORMANCE_SCHEMA'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_SYS_DATAFILES'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_SYS_TABLESPACES'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN_COLS'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_SYS_FIELDS'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_SYS_COLUMNS'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_SYS_INDEXES'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_SYS_TABLESTATS'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_SYS_TABLES'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_FT_INDEX_TABLE'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_FT_INDEX_CACHE'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_FT_CONFIG'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_FT_BEING_DELETED'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_FT_DELETED'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_FT_DEFAULT_STOPWORD'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_METRICS'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_BUFFER_POOL_STATS'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE_LRU'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX_RESET'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_CMPMEM_RESET'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_CMPMEM'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_CMP_RESET'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_CMP'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_LOCK_WAITS'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_LOCKS'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'INNODB_TRX'
2018-12-01 20:43:27 21788 [Note] Shutting down plugin 'InnoDB'
2018-12-01 20:43:27 21788 [Note] InnoDB: FTS optimize thread exiting.
2018-12-01 20:43:27 21788 [Note] InnoDB: Starting shutdown...
2018-12-01 20:43:29 21788 [Note] InnoDB: Shutdown completed; log sequence number 1366827658015
2018-12-01 20:43:29 21788 [Note] Shutting down plugin 'BLACKHOLE'
2018-12-01 20:43:29 21788 [Note] Shutting down plugin 'ARCHIVE'
2018-12-01 20:43:29 21788 [Note] Shutting down plugin 'MRG_MYISAM'
2018-12-01 20:43:29 21788 [Note] Shutting down plugin 'MyISAM'
2018-12-01 20:43:29 21788 [Note] Shutting down plugin 'MEMORY'
2018-12-01 20:43:29 21788 [Note] Shutting down plugin 'CSV'
2018-12-01 20:43:29 21788 [Note] Shutting down plugin 'sha256_password'
2018-12-01 20:43:29 21788 [Note] Shutting down plugin 'mysql_old_password'
2018-12-01 20:43:29 21788 [Note] Shutting down plugin 'mysql_native_password'
2018-12-01 20:43:29 21788 [Note] Shutting down plugin 'binlog'
2018-12-01 20:43:29 21788 [Note] /usr/sbin/mysqld: Shutdown complete

181201 20:43:29 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended
181201 20:43:32 mysqld_safe Logging to '/var/log/mysqld.log'.
181201 20:43:32 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
2018-12-01 20:43:32 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2018-12-01 20:43:32 0 [Note] /usr/sbin/mysqld (mysqld 5.6.41) starting as process 22687 ...
2018-12-01 20:43:32 22687 [Warning] Buffered warning: Changed limits: max_open_files: 1024 (requested 5000)

2018-12-01 20:43:32 22687 [Warning] Buffered warning: Changed limits: table_open_cache: 431 (requested 2000)

2018-12-01 20:43:32 22687 [Note] Plugin 'FEDERATED' is disabled.
2018-12-01 20:43:32 22687 [Note] InnoDB: Using atomics to ref count buffer pool pages
2018-12-01 20:43:32 22687 [Note] InnoDB: The InnoDB memory heap is disabled
2018-12-01 20:43:32 22687 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-12-01 20:43:32 22687 [Note] InnoDB: Memory barrier is not used
2018-12-01 20:43:32 22687 [Note] InnoDB: Compressed tables use zlib 1.2.3
2018-12-01 20:43:32 22687 [Note] InnoDB: Using Linux native AIO
2018-12-01 20:43:32 22687 [Note] InnoDB: Using CPU crc32 instructions
2018-12-01 20:43:32 22687 [Note] InnoDB: Initializing buffer pool, size = 1.0G
2018-12-01 20:43:32 22687 [Note] InnoDB: Completed initialization of buffer pool
2018-12-01 20:43:32 22687 [Note] InnoDB: Highest supported file format is Barracuda.
2018-12-01 20:43:33 22687 [Note] InnoDB: 128 rollback segment(s) are active.
2018-12-01 20:43:33 22687 [Note] InnoDB: Waiting for purge to start
2018-12-01 20:43:33 22687 [Note] InnoDB: 5.6.41 started; log sequence number 1366827658015
2018-12-01 20:43:33 22687 [Note] Server hostname (bind-address): '*'; port: 3306
2018-12-01 20:43:33 22687 [Note] IPv6 is available.
2018-12-01 20:43:33 22687 [Note]   - '::' resolves to '::';
2018-12-01 20:43:33 22687 [Note] Server socket created on IP: '::'.
2018-12-01 20:43:33 22687 [Note] Event Scheduler: Loaded 0 events
2018-12-01 20:43:33 22687 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.41'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)

maybe if anyone can help I am very grateful

best regards,

[MartinK 378]

16 minutes ago, Dump Kids said:

Hello,

I have a case in my server era log like this

2018-12-01 14:05:29 Error: CReplicationModule [Thread 7fded6ffd700]: CStepProcessor: Replication master rejected, slave is busy

what is the cause of the case as above?
does anyone experience like me? if so what is the solution

What it means that AGENT connections are rejected because server is overloaded. This might have multiple reasons, but most common are:

• insufficient free memory (RAM) on server
• non-working connection to database (this might be case especially in case database would be installed on separate host)
• pending log writes -> state where queue of data to be written into database is over some hard coded threshold.

I would recommend to check overall performance status of server, and also status.html (/var/log/eset/RemoteAdministrator/Server/status.html) for more details. Mentioned status.html should contain RAM and pending logs details.

[Dump Kids 0]

2 minutes ago, MartinK said:

What it means that AGENT connections are rejected because server is overloaded. This might have multiple reasons, but most common are:

• insufficient free memory (RAM) on server
• non-working connection to database (this might be case especially in case database would be installed on separate host)
• pending log writes -> state where queue of data to be written into database is over some hard coded threshold.

I would recommend to check overall performance status of server, and also status.html (/var/log/eset/RemoteAdministrator/Server/status.html) for more details. Mentioned status.html should contain RAM and pending logs details.

I installed the database with one machine
this is my system information from the era webmin

 

and this my log 

[Dump Kids 0]

[MartinK 378]

As you can see in status.html, problem will be with "Pending logs". Either there is performance problem with database not able to write all received logs in time, or clients are sending too much data.

In "Received logs" section of status.html, there is mentioned that ~14000 logs were received in last hour - could you please move mouse over this line and post shown data? Tooltip should contain detailed statistics of what kind of logs were received in last hour and could possibly result in this overloaded state.

Also are you using ERA Proxy? If so, what is the replication interval of it? In case interval is larger, it might result in state that too many logs is sent/received in a moment, resultin in temporary overloaded state.

[Dump Kids 0]

20 minutes ago, MartinK said:

In "Received logs" section of status.html, there is mentioned that ~14000 logs were received in last hour - could you please move mouse over this line and post shown data? Tooltip should contain detailed statistics of what kind of logs were received in last hour and could possibly result in this overloaded state.

i have quarantine_content_status 29466 on last hours, is that normal?
if not, what caused that?

this is a screenshort

 

Also are you using ERA Proxy? If so, what is the replication interval of it? In case interval is larger, it might result in state that too many logs is sent/received in a moment, resultin in temporary overloaded state.

No, i, dont use era proxy, the connection from client directly to era server & update using http proxy

[Dump Kids 0]

[MartinK 378]

Each client will every 24 hours send complete list of quarantine content, so that data shown in ERA are synchronized with clients. This might be problem in case there are clients with huge number of entries in quarantine and database is not fast enough to handle it. My only recommendation is to check which clients has this huge quarantines and possibly investigate, whether it could be result of some persistent threat, or it was just matter of time that some many objects were quarantined. There are also possibilities of how to reduce quarantine size directly from console.

Also second larges number are logs of client tasks execution progress - I guess you  have run some client task on all devices in last hour?

One last note: in first paragraph I mentioned that clients are re-synchronizing every 24 hours -> this has actually changed with latest release (ESMC 7.0) and AGENTs are sending data much less often and logic for detection of inconsistencies has been implemented.