Fix a bug that the instance is not deleted correctly

in specific cases, the master will not release the deleted instance'd resources.
It could be a leak.

After open a PD, the timer will be registered and the instance's refcnt will be increased.
But even though the service provider makes response via acquire_buffer, the master
doesn't decrease the instance's refcnt.
It makes a problem. even if the instance is deleted, the livebox doesn't cleared.
because the refcnt could not be reach to ZERO.

This patch will fix it.

And optimize the log.
Verbose logging message are deleted and optimized.

Change-Id: I1c85f428428ac16459c91dfe10dbfa43c972ed5b

6 files changed, 82 insertions, 86 deletions

diff --git a/src/dead_monitor.c b/src/dead_monitor.c
index 733abdf..a768f39 100644
--- a/src/dead_monitor.c
+++ b/src/dead_monitor.c
@@ -66,7 +66,6 @@ static int evt_cb(int handle, void *data)
 		return 0;
 	}
 
-	DbgPrint("This is not my favor: %d\n", handle);
 	return 0;
 }
 
diff --git a/src/instance.c b/src/instance.c
index b5632d6..25a0a11 100644
--- a/src/instance.c
+++ b/src/instance.c
@@ -1380,7 +1380,7 @@ HAPI int instance_state_reset(struct inst_info *inst)
 	}
 
 	if (inst->state == INST_DESTROYED)
-		return LB_STATUS_SUCCESS;
+		goto out;
 
 	lb_type = package_lb_type(inst->info);
 	pd_type = package_pd_type(inst->info);
@@ -1400,6 +1400,7 @@ HAPI int instance_state_reset(struct inst_info *inst)
 		buffer_handler_unload(inst->pd.canvas.buffer);
 	}
 
+out:
 	inst->state = INST_INIT;
 	inst->requested_state = INST_INIT;
 	return LB_STATUS_SUCCESS;
diff --git a/src/notification_service.c b/src/notification_service.c
index 06bf92e..12da940 100644
--- a/src/notification_service.c
+++ b/src/notification_service.c
@@ -385,7 +385,6 @@ static int service_thread_main(struct tcb *tcb, struct packet *packet, void *dat
 		},
 	};
 
-	DbgPrint("TCB: %p, Packet: %p\n", tcb, packet);
 	if (!packet) {
 		DbgPrint("TCB: %p is terminated\n", tcb);
 		return 0;
@@ -396,12 +395,11 @@ static int service_thread_main(struct tcb *tcb, struct packet *packet, void *dat
 		ErrPrint("Invalid command\n");
 		return -EINVAL;
 	}
-	DbgPrint("Command: %s, Packet type[%d]\n", command, packet_type(packet));
 
 	switch (packet_type(packet)) {
 	case PACKET_REQ:
 		/* Need to send reply packet */
-		DbgPrint("REQ: Command: [%s]\n", command);
+		DbgPrint("%p REQ: Command: [%s]\n", tcb, command);
 
 		for (i = 0; service_req_table[i].cmd; i++) {
 			if (strcmp(service_req_table[i].cmd, command))
diff --git a/src/server.c b/src/server.c
index 1ece6f3..517a4da 100644
--- a/src/server.c
+++ b/src/server.c
@@ -92,7 +92,7 @@ static Eina_Bool lazy_access_status_cb(void *data)
 	 * If instance_unref returns NULL,
 	 * The instance is destroyed. it means, we don't need to send event to the viewer
 	 */
-	free(cbdata);
+	DbgFree(cbdata);
 	return ECORE_CALLBACK_CANCEL;
 }
 
@@ -491,8 +491,8 @@ static Eina_Bool lazy_delete_cb(void *data)
 		instance_del_client(item->inst, item->client);
 	}
 
-	client_unref(item->client);
-	instance_unref(item->inst);
+	(void)client_unref(item->client);
+	(void)instance_unref(item->inst);
 	DbgFree(item);
 	return ECORE_CALLBACK_CANCEL;
 }
