bcmdhd: Fix deadlock issue by holding nested spinlock

[Issue & Analysis]
kernel panic with msg below
WDT expired - Debugging Information for Hardlockup core(0) - locked CPUs mask (0x7)

This issue occurred due to the use of spin_lock_bh under spin_lock_irqsave. (nested lock)
- dbg_ring_poll_worker() use spin_lock_irqsave()
- osl_malloc()  use spin_lock_bh()

When the tasklet (dhd_dpc) is pending, spin_unlock_bh is called in the woker thread(dbg_ring_poll_worker).
and then spin_unlock_bh invokes pending tasklet. it causes unwanted deadlock case.
It should fix to avoid nested spinlock with irqsave and _bh. because the task could be pending due to interrupt.

[Solution]
1. Split the critical section that poll from ring buffer to HAL to avoid grap spin_lock_bh under spin_lock_irqsave
2. Eliminate ASSERT in dhd_dbg_ring_pull_single() if buf_len < rlen
       - this is acceptable case and does not need to be ASSERT())
3. Add check to prevent the case of accessing ring buffer from HardIRQ context
4. Change logging macro from DHD_ERROR to DHD_DBGIF in critical section

BUG: 165487892
Change-Id: Ibd7dd796e024573d3921d2f1d7dde1e92dbdfec9

5 files changed, 74 insertions, 49 deletions

diff --git a/dhd.h b/dhd.h
index 363d7c7..3b69026 100755
--- a/dhd.h
+++ b/dhd.h
@@ -3014,10 +3014,10 @@ extern void dhd_os_general_spin_unlock(dhd_pub_t *pub, unsigned long flags);
 /* linux is defined for DHD EFI builds also,
 * since its cross-compiled for EFI from linux
 */
-#define DHD_DBG_RING_LOCK_INIT(osh)				dhd_os_dbgring_lock_init(osh)
-#define DHD_DBG_RING_LOCK_DEINIT(osh, lock)		dhd_os_dbgring_lock_deinit(osh, (lock))
-#define DHD_DBG_RING_LOCK(lock, flags)			(flags) = dhd_os_dbgring_lock(lock)
-#define DHD_DBG_RING_UNLOCK(lock, flags)		dhd_os_dbgring_unlock((lock), flags)
+#define DHD_DBG_RING_LOCK_INIT(osh)			osl_spin_lock_init(osh)
+#define DHD_DBG_RING_LOCK_DEINIT(osh, lock)		osl_spin_lock_deinit(osh, (lock))
+#define DHD_DBG_RING_LOCK(lock, flags)			(flags) = osl_spin_lock(lock)
+#define DHD_DBG_RING_UNLOCK(lock, flags)		osl_spin_unlock((lock), flags)
 
 #ifdef DHD_MEM_STATS
 /* memory stats lock/unlock */
