• State
  • Locked Locked
  • Replies 34 replies
  • Subscribers 44 subscribers
  • Views 5381 views
  • Users 0 members are here
Support feedback
Options
Options
Related

This thread has been locked.

If you have a related question, please click the "Ask a related question" button in the top right corner. The newly created question will be automatically linked to this question.

TCP socket does not stay open and will not reconnect

Zach Supalla
Prodigy 60 points


Hello,

My name's Zach, and I work at a start-up called Spark. We sell an open source development kit based on the CC3000 (paired with an STM32 microcontroller) called the Spark Core. We have shipped more than 10,000 CC3000 development kits around the world. More information can be found here: http://www.spark.io/

Many of our users have been running into an issue where TCP sockets do not stay open indefinitely, as they are supposed to. Instead, after some period of time ranging from a few minutes to many hours, the CC3000 will become uncommunicative and not only will it no longer communicate over the TCP socket, but it cannot open a new TCP socket either. These products have the latest version of the firmware (1.24) as well as the latest version of the host driver.

First, a brief explanation of the architecture:
- Once the Spark Core is connected to a Wi-Fi network (usually through Smart Config), it immediately opens a TCP socket to our server.
- The Core sends a heartbeat to the server every 15 seconds and opens a new socket if the server does not respond.
- Meanwhile, other communications happen over the TCP socket, which may be initiated by either the Core or the Cloud.
- If the connection is lost (for instance if you were to temporarily unplug the ethernet cable from your Wi-Fi router), the Core will recognize that the socket has closed and will attempt to create a new TCP socket every 60 seconds. In general when a failure is caused by a true network outage, the Core recovers gracefully when the network is re-connected.

