Skip to content

Protocol

Jump to bottom Edit New page
Matt Colyer edited this page Jun 2, 2013 · 8 revisions

Procedure

These logs are taken from /var/log/thinkecod/tracer.log, which is written to by the official client. They have been copied here and edited for clarity.

dtrace

It turns out OS X has this really handy utility called, DTrace which allows you to inspect any shared library call in the system. The reason it's handy here is that while the logs contain almost all of the binary messages, they don't contain the envelop of each message nor the checksum. In order to get that data it's necessary to use dtrace on the relevant FTDI library that thinkecod uses (FTDI is a maker of usb to serial chips used by the dongle).

Below is the script that I used to extract that information. Unfortunately DTrace doesn't provide a way to dynamically print a certain number of bytes of hex (or atleast I couldn't find one, if there's a better way please update it).

To execute it use the following sudo dtrace -s <filename of script> -p <pid of thinkecod>

pid$target::FT_Write:entry /arg2 > 0/{
    buffer = (char*)copyin(arg1, arg2);
    printf("%d %02x %02x %02x %02x %02x %02x %02x %02x %02x %02x %02x", arg2, buffer[0], buffer[1], buffer[2], buffer[3], buffer[4], buffer[5], buffer[6], buffer[7], buffer[8], buffer[9], buffer[10]);
}

pid$target::FT_Read:entry {
    got = arg1;
    bytes = arg2;
}

pid$target::FT_Read:return /arg0 == 539/{
    buffer = (char*)copyin(got, bytes);
    printf("%d %02x %02x %02x %02x %02x %02x %02x %02x %02x %02x %02x", bytes, buffer[0], buffer[1], buffer[2], buffer[3], buffer[4], buffer[5], buffer[6], buffer[7], buffer[8], buffer[9], buffer[10]);
}

pid$target::FT_SetBaudRate:entry {
  printf("%d", arg1)
}

pid$target::FT_SetDataCharacteristics:entry {
  printf("%d %d %d", arg1, arg2, arg3)
}

Logs

Commissioning a Brand New Device

14:32:53 [0x10379f000] INFO  DataManForCollector-v1.5 - Starting commissioning.
14:32:53 [0x10379f000] TRACE DongleController-v1.5 -           TX packet: A23604FCFF9001
14:32:54 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: A0F90100
14:32:54 [0x10379f000] INFO  CommissionStateMachine-v1.5 - Confirmed open network for modlet commissioning
14:33:12 [0x10379f000] INFO  DongleController-v1.5 - got packet: "99D12301CC1F100000584F8000772A8A33A7F4F680D09C5D3C84F52B43000000000000000000" - UNKNOWN HEADER, ignored
14:33:12 [0x10379f000] INFO  DongleController-v1.5 - got packet: "98C009CC1F100000584F8000" - UNKNOWN HEADER, ignored
14:33:12 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: A0130B66ADCC1F100000584F808E
14:33:13 [0x10379f000] INFO  DataManForCollector-v1.5 - Stopping commissioning - locking network
14:33:13 [0x10379f000] TRACE DongleController-v1.5 -           TX packet: A23604FCFF0001
14:33:14 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: A0F90100
14:33:14 [0x10379f000] INFO  DataManForCollector-v1.5 - Confirmed network lock - commissioning over.
14:33:14 [0x10379f000] INFO  DataManForCollector-v1.5 - Caught modlet device announce.  Proceeding to determine if it's new or rejoining.
14:33:14 [0x10379f000] INFO  CommissionStateMachine-v1.5 - Caught modlet device announce.  Proceeding to determine if it's new or rejoining.
14:33:19 [0x10379f000] TRACE DongleController-v1.5 -           TX packet: 40010105
14:33:19 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: 40010100
14:33:20 [0x10379f000] TRACE DongleController-v1.5 -           TX packet: 402012FCFFCC1F100000584F80b004000000000000
14:33:20 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: 40200100
14:33:21 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: 40A00A66ADCC1F100000584F80
14:33:21 [0x10379f000] INFO  DongleController-v1.5 - Find Lost Modlet Response Packet caught.  Modlet: CC1F100000584F80.
14:33:21 [0x10379f000] TRACE FindLostModlet-v1.5 - Found newly announced modlet CC1F100000584F80 and now proceeding to hardware packet step to complete commissioning
14:33:21 [0x10379f000] INFO  DataManForCollector-v1.5 - Found newly announced modlet CC1F100000584F80 and now proceeding to hardware packet step to complete commissioning
14:33:22 [0x10379f000] TRACE DongleController-v1.5 -           TX packet: 40030466AD0500
14:33:22 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: 40030100
14:33:22 [0x10379f000] TRACE DongleController-v1.5 -           TX packet: 40270266AD
14:33:22 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: 40270100
14:33:22 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: 40A72966AD020000F40B00100000000040D7A340000040D7A34001000000B0F0A5FFCC1F100000584F800A0B
14:33:22 [0x10379f000] INFO  FindLostModlet-v1.5 - Successfully received HW info packet from new modlet 1: Sent event to UI.
14:33:22 [0x103593000] INFO  DongleController-v1.5 - Stop looking for modlets
14:34:02 [0x10340a000] INFO  DongleController-v1.5 - UI updating modlet CC1F100000584F80, which *is* in Status list but *not* in DB, so adding to DB and setting OTA.
14:34:02 [0x10340a000] INFO  DataManForCollector-v1.5 - Modlet successfully configured.  Adding to the client database. Mac: CC1F100000584F80 Hardware Version: 02_0000 Firmware version:
14:34:02 [0x10340a000] DEBUG DataManForCollector-v1.5 - Need to update CC1F100000584F80 modlet to online (new)
14:34:02 [0x10340a000] INFO  DataManForCollector-v1.5 - Setting modlet CC1F100000584F80 on the air.
14:34:02 [0x10379f000] TRACE DongleController-v1.5 -           TX packet: 40030466AD0500
14:34:02 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: 40030100
14:34:02 [0x10379f000] TRACE DongleController-v1.5 -           TX packet: 40240666AD00000A00
14:34:02 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: 40240100
14:34:02 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: 40A41866AD80000A0000A2FF4E0500000000000000000000000000
14:34:02 [0x10379f000] WARN  RawReadingParser-v1.5 - Ignoring outdated reading packet 4EFFA200 Modlet: CC1F100000584F80 Channel: 00
14:34:02 [0x10379f000] INFO  Download-v1.5 - Downloading readings for modlet CC1F100000584F80, switching to channel 1
14:34:03 [0x10379f000] INFO  DataManForCollector-v1.5 - Updating time for CC1F100000584F80.
14:34:03 [0x10379f000] TRACE DongleController-v1.5 -           TX packet: 40220666ADdbb4a851
14:34:03 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: 40220100
14:34:03 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: 40A20366AD00
14:34:03 [0x10379f000] INFO  DataManForCollector-v1.5 - Time Update Successful for CC1F100000584F80.

