• State Not Answered
  • Replies 13 replies
  • Subscribers 74 subscribers
  • Views 4685 views
  • Users 0 members are here
Attachments (2) Download All
Nordic Case Info
  • Case ID: 215234
Options
This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

CPS/SEN/SPE/BI-04-C [Procedure Already In Progress] inconc

Kiyoshi Iwai

Hello ,

The test of CPS/SEN/SPE/BI-04-C [Procedure Already In Progress]  failed. 

While this test, the tester sometimes received the unexpected ATT Disconnect which our product might send.

Could you tell me how to stop the ATT Disconnect?

The test-log

Fullscreen test_log_CPS_SEN_SPE_BI-04-C.txt Download 
  +0 ms
  Initialize Test Case: Build date: Jul 18 2018, 09:31:58

  +0 ms
  Start Test Case: CPS/SEN/SPE/BI-04-C

  +0 ms
  Message: PTS Log started on Tuesday, October 02, 2018, 16:34:18

  +0 ms
  Message: PTS: v7.3.0 Build 40

  +0 ms
  Message: OS: Microsoft Windows NT 6.1.7601 Service Pack 1

  +0 ms
  Message: OS Name: Microsoft Windows 7 Home Premium

  +4009 ms
  Preliminary Verdict: PASS

  +4056 ms
  Send Event: HCI!HCI_RESET

  +4180 ms
  Receive Event: HCI?HCI_RESET_COMPLETE_EVENT{
  status=HCI_OK
  }

  +4180 ms
  Preliminary Verdict: PASS

  +4180 ms
  Send Event: HCI!HCI_SET_EVENT_MASK{
  eventMask=0x3FFFFFFFFFFFFFFF
  }

  +4180 ms
  Receive Event: HCI?HCI_SET_EVENT_MASK_COMPLETE_EVENT{
  status=HCI_OK
  }

  +4180 ms
  Preliminary Verdict: PASS

  +4180 ms
  Send Event: HCI!HCI_READ_LOCAL_VERSION_INFORMATION

  +4180 ms
  Receive Event: HCI?HCI_READ_LOCAL_VERSION_INFORMATION_COMPLETE_EVENT{
  status=HCI_OK,
  hciVersion=HCI_VERSION_4_0,
  hciRevision=0x2031,
  lmpVersion=0x06,
  manufacturerName=0x000A,
  lmpSubversion=0x2031
  } 

  +4180 ms
  Preliminary Verdict: PASS

  +4180 ms
  Send Event: HCI!HCI_READ_BD_ADDR

  +4196 ms
  Receive Event: HCI?HCI_READ_BD_ADDR_COMPLETE_EVENT{
  status=HCI_OK,
  bdAddress=0x001BDC0808A3
  }

  +4196 ms
  Preliminary Verdict: PASS

  +4196 ms
  Send Event: HCI!HCI_LE_SET_EVENT_MASK{
  leEventMask=0x000000000000001F
  }

  +4196 ms
  Receive Event: HCI?HCI_LE_SET_EVENT_MASK_COMPLETE_EVENT{
  status=HCI_OK
  }

  +4196 ms
  Preliminary Verdict: PASS

  +4196 ms
  Send Event: HCI!HCI_WRITE_LE_HOST_SUPPORTED{
  leSupportedHost=HCI_LE_SUPPORTED_HOST_ENABLED,
  simultaneousLeHost=HCI_SIMULTANEOUS_LE_HOST_ENABLED
  }

  +4196 ms
  Receive Event: HCI?HCI_WRITE_LE_HOST_SUPPORTED_COMPLETE_EVENT{
  status=HCI_OK
  }

  +4196 ms
  Preliminary Verdict: PASS

  +4196 ms
  Send Event: HCI!HCI_LE_CLEAR_WHITE_LIST

  +4196 ms
  Receive Event: HCI?HCI_LE_CLEAR_WHITE_LIST_COMPLETE_EVENT{
  status=HCI_OK
  }

  +4196 ms
  Preliminary Verdict: PASS

  +4196 ms
  Send Event: HCI!HCI_WRITE_SIMPLE_PAIRING_MODE{
  simplePairingMode=HCI_SIMPLE_PAIRING_ENABLED
  }

  +4212 ms
  Receive Event: HCI?HCI_WRITE_SIMPLE_PAIRING_MODE_COMPLETE_EVENT{
  status=HCI_OK
  }

  +4212 ms
  Preliminary Verdict: PASS

 +4212 ms
  Preliminary Verdict: PASS

  +4212 ms
  Send Event: HCI!HCI_LE_ADD_DEVICE_TO_WHITE_LIST{
  addressType=HCI_LE_PUBLIC_DEVICE_ADDRESS,
  address=0xC58DCE70012F
  }

  +4212 ms
  Receive Event: HCI?HCI_LE_ADD_DEVICE_TO_WHITE_LIST_COMPLETE_EVENT{
  status=HCI_OK
  }

  +4212 ms
  Preliminary Verdict: PASS

  +4212 ms
  Send Event: HCI!HCI_LE_ADD_DEVICE_TO_WHITE_LIST{
  addressType=HCI_LE_RANDOM_DEVICE_ADDRESS,
  address=0xC58DCE70012F
  }

  +4212 ms
  Receive Event: HCI?HCI_LE_ADD_DEVICE_TO_WHITE_LIST_COMPLETE_EVENT{
  status=HCI_OK
  }

  +4212 ms
  Preliminary Verdict: PASS

  +4212 ms
  Preliminary Verdict: PASS

  +4212 ms
  Preliminary Verdict: PASS

  +4212 ms
  Send Event: HCI!HCI_LE_SET_SCAN_PARAMETERS{
  leScanType=HCI_LE_ACTIVE_SCANNING,
  leScanInterval=0x001E,
  leScanWindow=0x001E,
  ownAddressType=HCI_LE_PUBLIC_DEVICE_ADDRESS,
  scanningFilterPolicy=HCI_LE_ACCEPT_WHITE_LIST_ADVERTISING_PACKETS
  }

  +4212 ms
  Receive Event: HCI?HCI_LE_SET_SCAN_PARAMETERS_COMPLETE_EVENT{
  status=HCI_OK
  }

  +4212 ms
  Preliminary Verdict: PASS

  +4227 ms
  Send Event: HCI!HCI_LE_SET_SCAN_ENABLE{
  leScanEnable=HCI_LE_SCAN_ENABLE,
  filterDuplicates=HCI_LE_DUPLICATE_FILTERING_DISABLE
  }

  +5506 ms
  Preliminary Verdict: PASS

  +5506 ms
  Preliminary Verdict: PASS

  +7519 ms
  Preliminary Verdict: PASS

  +7519 ms
  Preliminary Verdict: PASS

  +9516 ms
  Preliminary Verdict: PASS

  +9516 ms
  Send Event: HCI!HCI_LE_SET_SCAN_ENABLE{
  leScanEnable=HCI_LE_SCAN_DISABLE,
  filterDuplicates=HCI_LE_DUPLICATE_FILTERING_DISABLE
  }

  +9531 ms
  Preliminary Verdict: PASS

  +9562 ms
  Send Event: ATT!ATT_CONNECT_REQ{
  peerAddr=0xC58DCE70012F,
  peerAddrType=HCI_LE_RANDOM_DEVICE_ADDRESS,
  ownAddrType=HCI_LE_PUBLIC_DEVICE_ADDRESS,
  minInterval=0x0032,
  maxInterval=0x0046,
  latency=0x0000
  }

  +13556 ms
  Receive Event: SEC?SEC_LE_REMOTE_CSRK_REQUEST_REQ{
  peerAddr=0xC58DCE70012F,
  peerAddrType=HCI_LE_RANDOM_DEVICE_ADDRESS
  }

  +13556 ms
  Receive Event: ATT?ATT_CONNECT_RSP{
  bdAddr=0xC58DCE70012F,
  peerAddrType=HCI_LE_RANDOM_DEVICE_ADDRESS,
  lcid=0x0040,
  status=HCI_OK
  }

  +13556 ms
  Receive Event: HCI?HCI_LE_CONNECTION_COMPLETE_EVENT{
  status=HCI_OK,
  connectionHandle=0x004D,
  role=HCI_ROLE_MASTER,
  peerAddressType=HCI_LE_RANDOM_DEVICE_ADDRESS,
  peerAddress=C58DCE70012F,
  connInterval=0x0046,
  connLatency=0x0000,
  supervisionTimeout=0x07D0,
  clockAccuracy=HCI_LE_CLOCK_ACCURACY_500PPM
  }

  +13556 ms
  Send Event: SEC!SEC_LE_REMOTE_CSRK_REQUEST_RSP{
  peerAddr=0xC58DCE70012F,
  peerAddrType=HCI_LE_RANDOM_DEVICE_ADDRESS,
  accept=FALSE,
  keyType=HCI_UNAUTHENTICATED_COMBINATION_KEY,
  csrk=0x00000000000000000000000000000000,
  signCounter=0x00000000
  }

  +13556 ms
  Preliminary Verdict: PASS

  +13556 ms
  Verdict Description: Connection setup successfully.

  +13556 ms
  Pass: Tester successfully initiated connection.

  +13556 ms
  Verdict Description: Tester successfully initiated connection.

  +13556 ms
  Verdict Description: LE Security not initiated due to TSPX_security_enabled value.

  +13556 ms
  Send Event: ATT!ATT_FIND_BY_TYPE_VALUE_REQ{
  lcid=0x0040,
  startingHandle=0x0001,
  endingHandle=0xFFFF,
  attributeType=0x2800,
  length=0x0002,
  PrimaryService=0x1818
  }

  +13681 ms
  Receive Event: ATT?ATT_FIND_BY_TYPE_VALUE_RSP{
  lcid=0x0040,
  HandleRange={
  {
  foundAttributeHandle=0x000F,
  endFoundHandle=0x0019
  }
  }
  } 

  +13852 ms
  Receive Event: ATT?ATT_FIND_BY_TYPE_VALUE_CFM{
  lcid=0040,
  result=0x0100,
  errorHandle=0x0000,
  HandleRanges={
  {
  foundAttributeHandle=0x000F,
  endFoundHandle=0x0019,
  }
  }
  }

  +13852 ms
  Preliminary Verdict: PASS

  +13852 ms
  Verdict Description: Discover Primary Service by Service UUID Request completed successfully.

  +13852 ms
  Pass: The IUT successfully returned the UUID for Cycling Power

  +13852 ms
  Verdict Description: The IUT successfully returned the UUID for Cycling Power

  +13852 ms
  Send Event: ATT!ATT_READ_BY_TYPE_REQ{
  lcid=0x0040,
  startingHandle=0x000F,
  endingHandle=0x0019,
  attributeTypeSize=0x02,
  attributeType=0x2803
  }

  +14024 ms
  Receive Event: ATT?ATT_READ_BY_TYPE_RSP{
  {
  handle=0x0010
  value{
  Properties=0x10,
  Handle=0x0011,
  UUID=0x2A63
  }
  }
  {
  handle=0x0013
  value{
  Properties=0x02,
  Handle=0x0014,
  UUID=0x2A65
  }
  }
  {
  handle=0x0015
  value{
  Properties=0x02,
  Handle=0x0016,
  UUID=0x2A5D
  }
  }
  }

  +14196 ms
  Receive Event: ATT?ATT_READ_BY_TYPE_RSP{
  {
  handle=0x0017
  value{
  Properties=0x28,
  Handle=0x0018,
  UUID=0x2A66
  }
  }
  }

  +14383 ms
  Receive Event: ATT?ATT_READ_BY_TYPE_CFM{
  lcid=0x0040,
  attributeType=0x2803,
  attributeTypeSize=0x02,
  result=0x0100,
  errorHandle=0x0000
  }

  +14383 ms
  Receive Event: ATT?ATT_READ_BY_TYPE_CFM{
  {
  handle=0x0010
  value{
  Properties=0x10,
  Handle=0x0011,
  UUID=0x2A63
  }
  }
  {
  handle=0x0013
  value{
  Properties=0x02,
  Handle=0x0014,
  UUID=0x2A65
  }
  }
  {
  handle=0x0015
  value{
  Properties=0x02,
  Handle=0x0016,
  UUID=0x2A5D
  }
  }
  {
  handle=0x0017
  value{
  Properties=0x28,
  Handle=0x0018,
  UUID=0x2A66
  }
  }
  }

  +14383 ms
  Preliminary Verdict: PASS

  +14383 ms
  Verdict Description: Discover All Characteristics of Service Request completed successfully.

  +14383 ms
  Send Event: ATT!ATT_FIND_INFO_REQ{
  lcid=0x0040,
  startingHandle=0x0012,
  endingHandle=0x0012
  }

  +14554 ms
  Receive Event: ATT?ATT_FIND_INFO_CFM{
  lcid=0x0040,
  result=0x0100,
  errorHandle=0x0000
  }

  +14554 ms
  Receive Event: ATT?ATT_FIND_INFO_RSP{
  {
  handle=0x0012,
  uuid=0x2902
  }
  }

  +14554 ms
  Receive Event: ATT?ATT_FIND_INFO_CFM{
  {
  handle=0x0012,
  uuid=0x2902,
  }
  }

  +14554 ms
  Preliminary Verdict: PASS

  +14554 ms
  Verdict Description: Discover All Characteristic Descriptors Request completed successfully.

  +14554 ms
  Send Event: ATT!ATT_FIND_INFO_REQ{
  lcid=0x0040,
  startingHandle=0x0019,
  endingHandle=0x0019
  }

  +14726 ms
  Receive Event: ATT?ATT_FIND_INFO_CFM{
  lcid=0x0040,
  result=0x0100,
  errorHandle=0x0000
  }

  +14726 ms
  Receive Event: ATT?ATT_FIND_INFO_RSP{
  {
  handle=0x0019,
  uuid=0x2902
  }
  }

  +14726 ms
  Receive Event: ATT?ATT_FIND_INFO_CFM{
  {
  handle=0x0019,
  uuid=0x2902,
  }
  }

  +14726 ms
  Preliminary Verdict: PASS

  +14726 ms
  Verdict Description: Discover All Characteristic Descriptors Request completed successfully.

  +14726 ms
  Send Event: ATT!ATT_WRITE_REQ{
  lcid=0x0040,
  attributeHandle=0x0019,
  length=0x0002,
  value{
  Properties=0x0000
  }
  } 

  +14991 ms
  Receive Event: ATT?ATT_WRITE_CFM{
  lcid=0x0040,
  result=0x0100,
  errorHandle=0x0000
  }

  +14991 ms
  Preliminary Verdict: PASS

  +17987 ms
  Send Event: ATT!ATT_WRITE_REQ{
  lcid=0x0040,
  attributeHandle=0x0019,
  length=0x0002,
  value{
  Properties=0x0002
  }
  }

  +18143 ms
  Receive Event: ATT?ATT_WRITE_CFM{
  lcid=0x0040,
  result=0x0100,
  errorHandle=0x0000
  }

  +18143 ms
  Preliminary Verdict: PASS

  +18143 ms
  Send Event: ATT!ATT_WRITE_REQ{
  lcid=0x0040,
  attributeHandle=0x0012,
  length=0x0002,
  value{
  Properties=0x0000
  }
  }

  +18314 ms
  Receive Event: ATT?ATT_WRITE_CFM{
  lcid=0x0040,
  result=0x0100,
  errorHandle=0x0000
  }

  +18314 ms
  Preliminary Verdict: PASS

  +21309 ms
  Send Event: ATT!ATT_WRITE_REQ{
  lcid=0x0040,
  attributeHandle=0x0012,
  length=0x0002,
  value{
  Properties=0x0001
  }
  }

  +21543 ms
  Receive Event: ATT?ATT_WRITE_CFM{
  lcid=0x0040,
  result=0x0100,
  errorHandle=0x0000
  }

  +21543 ms
  Preliminary Verdict: PASS

  +21559 ms
  Send Event: ATT!ATT_READ_REQ{
  lcid=0x0040,
  attributeHandle=0x0014
  }

  +21731 ms
  Receive Event: ATT?ATT_READ_CFM{
  lcid=0x0040,
  length=0x0004,
  result=0x0100,
  errorHandle=0x0000,
  value{
  CyclingPowerFeature=0x0019020A
  }
  }

  +21731 ms
  Preliminary Verdict: PASS

  +21731 ms
  Verdict Description: Read Request completed successfully. 

  +21731 ms
  Preliminary Verdict: PASS

  +21731 ms
  Pass: The data received for 'Cycling Power Feature' conforms to the schema

  +21731 ms
  Verdict Description: The data received for 'Cycling Power Feature' conforms to the schema

  +21777 ms
  Send Event: ATT!ATT_WRITE_REQ{
  lcid=0x0040,
  attributeHandle=0x0018,
  length=0x0001,
  value{  OpCode=0x0C,  CyclingPowerVectorControlValue=0x0063  }  }   +21902 ms  Receive Event: ATT?ATT_WRITE_CFM{  lcid=0x0040,  result=0x0100,  errorHandle=0x0000  }   +21902 ms  Preliminary Verdict: PASS   +22511 ms  Receive Event: ATT?ATT_HANDLE_VALUE_NOTIFICATION_REQ{  lcid=0x0040,  attributeHandle=0x0011,  length=0x000A,  attributeValue=0x00000000005B0000002C  }   +22511 ms  Receive Event: ATT?ATT_HANDLE_VALUE_IND{  lcid=0x0040,  attributeHandle=0x0018,  length=0x0005,  attributeValue=0x00FFFF010C20  }   +22511 ms  Preliminary Verdict: PASS   +22511 ms  Pass: The value for 'Cycling Power Control Point' sent by the IUT was correctly formatted.   +22511 ms  Verdict Description: The value for 'Cycling Power Control Point' sent by the IUT was correctly formatted.   +22511 ms  Send Event: ATT!ATT_WRITE_REQ{  lcid=0x0040,  attributeHandle=0x0018,  length=0x0001,  value{  OpCode=0x0C,  CyclingPowerVectorControlValue=0x006E  }  }   +22682 ms  Receive Event: ATT?ATT_WRITE_CFM{  lcid=0x0040,  result=0x0100,  errorHandle=0x0000
  }

  +22682 ms
  Preliminary Verdict: PASS

  +22682 ms
  Verdict Description: Write Request completed successfully.

  +43383 ms
  Receive Event: ATT?ATT_DISCONNECT_REQ{
  lcid=0x0040
  }

  +43383 ms
  Verdict Description: Unexpected ATT Disconnect received.

  +43383 ms
  Receive Event: HCI?HCI_LE_DISCONNECTION_COMPLETE_EVENT{
  status=HCI_OK,
  connectionHandle=0x004D,
  reason=HCI_CONNECTION_TIMEOUT
  }

  +43383 ms
  Verdict Description: Unexpected ATT Disconnect received.

  +43383 ms
  Inconclusive: Non-passing verdict returned from APICOM, see log for more details.

  +43383 ms
  Verdict Description: Non-passing verdict returned from APICOM, see log for more details.

  +45021 ms
  Final Verdict: INCONC

  +45021 ms
  Encrypted Verdict:
 A1#ZWY4MzQ5MDg3MmQwNTIxOGQzMzQ5YjY2ODA5M2MzNjQ5ZDY4NmY0Yjc2MzIzM2VkNTUyNTFhNGU4Mjg1MjI0NA==#S7tk81R4UBM+y2jy+jTqSwIFbmqou/dBe0rGBnSk5Rd1NLMNsmJ6x0apjF5t71xW 

  +45021 ms
  Test Case Ended: CPS/SEN/SPE/BI-04-C

