Improved diagnostics

server/modules/include/blr.h

@@ -116,6 +116,7 @@ typedef struct {
 	unsigned int	n_heartbeats;	/*< Number of heartbeat messages */
 	time_t		lastReply;
 	uint64_t	n_fakeevents;	/*< Fake events not written to disk */
+	uint64_t	n_artificial;	/*< Artificial events not written to disk */
 	uint64_t	events[0x24];	/*< Per event counters */
 } ROUTER_STATS;
 

server/modules/routing/binlog/blr.c

@@ -548,6 +548,8 @@ struct tm	tm;
                    router_inst->stats.n_binlogs);
 	dcb_printf(dcb, "\tNumber of fake binlog events:      	%u\n",
                    router_inst->stats.n_fakeevents);
+	dcb_printf(dcb, "\tNumber of artificial binlog events: 	%u\n",
+                   router_inst->stats.n_artificial);
 	dcb_printf(dcb, "\tNumber of binlog events in error:  	%u\n",
                    router_inst->stats.n_binlog_errors);
 	dcb_printf(dcb, "\tNumber of binlog rotate events:  	%u\n",
@@ -568,7 +570,10 @@ struct tm	tm;
 		   router_inst->stats.n_residuals);
 	dcb_printf(dcb, "\tAverage events per packet		%.1f\n",
 		   (double)router_inst->stats.n_binlogs / router_inst->stats.n_reads);
-	dcb_printf(dcb, "\tLast event from master at:  		%s\n", buf);
+	dcb_printf(dcb, "\tLast event from master at:  		%s",
+				buf);
+	dcb_printf(dcb, "\t					(%d seconds ago)\n",
+			time(0) - router_inst->stats.lastReply);
 	dcb_printf(dcb, "\tLast event from master:  		0x%x\n",
 			router_inst->lastEventReceived);
 	if (router_inst->active_logs)

server/modules/routing/binlog/blr_master.c

@@ -70,6 +70,7 @@ static void blr_distribute_binlog_record(ROUTER_INSTANCE *router, REP_HEADER *hd
 static void *CreateMySQLAuthData(char *username, char *password, char *database);
 static void blr_extract_header(uint8_t *pkt, REP_HEADER *hdr);
 static uint32_t extract_field(uint8_t *src, int bits);
+static void blr_log_packet(logfile_id_t file, char *msg, uint8_t *ptr, int len);
 
 static int keepalive = 1;
 
@@ -468,7 +469,9 @@ int		no_residual = 1;
         			LOGIF(LE,(skygw_log_write(
 		                           LOGFILE_ERROR,
 					"Insufficient memory to buffer event "
-					"of %d bytes\n.", len)));
+					"of %d bytes. Binlog %s @ %d\n.",
+					len, router->binlog_name,
+					router->binlog_position)));
 				break;
 			}
 
@@ -489,7 +492,9 @@ int		no_residual = 1;
 		                           LOGFILE_ERROR,
 					"Expected entire message in buffer "
 					"chain, but failed to create complete "
-					"message as expected.\n")));
+					"message as expected. %s @ %d\n",
+					router->binlog_name,
+					router->binlog_position)));
 				break;
 			}
 
@@ -506,8 +511,9 @@ int		no_residual = 1;
 			router->stats.n_residuals++;
 	        	LOGIF(LD,(skygw_log_write(
                            LOGFILE_DEBUG,
-				"Residual data left after %d records.\n",
+			   "Residual data left after %d records. %s @ %d\n",
-					router->stats.n_binlogs)));
+					router->stats.n_binlogs,
+			   router->binlog_name, router->binlog_position)));
 			break;
 		}
 		else
@@ -529,6 +535,7 @@ int		no_residual = 1;
 					len, hdr.event_size,
 					router->binlog_name,
 					router->binlog_position)));
+			blr_log_packet(LOGFILE_ERROR, "Packet:", ptr, len);
 			break;
 		}
 		if (hdr.ok == 0)
@@ -545,6 +552,11 @@ int		no_residual = 1;
 			if (hdr.event_type == FORMAT_DESCRIPTION_EVENT && hdr.next_pos == 0)
 			{
 				// Fake format description message
+        			LOGIF(LD,(skygw_log_write(LOGFILE_DEBUG,
+					"Replication fake event. "
+						"Binlog %s @ %d.\n",
+					router->binlog_name,
+					router->binlog_position)));
 				router->stats.n_fakeevents++;
 				if (hdr.event_type == FORMAT_DESCRIPTION_EVENT)
 				{
@@ -568,6 +580,12 @@ int		no_residual = 1;
 #ifdef SHOW_EVENTS
 					printf("Replication heartbeat\n");
 #endif
+        				LOGIF(LD,(skygw_log_write(
+			                           LOGFILE_DEBUG,
+						"Replication heartbeat. "
+						"Binlog %s @ %d.\n",
+						router->binlog_name,
+						router->binlog_position)));
 					router->stats.n_heartbeats++;
 				}
 				else if (hdr.flags != LOG_EVENT_ARTIFICIAL_F)
@@ -583,6 +601,17 @@ int		no_residual = 1;
 				}
 				else
 				{
+					router->stats.n_artificial++;
+        				LOGIF(LD,(skygw_log_write(
+			                           LOGFILE_DEBUG,
+					"Artificial event not written "
+					"to disk or distributed. "
+					"Type 0x%x, Length %d, Binlog "
+					"%s @ %d\n.",
+						hdr.event_type,
+						hdr.event_size,
+						router->binlog_name,
+						router->binlog_position)));
 					ptr += 5;
 					if (hdr.event_type == ROTATE_EVENT)
 					{
@@ -594,6 +623,12 @@ int		no_residual = 1;
 		else
 		{
 			printf("Binlog router error: %s\n", &ptr[7]);
+			LOGIF(LE,(skygw_log_write(LOGFILE_ERROR,
+				"Error packet in binlog stream.%s @ %d\n.",
+						router->binlog_name,
+						router->binlog_position)));
+			blr_log_packet(LOGFILE_ERROR, "Error Packet:",
+				ptr, len);
 			router->stats.n_binlog_errors++;
 		}
 
@@ -794,3 +829,18 @@ ROUTER_SLAVE	*slave;
 	}
 	spinlock_release(&router->lock);
 }
+
+static void
+blr_log_packet(logfile_id_t file, char *msg, uint8_t *ptr, int len)
+{
+int	i;
+
+	skygw_log_write(file, "%s length = %d: ", msg, len);
+	for (i = 0; i < len && i < 40; i++)
+		skygw_log_write(file, "0x%02x ", ptr[i]);
+	if (i < len)
+		skygw_log_write_flush(file, "...\n");
+	else
+		skygw_log_write_flush(file, "\n");
+	
+}