Commissioning an Existing Device

15:04:20 [0x103304000] INFO  DongleController-v1.5 - Start looking for modlets
15:04:21 [0x10379f000] INFO  DataManForCollector-v1.5 - Starting commissioning.
15:04:21 [0x10379f000] TRACE DongleController-v1.5 -           TX packet: A23604FCFF9001
15:04:21 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: A0F90100
15:04:21 [0x10379f000] INFO  CommissionStateMachine-v1.5 - Confirmed open network for modlet commissioning
15:04:37 [0x10379f000] INFO  DataManForCollector-v1.5 - Last communication with client; USB connected.
15:04:39 [0x10379f000] INFO  DongleController-v1.5 - got packet: "99D12301CC1F100000584F8000772A8A33A7F4F680D09C5D3C84F52B43000000000000000000" - UNKNOWN HEADER, ignored
15:04:40 [0x10379f000] INFO  DongleController-v1.5 - got packet: "98C009CC1F100000584F8000" - UNKNOWN HEADER, ignored
15:04:40 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: A0130B66ADCC1F100000584F808E
15:04:41 [0x10379f000] INFO  DataManForCollector-v1.5 - Stopping commissioning - locking network
15:04:41 [0x10379f000] TRACE DongleController-v1.5 -           TX packet: A23604FCFF0001
15:04:41 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: A0F90100
15:04:41 [0x10379f000] INFO  DataManForCollector-v1.5 - Confirmed network lock - commissioning over.
15:04:42 [0x10379f000] INFO  DataManForCollector-v1.5 - Caught modlet device announce.  Proceeding to determine if it's new or rejoining.
15:04:42 [0x10379f000] INFO  CommissionStateMachine-v1.5 - Caught modlet device announce.  Proceeding to determine if it's new or rejoining.
15:04:43 [0x10379f000] INFO  DataManForCollector-v1.5 - Existing modlet CC1F100000584F80 rejoined.
15:04:43 [0x10379f000] DEBUG DataManForCollector-v1.5 - Need to update CC1F100000584F80 modlet to online (new)
15:04:46 [0x10379f000] INFO  Download-v1.5 - Fail count for modlet CC1F100000584F80 greater than FailCountMax
15:04:46 [0x10379f000] DEBUG DataManForCollector-v1.5 - Need to update CC1F100000584F80 modlet to offline (replaced)
15:04:46 [0x10379f000] INFO  DataManForCollector-v1.5 - Setting modlet CC1F100000584F80 off the air.
15:04:46 [0x10379f000] TRACE DongleController-v1.5 -           TX packet: 40010105
15:04:46 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: 40010100
15:04:47 [0x10379f000] TRACE DongleController-v1.5 -           TX packet: 402012FCFFCC1F100000584F80b004000000000000
15:04:47 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: 40200100
15:04:49 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: 40A00A66ADCC1F100000584F80
15:04:49 [0x10379f000] INFO  DongleController-v1.5 - Find Lost Modlet Response Packet caught.  Modlet: CC1F100000584F80.
15:04:49 [0x10379f000] DEBUG DataManForCollector-v1.5 - Need to update CC1F100000584F80 modlet to online (replaced)
15:04:49 [0x10379f000] INFO  DataManForCollector-v1.5 - Setting modlet CC1F100000584F80 on the air.
15:04:49 [0x10379f000] INFO  FindLostModlet-v1.5 - Finding lost modlet confirmed.  Will set ota true for modlet 1 upon receipt of Lost Modlet Response.
15:04:49 [0x10340a000] INFO  DongleController-v1.5 - Stop looking for modlets
15:04:59 [0x10379f000] TRACE DongleController-v1.5 -           TX packet: 40240666AD00000A00
15:04:59 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: 40240100
15:04:59 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: 40A41266AD80000A0000A2FF4E0200000000000000
15:04:59 [0x10379f000] WARN  RawReadingParser-v1.5 - Ignoring outdated reading packet 4EFFA200 Modlet: CC1F100000584F80 Channel: 00
15:04:59 [0x10379f000] INFO  Download-v1.5 - Downloading readings for modlet CC1F100000584F80, switching to channel 1
15:04:59 [0x10379f000] INFO  DataManForCollector-v1.5 - Updating time for CC1F100000584F80.
15:04:59 [0x10379f000] TRACE DongleController-v1.5 -           TX packet: 40220666AD1bbca851
15:04:59 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: 40220100
15:04:59 [0x10379f000] TRACE DongleController-v1.5 -           RX packet: 40A20366AD00
15:04:59 [0x10379f000] INFO  DataManForCollector-v1.5 - Time Update Successful for CC1F100000584F80.

