Merge pull request #4129 from zlamalp/logging

refactor(dispatcher): optimized logging in event processing

Author: zlamalp

perun-dispatcher/src/main/java/cz/metacentrum/perun/dispatcher/jms/EngineMessageConsumer.java

@@ -106,19 +106,19 @@ public void run() {
 		while (!shouldStop()) {
 
 			producer = producerFactory.getProducer();
-			
+
 			// Step 11. Deliver output and try to receive the message
 			TextMessage messageReceived = null;
 			try {
 				if(producer != null) {
 					producer.deliverOutputMessages();
 				}
 
-				log.debug("Gonna call messageConsumer.receive(timeout)...");
+				log.trace("Gonna call messageConsumer.receive(timeout)...");
 				messageReceived = (TextMessage) messageConsumer.receive(timeout);
 				if (messageReceived != null) {
-					if (log.isDebugEnabled()) {
-						log.debug("System message received [" + messageReceived.getText() + "]");
+					if (log.isTraceEnabled()) {
+						log.trace("System message received [" + messageReceived.getText() + "]");
 					}
 					try {
 						engineMessageProcessor.processEngineMessage(messageReceived.getText());
@@ -129,8 +129,8 @@ public void run() {
 					}
 					messageReceived.acknowledge();
 				} else {
-					if (log.isDebugEnabled()) {
-						log.debug("No message available...");
+					if (log.isTraceEnabled()) {
+						log.trace("No message available...");
 					}
 				}
 			} catch (JMSException e) {

perun-dispatcher/src/main/java/cz/metacentrum/perun/dispatcher/jms/EngineMessageProcessor.java

@@ -140,15 +140,15 @@ public void startProcessingSystemMessages() {
 		if(outputMessages == null) {
 			outputMessages = new LinkedBlockingDeque<TextMessage>();
 		}
-		
+
 		connection = null;
 		try {
 			if(restartHornetQServer) {
 				engineMessageProducerFactory.removeProducer();
 				perunHornetQServer.stopServer();
 				perunHornetQServer.startServer();
 			}
-			
+
 			// Step 2. Instantiate the TransportConfiguration object which
 			// contains the knowledge of what transport to use,
 			// The server port etc.
@@ -289,12 +289,12 @@ protected void processEngineMessage(String message) throws PerunHornetQServerExc
 
 			// process expected messages
 			EngineMessageProducer engineMessageProducer;
-			
+
 			if (clientMessageSplitter[0].equalsIgnoreCase("register")) {
 
 				// Do we have this queue already?
 				engineMessageProducer = engineMessageProducerFactory.getProducer();
-				
+
 				if (engineMessageProducer != null) {
 					// ...and close all tasks that could have been running there
 					schedulingPool.closeTasksForEngine();

perun-dispatcher/src/main/java/cz/metacentrum/perun/dispatcher/jms/EngineMessageProducer.java

@@ -83,19 +83,19 @@ public void sendMessage(String text) {
 
 	/**
 	 * Try to deliver all pending messages.
-	 * @throws JMSException 
-	 * 
+	 * @throws JMSException
+	 *
 	 */
 	public void deliverOutputMessages() throws JMSException {
 		while(!outputMessages.isEmpty()) {
 			TextMessage message = outputMessages.poll();
 			producer.send(message);
 			if (log.isDebugEnabled()) {
-				log.debug("Sent message (queue:" + queueName + "): " + message.getText());
+				log.debug("Sent message (queue name:" + queueName + "): " + message.getText());
 			}
 		}
 	}
-	
+
 	/**
 	 * Get name of the queue for engine.
 	 *
@@ -105,14 +105,13 @@ public String getQueueName() {
 		return queueName;
 	}
 
-	/** 
+	/**
 	 * Shutdown before destroying the producer.
-	 * 
 	 */
 	public void shutdown() {
 		try {
 			producer.close();
-			// session is not not ours to close
+			// session is not ours to close
 			// session.close();
 		} catch (JMSException e) {
 			log.error(e.toString(), e);

perun-dispatcher/src/main/java/cz/metacentrum/perun/dispatcher/processing/EventProcessor.java

@@ -134,17 +134,17 @@ public void run() {
 			try {
 				Event event = eventQueue.take();
 				createTaskFromEvent(event);
-				log.debug("Remaining events in a Queue = {}", eventQueue.size());
+				log.trace("Remaining events in a Queue = {}", eventQueue.size());
 			} catch (Exception e) {
 				log.error(e.getMessage(), e);
 			}
 		}
-		log.debug("EventProcessor has stopped.");
+		log.warn("EventProcessor has stopped.");
 	}
 
 	/**
 	 * Creates Task from Event data. Tries to resolve Service and Facility pairs from Event.
-	 * Events for non existing entities are discarded.
+	 * Events for non-existing entities are discarded.
 	 *
 	 * @param event Event to parse
 	 * @throws ServiceNotExistsException When Service from Event doesn't exists anymore
@@ -160,12 +160,20 @@ private void createTaskFromEvent(Event event) throws ServiceNotExistsException,
 			Facility facility = map.getKey();
 			for (Service service : map.getValue()) {
 				if (!service.isEnabled()) {
-					log.debug("Service not enabled: {}.", service);
+					if (log.isDebugEnabled()) {
+						log.debug("Service disabled: {}.", service);
+					} else {
+						log.info("Service disabled: {}.", service.getId() + " / " + service.getName());
+					}
 					continue;
 				}
 
 				if (((PerunBl) perun).getServicesManagerBl().isServiceBlockedOnFacility(service, facility)) {
-					log.debug("Service blocked on Facility: {} , {}.", service, facility);
+					if (log.isDebugEnabled()) {
+						log.debug("Service blocked on Facility: {} , {}.", service, facility);
+					} else {
+						log.info("Service blocked on Facility: {} , {}.", service.getId() + " / " + service.getName(), facility.getId() + " / " + facility.getName());
+					}
 					continue;
 				}
 
@@ -198,7 +206,12 @@ private void createTaskFromEvent(Event event) throws ServiceNotExistsException,
 						if (destinations.isEmpty()) {
 							// All service destinations were blocked -> Task is denied to be sent to engine just like
 							// when service is blocked globally in Perun or on facility as a whole.
-							log.debug("{} blocked on all destinations on {}.", service, facility);
+
+							if (log.isDebugEnabled()) {
+								log.debug("{} blocked on all destinations on {}.", service, facility);
+							} else {
+								log.info("Service: {} blocked on all destinations on Facility: {}.", service.getId() + " / " + service.getName(), facility.getId() + " / " + facility.getName());
+							}
 							continue;
 						}
 					}
@@ -227,7 +240,7 @@ private void createTaskFromEvent(Event event) throws ServiceNotExistsException,
 					task.setSourceUpdated(true);
 					if (isForced) task.setPropagationForced(true);
 					task.setRecurrence(0);
-					log.debug("[{}] Task is already in pool. Re-setting source updated and forced flags, {}.", task.getId(), task);
+					log.info("[{}] Task is already in pool. Re-setting source updated and forced flags, {}.", task.getId(), task);
 				} else {
 					// no such task yet, create one
 					task = new Task();
@@ -241,7 +254,7 @@ private void createTaskFromEvent(Event event) throws ServiceNotExistsException,
 					task.setPropagationForced(isForced);
 					try {
 						schedulingPool.addToPool(task);
-						log.debug("[{}] New Task added to pool. {}.", task.getId(), task);
+						log.info("[{}] New Task added to pool. {}.", task.getId(), task);
 					} catch (TaskStoreException e) {
 						log.error("[{}] Could not add Task to pool. Task {} will be lost: {}", task.getId(), task, e);
 					}

perun-dispatcher/src/main/java/cz/metacentrum/perun/dispatcher/processing/impl/EventServiceResolverImpl.java

@@ -85,15 +85,15 @@ public void setPerun(Perun perun) {
 	@Override
 	public Map<Facility, Set<Service>> resolveEvent(AuditEvent event) throws InvalidEventMessageException, ServiceNotExistsException, PrivilegeException {
 
-		log.info("Event - I am going to process event: {}", event);
-
 		Map<Facility, Set<Service>> result = new HashMap<Facility, Set<Service>>();
 
 		if (event instanceof EngineIgnoreEvent) {
-			log.info("Event ignored {} facilities will be returned", result.size());
+			log.debug("Event {} ignored 0 facilities will be returned", event.getName());
 			return result;
 		}
 
+		log.info("Event - I am going to process event: {}", event);
+
 		// GET All Beans (only PerunBeans) from message
 		List<PerunBean> listOfBeans = new ArrayList<PerunBean>();
 		listOfBeans = AuditParser.parseLog(event.getMessage());
@@ -282,7 +282,7 @@ public Map<Facility, Set<Service>> resolveEvent(AuditEvent event) throws Invalid
 			}
 		}
 
-		log.info("{} facilities will be returned", result.size());
+		log.debug("{} facilities will be returned", result.size());
 		return result;
 
 	}

perun-notification/src/main/java/cz/metacentrum/perun/notif/dao/jdbc/PerunNotifAuditMessageDaoImpl.java

@@ -1,6 +1,5 @@
 package cz.metacentrum.perun.notif.dao.jdbc;
 
-import cz.metacentrum.perun.core.api.exceptions.InternalErrorException;
 import cz.metacentrum.perun.core.impl.Utils;
 import cz.metacentrum.perun.notif.dao.PerunNotifAuditMessageDao;
 import cz.metacentrum.perun.notif.entities.PerunNotifAuditMessage;
@@ -29,22 +28,22 @@ public PerunNotifAuditMessage save(String message) {
 		int newPerunNotifAuditMessageId = Utils.getNewId(this.getJdbcTemplate(), "pn_audit_message_id_seq");
 		this.getJdbcTemplate().update("INSERT INTO pn_audit_message(id, message) values (?,?)", newPerunNotifAuditMessageId, message);
 
-		logger.debug("PerunNotifAuditMessage saved to db: id = {} message = {}", newPerunNotifAuditMessageId, message);
+		logger.trace("PerunNotifAuditMessage saved to db: id = {} message = {}", newPerunNotifAuditMessageId, message);
 		return new PerunNotifAuditMessage(newPerunNotifAuditMessageId, message);
 	}
 
 	public void remove(long id) {
 
 		logger.debug("Removing perunNotifAuditMessage with id = {}", id);
 		this.getJdbcTemplate().update("delete from pn_audit_message where id=?", id);
-		logger.debug("PerunNotifAuditMessage with id: {} removed.", id);
+		logger.trace("PerunNotifAuditMessage with id: {} removed.", id);
 	}
 
 	public List<PerunNotifAuditMessage> getAll() {
 
 		logger.debug("Listing all perunNotifAuditMessages.");
 		List<PerunNotifAuditMessage> result = this.getJdbcTemplate().query("SELECT * FROM pn_audit_message", PerunNotifAuditMessage.PERUN_NOTIF_MESSAGE);
-		logger.debug("Result of list of PerunNotifAuditMessage: {}", result);
+		logger.trace("Result of list of PerunNotifAuditMessage: {}", result);
 		return result;
 	}
 }

perun-notification/src/main/java/cz/metacentrum/perun/notif/managers/SchedulingManagerImpl.java

@@ -133,7 +133,7 @@ public void processPerunAuditMessages() {
 	private void processPerunNotifAuditMessage(PerunNotifAuditMessage perunAuditMessage, PerunSession session) throws Exception {
 
 		try {
-			logger.debug("Getting regexIds, matching received message with id: " + perunAuditMessage.getId());
+			logger.trace("Getting regexIds, matching received message with id: " + perunAuditMessage.getId());
 			Set<Integer> regexIds = perunNotifRegexManager.getIdsOfRegexesMatchingMessage(perunAuditMessage);
 			logger.debug("Received regexIds for message with id: " + perunAuditMessage.getId() + "; regexIds = " + regexIds + "; now getting templateIds.");
 			if (regexIds == null || regexIds.isEmpty()) {