Now here is an explanation of the failure mode:
- At some point, the MCU attempts to send() data to the cloud through the CC3000, and the CC3000 does not transmit said data (it doesn't show up on a tcpdump).
- At this point, the CC3000 never transmits another packet on the WiFi side. As the peer attempts to retry as per TCP, the CC3000 remains unresponsive. However, the SPI interface on the CC3000 continues to function and process commands, including send(), close(), netapp_ipconfig(), socket() amongst others.
- The microcontroller recognizes that the connection is dead (no response to the heartbeat), calls closesocket(), then socket(), then connect(). This connect() and all subsequent connect() calls fail, and no further data is heard from the CC3000 on the tcpdump. Our code is open souce, and this sequence of events can be found here: https://github.com/spark/core-firmware/blob/master/src/spark_utilities.cpp#L558
- We have not yet found a method to get the CC3000 back to a functioning state without resetting the entire system.
- Another symptom that we have noticed is that when the CC3000 reports the number of free buffers it has (free_buffers_event) for each open socket (which is usually 2), the number drops to 1 when the CC3000 goes mute.

On our own forums, we describe this failure as the "Cyan Flash of Death", because we have an RGB LED that displays the status of the connection, and it flashes cyan when it is connected to the Wi-Fi network but not connected to our cloud service.

This failure seems highly variable and affects many users differently. Here is what we have ascertained by surveying our users who have encountered this bug:
- The failure seems to be variable depending on the Wi-Fi network. For example, in our office we have two different networks we can connect to; on one network, the Core does not exhibit this failure at all, and on the other network, it exhibits this failure within minutes. Different users report different times to failure, anywhere between a few minutes to 18+ hours. However we have not been able to determine the pattern.
- The failure occurs more quickly when there is more traffic going through the CC3000.
- The failure seems to occur less frequently on Wi-Fi networks with fewer clients connected.

We have volumes of further data, including SPI traces (with selects removed for readability), tcpdumps, and dozens of reports on our own forum:

Fullscreen 8551.spi4.log Download 
-117.970124 02733 recv command fd 0, flags 0, length 2
-117.969832 02734 recv status fd 0, flags 1, length 2
-117.969636 02735 recv data length 2: 00 20

-117.967608 02738 recv command fd 0, flags 0, length 32
-117.967316 02739 recv status fd 0, flags 1, length 32
-117.967121 02740 recv data length 32: 52 a3 15 44 1e 9c 45 bd a1 f6 12 31 ba 4d 4c ec 04 c7 6f f5 43 b8 49 d6 a7 75 f9 bd ff e9 1f 92

-117.966410 02741 send data fd 0, flags 0, length 18: 10 40 b4 12 06 f2 75 65 bc d8 65 ab 18 52 6e a1 ee
-117.965963 02742 send status fd 0, length 18

-117.965672 02743 send data fd 0, flags 0, length 18: 10 f9 3a ff 58 ff 9c 81 b3 76 ed 35 89 01 bf bb 4a
-117.965224 02744 send status fd 0, length 18

-117.885129 02777 free buffers event 0:2

-107.675303 06860 recv command fd 0, flags 0, length 2
-107.675010 06861 recv status fd 0, flags 1, length 2
-107.674815 06862 recv data length 2: 00 20

-107.672779 06865 recv command fd 0, flags 0, length 32
-107.672486 06866 recv status fd 0, flags 1, length 32
-107.672291 06867 recv data length 32: 58 90 de 63 39 61 5b 16 fc b5 bc 22 08 45 4f 74 3b 1c 88 a4 16 f7 79 64 49 7c 4b 27 6f da f3 da

-107.671581 06868 send data fd 0, flags 0, length 18: 10 82 e6 9b af c9 3a 6a 1d d4 ab c3 07 55 bb 74 d9
-107.671135 06869 send status fd 0, length 18

-107.670830 06870 send data fd 0, flags 0, length 18: 10 18 24 a1 34 97 5a 1e 84 ad 43 40 18 50 7f a1 f7
-107.670397 06871 send status fd 0, length 18

-107.584542 06906 free buffers event 0:2

-97.323295 11009 recv command fd 0, flags 0, length 2
-97.323002 11010 recv status fd 0, flags 1, length 2
-97.322807 11011 recv data length 2: 00 20

-97.320592 11014 recv command fd 0, flags 0, length 32
-97.320299 11015 recv status fd 0, flags 1, length 32
-97.320104 11016 recv data length 32: b0 f1 7f 5a 0b 71 63 41 95 db 3a be fb b5 77 0d a0 d6 89 e3 7a 01 6e c8 72 ff ea 22 c4 05 ee d6

-97.319393 11017 send data fd 0, flags 0, length 18: 10 63 37 af 7e 1e fe 93 8d 06 76 36 95 81 04 07 fb
-97.318945 11018 send status fd 0, length 18

-97.318655 11019 send data fd 0, flags 0, length 18: 10 37 b7 0f 83 6d d1 a0 2a fe 13 68 21 64 b1 4f 1a
-97.318207 11020 send status fd 0, length 18

-97.232674 11055 free buffers event 0:2

-87.021261 15136 recv command fd 0, flags 0, length 2
-87.020968 15137 recv status fd 0, flags 1, length 2
-87.020773 15138 recv data length 2: 00 20

-87.018552 15141 recv command fd 0, flags 0, length 32
-87.018259 15142 recv status fd 0, flags 1, length 32
-87.018064 15143 recv data length 32: 14 60 33 bd 22 cb 89 b7 54 0f 6d b6 9d 77 fc e0 56 d2 b4 a7 16 af 08 c6 f1 0e 7d 5a b7 16 28 16

-87.017354 15144 send data fd 0, flags 0, length 18: 10 37 40 7a 5c 34 f5 09 a0 1d 1b e1 0d bc b6 46 69
-87.016909 15145 send status fd 0, length 18

-87.016601 15146 send data fd 0, flags 0, length 18: 10 e7 f2 62 5a f9 1b 9f fc fd 54 ae da 09 44 7b 6e
-87.016168 15147 send status fd 0, length 18

-86.935850 15180 free buffers event 0:2

-76.735823 19259 recv command fd 0, flags 0, length 2
-76.735530 19260 recv status fd 0, flags 1, length 2
-76.735334 19261 recv data length 2: 00 20

-76.733303 19264 recv command fd 0, flags 0, length 32
-76.733010 19265 recv status fd 0, flags 1, length 32
-76.732812 19266 recv data length 32: b1 86 ba 4c b7 ad ad f0 1f 9e de ee 53 2c 49 a9 a5 ca 7f d1 33 7b 57 0a 86 18 2d 0b 9c c5 00 86

-76.732105 19267 send data fd 0, flags 0, length 18: 10 d3 ce e4 b6 21 41 5b f9 20 6d 48 3a 9e be cc ec
-76.731669 19268 send status fd 0, length 18

-76.731379 19269 send data fd 0, flags 0, length 18: 10 50 69 fc 5f 75 a1 8f 25 62 c6 f3 f9 db 32 5e ab
-76.730931 19270 send status fd 0, length 18

-76.650284 19303 free buffers event 0:2

-66.407157 23398 recv command fd 0, flags 0, length 2
-66.406864 23399 recv status fd 0, flags 1, length 2
-66.406669 23400 recv data length 2: 00 20

-66.404477 23403 recv command fd 0, flags 0, length 32
-66.404185 23404 recv status fd 0, flags 1, length 32
-66.403990 23405 recv data length 32: 6c 63 3f b6 71 74 e8 fc 7a 58 97 bb f5 1b d1 a4 b3 a2 1d b7 4b 4f 65 34 b1 91 b3 d8 db 97 99 3d

-66.403282 23406 send data fd 0, flags 0, length 18: 10 ed 1a 3d cc db 8a cb 13 6d 75 0e 3c 01 e2 fe 3f
-66.402849 23407 send status fd 0, length 18

-66.402544 23408 send data fd 0, flags 0, length 18: 10 bd 3c 11 a8 5e a7 af 94 46 a4 1b da e7 89 38 e1
-66.402109 23409 send status fd 0, length 18

-66.325938 23440 free buffers event 0:2

-56.083293 27535 recv command fd 0, flags 0, length 2
-56.083000 27536 recv status fd 0, flags 1, length 2
-56.082805 27537 recv data length 2: 00 20

-56.080658 27540 recv command fd 0, flags 0, length 32
-56.080365 27541 recv status fd 0, flags 1, length 32
-56.080170 27542 recv data length 32: e9 1a 8c 40 a6 0b 9a a3 a4 48 fb d2 13 08 28 14 af bb 8d be 84 6a 5f 26 89 23 69 99 11 17 87 e7

-56.079460 27543 send data fd 0, flags 0, length 18: 10 6e fe 20 0d f4 23 bc a3 5b 3c 70 e6 96 89 74 ec
-56.079017 27544 send status fd 0, length 18

-56.078727 27545 send data fd 0, flags 0, length 18: 10 00 ed 34 31 45 14 de da ed b2 71 0c 72 a5 ab 28
-56.078279 27546 send status fd 0, length 18

-55.997842 27579 free buffers event 0:2

-45.749570 31678 recv command fd 0, flags 0, length 2
-45.749277 31679 recv status fd 0, flags 1, length 2
-45.749082 31680 recv data length 2: 00 20

-45.747049 31683 recv command fd 0, flags 0, length 32
-45.746757 31684 recv status fd 0, flags 1, length 32
-45.746559 31685 recv data length 32: b5 cb ee 69 b6 11 f1 ac 6f f3 96 37 fe 19 51 e4 a7 8c cb 65 a2 46 b7 27 5d 1d 4e fd 66 62 d9 2a

-45.745851 31686 send data fd 0, flags 0, length 18: 10 fb bc ae 73 c6 71 b6 de 8a 67 a0 3e a6 26 bf 82
-45.745408 31687 send status fd 0, length 18

-45.745103 31688 send data fd 0, flags 0, length 18: 10 8c ca bd ff 77 1c 65 46 92 3f 05 ad a5 3b 44 11
-45.744669 31689 send status fd 0, length 18

-45.658485 31724 free buffers event 0:2

-35.331811 35853 recv command fd 0, flags 0, length 2
-35.331518 35854 recv status fd 0, flags 1, length 2
-35.331323 35855 recv data length 2: 00 20

-35.329284 35858 recv command fd 0, flags 0, length 32
-35.328991 35859 recv status fd 0, flags 1, length 32
-35.328793 35860 recv data length 32: c1 4e 52 ea 0c 95 47 0a 78 d2 75 e0 db b9 0f e3 86 c9 2d a5 45 00 aa 9a d4 f2 64 34 24 69 f6 7c

-35.328086 35861 send data fd 0, flags 0, length 18: 10 27 2f d3 56 1f cd b9 65 f6 27 04 62 92 83 bf 68
-35.327637 35862 send status fd 0, length 18

-35.327347 35863 send data fd 0, flags 0, length 18: 10 23 b8 c6 b5 59 10 08 88 75 66 a7 ef c9 45 1c 6a
-35.326899 35864 send status fd 0, length 18

-35.251599 35895 free buffers event 0:2

-25.022812 39986 recv command fd 0, flags 0, length 2
-25.022520 39987 recv status fd 0, flags 1, length 2
-25.022324 39988 recv data length 2: 00 20

-25.021105 39991 recv command fd 0, flags 0, length 32
-25.020812 39992 recv status fd 0, flags 1, length 32
-25.020617 39993 recv data length 32: da a9 bf 56 e7 0b 1a b7 ae b9 5a cb 73 c3 28 28 05 d1 dd ab b1 9d b8 85 be 60 c6 b0 7a 92 b1 ad

-25.019907 39994 send data fd 0, flags 0, length 18: 10 f5 d3 64 7f d8 3d 83 a9 a6 7e 5b 43 b4 f4 38 0c
-25.019464 39995 send status fd 0, length 18

-25.019158 39996 send data fd 0, flags 0, length 18: 10 e8 01 1c 34 05 5e 99 01 f7 c5 fc 99 1e 0b 44 b3
-25.018725 39997 send status fd 0, length 18

-20.461069 41820 free buffers event 0:1

-10.010355 45999 send data fd 0, flags 0, length 18: 10 b7 fe cd 1c 56 61 92 45 ae c1 8d 33 a9 fe 80 19
-10.009920 46000 send status fd 0, length 18

-8.156915 46741 free buffers event 0:1

+0.099862 50002 Write opcode 2005
+0.099862 50002: 0x01 0x00 0x05 0x00 0x00 0x01 0x05 0x20 0x00 0x01
               : 0x02 0x00 0xff 0x00 0x00 0x00 0x00 0x00 0x00 0x00

+0.100194 50003 Read Event 2005
+0.100194 50003: 0x03 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x0c 0x03 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x0c 0x01 0x40 0x00 0x0c 0x01 0x40 0x00 0x0c 0x01 0x40 0x00 0x0c 0x01 0x40 0x00 0x0c 0x01 0x40 0x00 0x08 0x01 0x40 0x00 0x08 0x01 0x40 0x00 0x08 0x01 0x40 0x00 0x08 0x01 0x40 0x00 0x08 0x01 0x40 0x00 0x08 0x01 0x40 0x00 0x08 0x01 0x40 0x0c 0x00 0x48 0x00
               : 0x02 0x00 0x00 0x00 0x41 0x04 0x05 0x20 0x3d 0x00 0xb3 0x79 0xa8 0xc0 0x00 0xff 0xff 0xff 0x01 0x79 0xa8 0xc0 0x01 0x79 0xa8 0xc0 0x01 0x79 0xa8 0xc0 0x55 0x55 0x55 0x55 0x12 0x00 0x48 0x6f 0x6d 0x65 0x31 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00

+0.100744 50004 Write opcode 100b
+0.100744 50004: 0x01 0x00 0x09 0x00 0x00 0x01 0x0b 0x10 0x04 0x00 0x00 0x00 0x00 0x14
               : 0x02 0x00 0xff 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00

+3.703085 50005 Read Event 100b
+3.703085 50005: 0x03 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x0c 0x03 0x00 0x00 0x00
               : 0x02 0x00 0x00 0x00 0x09 0x04 0x0b 0x10 0x05 0x00 0x00 0x00 0x00 0x00

+3.703228 50006 Write opcode 1001
+3.703228 50006: 0x01 0x00 0x11 0x00 0x00 0x01 0x01 0x10 0x0c 0x02 0x00 0x00 0x00 0x01 0x00 0x00 0x00 0x06 0x00 0x00 0x00 0x14
               : 0x02 0x00 0xff 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00

+3.703614 50007 Read Event 1001
+3.703614 50007: 0x03 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x0c 0x03 0x00 0x00 0x00 0x01 0x00 0x19 0x00 0x00 0x01 0x07 0x10 0x14 0x00 0x00 0x00 0x00 0x08 0x00 0x00 0x00 0x08 0x00 0x00 0x00 0x02 0x00 0x16 0x33 0x36 0xd0 0xe5 0x04 0x00
               : 0x02 0x00 0x00 0x00 0x09 0x04 0x01 0x10 0x05 0x00 0x00 0x00 0x00 0x00 0x02 0x00 0xff 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00

3678.spi4.pcap.gz

Fullscreen 7776.spi7.log Download 
-117.775427 02889 recv command fd 0, flags 0, length 2
-117.775134 02890 recv status fd 0, flags 1, length 2
-117.774939 02891 recv data length 2: 00 20

-117.773035 02894 recv command fd 0, flags 0, length 32
-117.772742 02895 recv status fd 0, flags 1, length 32
-117.772544 02896 recv data length 32: 69 5e 6d 41 6d b6 87 c1 73 d9 a9 d6 ed 8b 64 6a 23 87 c3 8c 96 8d dd 0c ad 17 3a bc b4 9f 32 e7

-117.771837 02897 send data fd 0, flags 0, length 18: 10 5b 6b e3 21 76 bb c9 e6 31 58 a5 4d a7 49 68 88
-117.771305 02898 send status fd 0, length 18

-117.771014 02899 send data fd 0, flags 0, length 18: 10 89 07 db 97 5e 28 2f 10 82 04 47 33 2d a3 3d 49
-117.770581 02900 send status fd 0, length 18

-117.700044 02929 free buffers event 0:2

-107.491985 07012 recv command fd 0, flags 0, length 2
-107.491693 07013 recv status fd 0, flags 1, length 2
-107.491497 07014 recv data length 2: 00 20

-107.489478 07017 recv command fd 0, flags 0, length 32
-107.489185 07018 recv status fd 0, flags 1, length 32
-107.488990 07019 recv data length 32: 3a a7 93 52 dc 9e 97 db 93 58 ca 8b ff 7a ed 59 e0 00 2b ca 93 c1 9e b6 5c 00 4f 1d e4 73 ac 6b

-107.488280 07020 send data fd 0, flags 0, length 18: 10 04 18 ee 3e 7d 3d bb 1d 36 b9 9a 69 d8 08 a5 a3
-107.487847 07021 send status fd 0, length 18

-107.487541 07022 send data fd 0, flags 0, length 18: 10 92 db 24 fa 50 3e 42 e6 a7 ed 40 be 14 de ff be
-107.487107 07023 send status fd 0, length 18

-107.411963 07054 free buffers event 0:2

-97.206136 11135 recv command fd 0, flags 0, length 2
-97.205843 11136 recv status fd 0, flags 1, length 2
-97.205648 11137 recv data length 2: 00 20

-97.203440 11140 recv command fd 0, flags 0, length 32
-97.203148 11141 recv status fd 0, flags 1, length 32
-97.202952 11142 recv data length 32: 8a 28 94 7e 2d cb ef aa b8 03 b4 4b cb 5f 3d e7 15 3b 02 80 27 6c 7b 03 bf e7 c0 79 65 7b fb ec

-97.202245 11143 send data fd 0, flags 0, length 18: 10 af 88 87 35 a8 c5 b7 9b b2 5c e2 62 4a 7b 57 b4
-97.201812 11144 send status fd 0, length 18

-97.201521 11145 send data fd 0, flags 0, length 18: 10 9d 2c af 34 37 5f 18 10 32 8a 15 71 2f 63 db 5b
-97.201084 11146 send status fd 0, length 18

-97.125127 11177 free buffers event 0:2

-86.881249 15274 recv command fd 0, flags 0, length 2
-86.880957 15275 recv status fd 0, flags 1, length 2
-86.880762 15276 recv data length 2: 00 20

-86.878742 15279 recv command fd 0, flags 0, length 32
-86.878449 15280 recv status fd 0, flags 1, length 32
-86.878254 15281 recv data length 32: 0c d2 e3 c5 b8 64 d1 f7 f0 eb 7b 96 0b 02 03 83 14 9f 7e 1d 24 8a af 50 f4 3c 0e 58 13 f9 a7 b0

-86.877547 15282 send data fd 0, flags 0, length 18: 10 01 2b d8 cf aa 62 92 90 19 44 89 36 f5 81 69 b6
-86.877101 15283 send status fd 0, length 18

-86.876796 15284 send data fd 0, flags 0, length 18: 10 ee 7d c8 09 62 bd 49 3b 86 1c 36 4e cd ba 02 96
-86.876363 15285 send status fd 0, length 18

-86.805515 15314 free buffers event 0:2

-76.581760 19401 recv command fd 0, flags 0, length 2
-76.581468 19402 recv status fd 0, flags 1, length 2
-76.581273 19403 recv data length 2: 00 20

-76.579253 19406 recv command fd 0, flags 0, length 32
-76.578960 19407 recv status fd 0, flags 1, length 32
-76.578765 19408 recv data length 32: c2 2b 7c 11 73 6d 0f 5d 14 0a 48 19 8a e0 22 4b 1e ae a0 d2 f4 aa 14 cc 43 27 9c 46 1d 94 0c cf

-76.578055 19409 send data fd 0, flags 0, length 18: 10 d9 bd 33 2c 4e 41 d5 99 77 2e e6 fe 36 91 32 17
-76.577621 19410 send status fd 0, length 18

-76.577331 19411 send data fd 0, flags 0, length 18: 10 7c 16 eb b7 e9 2f 36 b4 32 1b 99 6b 42 52 54 3d
-76.576893 19412 send status fd 0, length 18

-76.501459 19443 free buffers event 0:2

-66.279918 23530 recv command fd 0, flags 0, length 2
-66.279626 23531 recv status fd 0, flags 1, length 2
-66.279431 23532 recv data length 2: 00 20

-66.278114 23535 recv command fd 0, flags 0, length 32
-66.277822 23536 recv status fd 0, flags 1, length 32
-66.277627 23537 recv data length 32: a1 8e 1e fd f8 72 5c 01 37 e0 17 f7 2f 2e 80 5c 01 9d c5 30 68 83 8e bd 54 60 e1 c7 3f 6c 67 7d

-66.276916 23538 send data fd 0, flags 0, length 18: 10 7f e8 50 38 76 a2 d6 f1 e2 81 4d a0 6a 71 cc 75
-66.276472 23539 send status fd 0, length 18

-66.276167 23540 send data fd 0, flags 0, length 18: 10 57 f4 d5 e7 25 32 06 a4 b9 09 3a f5 ca ec 98 1c
-66.275734 23541 send status fd 0, length 18

-66.194328 23574 free buffers event 0:2

-55.978687 27659 recv command fd 0, flags 0, length 2
-55.978394 27660 recv status fd 0, flags 1, length 2
-55.978196 27661 recv data length 2: 00 20

-55.976176 27664 recv command fd 0, flags 0, length 32
-55.975884 27665 recv status fd 0, flags 1, length 32
-55.975689 27666 recv data length 32: 6e f2 8a 56 9e 61 9a ac ce 9f 23 ac 3f 1b 02 30 fa 74 a8 85 a9 53 74 dc c5 21 6c 17 8a 5c 2f 13

-55.974978 27667 send data fd 0, flags 0, length 18: 10 f9 d2 8f e1 0d c7 72 df a2 b9 b9 36 87 8c 04 22
-55.974539 27668 send status fd 0, length 18

-55.974249 27669 send data fd 0, flags 0, length 18: 10 ed 10 58 bd 9a 94 c7 4f 79 4f 68 be ca 06 03 c4
-55.973811 27670 send status fd 0, length 18

-55.897788 27701 free buffers event 0:2

-45.686046 31784 recv command fd 0, flags 0, length 2
-45.685753 31785 recv status fd 0, flags 1, length 2
-45.685508 31786 recv data length 2: 00 20

-45.683360 31789 recv command fd 0, flags 0, length 32
-45.683067 31790 recv status fd 0, flags 1, length 32
-45.682870 31791 recv data length 32: a1 00 75 ff bb 53 cf e4 52 69 70 81 dd ff 50 da 52 5e 5c 4e 73 bb df 79 d6 97 0c 4f 24 29 2b 9d

-45.682161 31792 send data fd 0, flags 0, length 18: 10 94 7f 0a a9 f7 70 63 3d a1 59 9a f1 68 fa ad 7c
-45.681714 31793 send status fd 0, length 18

-45.681406 31794 send data fd 0, flags 0, length 18: 10 25 a6 a2 f8 69 a3 4c b7 9c 6c d2 b2 f4 17 3c 62
-45.680972 31795 send status fd 0, length 18

-45.609710 31824 free buffers event 0:2

-35.388151 35911 recv command fd 0, flags 0, length 2
-35.387858 35912 recv status fd 0, flags 1, length 2
-35.387660 35913 recv data length 2: 00 20

-35.386438 35916 recv command fd 0, flags 0, length 32
-35.386145 35917 recv status fd 0, flags 1, length 32
-35.385950 35918 recv data length 32: 51 30 49 45 ba c7 49 d7 33 e5 d8 49 ee 36 d5 3e f9 c5 50 9a 12 41 e3 b0 26 56 de f5 29 33 65 92

-35.385240 35919 send data fd 0, flags 0, length 18: 10 ea 9d 80 54 ad 15 eb 60 8e 37 00 12 ae 4c a2 02
-35.384806 35920 send status fd 0, length 18

-35.384513 35921 send data fd 0, flags 0, length 18: 10 cc 97 69 db d8 f6 e8 86 25 ce a5 64 81 55 a4 6d
-35.384079 35922 send status fd 0, length 18

-35.307887 35953 free buffers event 0:2

-25.020199 40068 recv command fd 0, flags 0, length 2
-25.019906 40069 recv status fd 0, flags 1, length 2
-25.019711 40070 recv data length 2: 00 20

-25.018222 40073 recv command fd 0, flags 0, length 32
-25.017929 40074 recv status fd 0, flags 1, length 32
-25.017734 40075 recv data length 32: 09 99 a0 d6 1f cb 73 dd ce d6 81 a4 d2 f5 94 81 91 55 dc dc c7 1f 6b 2c ba 19 9b 24 32 b5 56 33

-25.017027 40076 send data fd 0, flags 0, length 18: 10 2d 39 7d 7f 0b a2 6f 4f 1e ed d0 1f 26 84 66 9f
-25.016593 40077 send status fd 0, length 18

-25.016288 40078 send data fd 0, flags 0, length 18: 10 35 e0 82 1a d9 ab 83 84 83 9e 01 3c b5 7d 2e 3d
-25.015848 40079 send status fd 0, length 18

-22.826121 40954 free buffers event 0:1

-10.007866 46079 send data fd 0, flags 0, length 18: 10 60 08 11 dc c5 a5 b6 96 4b 79 2a 2b 72 cc 1d 4a
-10.007432 46080 send status fd 0, length 18

-8.119392 46835 free buffers event 0:1

+0.100042 50082 Write opcode 2005
+0.100042 50082: 0x01 0x00 0x05 0x00 0x00 0x01 0x05 0x20 0x00 0x01
               : 0x02 0x00 0xff 0x00 0x00 0x00 0x00 0x00 0x00 0x00

+0.100379 50083 Read Event 2005
+0.100379 50083: 0x03 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x0c 0x03 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x0c 0x01 0x40 0x00 0x0c 0x01 0x40 0x00 0x0c 0x01 0x40 0x00 0x0c 0x01 0x40 0x00 0x0c 0x01 0x40 0x00 0x08 0x01 0x40 0x00 0x08 0x01 0x40 0x00 0x08 0x01 0x40 0x00 0x08 0x01 0x40 0x00 0x08 0x01 0x40 0x00 0x08 0x01 0x40 0x00 0x08 0x01 0x40 0x0c 0x00 0x48 0x00
               : 0x02 0x00 0x00 0x00 0x41 0x04 0x05 0x20 0x3d 0x00 0xb3 0x79 0xa8 0xc0 0x00 0xff 0xff 0xff 0x01 0x79 0xa8 0xc0 0x01 0x79 0xa8 0xc0 0x01 0x79 0xa8 0xc0 0x55 0x55 0x55 0x55 0x12 0x00 0x48 0x6f 0x6d 0x65 0x31 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00

+0.100929 50084 Write opcode 100b
+0.100929 50084: 0x01 0x00 0x09 0x00 0x00 0x01 0x0b 0x10 0x04 0x00 0x00 0x00 0x00 0x14
               : 0x02 0x00 0xff 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00

+3.703064 50085 Read Event 100b
+3.703064 50085: 0x03 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x0c 0x03 0x00 0x00 0x00
               : 0x02 0x00 0x00 0x00 0x09 0x04 0x0b 0x10 0x05 0x00 0x00 0x00 0x00 0x00

+3.703207 50086 Write opcode 1001
+3.703207 50086: 0x01 0x00 0x11 0x00 0x00 0x01 0x01 0x10 0x0c 0x02 0x00 0x00 0x00 0x01 0x00 0x00 0x00 0x06 0x00 0x00 0x00 0x14
               : 0x02 0x00 0xff 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00

+3.703597 50087 Read Event 1001
+3.703597 50087: 0x03 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x0c 0x03 0x00 0x00 0x00 0x01 0x00 0x19 0x00 0x00 0x01 0x07 0x10 0x14 0x00 0x00 0x00 0x00 0x08 0x00 0x00 0x00 0x08 0x00 0x00 0x00 0x02 0x00 0x16 0x33 0x36 0xd0 0xe5 0x04 0x00
               : 0x02 0x00 0x00 0x00 0x09 0x04 0x01 0x10 0x05 0x00 0x00 0x00 0x00 0x00 0x02 0x00 0xff 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00

Fullscreen 2158.spi10.log Download 
-117.827759  2868 select status 0001, rd 0001, wr 0000, ex 0000

-117.827523  2869 recv command fd 0, flags 0, length 2
-117.827230  2870 recv status fd 0, flags 1, length 2
-117.827035  2871 recv data length 2: 00 20

-117.825239  2873 select status 0001, rd 0001, wr 0000, ex 0000

-117.825010  2874 recv command fd 0, flags 0, length 32
-117.824717  2875 recv status fd 0, flags 1, length 32
-117.824522  2876 recv data length 32: b2 76 8b 94 05 49 65 11 c1 df 89 6a 29 5d c9 6d 9f 61 58 24 43 ea ab 49 39 67 b6 aa 82 c8 26 ec

-117.823815  2877 send data fd 0, flags 0, length 18: 00 10 e5 1d e6 81 10 a7 9b 7f a3 4b 74 b0 6f 01 eb 1c
-117.823367  2878 send status fd 0, length 18

-117.823062  2879 send data fd 0, flags 0, length 18: 00 10 fb ce 5e a2 da f7 7d a8 80 19 9d 7f b9 81 5d 5c
-117.822626  2880 send status fd 0, length 18

-117.757335  2907 free buffers event 0:2

-107.403302  7047 select status 0001, rd 0001, wr 0000, ex 0000

-107.403072  7048 recv command fd 0, flags 0, length 2
-107.402780  7049 recv status fd 0, flags 1, length 2
-107.402584  7050 recv data length 2: 00 20

-107.400789  7052 select status 0001, rd 0001, wr 0000, ex 0000

-107.400559  7053 recv command fd 0, flags 0, length 32
-107.400267  7054 recv status fd 0, flags 1, length 32
-107.400072  7055 recv data length 32: 48 91 49 e7 15 f8 ac 0a fe 84 b1 6f 78 33 a8 62 54 f0 0b fd 92 9b 1b c1 1d 25 a3 0f 86 68 d4 c5

-107.399361  7056 send data fd 0, flags 0, length 18: 00 10 59 91 1e 1a 01 5a d0 a0 f5 75 b0 fb 86 76 cc aa
-107.398927  7057 send status fd 0, length 18

-107.398634  7058 send data fd 0, flags 0, length 18: 00 10 a2 d0 03 9a b2 61 96 10 e1 01 eb bb 97 a6 0e 48
-107.398185  7059 send status fd 0, length 18

-107.326920  7088 free buffers event 0:2

 -97.206471 11134 select status 0001, rd 0001, wr 0000, ex 0000

 -97.206242 11135 recv command fd 0, flags 0, length 2
 -97.205949 11136 recv status fd 0, flags 1, length 2
 -97.205754 11137 recv data length 2: 00 20

 -97.203767 11139 select status 0001, rd 0001, wr 0000, ex 0000

 -97.203538 11140 recv command fd 0, flags 0, length 32
 -97.203245 11141 recv status fd 0, flags 1, length 32
 -97.203047 11142 recv data length 32: 09 d2 59 52 de 40 5d e4 31 50 db 35 83 df 6b 01 90 97 c6 de 7f 75 55 49 df ca fd 95 cd b3 13 1a

 -97.202340 11143 send data fd 0, flags 0, length 18: 00 10 ba 83 27 a8 ce fe e2 cb 68 93 4b 9e fe 63 de 21
 -97.201906 11144 send status fd 0, length 18

 -97.201601 11145 send data fd 0, flags 0, length 18: 00 10 39 d2 22 81 36 42 a9 ae 70 c6 4c f1 6a 64 ef 5a
 -97.201165 11146 send status fd 0, length 18

 -97.130130 11175 free buffers event 0:2

 -86.924890 15255 select status 0001, rd 0001, wr 0000, ex 0000

 -86.924661 15256 recv command fd 0, flags 0, length 2
 -86.924368 15257 recv status fd 0, flags 1, length 2
 -86.924173 15258 recv data length 2: 00 20

 -86.922186 15260 select status 0001, rd 0001, wr 0000, ex 0000

 -86.921957 15261 recv command fd 0, flags 0, length 32
 -86.921664 15262 recv status fd 0, flags 1, length 32
 -86.921466 15263 recv data length 32: 25 f8 80 d5 fa 50 44 fd 33 42 74 a5 72 66 c5 3b f4 f2 a1 6f d7 46 78 8d 1b f1 bd ce 53 fb f4 eb

 -86.920759 15264 send data fd 0, flags 0, length 18: 00 10 ad bb 07 f5 41 cb a3 77 31 ac c4 92 a0 68 d0 62
 -86.920314 15265 send status fd 0, length 18

 -86.920024 15266 send data fd 0, flags 0, length 18: 00 10 07 3a 88 5c 6e b1 b8 fd 52 46 c3 61 40 65 7a 96
 -86.919572 15267 send status fd 0, length 18

 -86.848317 15296 free buffers event 0:2

 -76.634777 19380 select status 0001, rd 0001, wr 0000, ex 0000

 -76.634544 19381 recv command fd 0, flags 0, length 2
 -76.634251 19382 recv status fd 0, flags 1, length 2
 -76.634056 19383 recv data length 2: 00 20

 -76.632264 19385 select status 0001, rd 0001, wr 0000, ex 0000

 -76.632035 19386 recv command fd 0, flags 0, length 32
 -76.631742 19387 recv status fd 0, flags 1, length 32
 -76.631547 19388 recv data length 32: eb 75 bc a7 c1 e4 e2 f8 a8 c8 63 f8 7d 0a 15 4a 87 94 64 4f f4 72 6f 0e e5 44 89 bd 1e f2 f8 d1

 -76.630840 19389 send data fd 0, flags 0, length 18: 00 10 32 44 d2 c2 eb 8f 62 4b 4e dd 21 e9 36 23 8e e5
 -76.630404 19390 send status fd 0, length 18

 -76.630099 19391 send data fd 0, flags 0, length 18: 00 10 d0 23 a0 ca fa 9e e7 42 32 6a 6c bd 3c f8 25 e3
 -76.629662 19392 send status fd 0, length 18

 -76.563257 19419 free buffers event 0:2

 -66.353038 23501 select status 0001, rd 0001, wr 0000, ex 0000

 -66.352806 23502 recv command fd 0, flags 0, length 2
 -66.352513 23503 recv status fd 0, flags 1, length 2
 -66.352318 23504 recv data length 2: 00 20

 -66.350526 23506 select status 0001, rd 0001, wr 0000, ex 0000

 -66.350296 23507 recv command fd 0, flags 0, length 32
 -66.350003 23508 recv status fd 0, flags 1, length 32
 -66.349808 23509 recv data length 32: 44 3d 62 2e 12 4b 52 42 2c 24 88 a7 bc 6a 97 14 3e e0 b2 14 8a db 95 7f 31 9b da 31 38 35 4d bb

 -66.349101 23510 send data fd 0, flags 0, length 18: 00 10 6b 81 70 14 31 19 a9 d9 62 bf 9c 49 3f b1 df 30
 -66.348665 23511 send status fd 0, length 18

 -66.348375 23512 send data fd 0, flags 0, length 18: 00 10 6c b5 aa 6d bf 53 0b be 8c ab ba 3e 2b dd d7 ba
 -66.347924 23513 send status fd 0, length 18

 -66.277171 23542 free buffers event 0:2

 -55.996517 27652 select status 0001, rd 0001, wr 0000, ex 0000

 -55.996288 27653 recv command fd 0, flags 0, length 2
 -55.995995 27654 recv status fd 0, flags 1, length 2
 -55.995800 27655 recv data length 2: 00 20

 -55.993814 27657 select status 0001, rd 0001, wr 0000, ex 0000

 -55.993584 27658 recv command fd 0, flags 0, length 32
 -55.993291 27659 recv status fd 0, flags 1, length 32
 -55.993093 27660 recv data length 32: 2d 38 f7 e8 3a c7 3e 39 7a c8 6c 3c 23 c5 33 55 ab bf a3 66 cf 02 52 3d 15 33 16 f0 fd d0 59 ac

 -55.992386 27661 send data fd 0, flags 0, length 18: 00 10 3b bf 0e b6 6b 56 cf dd 4f 35 d6 f7 ad 3f 8b 57
 -55.991949 27662 send status fd 0, length 18

 -55.991644 27663 send data fd 0, flags 0, length 18: 00 10 28 1b 2f 5e bb d7 6f 79 bb 8b ec fb 8e 96 13 b9
 -55.991207 27664 send status fd 0, length 18

 -55.910301 27697 free buffers event 0:2

 -45.489057 31863 select status 0001, rd 0001, wr 0000, ex 0000

 -45.488828 31864 recv command fd 0, flags 0, length 2
 -45.488534 31865 recv status fd 0, flags 1, length 2
 -45.488336 31866 recv data length 2: 00 20

 -45.487352 31868 select status 0001, rd 0001, wr 0000, ex 0000

 -45.487122 31869 recv command fd 0, flags 0, length 32
 -45.486820 31870 recv status fd 0, flags 1, length 32
 -45.486625 31871 recv data length 32: 41 5a c3 d3 e4 d3 4c 2f 36 95 d4 0d 3f 1e 3e 5b 34 c1 82 f6 c5 f0 78 3f ef 51 59 19 bb 18 7a ab

 -45.485915 31872 send data fd 0, flags 0, length 18: 00 10 f4 93 56 73 c6 17 86 aa 83 73 32 2b 4e 13 31 d9
 -45.485480 31873 send status fd 0, length 18

 -45.485186 31874 send data fd 0, flags 0, length 18: 00 10 ad 4e f5 3e 30 af e8 a0 24 17 98 5c 92 90 42 3e
 -45.484738 31875 send status fd 0, length 18

 -45.418366 31902 free buffers event 0:2

 -35.310810 35944 select status 0001, rd 0001, wr 0000, ex 0000

 -35.310578 35945 recv command fd 0, flags 0, length 2
 -35.310285 35946 recv status fd 0, flags 1, length 2
 -35.310090 35947 recv data length 2: 00 20

 -35.308298 35949 select status 0001, rd 0001, wr 0000, ex 0000

 -35.308068 35950 recv command fd 0, flags 0, length 32
 -35.307776 35951 recv status fd 0, flags 1, length 32
 -35.307578 35952 recv data length 32: 64 c4 60 94 15 61 fa 08 21 94 aa c9 58 8b 1e 04 9b 26 a6 52 59 10 d6 fb 1f a3 b3 ce de 40 ad bb

 -35.306870 35953 send data fd 0, flags 0, length 18: 00 10 5a b5 43 a9 f7 e5 c1 7e d7 c1 27 5a c5 80 00 7d
 -35.306437 35954 send status fd 0, length 18

 -35.306132 35955 send data fd 0, flags 0, length 18: 00 10 11 0a 95 53 f9 dc 99 a4 89 64 84 90 8d 79 96 d9
 -35.305695 35956 send status fd 0, length 18

 -35.235179 35985 free buffers event 0:2

 -25.020645 40067 select status 0001, rd 0001, wr 0000, ex 0000

 -25.020416 40068 recv command fd 0, flags 0, length 2
 -25.020123 40069 recv status fd 0, flags 1, length 2
 -25.019924 40070 recv data length 2: 00 20

 -25.018674 40072 select status 0001, rd 0001, wr 0000, ex 0000

 -25.018445 40073 recv command fd 0, flags 0, length 32
 -25.018150 40074 recv status fd 0, flags 1, length 32
 -25.017951 40075 recv data length 32: 0e 53 bb d9 0a 66 f2 62 5c 76 e2 4e 2e f4 35 c6 44 29 b5 28 9c df d9 8f d0 b2 e0 82 b9 5b d8 db

 -25.017244 40076 send data fd 0, flags 0, length 18: 00 10 43 ad 33 5e 9a b3 98 43 82 60 6f ff ad c9 25 ba
 -25.016811 40077 send status fd 0, length 18

 -25.016520 40078 send data fd 0, flags 0, length 18: 00 10 9a b3 c9 55 89 13 7a 17 2a f0 d1 85 36 51 29 a3
 -25.016081 40079 send status fd 0, length 18

 -22.857388 40942 free buffers event 0:1

 -10.007862 46079 send data fd 0, flags 0, length 18: 00 10 9e 25 18 1a 4d 64 75 63 ca 23 a3 c5 64 df e4 39
 -10.007428 46080 send status fd 0, length 18

  -8.149413 46823 free buffers event 0:1

  +0.100034 50082 ipconfig command
  +0.100367 50083 ipconfig status: 192.168.121.179 255.255.255.0 192.168.121.1 192.168.121.1 192.168.121.1 00:12:55:55:55:55 Home1

  +0.100917 50084 close command fd 0
  +3.703081 50085 close status 0

  +3.703224 50086 socket command domain 2, type 1, protocol 6
  +3.703610 50087 socket status 0

https://community.sparkdevices.com/t/bug-bounty-kill-the-cyan-flash-of-death/1322

Any ideas for either why send() would fail, why subsequent connect() calls would fail, or both? Any information on the meaning behind free_buffers_event and its relation to all of this?

Many thanks,
Zach

  • 0
    TI__Mastermind 18455 points

    Hi Zach,

    Can you please describe a bit on your HW environment? which MCU is being used?
    In addition please try to capture CC3000 logs of the problematic scenario, you can check our wiki for how it is done: http://processors.wiki.ti.com/index.php/CC3000_Logger

    In addition, before starting to capture the debug trace please run the following command: netapp_set_debug_level(ox3ff);

    Thanks,
    Alon

  • 0 in reply to Alon Srednizki
    Prodigy 60 points

    The MCU is an STM32. Schematic is here:

    core-schematic-v1.pdf

    We cannot capture these logs, as the debug pins are not exposed on our hardware.

    I provided quite a bit of information in my previous post, can you please provide some feedback based on the information I sent?

  • 0 in reply to Alon Srednizki
    Intellectual 310 points

    I'm working with Zach on this - we have reworked a board to expose the debug pads.

    Do you want driver logs, firmware logs  (pin 2 or pin 4), or both (will need to be separate test runs.)

  • 0 in reply to Andy Warner
    Intellectual 310 points

    That question kinda answered itself, I don't actually see any output on pin 4, but I see plenty of chatter on pin 2.

    This error can take hours to reproduce, I'm generating about 76KBytes of log every minute.

    How much data around the failure do you need me to upload as a starting point ?

  • 0 in reply to Andy Warner
    Intellectual 310 points

    OK - attached is a zip file containing: the pin 2 debug stream and the matching tcpdump.

    The debug log continues for many hours after the failure occurs, I can't pinpoint exactly when, but the fist hour or so of the debug file should be a normal usage pattern. As I mentioned, the failure can take hours to happen and in this case it occurred overnight.

    I can tell you that approx 25 secs after the failure, the following command sequence occurs on the SPI bus:

    +0.100058 9993 ipconfig command
    +0.100406 9994 ipconfig status: 192.168.121.177 255.255.255.0 192.168.121.1 192.168.121.1 192.168.121.1 08:00:28:58:e7:72 Home1
    +0.100956 9995 close command fd 0
    +3.703078 9996 close status 0
    +3.703221 9997 socket command domain 2, type 1, protocol 6
    +3.703624 9998 socket status 0

    So if you can locate this sequence, the CC3000 went mute approx 25 seconds earlier.

    Questions/problems -> me.

    4667.20130125-3.zip

  • 0 in reply to Andy Warner
    Genius 4895 points

    Hello Andy, hello Zach,

    I am not from TI, but just had a quick look into the pcap file: When scrolling fast down with the mouse, there are almost no error frames in the beginning. Seldom there is one or two lines with an error.

    But then around frame 16170 (timestamp 897) there are a lot of errors.

    Interesting: Just before a TI MAC address (which I assume it is CC3000) is doing an ARP request for address 192.168.121.1. After this I see ~ 4 error frames (black-red-marked frames) per page.

    At frame 18087 (timestamp 3324) there is again the ARP request (which is 2427 seconds after the last one).

    Then in frame 18111 (timestamp 3355) again (only 30 seconds after last one). And still a lot error frames till the end.

    Can you describe a bit more what IP devices are used, which addresses they use, and what data the exchange (e.g. data transfer from x to y every 10 seconds, or every random seconds. Only one or more connection? You wrote above that you send a heartbeat. Have you checked if you see the heartbeat regularly? Do you see it around the problem point in pcap I have mentioned above?

    When I startup my CC3000, I see "0B 56 00" and "0B 55 00". I have not found these both sequences in your debug pin logfile. I assume this is ok, because startup was not recorded? Because I don't see them I assume the CC3000 was not reset by host or reseted itself. Can you do a quick check just to be sure your logfile and recording mechanism is ok, if you also can see the two byte sequences when you startup your CC3000?

    BTW: But I saw some "HOME" / "home" and "Open" in logfile, so I assume in general your logfile is ok. Are these SSIDs in your environment?

    Only TI can decode the logfile and can give details what is wrong. There is unfortunately no public decoder for the logfile.

    Best regards,

    Martin

  • 0 in reply to Marie Maurer
    Intellectual 310 points

    Indeed, the logfile does not capture the startup.

    "Home1" is the SSID of the AP this unit is connected to.

    I'll let Zach describe the setup, but this unit is connected to some cloud services of Spark's invention (http://spark.io), all the data xfer is encrypted, but you can see the predictable pattern of packets in the happy state in the tcpdump.

    There are occasional flurries of errors and recoveries, and while eventually I would like to get to the bottom of those too, there is a massive showstopper bug here where the CC3000 goes mute on it's radio side. If it went deaf, I'd expect to see it trying to maintain the TCP connection, but the fact that the cloud keeps trying and there is not a single reply from the CC3000 suggests to me that the radio side of the module has gone AWOL. Our SPI traces show that the host-side interface is still functioning, although nothing useful actually gets accomplished.

    Another trace is attached, this one should include the startup sequence (and yeah, I know I was still calling the files 2013xxx, that's fixed here..)

    8867.20140126-1.zip

  • 0 in reply to Andy Warner
    Intellectual 310 points

    Here is another failure package, with both tcpdump and debug log. Both should be from reset to failure.

    6644.20140126-2.zip

  • 0 in reply to Andy Warner
    Intellectual 310 points

    I can clarify what the firmware talking to the CC3000 does after startup - it issues selects on a single read file descriptor, with the min timeout. The read data consists of a single packet (length 2) with the length of the following packet encoded in it (in our case almost always 32 bytes) - the firmware reads the second packet (32 bytes, and responds with two 18 byte packets (again, each is a 2 byte header indicating and followed by a 16-byte payload.)

    Then it goes back to select()ing looking for more traffic from the cloud.

    That pattern is repeated with assorted delays inserted by the cloud side until failure.

  • 0 in reply to Andy Warner
    Genius 4895 points

    Hi Andy,

    also in second pcap file (20140126-2.pcap) in frame 3598 there is the ARP request.

    General question (not sure if it is related to error): Why does CC3000 want to communicate with 192.168.121.1? Before it already has exchanged data with 54.208.229.4 (which also goes via same MAC address), and after ARP reply it does NOT exchange data with 192.168.121.1...

    Best regards,

    Martin

  • 0 in reply to Andy Warner
    Intellectual 310 points

    And another pair of files. Again, should be from reset to beyond failure.

    6064.20140126-3.zip

    Comments/Questions -> me.

  • 0 in reply to Marie Maurer
    Intellectual 310 points

    192.168.121.1 is the default gateway.

    That's my firewall/NAT box, so it is the next hop that the CC3000 needs to talk to in order to talk to the internet.

  • 0 in reply to Andy Warner
    TI__Mastermind 27095 points

    Hi Andy,

    Can you please check if you are calling 'netapp_arp_flush' anywhere? Just try by avoiding a call to that API. And I would also suggest you to try with a call to the API 'netapp_timeout_values', with 'aucARP' set to 0. Let us rule out any such possibilities due to ARP.

    With respect to the logs, thank you for providing the logs. But they seem to be corrupted. Can you please add the line 'netapp_set_debug_level(0x1FF) ' everytime after you call 'wlan_start()'? This will give out maximum debugs. Thanks.

    Thanks & Regards,

    Raghavendra

  • 0 in reply to Raghavendra Shenoy
    Intellectual 310 points

    1. The firmware never calls netapp_arp_flush()

    2. I will retest with aucARP = 0. However: tcpdumps show that the failure does not correlate strongly with ARP activity.

    3. How large is the arp cache in the CC3000 ?

    4. Here are the other timeout settings in use: DHCP = 14400, Keepalive = 10, Inactivity = 60

    5. I was running with debug_level == 0x3ff as requested earlier, I will modify to 0x1ff.

    6. Can you describe the type of corruption in the logfiles ? Does it look like:

      - baud rate problems (using a crystal-less FTDI chip, so clock accuracy at high speeds might be so-so)?

      - buffer overruns ?

      - noise (picked bits, this is a reworked fixture) ?

      - non-binary ?

      - are all my logfiles corrupted the same way ?

      Help me out with more info so I can try and eradicate the corruption in the logfiles, and give you the data you need.

     7. Do you have known problems with ARP that make you suggest this route ?

    I will rebuild, retest and report back.

  • 0 in reply to Andy Warner
    Genius 4895 points

    Hello Andy,

    have you taken into account, that the voltage level on the debug pins is 1.8V. Do you use a USB <-> serial converter which has 1.8V voltage level. I can suggest, the TTL-232RG-VREG1V8-WE from FTDI (around 20 Euro), which works on my side. As written above I see "0B 56 00" and "0B 55 00". I would assume your trace is not completely wrong, because I have seen the SSID, but perhaps too much bits are wrong to be able to decode the trace.

    The other point is why you don't see something on the other debug pin. Have you had a look with an oscilloskop, if there is a changing signal and your USB <-> serial converter can only not detect/record the signal?

    Best regards,

    Martin

  • 0 in reply to Marie Maurer
    Intellectual 310 points

    I'm using the FTDI 232RL, which claims v(in)H of ~1.1-1.2V, so it should be working with 1.8V logic.

    I can perform further butchery to find a way to drive V(io) off the 1.8V line on the CC3000, but without knowing what the corruption is, it's hard to know what to fix.

    Yes - I've hung a scope off Pin 4, and do not see any chit-chat on that line, it is steady @ 1,.8V

  • 0 in reply to Raghavendra Shenoy
    Intellectual 310 points

    Setting the arp timeout to zero does not change the failure mode.

    In the absence of any other info, I'll work on the theory that the FTDI 232RL chip isn't doing a good job of reading the 1.8V levels coming out of the CC3000, and find a solution to that problem before submitting any more debug logs.

  • 0 in reply to Andy Warner
    TI__Mastermind 27095 points

    Hi Andy,

    Thanks for the clarification.

    The setting of 'aucARP=0' was just to streamline our observation. Currently there are no known issues, but there was an ARP issue fixed in the previous release. Thanks for your observation after testing it with aucARP=0.

    With respect to the logs, not all parts are corrupt. But most of it does not make meaningful reading, failing to parse. As i have mentioned above, make call to netapp_set_debug_level API everytime after you call wlan_start().

    Thanks & Regards,

    Raghavendra

  • 0 in reply to Raghavendra Shenoy
    Intellectual 310 points

    OK - we are currently assuming that the 232RL is not working reliably with the 1.8V logic input, and adding a level converting buffer to the test fixture. Will upload more logs when we have them.

    Raghavendra, should we also be seeing traffic on pin 4, or is the steady 1.8V there expected ?

  • 0 in reply to Andy Warner
    Intellectual 310 points

    OK - let's try the attached file.

    This has V(io) on the FT232RL set to 1.8V, please inspect and let me know if it is good or still mangled.

    8838.20140128-1.zip

  • 0 in reply to Andy Warner
    Prodigy 60 points

    Any response from TI on this? Would be very helpful to get a review of the logs from Andy's most recent post, above.

  • 0 in reply to Zach Supalla
    TI__Mastermind 27095 points

    Hi Zach, Andy,

    Unfortunately, the logs are not good. They fail to parse. Till we get the correct logs, let us proceed with the debug. Can you please tell me when the error occurs, do you always see 'free_buffers_event' returning 0? What is the initial value, when you start testing it?

    Thanks & Regards,

    Raghavendra

  • 0 in reply to Raghavendra Shenoy
    Intellectual 310 points

    OK - I will continue to work on the debug mechanism.

    Another poster reported that the sequence "0b 55 00" and "0b 56 00" should appear in good logs, can you confirm this, so I can iterate on the debug mechanism until I see these at the start of a debug log ?

    I never see an event saying there are zero buffers.

    The number varies between 1 and 6. During most of the stable operation, it is 2.

    The app only has 1 socket open in the steady state.

  • 0 in reply to Andy Warner
    Intellectual 310 points

    Can you (or anyone else reading) recommend a level translator that is known to work with the FT232RL and has produced successful logs.

    Alternatively, any alternative to the FT232RL that is known to work ?

  • 0 in reply to Andy Warner
    TI__Mastermind 27095 points

    Hi Andy,

    It has to be at the 1.8V level. Are you pulling the data from NS_UART_DBG? Let us get only the driver logs first. The log 6064.20140126-3.zip was better than the log sent yesterday.

    Also, can you please confirm on the 'free_buffers_event'?

    Thanks & Regards,

    Raghavendra

  • 0 in reply to Raghavendra Shenoy
    Intellectual 310 points

    we are pulling this data from Pin 2.

    I'll repeat - we see no activity on Pin 4.

    I get the 1.8V, just asking for known good configs to deliver the debug info. Currently looking at 74AVCH2T45 to front the FT232RL. However, as far as I can tell, the CC3000 does not make the 1.8V rail available externally, so I have been adding an external 1.8V regulator to supply the low side of the level translator.

    Free buffers (from my previous reply):

       I never see an event saying there are zero buffers.

       The number varies between 1 and 6. During most of the stable operation, it is 2.

       The app only has 1 socket open in the steady state.

  • 0 in reply to Andy Warner
    Genius 4895 points

    Hi Andy,

    have you read the last message on page 1 of this thread?

    There is a cable, ready to use, which is also suggested on Wiki pages of TI.

    No need for long thinking over a few days, just buying this cable (20 Euro, I don't know exact exchange rate, around US$ 20) and using it. I am almost sure you get it, independent where you work.

    Have you checked if bad soldering could be a problem on pin 4 or do you directly measure with your scope on the pin of CC3000?

    Best regards,

    Martin

  • 0 in reply to Marie Maurer
    Intellectual 310 points

    Missed that - thx for the reminder. Just ordered 2 from Digikey. Will have them tomorrow (snow permitting.)

  • 0 in reply to Andy Warner
    Genius 4895 points

    Small hints:

    http://processors.wiki.ti.com/index.php/CC3000_Radio_Tool

    See cable colors on bottom of this page.

    But pay attention: Left and right side has different numbers and don't match in sequence!

    You need only the black and yellow cable. Black to GND and yellow to debug pin.

    Then you need the following page:

    http://processors.wiki.ti.com/index.php/CC3000_Logger

  • 0 in reply to Marie Maurer
    Intellectual 310 points

    Got it - thanks. We have the right cable, and we are generating debug logs from both pins 2 & 4.

    I'm waiting for confirmation from TI that these are not corrupt, before I celebrate too much.

    I still don't see "0b 55 .." or "0b 56 .." in either data stream, as  you said was likely.

    I'll send an update as soon as I learn if my debug logs are any good or not.

    Thanks again for the suggestions.

  • 0 in reply to Andy Warner
    Genius 4895 points

    Hi Andy,

    can you upload the traces here to the thread?

    I see the sequence during startup of the module. Perhaps you must keep reset of your host hold, start tracing on debug pins and then release reset? Or some kind of debugger break or key press before module is started.

    You can also try to query for patch version. Have a look if you get a data packet on debug pin, which looks (at least for some point) unique.

    Best regards,

    Martin

  • 0 in reply to Marie Maurer
    Intellectual 310 points

    OK - try these for size.

    Two separate test runs:

    6064.20140201-1.zip - Pin 4 output & pcap

    3343.20140202-3.zip - Pin 2 output & pcap

  • 0 in reply to Andy Warner
    Intellectual 310 points

    OK - brief update to catch up with some off-forum activity.

    We are now generating known good debug dumps for TI, preliminary analysis of these shows some unexpected and unexplained ARP activity at the time of failure. Further analysis is underway.

  • 0 in reply to Andy Warner
    Guru 21435 points

    Thanks Andy!

    I really appreciate the update. A few of us are watching and waiting to see what the outcome will be.

    Glenn.