Merge "[RFCOMM] Reduce log levels of frequent events" into main (55df697a) · Commits · e / os / android_packages_modules_Bluetooth

system/btif/src/btif_sock_rfc.cc

+7 −1

Original line number	Diff line number	Diff line
		@@ -682,7 +682,13 @@ static void on_rfc_outgoing_congest(tBTA_JV_RFCOMM_CONG* p, uint32_t id) {
		static uint32_t rfcomm_cback(tBTA_JV_EVT event, tBTA_JV* p_data,
		uint32_t rfcomm_slot_id) {
		uint32_t id = 0;

		// Write events are too frequent to log at info level
		if (event != BTA_JV_RFCOMM_WRITE_EVT) {
		LOG_INFO("handling event:%d id:%u", event, rfcomm_slot_id);
		} else {
		LOG_VERBOSE("handling event:%d id:%u", event, rfcomm_slot_id);
		}

		switch (event) {
		case BTA_JV_RFCOMM_START_EVT:

system/stack/rfcomm/rfc_port_fsm.cc

+32 −9

Original line number	Diff line number	Diff line
		@@ -84,9 +84,13 @@ static void rfc_set_port_state(tPORT_STATE* port_pars, MX_FRAME* p_frame);
		******************************************************************************/
		void rfc_port_sm_execute(tPORT* p_port, tRFC_PORT_EVENT event, void* p_data) {
		CHECK(p_port != nullptr) << __func__ << ": NULL port event " << event;
		log::info("bd_addr:{}, port:{}, state:{}, event:{}",

		// logs for state RFC_STATE_OPENED handled in rfc_port_sm_opened()
		if (p_port->rfc.state != RFC_STATE_OPENED) {
		log::info("bd_addr:{}, index:{}, state:{}, event:{}",
		ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->handle,
		p_port->rfc.state, event);
		}
		switch (p_port->rfc.state) {
		case RFC_STATE_CLOSED:
		rfc_port_sm_state_closed(p_port, event, p_data);
		@@ -460,10 +464,14 @@ void rfc_port_sm_orig_wait_sec_check(tPORT* p_port, tRFC_PORT_EVENT event,
		void rfc_port_sm_opened(tPORT* p_port, tRFC_PORT_EVENT event, void* p_data) {
		switch (event) {
		case RFC_PORT_EVENT_OPEN:
		log::error("Port error state {} event {}", p_port->rfc.state, event);
		log::error("Port error, bd_addr={}, state={}, event={}",
		ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->rfc.state,
		event);
		return;

		case RFC_PORT_EVENT_CLOSE:
		log::info("RFC_PORT_EVENT_CLOSE bd_addr={}, index={}",
		ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->handle);
		rfc_port_timer_start(p_port, RFC_DISC_TIMEOUT);
		rfc_send_disc(p_port->rfc.p_mcb, p_port->dlci);
		p_port->rfc.expected_rsp = 0;
		@@ -471,7 +479,8 @@ void rfc_port_sm_opened(tPORT* p_port, tRFC_PORT_EVENT event, void* p_data) {
		return;

		case RFC_PORT_EVENT_CLEAR:
		log::warn("RFC_PORT_EVENT_CLEAR, index={}", p_port->handle);
		log::warn("RFC_PORT_EVENT_CLEAR, bd_addr={}, index={}",
		ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->handle);
		rfc_port_closed(p_port);
		return;

		@@ -481,6 +490,8 @@ void rfc_port_sm_opened(tPORT* p_port, tRFC_PORT_EVENT event, void* p_data) {
		/* There might be an initial case when we reduced rx_max and credit_rx is
		* still */
		/* bigger. Make sure that we do not send 255 */
		log::verbose("RFC_PORT_EVENT_DATA bd_addr={}, index={}",
		ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->handle);
		if ((p_port->rfc.p_mcb->flow == PORT_FC_CREDIT) &&
		(((BT_HDR*)p_data)->len < p_port->peer_mtu) &&
		(!p_port->rx.user_fc) &&
		@@ -496,19 +507,27 @@ void rfc_port_sm_opened(tPORT* p_port, tRFC_PORT_EVENT event, void* p_data) {
		return;

		case RFC_PORT_EVENT_UA:
		log::verbose("RFC_PORT_EVENT_UA bd_addr={}, index={}",
		ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->handle);
		return;

		case RFC_PORT_EVENT_SABME:
		log::verbose("RFC_PORT_EVENT_SABME bd_addr={}, index={}",
		ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->handle);
		rfc_send_ua(p_port->rfc.p_mcb, p_port->dlci);
		return;

		case RFC_PORT_EVENT_DM:
		log::warn("RFC_EVENT_DM, index={}", p_port->handle);
		log::info("RFC_EVENT_DM, bd_addr={}, index={}",
		ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->handle);
		PORT_DlcReleaseInd(p_port->rfc.p_mcb, p_port->dlci);
		rfc_port_closed(p_port);
		return;

		case RFC_PORT_EVENT_DISC:
		log::info("RFC_PORT_EVENT_DISC, bd_addr={}, index={}",
		ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->handle,
		p_port->rfc.state, event);
		p_port->rfc.state = RFC_STATE_CLOSED;
		rfc_send_ua(p_port->rfc.p_mcb, p_port->dlci);
		if (!fixed_queue_is_empty(p_port->rx.queue)) {
		@@ -520,16 +539,20 @@ void rfc_port_sm_opened(tPORT* p_port, tRFC_PORT_EVENT event, void* p_data) {
		return;

		case RFC_PORT_EVENT_UIH:
		log::verbose("RFC_PORT_EVENT_UIH bd_addr={}, index={}",
		ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->handle);
		rfc_port_uplink_data(p_port, (BT_HDR*)p_data);
		return;

		case RFC_PORT_EVENT_TIMEOUT:
		PORT_TimeOutCloseMux(p_port->rfc.p_mcb);
		log::error("Port error state {} event {}", p_port->rfc.state, event);
		log::error("Port error, bd_addr={}, state={}, event={}",
		ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->rfc.state,
		event);
		return;
		default:
		log::error("Received unexpected event:{} in state:{}", event,
		p_port->rfc.state);
		log::error("Received unexpected event {}, bd_addr={}, state={}", event,
		ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->rfc.state);
		}
		log::warn("Port state opened Event ignored {}", event);
		}