diff --git a/dhd_common.c b/dhd_common.c
index 600d146..1c66848 100755
--- a/dhd_common.c
+++ b/dhd_common.c
@@ -8190,9 +8190,9 @@ dhd_dump_debug_ring(dhd_pub_t *dhdp, void *ring_ptr, const void *user_buf,
 	/* do not allow further writes to the ring
 	 * till we flush it
 	 */
-	flags = dhd_os_spin_lock(ring->lock);
+	DHD_DBG_RING_LOCK(ring->lock, flags);
 	ring->state = RING_SUSPEND;
-	dhd_os_spin_unlock(ring->lock, flags);
+	DHD_DBG_RING_UNLOCK(ring->lock, flags);
 
 	if (dhdp->concise_dbg_buf) {
 		/* re-use concise debug buffer temporarily
@@ -8227,13 +8227,13 @@ dhd_dump_debug_ring(dhd_pub_t *dhdp, void *ring_ptr, const void *user_buf,
 	} else {
 		DHD_ERROR(("%s: No concise buffer available !\n", __FUNCTION__));
 	}
-	flags = dhd_os_spin_lock(ring->lock);
+	DHD_DBG_RING_LOCK(ring->lock, flags);
 	ring->state = RING_ACTIVE;
 	/* Resetting both read and write pointer,
 	 * since all items are read.
 	 */
 	ring->rp = ring->wp = 0;
-	dhd_os_spin_unlock(ring->lock, flags);
+	DHD_DBG_RING_UNLOCK(ring->lock, flags);
 
 	return ret;
 }
@@ -8258,9 +8258,9 @@ dhd_log_dump_ring_to_file(dhd_pub_t *dhdp, void *ring_ptr, void *file,
 	/* do not allow further writes to the ring
 	 * till we flush it
 	 */
-	flags = dhd_os_spin_lock(ring->lock);
+	DHD_DBG_RING_LOCK(ring->lock, flags);
 	ring->state = RING_SUSPEND;
-	dhd_os_spin_unlock(ring->lock, flags);
+	DHD_DBG_RING_UNLOCK(ring->lock, flags);
 
 	if (dhdp->concise_dbg_buf) {
 		/* re-use concise debug buffer temporarily
@@ -8288,9 +8288,9 @@ dhd_log_dump_ring_to_file(dhd_pub_t *dhdp, void *ring_ptr, void *file,
 				ret = dhd_os_write_file_posn(file, file_posn, data, rlen);
 				if (ret < 0) {
 					DHD_ERROR(("%s: write file error !\n", __FUNCTION__));
-					flags = dhd_os_spin_lock(ring->lock);
+					DHD_DBG_RING_LOCK(ring->lock, flags);
 					ring->state = RING_ACTIVE;
-					dhd_os_spin_unlock(ring->lock, flags);
+					DHD_DBG_RING_UNLOCK(ring->lock, flags);
 					return BCME_ERROR;
 				}
 			}
@@ -8303,13 +8303,13 @@ dhd_log_dump_ring_to_file(dhd_pub_t *dhdp, void *ring_ptr, void *file,
 		DHD_ERROR(("%s: No concise buffer available !\n", __FUNCTION__));
 	}
 
-	flags = dhd_os_spin_lock(ring->lock);
+	DHD_DBG_RING_LOCK(ring->lock, flags);
 	ring->state = RING_ACTIVE;
 	/* Resetting both read and write pointer,
 	 * since all items are read.
 	 */
 	ring->rp = ring->wp = 0;
-	dhd_os_spin_unlock(ring->lock, flags);
+	DHD_DBG_RING_UNLOCK(ring->lock, flags);
 	return BCME_OK;
 }
 
diff --git a/dhd_dbg_ring.c b/dhd_dbg_ring.c
index 6ec4fb8..dfa645b 100755
--- a/dhd_dbg_ring.c
+++ b/dhd_dbg_ring.c
@@ -44,9 +44,9 @@ dhd_dbg_ring_init(dhd_pub_t *dhdp, dhd_dbg_ring_t *ring, uint16 id, uint8 *name,
 		buf = allocd_buf;
 	}
 
-	ring->lock = dhd_os_spin_lock_init(dhdp->osh);
+	ring->lock = DHD_DBG_RING_LOCK_INIT(dhdp->osh);
 
-	flags = dhd_os_spin_lock(ring->lock);
+	DHD_DBG_RING_LOCK(ring->lock, flags);
 	ring->id = id;
 	strlcpy((char *)ring->name, (char *)name, sizeof(ring->name));
 	ring->ring_size = ring_sz;
@@ -57,7 +57,7 @@ dhd_dbg_ring_init(dhd_pub_t *dhdp, dhd_dbg_ring_t *ring, uint16 id, uint8 *name,
 	ring->rem_len = 0;
 	ring->sched_pull = TRUE;
 	ring->pull_inactive = pull_inactive;
-	dhd_os_spin_unlock(ring->lock, flags);
+	DHD_DBG_RING_UNLOCK(ring->lock, flags);
 
 	return BCME_OK;
 }
@@ -67,16 +67,16 @@ dhd_dbg_ring_deinit(dhd_pub_t *dhdp, dhd_dbg_ring_t *ring)
 {
 	unsigned long flags = 0;
 
-	flags = dhd_os_spin_lock(ring->lock);
+	DHD_DBG_RING_LOCK(ring->lock, flags);
 	ring->id = 0;
 	ring->name[0] = 0;
 	ring->wp = ring->rp = 0;
 	memset(&ring->stat, 0, sizeof(ring->stat));
 	ring->threshold = 0;
 	ring->state = RING_STOP;
-	dhd_os_spin_unlock(ring->lock, flags);
+	DHD_DBG_RING_UNLOCK(ring->lock, flags);
 
-	dhd_os_spin_lock_deinit(dhdp->osh, ring->lock);
+	DHD_DBG_RING_LOCK_DEINIT(dhdp->osh, ring->lock);
 }
 
 void
@@ -85,7 +85,7 @@ dhd_dbg_ring_sched_pull(dhd_dbg_ring_t *ring, uint32 pending_len,
 {
 	unsigned long flags = 0;
 
-	flags = dhd_os_spin_lock(ring->lock);
+	DHD_DBG_RING_LOCK(ring->lock, flags);
 	/* if the current pending size is bigger than threshold and
 	 * threshold is set
 	 */
@@ -98,10 +98,10 @@ dhd_dbg_ring_sched_pull(dhd_dbg_ring_t *ring, uint32 pending_len,
 		 * the same layer fro this context, can lead to deadlock.
 		 */
 		ring->sched_pull = FALSE;
-		dhd_os_spin_unlock(ring->lock, flags);
+		DHD_DBG_RING_UNLOCK(ring->lock, flags);
 		pull_fn(os_pvt, id);
 	} else {
-		dhd_os_spin_unlock(ring->lock, flags);
+		DHD_DBG_RING_UNLOCK(ring->lock, flags);
 	}
 }
 
@@ -111,7 +111,7 @@ dhd_dbg_ring_get_pending_len(dhd_dbg_ring_t *ring)
 	uint32 pending_len = 0;
 	unsigned long flags = 0;
 
-	flags = dhd_os_spin_lock(ring->lock);
+	DHD_DBG_RING_LOCK(ring->lock, flags);
 	if (ring->stat.written_bytes > ring->stat.read_bytes) {
 		pending_len = ring->stat.written_bytes - ring->stat.read_bytes;
 	} else if (ring->stat.written_bytes < ring->stat.read_bytes) {
@@ -119,7 +119,7 @@ dhd_dbg_ring_get_pending_len(dhd_dbg_ring_t *ring)
 	} else {
 		pending_len = 0;
 	}
-	dhd_os_spin_unlock(ring->lock, flags);
+	DHD_DBG_RING_UNLOCK(ring->lock, flags);
 
 	return pending_len;
 }
@@ -136,10 +136,20 @@ dhd_dbg_ring_push(dhd_dbg_ring_t *ring, dhd_dbg_ring_entry_t *hdr, void *data)
 		return BCME_BADARG;
 	}
 
-	flags = dhd_os_spin_lock(ring->lock);
+#if defined(__linux__)
+	/* Prevents the case of accessing the ring buffer in the HardIRQ context.
+	 * If an interrupt arise after holding ring lock, It could try the same lock.
+	 * This is to use the ring lock as spin_lock_bh instead of spin_lock_irqsave.
+	 */
+	if (in_irq()) {
+		return BCME_BUSY;
+	}
+#endif /* defined(__linux__) */
+
+	DHD_DBG_RING_LOCK(ring->lock, flags);
 
 	if (ring->state != RING_ACTIVE) {
-		dhd_os_spin_unlock(ring->lock, flags);
+		DHD_DBG_RING_UNLOCK(ring->lock, flags);
 		return BCME_OK;
 	}
 
@@ -151,7 +161,7 @@ dhd_dbg_ring_push(dhd_dbg_ring_t *ring, dhd_dbg_ring_entry_t *hdr, void *data)
 		ring->ring_buf, ring->ring_size));
 
 	if (w_len > ring->ring_size) {
-		dhd_os_spin_unlock(ring->lock, flags);
+		DHD_DBG_RING_UNLOCK(ring->lock, flags);
 		DHD_ERROR(("%s: RING%d[%s] w_len=%u, ring_size=%u,"
 			" write size exceeds ring size !\n",
 			__FUNCTION__, ring->id, ring->name, w_len, ring->ring_size));
@@ -196,12 +206,12 @@ dhd_dbg_ring_push(dhd_dbg_ring_t *ring, dhd_dbg_ring_entry_t *hdr, void *data)
 					ring->rp);
 				/* check bounds before incrementing read ptr */
 				if (ring->rp + ENTRY_LENGTH(r_entry) >= ring->ring_size) {
-					DHD_ERROR(("%s: RING%d[%s] rp points out of boundary,"
+					DHD_DBGIF(("%s: RING%d[%s] rp points out of boundary,"
 						"ring->wp=%u, ring->rp=%u, ring->ring_size=%d\n",
 						__FUNCTION__, ring->id, ring->name, ring->wp,
 						ring->rp, ring->ring_size));
 					ASSERT(0);
-					dhd_os_spin_unlock(ring->lock, flags);
+					DHD_DBG_RING_UNLOCK(ring->lock, flags);
 					return BCME_BUFTOOSHORT;
 				}
 				ring->rp += ENTRY_LENGTH(r_entry);
@@ -228,11 +238,11 @@ dhd_dbg_ring_push(dhd_dbg_ring_t *ring, dhd_dbg_ring_entry_t *hdr, void *data)
 
 	/* check before writing to the ring */
 	if (ring->wp + w_len >= ring->ring_size) {
-		DHD_ERROR(("%s: RING%d[%s] wp pointed out of ring boundary, "
+		DHD_DBGIF(("%s: RING%d[%s] wp pointed out of ring boundary, "
 			"wp=%d, ring_size=%d, w_len=%u\n", __FUNCTION__, ring->id,
 			ring->name, ring->wp, ring->ring_size, w_len));
 		ASSERT(0);
-		dhd_os_spin_unlock(ring->lock, flags);
+		DHD_DBG_RING_UNLOCK(ring->lock, flags);
 		return BCME_BUFTOOLONG;
 	}
 
@@ -253,7 +263,7 @@ dhd_dbg_ring_push(dhd_dbg_ring_t *ring, dhd_dbg_ring_entry_t *hdr, void *data)
 		ring->stat.written_records, ring->stat.written_bytes, ring->stat.read_bytes,
 		ring->threshold, ring->wp, ring->rp));
 
-	dhd_os_spin_unlock(ring->lock, flags);
+	DHD_DBG_RING_UNLOCK(ring->lock, flags);
 	return BCME_OK;
 }
 
@@ -267,11 +277,14 @@ dhd_dbg_ring_pull_single(dhd_dbg_ring_t *ring, void *data, uint32 buf_len, bool
 	dhd_dbg_ring_entry_t *r_entry = NULL;
 	uint32 rlen = 0;
 	char *buf = NULL;
+	unsigned long flags;
 
 	if (!ring || !data || buf_len <= 0) {
 		return 0;
 	}
 
+	DHD_DBG_RING_LOCK(ring->lock, flags);
+
 	/* pull from ring is allowed for inactive (suspended) ring
 	 * in case of ecounters only, this is because, for ecounters
 	 * when a trap occurs the ring is suspended and data is then
@@ -295,7 +308,7 @@ dhd_dbg_ring_pull_single(dhd_dbg_ring_t *ring, void *data, uint32 buf_len, bool
 	/* Boundary Check */
 	rlen = ENTRY_LENGTH(r_entry);
 	if ((ring->rp + rlen) > ring->ring_size) {
-		DHD_ERROR(("%s: entry len %d is out of boundary of ring size %d,"
+		DHD_DBGIF(("%s: entry len %d is out of boundary of ring size %d,"
 			" current ring %d[%s] - rp=%d\n", __FUNCTION__, rlen,
 			ring->ring_size, ring->id, ring->name, ring->rp));
 		rlen = 0;
@@ -310,12 +323,17 @@ dhd_dbg_ring_pull_single(dhd_dbg_ring_t *ring, void *data, uint32 buf_len, bool
 		buf = (char *)r_entry;
 	}
 	if (rlen > buf_len) {
-		DHD_ERROR(("%s: buf len %d is too small for entry len %d\n",
+		/* The state of ringbuffer is different between calculating buf_len
+		 * and current. ring->rp have chance to be update by pushing data
+		 * to ring buffer when unlocking after calculating buf_len.
+		 * But, It doesn't need to ASSERT because we only send up the
+		 * entries stored so far.
+		 */
+		DHD_DBGIF(("%s: buf len %d is too small for entry len %d\n",
 			__FUNCTION__, buf_len, rlen));
-		DHD_ERROR(("%s: ring %d[%s] - ring size=%d, wp=%d, rp=%d\n",
+		DHD_DBGIF(("%s: ring %d[%s] - ring size=%d, wp=%d, rp=%d\n",
 			__FUNCTION__, ring->id, ring->name, ring->ring_size,
 			ring->wp, ring->rp));
-		ASSERT(0);
 		rlen = 0;
 		goto exit;
 	}
@@ -333,7 +351,7 @@ dhd_dbg_ring_pull_single(dhd_dbg_ring_t *ring, void *data, uint32 buf_len, bool
 		ring->rem_len = 0;
 	}
 	if (ring->rp >= ring->ring_size) {
-		DHD_ERROR(("%s: RING%d[%s] rp pointed out of ring boundary,"
+		DHD_DBGIF(("%s: RING%d[%s] rp pointed out of ring boundary,"
 			" rp=%d, ring_size=%d\n", __FUNCTION__, ring->id,
 			ring->name, ring->rp, ring->ring_size));
 		ASSERT(0);
@@ -345,6 +363,7 @@ dhd_dbg_ring_pull_single(dhd_dbg_ring_t *ring, void *data, uint32 buf_len, bool
 		ring->id, ring->name, ring->stat.read_bytes, ring->wp, ring->rp));
 
 exit:
+	DHD_DBG_RING_UNLOCK(ring->lock, flags);
 
 	return rlen;
 }
@@ -353,13 +372,17 @@ int
 dhd_dbg_ring_pull(dhd_dbg_ring_t *ring, void *data, uint32 buf_len, bool strip_hdr)
 {
 	int32 r_len, total_r_len = 0;
+	unsigned long flags;
 
 	if (!ring || !data)
 		return 0;
 
+	DHD_DBG_RING_LOCK(ring->lock, flags);
 	if (!ring->pull_inactive && (ring->state != RING_ACTIVE)) {
+		DHD_DBG_RING_UNLOCK(ring->lock, flags);
 		return 0;
 	}
+	DHD_DBG_RING_UNLOCK(ring->lock, flags);
 
 	while (buf_len > 0) {
 		r_len = dhd_dbg_ring_pull_single(ring, data, buf_len, strip_hdr);
@@ -384,7 +407,7 @@ dhd_dbg_ring_config(dhd_dbg_ring_t *ring, int log_level, uint32 threshold)
 	if (ring->state == RING_STOP)
 		return BCME_UNSUPPORTED;
 
-	flags = dhd_os_spin_lock(ring->lock);
+	DHD_DBG_RING_LOCK(ring->lock, flags);
 
 	if (log_level == 0)
 		ring->state = RING_SUSPEND;
@@ -394,7 +417,7 @@ dhd_dbg_ring_config(dhd_dbg_ring_t *ring, int log_level, uint32 threshold)
 	ring->log_level = log_level;
 	ring->threshold = MIN(threshold, DBGRING_FLUSH_THRESHOLD(ring));
 
-	dhd_os_spin_unlock(ring->lock, flags);
+	DHD_DBG_RING_UNLOCK(ring->lock, flags);
 
 	return BCME_OK;
 }
diff --git a/dhd_debug_linux.c b/dhd_debug_linux.c
index 5b512fd..389093a 100755
--- a/dhd_debug_linux.c
+++ b/dhd_debug_linux.c
@@ -117,7 +117,7 @@ dbg_ring_poll_worker(struct work_struct *work)
 	ringid = ring_info->ring_id;
 
 	ring = &dhdp->dbg->dbg_rings[ringid];
-	flags = dhd_os_spin_lock(ring->lock);
+	DHD_DBG_RING_LOCK(ring->lock, flags);
 
 	dhd_dbg_get_ring_status(dhdp, ringid, &ring_status);
 
@@ -126,22 +126,25 @@ dbg_ring_poll_worker(struct work_struct *work)
 	} else if (ring->wp < ring->rp) {
 		buflen = ring->ring_size - ring->rp + ring->wp;
 	} else {
+		DHD_DBG_RING_UNLOCK(ring->lock, flags);
 		goto exit;
 	}
 
 	if (buflen > ring->ring_size) {
+		DHD_DBG_RING_UNLOCK(ring->lock, flags);
 		goto exit;
 	}
+	DHD_DBG_RING_UNLOCK(ring->lock, flags);
 
 	buf = MALLOCZ(dhdp->osh, buflen);
 	if (!buf) {
-		dhd_os_spin_unlock(ring->lock, flags);
 		DHD_ERROR(("%s failed to allocate read buf\n", __FUNCTION__));
 		return;
 	}
 
 	rlen = dhd_dbg_pull_from_ring(dhdp, ringid, buf, buflen);
 
+	DHD_DBG_RING_LOCK(ring->lock, flags);
 	if (!ring->sched_pull) {
 		ring->sched_pull = TRUE;
 	}
@@ -157,6 +160,7 @@ dbg_ring_poll_worker(struct work_struct *work)
 		rlen -= ENTRY_LENGTH(hdr);
 		hdr = (dhd_dbg_ring_entry_t *)((char *)hdr + ENTRY_LENGTH(hdr));
 	}
+	DHD_DBG_RING_UNLOCK(ring->lock, flags);
 	MFREE(dhdp->osh, buf, buflen);
 
 exit:
@@ -167,8 +171,6 @@ exit:
 			schedule_delayed_work(d_work, ring_info->interval);
 		}
 	}
-	dhd_os_spin_unlock(ring->lock, flags);
-
 	return;
 }
 
@@ -375,7 +377,7 @@ dhd_os_push_push_ring_data(dhd_pub_t *dhdp, int ring_id, void *data, int32 data_
 		msg_hdr.len = strlen(data);
 	}
 	ret = dhd_dbg_push_to_ring(dhdp, ring_id, &msg_hdr, event_data);
-	if (ret) {
+	if (ret && ret != BCME_BUSY) {
 		DHD_ERROR(("%s : failed to push data into the ring (%d) with ret(%d)\n",
 			__FUNCTION__, ring_id, ret));
 	}
diff --git a/dhd_linux.c b/dhd_linux.c
index 63c6432..8c7f021 100755
--- a/dhd_linux.c
+++ b/dhd_linux.c
@@ -21343,10 +21343,10 @@ dhd_log_dump_init(dhd_pub_t *dhd)
 				__FUNCTION__));
 		goto fail;
 	}
-	flags = dhd_os_spin_lock(ring->lock);
+	DHD_DBG_RING_LOCK(ring->lock, flags);
 	ring->state = RING_ACTIVE;
 	ring->threshold = 0;
-	dhd_os_spin_unlock(ring->lock, flags);
+	DHD_DBG_RING_UNLOCK(ring->lock, flags);
 
 	bufptr += LOG_DUMP_ECNTRS_MAX_BUFSIZE;
 #endif /* EWP_ECNTRS_LOGGING */
@@ -21366,10 +21366,10 @@ dhd_log_dump_init(dhd_pub_t *dhd)
 				__FUNCTION__));
 		goto fail;
 	}
-	flags = dhd_os_spin_lock(ring->lock);
+	DHD_DBG_RING_LOCK(ring->lock, flags);
 	ring->state = RING_ACTIVE;
 	ring->threshold = 0;
-	dhd_os_spin_unlock(ring->lock, flags);
+	DHD_DBG_RING_UNLOCK(ring->lock, flags);
 
 	bufptr += LOG_DUMP_RTT_MAX_BUFSIZE;
 #endif /* EWP_RTT_LOGGING */