From 9bada09d2d9efc4ef873e270c8678dcccfd2d1dd Mon Sep 17 00:00:00 2001 From: MassimilianoPinto Date: Sun, 9 Aug 2015 23:14:55 +0200 Subject: [PATCH] Update messages on errors Update messages on errors --- server/modules/routing/binlog/blr.c | 41 ++++++++++------ server/modules/routing/binlog/blr_file.c | 34 +++++++------- server/modules/routing/binlog/blr_master.c | 54 ++++++++++------------ server/modules/routing/binlog/blr_slave.c | 1 + 4 files changed, 69 insertions(+), 61 deletions(-) diff --git a/server/modules/routing/binlog/blr.c b/server/modules/routing/binlog/blr.c index 5aef7aea6..8eb76a438 100644 --- a/server/modules/routing/binlog/blr.c +++ b/server/modules/routing/binlog/blr.c @@ -271,7 +271,7 @@ int rc = 0; inst->m_errno = 0; inst->m_errmsg = NULL; - inst->trx_safe = 0; + inst->trx_safe = 1; inst->pending_transaction = 0; inst->last_safe_pos = 0; @@ -425,8 +425,6 @@ int rc = 0; service->name))); } - fprintf(stderr, "Transaction safety is [%i]\n", inst->trx_safe); - if (inst->fileroot == NULL) inst->fileroot = strdup(BINLOG_NAME_ROOT); inst->active_logs = 0; @@ -602,6 +600,14 @@ int rc = 0; free(name); } + /* Log whether the transaction safety option value is on*/ + if (inst->trx_safe) { + LOGIF(LT, (skygw_log_write_flush( + LOGFILE_TRACE, + "%s: Service has transaction safety option set to ON", + service->name))); + } + /** * Check whether replication can be started */ @@ -613,9 +619,9 @@ int rc = 0; } LOGIF(LT, (skygw_log_write_flush( - LOGFILE_TRACE, - "Binlog router: current binlog file is: %s, current position %u\n", - inst->binlog_name, inst->binlog_position))); + LOGFILE_TRACE, + "Current binlog file is %s, current pos is %lu\n", + inst->binlog_name, inst->binlog_position))); /* Start replication from master server */ blr_start_master(inst); @@ -954,7 +960,13 @@ struct tm tm; dcb_printf(dcb, "\tCurrent binlog file: %s\n", router_inst->binlog_name); dcb_printf(dcb, "\tCurrent binlog position: %u\n", - router_inst->binlog_position); + router_inst->current_pos); + if (router_inst->trx_safe) { + if (router_inst->pending_transaction) { + dcb_printf(dcb, "\tCurrent open transaction pos: %u\n", + router_inst->binlog_position); + } + } dcb_printf(dcb, "\tNumber of slave servers: %u\n", router_inst->stats.n_slaves); dcb_printf(dcb, "\tNo. of binlog events received this session: %u\n", @@ -1828,20 +1840,17 @@ static int blr_check_binlog(ROUTER_INSTANCE *router) { n = blr_read_events_all_events(router, 0, 0); - LOGIF(LT, (skygw_log_write_flush( - LOGFILE_TRACE, + LOGIF(LD, (skygw_log_write_flush( + LOGFILE_DEBUG, "blr_read_events_all_events() ret = %i\n", n))); - fprintf(stderr, "blr_read_events_all_events() ret = %i\n", n); - fprintf(stderr, "current_pos / binlog_pos are [%llu] / [%llu]\n", router->current_pos, router->binlog_position); - if (n != 0) { char msg_err[1024 + 1] = ""; router->master_state = BLRM_SLAVE_STOPPED; snprintf(msg_err, 1024, "Error found in binlog %s. Safe pos is %lu", router->binlog_name, router->binlog_position); /* set mysql_errno */ - router->m_errno = 1111; + router->m_errno = 2032; /* set io error message */ router->m_errmsg = strdup(msg_err); @@ -1849,7 +1858,11 @@ static int blr_check_binlog(ROUTER_INSTANCE *router) { /* set last_safe_pos */ router->last_safe_pos = router->binlog_position; - /** LOG THE ERROR **/ + LOGIF(LE, (skygw_log_write_flush( + LOGFILE_ERROR, + "Error found in binlog file %s. Safe starting pos is %lu", + router->binlog_name, + router->binlog_position))); return 0; } else { diff --git a/server/modules/routing/binlog/blr_file.c b/server/modules/routing/binlog/blr_file.c index a27e26b22..0125258a7 100644 --- a/server/modules/routing/binlog/blr_file.c +++ b/server/modules/routing/binlog/blr_file.c @@ -397,9 +397,10 @@ struct stat statb; } if (fstat(file->fd, &statb) == 0) filelen = statb.st_size; - if (pos >= filelen) + + if (pos > filelen) { - LOGIF(LD, (skygw_log_write(LOGFILE_ERROR, + LOGIF(LE, (skygw_log_write(LOGFILE_ERROR, "Attempting to read off the end of the binlog file %s, " "event at %lu.", file->binlogname, pos))); return NULL; @@ -408,9 +409,15 @@ struct stat statb; if (strcmp(router->binlog_name, file->binlogname) == 0 && pos >= router->binlog_position) { + if (pos > router->binlog_position) + { + LOGIF(LE, (skygw_log_write(LOGFILE_ERROR, + "Attempting to read off the binlog pos in file %s, " + "event at %lu.", file->binlogname, pos))); + } + return NULL; } - /* Read the header information from the file */ if ((n = pread(file->fd, hdbuf, 19, pos)) != 19) @@ -1032,19 +1039,14 @@ int found_chksum = 0; hdr.next_pos = EXTRACT32(&hdbuf[13]); hdr.flags = EXTRACT16(&hdbuf[17]); - //fprintf(stderr, ">>>> pos [%llu] event type %i\n", pos, hdr.event_type); - //fprintf(stderr, ">>>> pos [%llu] event size %lu\n", pos, hdr.event_size); - //fprintf(stderr, ">>>> pos [%llu] event next_pos %lu\n", pos, hdr.next_pos); - /* TO DO */ - - /* Add MariaDB 10 check */ + /* Add MariaDB 10 check for MAX_EVENT_TYPE */ /* Check event type against MAX_EVENT_TYPE */ if (hdr.event_type > MAX_EVENT_TYPE) { LOGIF(LE, (skygw_log_write_flush(LOGFILE_ERROR, - "*** ERROR: Found an Invalid event type 0x%x. " + "Found an Invalid event type 0x%x. " "Binlog file is %s, position %llu", hdr.event_type, router->binlog_name, pos))); @@ -1068,7 +1070,7 @@ int found_chksum = 0; if (hdr.event_size <= 0) { LOGIF(LE, (skygw_log_write_flush(LOGFILE_ERROR, - "*** ERROR: event size error: " + "Event size error: " "size %d at %llu.", hdr.event_size, pos))); @@ -1121,7 +1123,7 @@ int found_chksum = 0; if (n == -1) { LOGIF(LE, (skygw_log_write_flush(LOGFILE_ERROR, - "*** ERROR: Error reading the event at %llu in %s. " + "Error reading the event at %llu in %s. " "%s, expected %d bytes.", pos, router->binlog_name, strerror(errno), hdr.event_size - 19))); @@ -1129,14 +1131,14 @@ int found_chksum = 0; else { LOGIF(LE, (skygw_log_write_flush(LOGFILE_ERROR, - "*** ERROR: Short read when reading the event at %llu in %s. " + "Short read when reading the event at %llu in %s. " "Expected %d bytes got %d bytes.", pos, router->binlog_name, hdr.event_size - 19, n))); if (filelen > 0 && filelen - pos < hdr.event_size) { LOGIF(LE, (skygw_log_write_flush(LOGFILE_ERROR, - "*** ERROR: Binlog event is close to the end of the binlog file %s, " + "Binlog event is close to the end of the binlog file %s, " " size is %lu.", router->binlog_name, filelen))); } @@ -1264,8 +1266,6 @@ int found_chksum = 0; statement_sql = calloc(1, statement_len+1); strncpy(statement_sql, (char *)ptr+4+4+1+2+2+var_block_len+1+db_name_len, statement_len); - //fprintf(stderr, "QUERY_EVENT = [%s] %i / %i\n", statement_sql, (4+4+1+2+2+var_block_len+1+db_name_len), statement_len); - /* A transaction starts with this event */ if (strncmp(statement_sql, "BEGIN", 5) == 0) { if (pending_transaction > 0) { @@ -1380,7 +1380,7 @@ int found_chksum = 0; } else { LOGIF(LE, (skygw_log_write_flush(LOGFILE_ERROR, - "*** ERROR: Current event type %lu @ %llu has nex pos = %llu : exiting", hdr.event_type, pos, hdr.next_pos))); + "Current event type %lu @ %llu has nex pos = %llu : exiting", hdr.event_type, pos, hdr.next_pos))); break; } } diff --git a/server/modules/routing/binlog/blr_master.c b/server/modules/routing/binlog/blr_master.c index 3e5499404..7dffdc8c6 100644 --- a/server/modules/routing/binlog/blr_master.c +++ b/server/modules/routing/binlog/blr_master.c @@ -1016,40 +1016,27 @@ int n_bufs = -1, pn_bufs = -1; router->lastEventReceived = hdr.event_type; router->lastEventTimestamp = hdr.timestamp; +#ifdef SHOW_EVENTS + printf("blr: event type 0x%02x, flags 0x%04x, event size %d", hdr.event_type, hdr.flags, hdr.event_size); +#endif /** * Check for an open transaction, if the option is set * Only complete transactions should be sent to sleves * - * If a trasaction is pending router->last_commit_pos - * won't be updated. + * If a trasaction is pending router->binlog_position + * won't be updated to router->current_pos */ if (router->trx_safe == 0 || (router->trx_safe && router->pending_transaction == 0)) { - /* set last_commit_pos to binlog_position */ + /* no pending transaction: set current_pos to binlog_position */ spinlock_acquire(&router->binlog_lock); router->binlog_position = router->current_pos; spinlock_release(&router->binlog_lock); - } else { - /** - * A transaction is pending. - * Last_commit_pos is on hold. - * - * Log a message if the transaction was opened - * at binlog router start - */ - - if (router->last_written == 0) { - fprintf(stderr, "*** Router started with an Open transaction at %lu / %lu\n", router->binlog_position, router->current_pos); - } } -#ifdef SHOW_EVENTS - printf("blr: event type 0x%02x, flags 0x%04x, event size %d", hdr.event_type, hdr.flags, hdr.event_size); -#endif - /** * Detect transactions in events * Only complete transactions should be sent to sleves @@ -1072,24 +1059,31 @@ int n_bufs = -1, pn_bufs = -1; /* Check for BEGIN (it comes for START TRANSACTION too) */ if (strncmp(statement_sql, "BEGIN", 5) == 0) { - spinlock_acquire(&router->binlog_lock); if (router->pending_transaction > 0) { - fprintf(stderr, "*** A transaction is already open @ %lu and a new one starts @ %lu\n", router->binlog_position, router->current_pos); + LOGIF(LE,(skygw_log_write_flush(LOGFILE_ERROR, + "Error: a transaction is already open " + "@ %lu and a new one starts @ %lu", + router->binlog_position, + router->current_pos))); + + // An action should be taken here } + spinlock_acquire(&router->lock); + router->pending_transaction = 1; - spinlock_release(&router->binlog_lock); + spinlock_release(&router->lock); } /* Check for COMMIT in non transactional store engines */ if (strncmp(statement_sql, "COMMIT", 6) == 0) { - spinlock_acquire(&router->binlog_lock); + spinlock_acquire(&router->lock); router->pending_transaction = 2; - spinlock_release(&router->binlog_lock); + spinlock_release(&router->lock); } free(statement_sql); @@ -1101,11 +1095,11 @@ int n_bufs = -1, pn_bufs = -1; xid = extract_field(ptr+4+20, 64); if (router->pending_transaction) { - spinlock_acquire(&router->binlog_lock); + spinlock_acquire(&router->lock); router->pending_transaction = 3; - spinlock_release(&router->binlog_lock); + spinlock_release(&router->lock); } } } @@ -1231,12 +1225,12 @@ int n_bufs = -1, pn_bufs = -1; * If transaction is closed: * * 1) read current binlog starting - * from router->last_commit_pos + * from router->binlog_position * * 2) distribute read event * - * 3) if current pos = router->binlog_position - * update router->last_commit_pos + * 3) set router->binlog_position to + * router->current_pos * */ @@ -1538,7 +1532,7 @@ int action; if (action == 1) { - if (slave->binlog_pos == router->last_written && + if (slave->binlog_pos <= router->last_written && (strcmp(slave->binlogfile, router->binlog_name) == 0 || (hdr->event_type == ROTATE_EVENT && strcmp(slave->binlogfile, router->prevbinlog)))) diff --git a/server/modules/routing/binlog/blr_slave.c b/server/modules/routing/binlog/blr_slave.c index 6125c5d28..63cc2e4f2 100644 --- a/server/modules/routing/binlog/blr_slave.c +++ b/server/modules/routing/binlog/blr_slave.c @@ -1769,6 +1769,7 @@ uint8_t *ptr; } } slave->stats.n_bursts++; + while (burst-- && burst_size > 0 && (record = blr_read_binlog(router, slave->file, slave->binlog_pos, &hdr)) != NULL) {