Best regards,

Kiyoshi Iwai

  • 0

    Could you provide a sniffer log of what happens between line 613 and 616 (Verdict Description and Receive Event)? The time span between these two event was quite long. Also, the HCI_CONNECTION_TIMEOUT might be due to a too low accuracy for the low frequency clock, check the value of NRF_SDH_CLOCK_LF_ACCURACY or what accuracy you have provided to sd_softdevice_enable(..).

  • 0 in reply to Simon

    Hello Simon,

    Thank you for reply.

    Unfortunately I don't have the log of 613-616. 

    As you said, it took long time between two event, because this test may be abnormal check.

    So could you tell me how to change the HCI_CONNECTION_TIMEOUT longer, or how to stop the ATT Disconnect Request?

    Best regards,

    Kiyoshi Iwai

  • 0 in reply to Kiyoshi Iwai

    Hello Simon,

    I will send the test specification of BLE.

    Please find the page 68

    CPS.TS.1.1.2.pdf

  • 0 in reply to Kiyoshi Iwai

    The received event ATT_DISCONNECT_REQ is misleading, I don't think the application sends any such request. However, I think the problem is that the clock goes out of sync and thus the error HCI_CONNECTION_TIMEOUT. 

    In order to test this, open the sdk_config.h file of your product. Then you will find the following lines (assuming you are using sdk 14):

    // <o> NRF_SDH_CLOCK_LF_XTAL_ACCURACY  - External crystal clock accuracy used in the LL to compute timing windows.
 
// <0=> NRF_CLOCK_LF_XTAL_ACCURACY_250_PPM 
// <1=> NRF_CLOCK_LF_XTAL_ACCURACY_500_PPM 
// <2=> NRF_CLOCK_LF_XTAL_ACCURACY_150_PPM 
// <3=> NRF_CLOCK_LF_XTAL_ACCURACY_100_PPM 
// <4=> NRF_CLOCK_LF_XTAL_ACCURACY_75_PPM 
// <5=> NRF_CLOCK_LF_XTAL_ACCURACY_50_PPM 
// <6=> NRF_CLOCK_LF_XTAL_ACCURACY_30_PPM 
// <7=> NRF_CLOCK_LF_XTAL_ACCURACY_20_PPM 

#ifndef NRF_SDH_CLOCK_LF_XTAL_ACCURACY
#define NRF_SDH_CLOCK_LF_XTAL_ACCURACY 7
#endif

    Then change the value to 1 (accuracy of 500 ppm), and check if the problem disappear.

  • 0 in reply to Simon

    Thank you for the information.

    If the tester does not send the confirmation, the BLE_GATTS_EVT_HVC continues the pending state and approx.30 second passed(time-out expired) , will HCI_CONNECTION_TIMEOUT occur?

Related
Terms of service