Lookup network id for an existing device

14:55:17 [0x10389f000] TRACE DongleController-v1.5 -           TX packet: 40010105
14:55:17 [0x10389f000] TRACE DongleController-v1.5 -           RX packet: 40010100
14:55:18 [0x10389f000] TRACE DongleController-v1.5 -           TX packet: 402012FCFF0B1F100000584F80b004000000000000
14:55:18 [0x10389f000] TRACE DongleController-v1.5 -           RX packet: 40200100
14:55:19 [0x10389f000] TRACE DongleController-v1.5 -           RX packet: 40A00AA7B40B1F100000584F80
14:55:19 [0x10389f000] INFO  DongleController-v1.5 - Find Lost Modlet Response Packet caught.  Modlet: 0B1F100000584F80.
14:55:19 [0x10389f000] DEBUG DataManForCollector-v1.5 - Need to update 0B1F100000584F80 modlet to online (replaced)
14:55:19 [0x10389f000] INFO  DataManForCollector-v1.5 - Setting modlet 0B1F100000584F80 on the air.

Dongle boot

16:07:49 [0x10389f000] INFO  DataManForCollector-v1.5 - Opened USB Receiver for communication.
16:07:49 [0x10389f000] TRACE DongleController-v1.5 - Dongle detected.  Loading Collector...
16:07:49 [0x10389f000] INFO  classLogs.PusherClient - restarting PusherClient...
16:07:49 [0x10389f000] DEBUG classLogs.PusherClient - PusherClient::formHeaders start; isDongleOK:1
16:07:49 [0x10389f000] DEBUG classLogs.PusherClient - PusherClient::formHeaders - dongle is in OKAY state.
16:07:49 [0x10389f000] DEBUG classLogs.PusherClient - PusherClient::formHeaders finish
16:07:49 [0x10389f000] INFO  classLogs.PusherClient - ...PusherClient restarted
16:07:49 [0x103b2e000] WARN  classLogs.PusherClient - PusherClient - exception:NULL response
16:07:49 [0x103b2e000] DEBUG classLogs.PusherClient - PusherClient::poll...
16:07:49 [0x103b2e000] TRACE classLogs.PusherClient - PusherClient::poll - filling request
16:07:49 [0x103b2e000] TRACE classLogs.PusherClient - PusherClient::poll - sending request and waiting for response
16:07:49 [0x10389f000] INFO  DataManForCollector-v1.5 - Added 1 modlets to the download queue upon Load.
16:07:49 [0x10389f000] DEBUG DataManForCollector-v1.5 - Setting all modlets OTA status = 1
16:07:49 [0x10389f000] TRACE DataManForCollector-v1.5 - 1
16:07:49 [0x10389f000] TRACE DataManForCollector-v1.5 - 2
16:07:49 [0x10389f000] TRACE DataManForCollector-v1.5 - 3
16:07:49 [0x10389f000] DEBUG DataManForCollector-v1.5 - Need to update 0B1F100000584F80 modlet to online (replaced)
16:07:49 [0x10389f000] DEBUG DataManForCollector-v1.5 - Setting all modlets isOverridden status = 0
16:07:49 [0x10389f000] DEBUG DataManForCollector-v1.5 - Need to update 0B1F100000584F80 modlet to not overridden (new)
16:07:49 [0x10389f000] TRACE DongleController-v1.5 - Collector loaded
16:07:49 [0x10389f000] INFO  DataManForCollector-v1.5 - Starting boot process.
16:07:49 [0x10389f000] INFO  Boot-v1.5 - starting boot process
16:07:49 [0x10389f000] TRACE DongleController-v1.5 -           TX packet: 400400
16:07:49 [0x10389f000] TRACE DongleController-v1.5 -           RX packet: 40841601000087030030003383699A0B2F000000584F800A1C
16:07:49 [0x10389f000] TRACE DongleController-v1.5 -           TX packet: 400000
16:07:49 [0x10389f000] TRACE DongleController-v1.5 -           RX packet: 40800110
16:07:49 [0x10389f000] INFO  Boot-v1.5 - Booted dongle
16:07:49 [0x10389f000] INFO  DataManForCollector-v1.5 - Dongle is booted:0B2F000000584F80
16:07:50 [0x10389f000] DEBUG classLogs.ServerProg - Dongle 1 successfully updated
16:07:50 [0x10389f000] INFO  Boot-v1.5 - Locking the network
16:07:50 [0x10389f000] TRACE DongleController-v1.5 -           TX packet: A23604FCFF0001
16:07:51 [0x10389f000] TRACE DongleController-v1.5 -           RX packet: A0F90100
16:07:52 [0x10389f000] INFO  Boot-v1.5 - Boot completed!
16:07:52 [0x10389f000] INFO  DataManForCollector-v1.5 - Boot completed!

