[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

[bluetooth-dev] Buffer and l2cap problem after link is up...



Hi all,

I use the stack in generic mode. I'm able to make a connection (pairing included). But at the end of the connection establishment, I've a problem with the in-buffers (BT SYS: ERROR: invalid inbuffer). Here is what I conclued on this problem :

- The function that should create the buffer (get_free_inbuffer()) is not called before the stack want to use the buffer.

Here is more precision, relating to code.

First observation, the problem is situated in function hci_receive_data() in the switch, in the "case WAIT_FOR_ACL_HDR:"

Here is the code (with some debug added) :

******* Start of source code ******

			/* Here we wait for the whole data header, four bytes*/
		case WAIT_FOR_ACL_HDR:
			D_STATE(__FUNCTION__ ": WAIT_FOR_ACL_HDR\n");
			c = MIN(count, ACL_HDR_LEN - tmp_pos);
			memcpy(hdr + tmp_pos, buf, c);
			tmp_pos += c;
			buf += c;
			count -= c;
			if (tmp_pos == ACL_HDR_LEN) {
				u32 tmp_hdr = le32_to_cpuu(hdr);
				hci_hdl = GET_BITS(tmp_hdr, 0, 12);
				pb_flag = GET_BITS(tmp_hdr, 12, 2);
				bc_flag = GET_BITS(tmp_hdr, 14, 2);
				data_len = GET_BITS(tmp_hdr, 16, 16);


              printk("pg_flag = %d\n", pb_flag);
	      printk("bc_flag = %d\n", bc_flag);
	      printk("data_len = %d\n", data_len);
	      
				/* Check the length to make sure we won't 
				   overrun in_buf->buf_ptr in a memcpy later.
				   --gmcnutt
				 */
				if (data_len > HCI_IN_SIZE) {
					D_ERR(__FUNCTION__ ": %d is too big "\
					      "for our HCI input buffers -- "\
					      "discarding buffer\n",
					      data_len);
					state = WAIT_FOR_PACKET_TYPE;
					return;
				}

				if (pb_flag == L2CAP_FRAME_START) {
					D_REC(__FUNCTION__ ": New frame\n");
					
					/* BT Specification Part D 2.4.1: All segments associated
					   with and L2CAP packet must be passed through to the 
					   baseband before any other L2CAP packet destined to 
					   the same unit may be sent. This means if we got a 
					   new L2CAP packet while we expecting another segment
					   of the previous packet something is wrong. This may
					   be a result of wrong length-indicator in the l2cap
					   header and we silently discard the previous packet */

					if(get_inbuffer(hci_hdl)) {
						D_ERR(__FUNCTION__ ": Discarding data in previous buffer\n");
						hci_clear_buffer(hci_hdl);
					}
					
					in_buf = get_free_inbuffer();
					if (in_buf) {
					  D_ERR(">>>>>> WAIT_FOR_ACL_HDR: Found buffer\n"); // PAL
						in_buf->nbr_of_hci_pkt = 1;
						in_buf->hci_hdl = hci_hdl;
					}	
				} else {
				  D_ERR(">>>>>> WAIT_FOR_ACL_HDR: No buffer found\n"); // PAL
					D_REC(__FUNCTION__ ": Cont frame\n");
					in_buf = get_inbuffer(hci_hdl);
					if (in_buf) {
						in_buf->nbr_of_hci_pkt++;
					}
				}

				host_nbrcompleted_packets(hci_hdl, 1);

				/* When we change state we reset data_index,
				   because we are using separate buffers for
				   the HCI header and the HCI data */
				tmp_pos = 0;
				state = WAIT_FOR_ACL_DATA;
			} else if (tmp_pos < ACL_HDR_LEN) {
				D_REC(__FUNCTION__ ": Didn't got whole header length, waiting for more\n");
			} else {
				D_ERR(__FUNCTION__ ": incorredt ACL header length\n");
			}
			break;

**** End of source code *****

When the stack go for the first time in this case, the value "pb_flag" is 0. So it is different from L2CAP_FRAME_START.
The consequence is that the "if (pb_flag == L2CAP_FRAME_START)" is false, and the code go to the else. In this else, a buffer is used, but this buffer has never been alocated, because it is normally alocated when this "if" is true (see code).

So here is my problem : is there a bug from the firmware on my hardware ? Is there something wrong in the stack ?

Of course, after that, I've a lot of problems, bytes are discarded, etc.

Note : I use a bluetooth chip (baseband BSN30), communicating through UART with latest sources

Thank you for any help.

Here are the logs I get when this problem appears :


Apr 30 17:34:16 danube kernel: BT SYS: process_event: ACL link is up 
Apr 30 17:34:16 danube kernel: BT DATA <--|X|      7 
Apr 30 17:34:16 danube kernel:  
Apr 30 17:34:16 danube kernel: <--|X| (7): 
Apr 30 17:34:16 danube kernel: 0x01 0x24 0x0c 0x03 0x20 0x03 0x02  
Apr 30 17:34:16 danube kernel: BT DATA <--|X|      8 
Apr 30 17:34:16 danube kernel:  
Apr 30 17:34:16 danube kernel: <--|X| (8): 
Apr 30 17:34:16 danube kernel: 0x01 0x0f 0x04 0x04 0x01 0x00 0x00 0xcc  
Apr 30 17:34:16 danube kernel: BT DATA <--|X|     14 
Apr 30 17:34:17 danube kernel:  
Apr 30 17:34:17 danube kernel: <--|X| (14): 
Apr 30 17:34:17 danube kernel: 0x01 0x19 0x04 0x0a 0x82 0xae 0x16 0x37 0x80 0x00 0x00 0x00 0x00 0x00  
Apr 30 17:34:17 danube kernel: BT DATA <--|X|      8 
Apr 30 17:34:17 danube kernel:  
Apr 30 17:34:17 danube kernel: <--|X| (8): 
Apr 30 17:34:17 danube kernel: 0x01 0x0d 0x08 0x04 0x01 0x00 0x01 0x00  
Apr 30 17:34:17 danube kernel: BT DATA <--|X|      8 
Apr 30 17:34:17 danube kernel:  
Apr 30 17:34:17 danube kernel: <--|X| (8): 
Apr 30 17:34:17 danube kernel: 0x01 0x37 0x0c 0x04 0x01 0x00 0x40 0x1f  
Apr 30 17:34:17 danube kernel: l2ca_connect_req: wait baseband, woke up ! 
Apr 30 17:34:17 danube kernel: l2ca_connect_req: wait rsp, sleep on wq 0xc757df3c 
Apr 30 17:34:17 danube kernel: BT DATA <--|X|     17 
Apr 30 17:34:17 danube kernel:  
Apr 30 17:34:17 danube kernel: <--|X| (17): 
Apr 30 17:34:17 danube kernel: 0x02 0x01 0x20 0x0c 0x00 0x08 0x00 0x01 0x00 0x02 0x01 0x04 0x00 0x03 0x00 0x40  
Apr 30 17:34:17 danube kernel: 0x00  
Apr 30 17:34:17 danube kernel: BT DATA -->|X|     38 
Apr 30 17:34:17 danube kernel:  
Apr 30 17:34:17 danube kernel: -->|X| (38): 
Apr 30 17:34:17 danube kernel: 0x04 0x0e 0x04 0x0a 0x24 0x0c 0x00 0x04 0x0f 0x04 0x00 0x0a 0x0f 0x04 0x04 0x1d  
Apr 30 17:34:17 danube kernel: 0x05 0x00 0x01 0x00 0x00 0x00 0x04 0x0f 0x04 0x00 0x0a 0x19 0x04 0x04 0x0e 0x06  
Apr 30 17:34:17 danube kernel: 0x0a 0x0d 0x08 0x00 0x01 0x00  
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_PACKET_TYPE 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_EVENT_TYPE 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_EVENT_LENGTH 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_PACKET_TYPE 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_EVENT_TYPE 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_EVENT_LENGTH 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_PACKET_TYPE 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_EVENT_TYPE 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_EVENT_LENGTH 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_PACKET_TYPE 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_EVENT_TYPE 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_EVENT_LENGTH 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_PACKET_TYPE 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_EVENT_TYPE 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_EVENT_LENGTH 
Apr 30 17:34:17 danube kernel: BT DATA -->|X|    134 
Apr 30 17:34:17 danube kernel:  
Apr 30 17:34:17 danube kernel: -->|X| (134): 
Apr 30 17:34:17 danube kernel: 0x02 0x01 0x10 0x00 0x00 0x02 0x01 0x10 0x00 0x00 0x04 0x07 0xff 0x00 0x82 0xae  
Apr 30 17:34:17 danube kernel: 0x16 0x00 0x37 0x80 0x00 0x54 0x75 0x72 0x6c 0x75 0x73 0x69 0x70 0x68 0x6f 0x6e  
Apr 30 17:34:17 danube kernel: 0x00 0x68 0x29 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00  
Apr 30 17:34:17 danube kernel: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00  
Apr 30 17:34:17 danube last message repeated 4 times
Apr 30 17:34:17 danube kernel: 0x00 0x00 0x00 0x00 0x00 0x00  
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_PACKET_TYPE 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_ACL_HDR 
Apr 30 17:34:17 danube kernel: pg_flag = 1 
Apr 30 17:34:17 danube kernel: bc_flag = 0 
Apr 30 17:34:17 danube kernel: data_len = 0 
Apr 30 17:34:17 danube kernel: BT SYS: ERROR: >>>>>> WAIT_FOR_ACL_HDR: No buffer found 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_ACL_DATA 
Apr 30 17:34:17 danube kernel: BT SYS: ERROR: invalid inbuffer PAL 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_PACKET_TYPE 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_ACL_HDR 
Apr 30 17:34:17 danube kernel: pg_flag = 1 
Apr 30 17:34:17 danube kernel: bc_flag = 0 
Apr 30 17:34:17 danube kernel: data_len = 0 
Apr 30 17:34:17 danube kernel: BT SYS: ERROR: >>>>>> WAIT_FOR_ACL_HDR: No buffer found 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_ACL_DATA 
Apr 30 17:34:17 danube kernel: BT SYS: ERROR: invalid inbuffer PAL 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_PACKET_TYPE 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_EVENT_TYPE 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_EVENT_LENGTH 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_EVENT_PARAM 
Apr 30 17:34:17 danube kernel: BT DATA -->|X|    100 
Apr 30 17:34:17 danube kernel:  
Apr 30 17:34:17 danube kernel: -->|X| (100): 
Apr 30 17:34:17 danube kernel: 0x00 0x0e 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00  
Apr 30 17:34:17 danube kernel: 0x00 0x00 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00  
Apr 30 17:34:17 danube kernel: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00  
Apr 30 17:34:17 danube last message repeated 3 times
Apr 30 17:34:17 danube kernel: 0x00 0x00 0x00 0x00  
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_EVENT_PARAM 
Apr 30 17:34:17 danube kernel: BT DATA -->|X|     36 
Apr 30 17:34:17 danube kernel:  
Apr 30 17:34:17 danube kernel: -->|X| (36): 
Apr 30 17:34:17 danube kernel: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00  
Apr 30 17:34:17 danube kernel: 0x00 0x00 0x37 0x00 0x00 0x00 0x00 0xd9 0x00 0x00 0xb6 0x76 0x00 0x04 0x0e 0x06  
Apr 30 17:34:17 danube kernel: 0x0a 0x37 0x01 0x00  
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_EVENT_PARAM 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_PACKET_TYPE 
Apr 30 17:34:17 danube kernel: BT SYS: ERROR: hci_receive_data: discarding 2 bytes 
Apr 30 17:34:17 danube kernel: BT DATA -->|X|     27 
Apr 30 17:34:17 danube kernel:  
Apr 30 17:34:17 danube kernel: -->|X| (27): 
Apr 30 17:34:17 danube kernel: 0x02 0x01 0x10 0x00 0x00 0x02 0x01 0x10 0x00 0x00 0x02 0x00 0x01 0x20 0x10 0x00  
Apr 30 17:34:17 danube kernel: 0x0c 0x00 0x01 0x00 0x03 0x01 0x08 0x00 0x45 0x00 0x40  
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_PACKET_TYPE 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_ACL_HDR 
Apr 30 17:34:17 danube kernel: pg_flag = 1 
Apr 30 17:34:17 danube kernel: bc_flag = 0 
Apr 30 17:34:17 danube kernel: data_len = 0 
Apr 30 17:34:17 danube kernel: BT SYS: ERROR: >>>>>> WAIT_FOR_ACL_HDR: No buffer found 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_ACL_DATA 
Apr 30 17:34:17 danube kernel: BT SYS: ERROR: invalid inbuffer PAL 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_PACKET_TYPE 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_ACL_HDR 
Apr 30 17:34:17 danube kernel: pg_flag = 1 
Apr 30 17:34:17 danube kernel: bc_flag = 0 
Apr 30 17:34:17 danube kernel: data_len = 0 
Apr 30 17:34:17 danube kernel: BT SYS: ERROR: >>>>>> WAIT_FOR_ACL_HDR: No buffer found 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_ACL_DATA 
Apr 30 17:34:17 danube kernel: BT SYS: ERROR: invalid inbuffer PAL 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_PACKET_TYPE 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_ACL_HDR 
Apr 30 17:34:17 danube kernel: pg_flag = 0 
Apr 30 17:34:17 danube kernel: bc_flag = 0 
Apr 30 17:34:17 danube kernel: data_len = 4128 
Apr 30 17:34:17 danube kernel: BT SYS: ERROR: hci_receive_data: 4128 is too big for our HCI input buffers -- discarding buffer 
Apr 30 17:34:17 danube kernel: BT DATA -->|X|     10 
Apr 30 17:34:17 danube kernel:  
Apr 30 17:34:17 danube kernel: -->|X| (10): 
Apr 30 17:34:17 danube kernel: 0x02 0x01 0x10 0x00 0x00 0x02 0x01 0x10 0x00 0x00  
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_PACKET_TYPE 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_ACL_HDR 
Apr 30 17:34:17 danube kernel: pg_flag = 1 
Apr 30 17:34:17 danube kernel: bc_flag = 0 
Apr 30 17:34:17 danube kernel: data_len = 0 
Apr 30 17:34:17 danube kernel: BT SYS: ERROR: >>>>>> WAIT_FOR_ACL_HDR: No buffer found 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_ACL_DATA 
Apr 30 17:34:17 danube kernel: BT SYS: ERROR: invalid inbuffer PAL 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_PACKET_TYPE 
Apr 30 17:34:17 danube kernel: HCI: hci_receive_data: WAIT_FOR_ACL_HDR 
Apr 30 17:34:17 danube kernel: pg_flag = 1 
Apr 30 17:34:17 danube kernel: bc_flag = 0 
Apr 30 17:34:17 danube kernel: data_len = 0 
Apr 30 17:34:17 danube kernel: BT SYS: ERROR: >>>>>> WAIT_FOR_ACL_HDR: No buffer found 
Apr 30 17:34:25 danube kernel: BT DATA -->|X|      8 
Apr 30 17:34:25 danube kernel:  
Apr 30 17:34:25 danube kernel: -->|X| (8): 
Apr 30 17:34:25 danube kernel: 0x04 0x13 0x05 0x01 0x01 0x00 0x01 0x00  
Apr 30 17:34:25 danube kernel: HCI: hci_receive_data: WAIT_FOR_ACL_DATA 
Apr 30 17:34:25 danube kernel: BT SYS: ERROR: invalid inbuffer PAL 
Apr 30 17:34:25 danube kernel: HCI: hci_receive_data: WAIT_FOR_PACKET_TYPE 
Apr 30 17:34:25 danube kernel: HCI: hci_receive_data: WAIT_FOR_EVENT_TYPE 
Apr 30 17:34:25 danube kernel: HCI: hci_receive_data: WAIT_FOR_EVENT_LENGTH 
Apr 30 17:34:27 danube kernel: BT DATA -->|X|     10 
Apr 30 17:34:27 danube kernel:  
Apr 30 17:34:27 danube kernel: -->|X| (10): 
Apr 30 17:34:27 danube kernel: 0x02 0x01 0x10 0x00 0x00 0x02 0x01 0x10 0x00 0x00  
Apr 30 17:34:27 danube kernel: HCI: hci_receive_data: WAIT_FOR_PACKET_TYPE 
Apr 30 17:34:27 danube kernel: HCI: hci_receive_data: WAIT_FOR_ACL_HDR 
Apr 30 17:34:27 danube kernel: pg_flag = 1 
Apr 30 17:34:27 danube kernel: bc_flag = 0 
Apr 30 17:34:27 danube kernel: data_len = 0 
Apr 30 17:34:27 danube kernel: BT SYS: ERROR: >>>>>> WAIT_FOR_ACL_HDR: No buffer found 
Apr 30 17:34:27 danube kernel: HCI: hci_receive_data: WAIT_FOR_ACL_DATA 
Apr 30 17:34:27 danube kernel: BT SYS: ERROR: invalid inbuffer PAL 
Apr 30 17:34:27 danube kernel: HCI: hci_receive_data: WAIT_FOR_PACKET_TYPE 
Apr 30 17:34:27 danube kernel: HCI: hci_receive_data: WAIT_FOR_ACL_HDR 
Apr 30 17:34:27 danube kernel: pg_flag = 1 
Apr 30 17:34:27 danube kernel: bc_flag = 0 
Apr 30 17:34:27 danube kernel: data_len = 0 
Apr 30 17:34:27 danube kernel: BT SYS: ERROR: >>>>>> WAIT_FOR_ACL_HDR: No buffer found 


-- 
Alain Paschoud                      SMARTDATA SA
alain.paschoud@xxxxxxx.ch         PSE-A
http://www.smartdata.ch             1015 Lausanne
Phone +41-21-693'84'98              
Fax   +41-27-693'84'91              
-
To unsubscribe from this list: send the line "unsubscribe bluetooth-dev" in
the body of a message to majordomo@xxxxxxx.com