@@ -554,8 +554,8 @@ static struct packet *client_delete(pid_t pid, int handle, const struct packet *
 
 				if (!ecore_timer_add(DELAY_TIME, lazy_delete_cb, item)) {
 					ErrPrint("Failed to add a delayzed delete callback\n");
-					client_unref(client);
-					instance_unref(inst);
+					(void)client_unref(client);
+					(void)instance_unref(inst);
 					DbgFree(item);
 					ret = LB_STATUS_ERROR_FAULT;
 				} else {
@@ -1921,8 +1921,8 @@ static struct packet *client_pd_access_action_up(pid_t pid, int handle, const st
 				cbdata->status = ret;
 
 				if (!ecore_timer_add(DELAY_TIME, lazy_access_status_cb, cbdata)) {
-					instance_unref(cbdata->inst);
-					free(cbdata);
+					(void)instance_unref(cbdata->inst);
+					DbgFree(cbdata);
 					ret = LB_STATUS_ERROR_FAULT;
 				} else {
 					ret = LB_STATUS_SUCCESS;
@@ -2022,8 +2022,8 @@ static struct packet *client_pd_access_action_down(pid_t pid, int handle, const
 				cbdata->status = ret;
 
 				if (!ecore_timer_add(DELAY_TIME, lazy_access_status_cb, cbdata)) {
-					instance_unref(cbdata->inst);
-					free(cbdata);
+					(void)instance_unref(cbdata->inst);
+					DbgFree(cbdata);
 					ret = LB_STATUS_ERROR_FAULT;
 				} else {
 					ret = LB_STATUS_SUCCESS;
@@ -2123,8 +2123,8 @@ static struct packet *client_pd_access_scroll_down(pid_t pid, int handle, const
 				cbdata->status = ret;
 
 				if (!ecore_timer_add(DELAY_TIME, lazy_access_status_cb, cbdata)) {
-					instance_unref(cbdata->inst);
-					free(cbdata);
+					(void)instance_unref(cbdata->inst);
+					DbgFree(cbdata);
 					ret = LB_STATUS_ERROR_FAULT;
 				} else {
 					ret = LB_STATUS_SUCCESS;
@@ -2224,8 +2224,8 @@ static struct packet *client_pd_access_scroll_move(pid_t pid, int handle, const
 				cbdata->status = ret;
 
 				if (!ecore_timer_add(DELAY_TIME, lazy_access_status_cb, cbdata)) {
-					instance_unref(cbdata->inst);
-					free(cbdata);
+					(void)instance_unref(cbdata->inst);
+					DbgFree(cbdata);
 					ret = LB_STATUS_ERROR_FAULT;
 				} else {
 					ret = LB_STATUS_SUCCESS;
@@ -2325,8 +2325,8 @@ static struct packet *client_pd_access_scroll_up(pid_t pid, int handle, const st
 				cbdata->status = ret;
 
 				if (!ecore_timer_add(DELAY_TIME, lazy_access_status_cb, cbdata)) {
-					instance_unref(cbdata->inst);
-					free(cbdata);
+					(void)instance_unref(cbdata->inst);
+					DbgFree(cbdata);
 					ret = LB_STATUS_ERROR_FAULT;
 				} else {
 					ret = LB_STATUS_SUCCESS;
@@ -2426,8 +2426,8 @@ static struct packet *client_pd_access_unhighlight(pid_t pid, int handle, const
 				cbdata->status = ret;
 
 				if (!ecore_timer_add(DELAY_TIME, lazy_access_status_cb, cbdata)) {
-					instance_unref(cbdata->inst);
-					free(cbdata);
+					(void)instance_unref(cbdata->inst);
+					DbgFree(cbdata);
 					ret = LB_STATUS_ERROR_FAULT;
 				} else {
 					ret = LB_STATUS_SUCCESS;
@@ -2526,8 +2526,8 @@ static struct packet *client_pd_access_hl(pid_t pid, int handle, const struct pa
 				cbdata->status = ret;
 
 				if (!ecore_timer_add(DELAY_TIME, lazy_access_status_cb, cbdata)) {
-					instance_unref(cbdata->inst);
-					free(cbdata);
+					(void)instance_unref(cbdata->inst);
+					DbgFree(cbdata);
 					ret = LB_STATUS_ERROR_FAULT;
 				} else {
 					ret = LB_STATUS_SUCCESS;
@@ -2627,8 +2627,8 @@ static struct packet *client_pd_access_hl_prev(pid_t pid, int handle, const stru
 				cbdata->status = ret;
 
 				if (!ecore_timer_add(DELAY_TIME, lazy_access_status_cb, cbdata)) {
-					instance_unref(cbdata->inst);
-					free(cbdata);
+					(void)instance_unref(cbdata->inst);
+					DbgFree(cbdata);
 					ret = LB_STATUS_ERROR_FAULT;
 				} else {
 					ret = LB_STATUS_SUCCESS;
@@ -2734,8 +2734,8 @@ static struct packet *client_pd_access_hl_next(pid_t pid, int handle, const stru
 
 				if (!ecore_timer_add(DELAY_TIME, lazy_access_status_cb, cbdata)) {
 					DbgPrint("Failed to add timer\n");
-					instance_unref(cbdata->inst);
-					free(cbdata);
+					(void)instance_unref(cbdata->inst);
+					DbgFree(cbdata);
 					ret = LB_STATUS_ERROR_FAULT;
 				} else {
 					DbgPrint("Timer is added\n");
@@ -2838,8 +2838,8 @@ static struct packet *client_pd_access_activate(pid_t pid, int handle, const str
 				cbdata->status = ret;
 
 				if (!ecore_timer_add(DELAY_TIME, lazy_access_status_cb, cbdata)) {
-					instance_unref(cbdata->inst);
-					free(cbdata);
+					(void)instance_unref(cbdata->inst);
+					DbgFree(cbdata);
 					ret = LB_STATUS_ERROR_FAULT;
 				} else {
 					ret = LB_STATUS_SUCCESS;
@@ -3157,8 +3157,8 @@ static struct packet *client_lb_access_hl(pid_t pid, int handle, const struct pa
 				cbdata->status = ret;
 
 				if (!ecore_timer_add(DELAY_TIME, lazy_access_status_cb, cbdata)) {
-					instance_unref(cbdata->inst);
-					free(cbdata);
+					(void)instance_unref(cbdata->inst);
+					DbgFree(cbdata);
 					ret = LB_STATUS_ERROR_FAULT;
 				} else {
 					ret = LB_STATUS_SUCCESS;
@@ -3258,8 +3258,8 @@ static struct packet *client_lb_access_hl_prev(pid_t pid, int handle, const stru
 				cbdata->status = ret;
 
 				if (!ecore_timer_add(DELAY_TIME, lazy_access_status_cb, cbdata)) {
-					instance_unref(cbdata->inst);
-					free(cbdata);
+					(void)instance_unref(cbdata->inst);
+					DbgFree(cbdata);
 					ret = LB_STATUS_ERROR_FAULT;
 				} else {
 					ret = LB_STATUS_SUCCESS;
@@ -3359,8 +3359,8 @@ static struct packet *client_lb_access_hl_next(pid_t pid, int handle, const stru
 				cbdata->status = ret;
 
 				if (!ecore_timer_add(DELAY_TIME, lazy_access_status_cb, cbdata)) {
-					instance_unref(cbdata->inst);
-					free(cbdata);
+					(void)instance_unref(cbdata->inst);
+					DbgFree(cbdata);
 					ret = LB_STATUS_ERROR_FAULT;
 				} else {
 					ret = LB_STATUS_SUCCESS;
@@ -3467,8 +3467,8 @@ static struct packet *client_lb_access_action_up(pid_t pid, int handle, const st
 				cbdata->status = ret;
 
 				if (!ecore_timer_add(DELAY_TIME, lazy_access_status_cb, cbdata)) {
-					instance_unref(cbdata->inst);
-					free(cbdata);
+					(void)instance_unref(cbdata->inst);
+					DbgFree(cbdata);
 					ret = LB_STATUS_ERROR_FAULT;
 				} else {
 					ret = LB_STATUS_SUCCESS;
@@ -3575,8 +3575,8 @@ static struct packet *client_lb_access_action_down(pid_t pid, int handle, const
 				cbdata->status = ret;
 
 				if (!ecore_timer_add(DELAY_TIME, lazy_access_status_cb, cbdata)) {
-					instance_unref(cbdata->inst);
-					free(cbdata);
+					(void)instance_unref(cbdata->inst);
+					DbgFree(cbdata);
 					ret = LB_STATUS_ERROR_FAULT;
 				} else {
 					ret = LB_STATUS_SUCCESS;
@@ -3676,8 +3676,8 @@ static struct packet *client_lb_access_unhighlight(pid_t pid, int handle, const
 				cbdata->status = ret;
 
 				if (!ecore_timer_add(DELAY_TIME, lazy_access_status_cb, cbdata)) {
-					instance_unref(cbdata->inst);
-					free(cbdata);
+					(void)instance_unref(cbdata->inst);
+					DbgFree(cbdata);
 					ret = LB_STATUS_ERROR_FAULT;
 				} else {
 					ret = LB_STATUS_SUCCESS;
@@ -3784,8 +3784,8 @@ static struct packet *client_lb_access_scroll_down(pid_t pid, int handle, const
 				cbdata->status = ret;
 
 				if (!ecore_timer_add(DELAY_TIME, lazy_access_status_cb, cbdata)) {
-					instance_unref(cbdata->inst);
-					free(cbdata);
+					(void)instance_unref(cbdata->inst);
+					DbgFree(cbdata);
 					ret = LB_STATUS_ERROR_FAULT;
 				} else {
 					ret = LB_STATUS_SUCCESS;
@@ -3892,8 +3892,8 @@ static struct packet *client_lb_access_scroll_move(pid_t pid, int handle, const
 				cbdata->status = ret;
 
 				if (!ecore_timer_add(DELAY_TIME, lazy_access_status_cb, cbdata)) {
-					instance_unref(cbdata->inst);
-					free(cbdata);
+					(void)instance_unref(cbdata->inst);
+					DbgFree(cbdata);
 					ret = LB_STATUS_ERROR_FAULT;
 				} else {
 					ret = LB_STATUS_SUCCESS;
@@ -4000,8 +4000,8 @@ static struct packet *client_lb_access_scroll_up(pid_t pid, int handle, const st
 				cbdata->status = ret;
 
 				if (!ecore_timer_add(DELAY_TIME, lazy_access_status_cb, cbdata)) {
-					instance_unref(cbdata->inst);
-					free(cbdata);
+					(void)instance_unref(cbdata->inst);
+					DbgFree(cbdata);
 					ret = LB_STATUS_ERROR_FAULT;
 				} else {
 					ret = LB_STATUS_SUCCESS;
@@ -4103,8 +4103,8 @@ static struct packet *client_lb_access_activate(pid_t pid, int handle, const str
 				cbdata->status = ret;
 
 				if (!ecore_timer_add(DELAY_TIME, lazy_access_status_cb, cbdata)) {
-					instance_unref(cbdata->inst);
-					free(cbdata);
+					(void)instance_unref(cbdata->inst);
+					DbgFree(cbdata);
 					ret = LB_STATUS_ERROR_FAULT;
 				} else {
 					ret = LB_STATUS_SUCCESS;
@@ -4667,15 +4667,14 @@ static struct packet *client_create_pd(pid_t pid, int handle, const struct packe
 				tmp_ret = instance_slave_close_pd(inst, client);
 				ErrPrint("Unable to send script event for openning PD [%s], %d\n", pkgname, tmp_ret);
 			} else {
-				Ecore_Timer *pd_open_monitor;
+				Ecore_Timer *pd_monitor;
 
-				inst = instance_ref(inst);
-				pd_open_monitor = ecore_timer_add(PD_REQUEST_TIMEOUT, pd_open_monitor_cb, inst);
-				if (!pd_open_monitor) {
-					instance_unref(inst);
+				pd_monitor = ecore_timer_add(PD_REQUEST_TIMEOUT, pd_open_monitor_cb, instance_ref(inst));
+				if (!pd_monitor) {
+					(void)instance_unref(inst);
 					ErrPrint("Failed to create a timer for PD Open monitor\n");
 				} else {
-					(void)instance_set_data(inst, "pd,open,monitor", pd_open_monitor);
+					(void)instance_set_data(inst, "pd,open,monitor", pd_monitor);
 				}
 			}
 		} else {
@@ -4822,8 +4821,8 @@ static struct packet *client_destroy_pd(pid_t pid, int handle, const struct pack
 			ret = LB_STATUS_ERROR_CANCEL;
 
 			(void)instance_client_pd_created(inst, ret);
-			instance_unref(inst);
 			ecore_timer_del(pd_monitor);
+			(void)instance_unref(inst);
 			goto out;
 		}
 
@@ -4835,9 +4834,7 @@ static struct packet *client_destroy_pd(pid_t pid, int handle, const struct pack
 		if (ret < 0) {
 			ErrPrint("PD close request failed: %d\n", ret);
 		} else {
-			inst = instance_ref(inst);
-
-			pd_monitor = ecore_timer_add(PD_REQUEST_TIMEOUT, pd_close_monitor_cb, inst);
+			pd_monitor = ecore_timer_add(PD_REQUEST_TIMEOUT, pd_close_monitor_cb, instance_ref(inst));
 			if (!pd_monitor) {
 				(void)instance_unref(inst);
 				ErrPrint("Failed to add pd close monitor\n");
@@ -4885,7 +4882,7 @@ static struct packet *client_destroy_pd(pid_t pid, int handle, const struct pack
 			timer = ecore_timer_add(DELAY_TIME, lazy_pd_destroyed_cb, inst);
 			if (!timer) {
 				ErrPrint("Failed to create a timer: %s\n", pkgname);
-				instance_unref(inst);
+				(void)instance_unref(inst);
 				/*!
 				 * How can we handle this?
 				 */
@@ -5888,13 +5885,18 @@ static struct packet *slave_acquire_buffer(pid_t pid, int handle, const struct p
 		}
 	} else if (target == TYPE_PD && package_pd_type(pkg) == PD_TYPE_BUFFER) {
 		struct buffer_info *info;
-		Ecore_Timer *pd_open_monitor;
+		Ecore_Timer *pd_monitor;
 
-		pd_open_monitor = instance_del_data(inst, "pd,open,monitor");
-		if (!pd_open_monitor)
+		pd_monitor = instance_del_data(inst, "pd,open,monitor");
+		if (!pd_monitor)
 			goto out;
 
-		ecore_timer_del(pd_open_monitor);
+		ecore_timer_del(pd_monitor);
+		inst = instance_unref(inst);
+		if (!inst) {
+			ErrPrint("Instance refcnt is ZERO: %s\n", pkgname);
+			goto out;
+		}
 
 		info = instance_pd_buffer(inst);
 		if (!info) {
@@ -6065,11 +6067,6 @@ static struct packet *slave_release_buffer(pid_t pid, int handle, const struct p
 
 	ret = LB_STATUS_ERROR_INVALID;
 
-	if (instance_state(inst) == INST_DESTROYED) {
-		ErrPrint("Package[%s] instance is already destroyed\n", pkgname);
-		goto out;
-	}
-
 	if (type == TYPE_LB && package_lb_type(pkg) == LB_TYPE_BUFFER) {
 		struct buffer_info *info;
 
@@ -6077,10 +6074,10 @@ static struct packet *slave_release_buffer(pid_t pid, int handle, const struct p
 		ret = buffer_handler_unload(info);
 	} else if (type == TYPE_PD && package_pd_type(pkg) == PD_TYPE_BUFFER) {
 		struct buffer_info *info;
-		Ecore_Timer *pd_close_monitor;
+		Ecore_Timer *pd_monitor;
 
-		pd_close_monitor = instance_del_data(inst, "pd,close,monitor");
-		if (!pd_close_monitor) {
+		pd_monitor = instance_del_data(inst, "pd,close,monitor");
+		if (!pd_monitor) {
 			ErrPrint("There is no requests to release pd buffer\n");
 			/*!
 			 * \note
@@ -6096,7 +6093,13 @@ static struct packet *slave_release_buffer(pid_t pid, int handle, const struct p
 			 * which will be checked by instance_client_pd_destroyed function.
 			 */
 		} else {
-			ecore_timer_del(pd_close_monitor);
+			ecore_timer_del(pd_monitor);
+			inst = instance_unref(inst);
+			if (!inst) {
+				ErrPrint("Instance is released: %s\n", pkgname);
+				ret = LB_STATUS_ERROR_FAULT;
+				goto out;
+			}
 		}
 
 		info = instance_pd_buffer(inst);
diff --git a/src/service_common.c b/src/service_common.c
index 91c046d..8b5405f 100644
--- a/src/service_common.c
+++ b/src/service_common.c
@@ -121,7 +121,6 @@ static void *client_packet_pump_main(void *data)
 
 	ret = 0;
 	recv_state = RECV_INIT;
-	DbgPrint("Socket data pumping thread is activated\n");
 	/*!
 	 * \note
 	 * To escape from the switch statement, we use this ret value
@@ -266,7 +265,6 @@ static void *client_packet_pump_main(void *data)
 			packet_info->packet = packet;
 			packet_info->tcb = tcb;
 
-			DbgPrint("New packet is built\n");
 			CRITICAL_SECTION_BEGIN(&svc_ctx->packet_list_lock);
 			svc_ctx->packet_list = eina_list_append(svc_ctx->packet_list, packet_info);
 			CRITICAL_SECTION_END(&svc_ctx->packet_list_lock);
@@ -302,7 +300,6 @@ static void *client_packet_pump_main(void *data)
 	 * \note
 	 * Emit a signal to collect this TCB from the SERVER THREAD.
 	 */
-	DbgPrint("Emit a signal to destroy TCB[%p]\n", tcb);
 	if (write(svc_ctx->tcb_pipe[PIPE_WRITE], &tcb, sizeof(tcb)) != sizeof(tcb))
 		ErrPrint("Unable to write pipe: %s\n", strerror(errno));
 
@@ -509,18 +506,17 @@ static void *server_main(void *data)
 
 		if (FD_ISSET(svc_ctx->fd, &set)) {
 			client_fd = secure_socket_get_connection_handle(svc_ctx->fd);
-			DbgPrint("New client connection arrived (%d)\n", client_fd);
 			if (client_fd < 0) {
-				ErrPrint("Failed to establish the client connection\n");
+				ErrPrint("Failed to establish a new connection [%d]\n", svc_ctx->fd);
 				ret = -EFAULT;
 				break;
 			}
 
 			tcb = tcb_create(svc_ctx, client_fd);
-			if (!tcb)
+			if (!tcb) {
+				ErrPrint("Failed to create a new TCB: %d (%d)\n", client_fd, svc_ctx->fd);
 				secure_socket_destroy_handle(client_fd);
-			else
-				DbgPrint("Creating TCB[%p]\n", tcb);
+			}
 		} 
 
 		if (FD_ISSET(svc_ctx->tcb_pipe[PIPE_READ], &set)) {
@@ -536,7 +532,6 @@ static void *server_main(void *data)
 			 */
 			ret = svc_ctx->service_thread_main(tcb, NULL, svc_ctx->service_thread_data);
 
-			DbgPrint("Destroying TCB[%p]\n", tcb);
 			/*!
 			 * at this time, the client thread can access this tcb.
 			 * how can I protect this TCB from deletion without disturbing the server thread?
diff --git a/src/shortcut_service.c b/src/shortcut_service.c
index 973a2ba..a2f74af 100644
--- a/src/shortcut_service.c
+++ b/src/shortcut_service.c
@@ -108,7 +108,7 @@ static int service_thread_main(struct tcb *tcb, struct packet *packet, void *dat
 	switch (packet_type(packet)) {
 	case PACKET_REQ:
 		/* Need to send reply packet */
-		DbgPrint("REQ: Command: [%s]\n", command);
+		DbgPrint("%p REQ: Command: [%s]\n", tcb, command);
 		if (service_common_multicast_packet(tcb, packet, TCB_CLIENT_TYPE_SERVICE) < 0)
 			ErrPrint("Unable to send service request packet\n");
 		else
@@ -116,7 +116,7 @@ static int service_thread_main(struct tcb *tcb, struct packet *packet, void *dat
 		break;
 	case PACKET_REQ_NOACK:
 		/* Doesn't need to send reply packet */
-		DbgPrint("REQ_NOACK: Command: [%s]\n", command);
+		DbgPrint("%p REQ_NOACK: Command: [%s]\n", tcb, command);
 		if (!strcmp(command, "service_register")) {
 			tcb_client_type_set(tcb, TCB_CLIENT_TYPE_SERVICE);
 			break;
@@ -127,7 +127,7 @@ static int service_thread_main(struct tcb *tcb, struct packet *packet, void *dat
 		break;
 	case PACKET_ACK:
 		/* Okay, client(or app) send a reply packet to us. */
-		DbgPrint("ACK: Command: [%s]\n", command);
+		DbgPrint("%p ACK: Command: [%s]\n", tcb, command);
 		tcb = get_reply_context(packet_seq(packet));
 		if (!tcb) {
 			ErrPrint("There is no proper context\n");