A reading from channel 1

15:19:24 [0x10389f000] TRACE DongleController-v1.5 -           TX packet: 402406A7B400000A00
15:19:24 [0x10389f000] TRACE DongleController-v1.5 -           RX packet: 40240100
15:19:24 [0x10389f000] TRACE DongleController-v1.5 -           RX packet: 40A412A7B400000A00698D44510200000005040704
15:19:24 [0x10389f000] TRACE RawReadingParser-v1.5 - Downloaded 2 valid readings from modlet 0B1F100000584F80, channel 1
15:19:24 [0x10389f000] INFO  Download-v1.5 - Downloading readings for modlet 0B1F100000584F80, switching to channel 1

A reading from channel 2

15:19:25 [0x10389f000] TRACE DongleController-v1.5 -           TX packet: 402406A7B400010A00
15:19:25 [0x10389f000] TRACE DongleController-v1.5 -           RX packet: 40240100
15:19:25 [0x10389f000] TRACE DongleController-v1.5 -           RX packet: 40A412A7B400010A00698D44510200000000000000
15:19:25 [0x10389f000] TRACE RawReadingParser-v1.5 - Downloaded 2 valid readings from modlet 0B1F100000584F80, channel 2

Setting the schedule on channel 1

14:05:37 [0x10389f000] TRACE Schedule-v1.5 - Modlet of active schedule is not the one currently on dongle, so proceeding to Update Route Request state
14:05:37 [0x10389f000] TRACE DongleController-v1.5 -           TX packet: 400304A7B40500
14:05:37 [0x10389f000] TRACE DongleController-v1.5 -           RX packet: 40030100
14:05:37 [0x10389f000] TRACE DongleController-v1.5 -           TX packet: 40233BA7B400ffffffffffa5FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
14:05:37 [0x10389f000] TRACE DongleController-v1.5 -           RX packet: 40230100
14:05:38 [0x103b2e000] TRACE classLogs.PusherClient - PusherClient::poll - response arrived
14:05:38 [0x103b2e000] DEBUG classLogs.PusherClient - PusherClient::poll headers are ok; process response
14:05:38 [0x103b2e000] TRACE classLogs.LPBodyVisitor - BodyVisitor Schedules obj.size():1
14:05:38 [0x103b2e000] TRACE DongleController-v1.5 - Updating desired schedule for channel 1 on modlet 0B1F100000584F80:
 Old Desired schedule=ffffffffffa5FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
 newScheduleString=ffffffffffa5FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
Add a custom footer
Add a custom sidebar
Clone this wiki locally