Connection not ready - Githubissues

eyalcha commented 3 years ago

Coffee machine: ECAM 370.95 Hardware: Raspberry pi 3

Seems that it is trying to connect to the wrong device. Is it auto-detection? Should I set the device address somewhere?

  App BLE: activating... +0ms
  hci setting filter to: 1600000020c10000000000400000 +0ms
  hci set event mask - writing: 01010c08fffffbff07f8bf3d +5ms
  hci set le event mask - writing: 010120081f00000000000000 +1ms
  hci read local version - writing: 01011000 +2ms
  hci write LE host supported - writing: 016d0c020100 +1ms
  hci read LE host supported - writing: 016c0c00 +1ms
  hci read bd addr - writing: 01091000 +2ms
  hci onSocketData: 040e0401010c00 +6ms
  hci   event type = 4 +1ms
  hci   sub event type = 14 +1ms
  hci       cmd = 3073 +2ms
  hci       status = 0 +1ms
  hci       result =  +0ms
  hci onSocketData: 040e0401012000 +2ms
  hci   event type = 4 +1ms
  hci   sub event type = 14 +0ms
  hci       cmd = 8193 +1ms
  hci       status = 0 +0ms
  hci       result =  +1ms
  hci onSocketData: 040e0c0101100007fc01070f000922 +1ms
  hci   event type = 4 +0ms
  hci   sub event type = 14 +1ms
  hci       cmd = 4097 +0ms
  hci       status = 0 +1ms
  hci       result = 07fc01070f000922 +0ms
  hci set scan enabled - writing: 010c20020001 +2ms
  hci set scan parameters - writing: 010b200701100010000000 +1ms
  hci onSocketData: 040e04016d0c00 +1ms
  hci   event type = 4 +1ms
  hci   sub event type = 14 +0ms
  hci       cmd = 3181 +1ms
  hci       status = 0 +0ms
  hci       result =  +0ms
  hci onSocketData: 040e06016c0c000100 +2ms
  hci   event type = 4 +0ms
  hci   sub event type = 14 +0ms
  hci       cmd = 3180 +1ms
  hci       status = 0 +0ms
  hci       result = 0100 +1ms
  hci           le = 1 +0ms
  hci           simul = 0 +0ms
  hci onSocketData: 040e0a01091000c15cabeb27b8 +1ms
  hci   event type = 4 +0ms
  hci   sub event type = 14 +1ms
  hci       cmd = 4105 +0ms
  hci       status = 0 +0ms
  hci       result = c15cabeb27b8 +1ms
  hci address = b8:27:eb:ab:5c:c1 +1ms
  hci onSocketData: 040e04010c200c +1ms
  hci   event type = 4 +1ms
  hci   sub event type = 14 +0ms
  hci       cmd = 8204 +0ms
  hci       status = 12 +1ms
  hci       result =  +0ms
  hci onSocketData: 040e04010b2000 +1ms
  hci   event type = 4 +1ms
  hci   sub event type = 14 +0ms
  hci       cmd = 8203 +1ms
  hci       status = 0 +0ms
  hci       result =  +0ms
  App BLE: state= poweredOn +80ms
  hci set scan enabled - writing: 010c20020001 +7ms
  hci set scan parameters - writing: 010b200701100010000000 +1ms
  hci set scan enabled - writing: 010c20020101 +1ms
  hci onSocketData: 040e04010c200c +1ms
  hci   event type = 4 +1ms
  hci   sub event type = 14 +0ms
  hci       cmd = 8204 +1ms
  hci       status = 12 +0ms
  hci       result =  +0ms
  hci onSocketData: 040e04010b2000 +1ms
  hci   event type = 4 +1ms
  hci   sub event type = 14 +0ms
  hci       cmd = 8203 +1ms
  hci       status = 0 +0ms
  hci       result =  +0ms
  hci onSocketData: 040e04010c2000 +1ms
  hci   event type = 4 +0ms
  hci   sub event type = 14 +1ms
  hci       cmd = 8204 +0ms
  hci       status = 0 +0ms
  hci       result =  +1ms
  App BLE: scanning... +16ms
  hci onSocketData: 043e2b02010000a0478450a0001f0201060909443135333332383711070003003a12081a02dd07e658035b0300a5 +25ms
  hci   event type = 4 +1ms
  hci   sub event type = 62 +0ms
  hci       LE meta event type = 2 +0ms
  hci       LE meta event status = 1 +1ms
  hci       LE meta event data = 0000a0478450a0001f0201060909443135333332383711070003003a12081a02dd07e658035b0300a5 +0ms
  hci           type = 0 +2ms
  hci           address = 00:a0:50:84:47:a0 +1ms
  hci           address type = public +0ms
  hci           eir = 0201060909443135333332383711070003003a12081a02dd07e658035b0300 +1ms
  hci           rssi = -91 +0ms
  gap advertisement = {"localName":"D1533287","serviceData":[],"serviceUuids":["00035b0358e607dd021a08123a000300"],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +0ms
  hci onSocketData: 043e0c02010400a0478450a00000a4 +6ms
  hci   event type = 4 +0ms
  hci   sub event type = 62 +1ms
  hci       LE meta event type = 2 +0ms
  hci       LE meta event status = 1 +1ms
  hci       LE meta event data = 0400a0478450a00000a4 +0ms
  hci           type = 4 +0ms
  hci           address = 00:a0:50:84:47:a0 +1ms
  hci           address type = public +0ms
  hci           eir =  +0ms
  hci           rssi = -92 +1ms
  gap advertisement = {"localName":"D1533287","serviceData":[],"serviceUuids":["00035b0358e607dd021a08123a000300"],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +6ms
  hci onSocketData: 043e1a020100016246b9bd567d0e0201060aff4c001005581c990599a0 +252ms
  hci   event type = 4 +0ms
  hci   sub event type = 62 +1ms
  hci       LE meta event type = 2 +0ms
  hci       LE meta event status = 1 +0ms
  hci       LE meta event data = 00016246b9bd567d0e0201060aff4c001005581c990599a0 +1ms
  hci           type = 0 +0ms
  hci           address = 7d:56:bd:b9:46:62 +1ms
  hci           address type = random +0ms
  hci           eir = 0201060aff4c001005581c990599 +0ms
  hci           rssi = -96 +1ms
  gap advertisement = {"manufacturerData":{"type":"Buffer","data":[76,0,16,5,88,28,153,5,153]},"serviceData":[],"serviceUuids":[],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +257ms
  hci onSocketData: 043e2b020100007315a6e95c441f02011a1bff75004204010166445ce9a61573465ce9a6157201000000000000a1 +48ms
  hci   event type = 4 +1ms
  hci   sub event type = 62 +0ms
  hci       LE meta event type = 2 +1ms
  hci       LE meta event status = 1 +0ms
  hci       LE meta event data = 00007315a6e95c441f02011a1bff75004204010166445ce9a61573465ce9a6157201000000000000a1 +0ms
  hci           type = 0 +1ms
  hci           address = 44:5c:e9:a6:15:73 +1ms
  hci           address type = public +0ms
  hci           eir = 02011a1bff75004204010166445ce9a61573465ce9a6157201000000000000 +0ms
  hci           rssi = -95 +1ms
  gap advertisement = {"manufacturerData":{"type":"Buffer","data":[117,0,66,4,1,1,102,68,92,233,166,21,115,70,92,233,166,21,114,1,0,0,0,0,0,0]},"serviceData":[],"serviceUuids":[],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +52ms
  hci onSocketData: 043e28020102015912260109591c03039ffe17169ffe0000000000000000000000000000000000000000c5 +109ms
  hci   event type = 4 +0ms
  hci   sub event type = 62 +1ms
  hci       LE meta event type = 2 +0ms
  hci       LE meta event status = 1 +0ms
  hci       LE meta event data = 02015912260109591c03039ffe17169ffe0000000000000000000000000000000000000000c5 +1ms
  hci           type = 2 +1ms
  hci           address = 59:09:01:26:12:59 +0ms
  hci           address type = random +0ms
  hci           eir = 03039ffe17169ffe0000000000000000000000000000000000000000 +1ms
  hci           rssi = -59 +0ms
  gap advertisement = {"serviceData":[{"uuid":"fe9f","data":{"type":"Buffer","data":[0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0]}}],"serviceUuids":["fe9f"],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +114ms
  hci onSocketData: 043e16020104015912260109590a09ffe00000c9ca88fcc1b5 +2ms
  hci   event type = 4 +1ms
  hci   sub event type = 62 +0ms
  hci       LE meta event type = 2 +1ms
  hci       LE meta event status = 1 +0ms
  hci       LE meta event data = 04015912260109590a09ffe00000c9ca88fcc1b5 +0ms
  hci           type = 4 +1ms
  hci           address = 59:09:01:26:12:59 +0ms
  hci           address type = random +0ms
  hci           eir = 09ffe00000c9ca88fcc1 +1ms
  hci           rssi = -75 +0ms
  gap advertisement = {"manufacturerData":{"type":"Buffer","data":[224,0,0,201,202,136,252,193]},"serviceData":[{"uuid":"fe9f","data":{"type":"Buffer","data":[0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0]}}],"serviceUuids":["fe9f"],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +6ms
  hci onSocketData: 043e0c020104016246b9bd567d00a4 +376ms
  hci   event type = 4 +1ms
  hci   sub event type = 62 +0ms
  hci       LE meta event type = 2 +0ms
  hci       LE meta event status = 1 +1ms
  hci       LE meta event data = 04016246b9bd567d00a4 +0ms
  hci           type = 4 +1ms
  hci           address = 7d:56:bd:b9:46:62 +0ms
  hci           address type = random +0ms
  hci           eir =  +0ms
  hci           rssi = -92 +1ms
  gap advertisement = {"manufacturerData":{"type":"Buffer","data":[76,0,16,5,88,28,153,5,153]},"serviceData":[],"serviceUuids":[],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +379ms
  hci onSocketData: 043e2b02010001ec36f67209c01f0709534d492d4d31031900000201060f1695fe3120a10100ec36f67209c00db0 +557ms
  hci   event type = 4 +5ms
  hci   sub event type = 62 +0ms
  hci       LE meta event type = 2 +1ms
  hci       LE meta event status = 1 +0ms
  hci       LE meta event data = 0001ec36f67209c01f0709534d492d4d31031900000201060f1695fe3120a10100ec36f67209c00db0 +0ms
  hci           type = 0 +1ms
  hci           address = c0:09:72:f6:36:ec +0ms
  hci           address type = random +1ms
  hci           eir = 0709534d492d4d31031900000201060f1695fe3120a10100ec36f67209c00d +0ms
  hci           rssi = -80 +1ms
  gap advertisement = {"localName":"SMI-M1","serviceData":[{"uuid":"fe95","data":{"type":"Buffer","data":[49,32,161,1,0,236,54,246,114,9,192,13]}}],"serviceUuids":[],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +567ms
  hci onSocketData: 043e2702010401ec36f67209c01b07030a180100301512ff5500736f6f636172656d31c00972f636ecb0 +2ms
  hci   event type = 4 +1ms
  hci   sub event type = 62 +0ms
  hci       LE meta event type = 2 +0ms
  hci       LE meta event status = 1 +1ms
  hci       LE meta event data = 0401ec36f67209c01b07030a180100301512ff5500736f6f636172656d31c00972f636ecb0 +0ms
  hci           type = 4 +1ms
  hci           address = c0:09:72:f6:36:ec +0ms
  hci           address type = random +0ms
  hci           eir = 07030a180100301512ff5500736f6f636172656d31c00972f636ec +1ms
  hci           rssi = -80 +0ms
  gap advertisement = {"localName":"SMI-M1","manufacturerData":{"type":"Buffer","data":[85,0,115,111,111,99,97,114,101,109,49,192,9,114,246,54,236]},"serviceData":[{"uuid":"fe95","data":{"type":"Buffer","data":[49,32,161,1,0,236,54,246,114,9,192,13]}}],"serviceUuids":["180a","1","1530"],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +6ms
  App packets to send: id= health_check +5s
  App                 hex= [0d 05 75 0f da 25] (6) +3ms
  App                 dec= [13 5 117 15 -38 37] (6) +1ms
  App Warning: Trying to send packets but connection is not ready. Retrying... (5) +1ms
  App packets to send: id= health_check +1s
  App                 hex= [0d 05 75 0f da 25] (6) +1ms
  App                 dec= [13 5 117 15 -38 37] (6) +0ms
  App Warning: Trying to send packets but connection is not ready. Retrying... (4) +1ms
  App packets to send: id= health_check +1s
  App                 hex= [0d 05 75 0f da 25] (6) +1ms
  App                 dec= [13 5 117 15 -38 37] (6) +1ms
  App Warning: Trying to send packets but connection is not ready. Retrying... (3) +0ms
  App packets to send: id= health_check +1s
  App                 hex= [0d 05 75 0f da 25] (6) +1ms
  App                 dec= [13 5 117 15 -38 37] (6) +1ms
  App Warning: Trying to send packets but connection is not ready. Retrying... (2) +0ms
  App packets to send: id= health_check +1s
  App                 hex= [0d 05 75 0f da 25] (6) +3ms
  App                 dec= [13 5 117 15 -38 37] (6) +1ms
  App Warning: Trying to send packets but connection is not ready. Retrying... (1) +1ms
  App Abort +1ms
  App disconnecting... +2ms
  hci set scan enabled - writing: 010c20020001 +8s

manekinekko commented 3 years ago

Do you have many ECAM coffee machines? Currently, Cafy discovers all devices that expose this special service 00035b03-58e6-07dd-021a-08123a000300. If you have multiple devices, Cay will randomly pick one of them.
Is your coffee machine already connected to your phone? If yes, then disconnect your phone, and rerun Cafy.

Also, the app.sync() command is currently still in progress. Can you check the latest code from main branch? I've changed the initialisation to perform a health check instead.

eyalcha commented 3 years ago

I have only one machine :-).

eyalcha commented 3 years ago

After last update:

  App BLE: activating... +0ms
  hci setting filter to: 1600000020c10000000000400000 +0ms
  hci set event mask - writing: 01010c08fffffbff07f8bf3d +4ms
  hci set le event mask - writing: 010120081f00000000000000 +2ms
  hci read local version - writing: 01011000 +2ms
  hci write LE host supported - writing: 016d0c020100 +1ms
  hci read LE host supported - writing: 016c0c00 +2ms
  hci read bd addr - writing: 01091000 +1ms
  hci onSocketData: 040e0401010c00 +7ms
  hci   event type = 4 +1ms
  hci   sub event type = 14 +1ms
  hci       cmd = 3073 +1ms
  hci       status = 0 +1ms
  hci       result =  +0ms
  hci onSocketData: 040e0401012000 +2ms
  hci   event type = 4 +1ms
  hci   sub event type = 14 +0ms
  hci       cmd = 8193 +1ms
  hci       status = 0 +0ms
  hci       result =  +1ms
  hci onSocketData: 040e0c0101100007fc01070f000922 +0ms
  hci   event type = 4 +1ms
  hci   sub event type = 14 +0ms
  hci       cmd = 4097 +1ms
  hci       status = 0 +0ms
  hci       result = 07fc01070f000922 +0ms
  hci set scan enabled - writing: 010c20020001 +2ms
  hci set scan parameters - writing: 010b200701100010000000 +1ms
  hci onSocketData: 040e04016d0c00 +2ms
  hci   event type = 4 +1ms
  hci   sub event type = 14 +0ms
  hci       cmd = 3181 +0ms
  hci       status = 0 +1ms
  hci       result =  +0ms
  hci onSocketData: 040e06016c0c000100 +1ms
  hci   event type = 4 +1ms
  hci   sub event type = 14 +0ms
  hci       cmd = 3180 +0ms
  hci       status = 0 +1ms
  hci       result = 0100 +0ms
  hci           le = 1 +0ms
  hci           simul = 0 +1ms
  hci onSocketData: 040e0a01091000c15cabeb27b8 +0ms
  hci   event type = 4 +1ms
  hci   sub event type = 14 +0ms
  hci       cmd = 4105 +1ms
  hci       status = 0 +0ms
  hci       result = c15cabeb27b8 +0ms
  hci address = b8:27:eb:ab:5c:c1 +1ms
  hci onSocketData: 040e04010c200c +2ms
  hci   event type = 4 +0ms
  hci   sub event type = 14 +1ms
  hci       cmd = 8204 +0ms
  hci       status = 12 +0ms
  hci       result =  +1ms
  hci onSocketData: 040e04010b2000 +1ms
  hci   event type = 4 +0ms
  hci   sub event type = 14 +1ms
  hci       cmd = 8203 +0ms
  hci       status = 0 +0ms
  hci       result =  +1ms
  App BLE: state= poweredOn +81ms
  hci set scan enabled - writing: 010c20020001 +6ms
  hci set scan parameters - writing: 010b200701100010000000 +1ms
  hci set scan enabled - writing: 010c20020101 +1ms
  hci onSocketData: 040e04010c200c +1ms
  hci   event type = 4 +1ms
  hci   sub event type = 14 +0ms
  hci       cmd = 8204 +1ms
  hci       status = 12 +0ms
  hci       result =  +0ms
  hci onSocketData: 040e04010b2000 +1ms
  hci   event type = 4 +0ms
  hci   sub event type = 14 +1ms
  hci       cmd = 8203 +0ms
  hci       status = 0 +1ms
  hci       result =  +0ms
  hci onSocketData: 040e04010c2000 +1ms
  hci   event type = 4 +0ms
  hci   sub event type = 14 +0ms
  hci       cmd = 8204 +1ms
  hci       status = 0 +0ms
  hci       result =  +0ms
  App BLE: scanning... +15ms
  hci onSocketData: 043e1a020100014fc9c5538c5c0e0201060aff4c0010055a1c3ee839a4 +29ms
  hci   event type = 4 +1ms
  hci   sub event type = 62 +0ms
  hci       LE meta event type = 2 +1ms
  hci       LE meta event status = 1 +0ms
  hci       LE meta event data = 00014fc9c5538c5c0e0201060aff4c0010055a1c3ee839a4 +0ms
  hci           type = 0 +2ms
  hci           address = 5c:8c:53:c5:c9:4f +1ms
  hci           address type = random +0ms
  hci           eir = 0201060aff4c0010055a1c3ee839 +1ms
  hci           rssi = -92 +0ms
  gap advertisement = {"manufacturerData":{"type":"Buffer","data":[76,0,16,5,90,28,62,232,57]},"serviceData":[],"serviceUuids":[],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +0ms
  hci onSocketData: 043e28020102013eb031219c671c03039ffe17169ffe0000000000000000000000000000000000000000c1 +6ms
  hci   event type = 4 +1ms
  hci   sub event type = 62 +0ms
  hci       LE meta event type = 2 +1ms
  hci       LE meta event status = 1 +0ms
  hci       LE meta event data = 02013eb031219c671c03039ffe17169ffe0000000000000000000000000000000000000000c1 +0ms
  hci           type = 2 +1ms
  hci           address = 67:9c:21:31:b0:3e +0ms
  hci           address type = random +1ms
  hci           eir = 03039ffe17169ffe0000000000000000000000000000000000000000 +0ms
  hci           rssi = -63 +0ms
  gap advertisement = {"serviceData":[{"uuid":"fe9f","data":{"type":"Buffer","data":[0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0]}}],"serviceUuids":["fe9f"],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +7ms
  hci onSocketData: 043e2b02010000a0478450a0001f0201060909443135333332383711070003003a12081a02dd07e658035b0300a3 +4ms
  hci   event type = 4 +1ms
  hci   sub event type = 62 +0ms
  hci       LE meta event type = 2 +1ms
  hci       LE meta event status = 1 +0ms
  hci       LE meta event data = 0000a0478450a0001f0201060909443135333332383711070003003a12081a02dd07e658035b0300a3 +0ms
  hci           type = 0 +1ms
  hci           address = 00:a0:50:84:47:a0 +0ms
  hci           address type = public +0ms
  hci           eir = 0201060909443135333332383711070003003a12081a02dd07e658035b0300 +1ms
  hci           rssi = -93 +0ms
  gap advertisement = {"localName":"D1533287","serviceData":[],"serviceUuids":["00035b0358e607dd021a08123a000300"],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +8ms
  hci onSocketData: 043e0c02010400a0478450a00000a4 +2ms
  hci   event type = 4 +1ms
  hci   sub event type = 62 +0ms
  hci       LE meta event type = 2 +0ms
  hci       LE meta event status = 1 +1ms
  hci       LE meta event data = 0400a0478450a00000a4 +0ms
  hci           type = 4 +1ms
  hci           address = 00:a0:50:84:47:a0 +0ms
  hci           address type = public +0ms
  hci           eir =  +1ms
  hci           rssi = -92 +0ms
  gap advertisement = {"localName":"D1533287","serviceData":[],"serviceUuids":["00035b0358e607dd021a08123a000300"],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +5ms
  hci onSocketData: 043e16020104013eb031219c670a09ffe00000c9ca88fcc1b2 +235ms
  hci   event type = 4 +1ms
  hci   sub event type = 62 +0ms
  hci       LE meta event type = 2 +0ms
  hci       LE meta event status = 1 +1ms
  hci       LE meta event data = 04013eb031219c670a09ffe00000c9ca88fcc1b2 +0ms
  hci           type = 4 +1ms
  hci           address = 67:9c:21:31:b0:3e +0ms
  hci           address type = random +0ms
  hci           eir = 09ffe00000c9ca88fcc1 +1ms
  hci           rssi = -78 +0ms
  gap advertisement = {"manufacturerData":{"type":"Buffer","data":[224,0,0,201,202,136,252,193]},"serviceData":[{"uuid":"fe9f","data":{"type":"Buffer","data":[0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0]}}],"serviceUuids":["fe9f"],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +240ms
  hci onSocketData: 043e2b020100007315a6e95c441f02011a1bff75004204010166445ce9a61573465ce9a6157201000000000000a9 +1s
  hci   event type = 4 +1ms
  hci   sub event type = 62 +0ms
  hci       LE meta event type = 2 +1ms
  hci       LE meta event status = 1 +0ms
  hci       LE meta event data = 00007315a6e95c441f02011a1bff75004204010166445ce9a61573465ce9a6157201000000000000a9 +0ms
  hci           type = 0 +1ms
  hci           address = 44:5c:e9:a6:15:73 +0ms
  hci           address type = public +1ms
  hci           eir = 02011a1bff75004204010166445ce9a61573465ce9a6157201000000000000 +0ms
  hci           rssi = -87 +0ms
  gap advertisement = {"manufacturerData":{"type":"Buffer","data":[117,0,66,4,1,1,102,68,92,233,166,21,115,70,92,233,166,21,114,1,0,0,0,0,0,0]},"serviceData":[],"serviceUuids":[],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +1s
  hci onSocketData: 043e0c020104014fc9c5538c5c00a3 +318ms
  hci   event type = 4 +1ms
  hci   sub event type = 62 +0ms
  hci       LE meta event type = 2 +0ms
  hci       LE meta event status = 1 +1ms
  hci       LE meta event data = 04014fc9c5538c5c00a3 +0ms
  hci           type = 4 +1ms
  hci           address = 5c:8c:53:c5:c9:4f +0ms
  hci           address type = random +0ms
  hci           eir =  +1ms
  hci           rssi = -93 +0ms
  gap advertisement = {"manufacturerData":{"type":"Buffer","data":[76,0,16,5,90,28,62,232,57]},"serviceData":[],"serviceUuids":[],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +321ms
  hci onSocketData: 043e2b02010001ec36f67209c01f0709534d492d4d31031900000201060f1695fe3120a10100ec36f67209c00db2 +2s
  hci   event type = 4 +6ms
  hci   sub event type = 62 +0ms
  hci       LE meta event type = 2 +1ms
  hci       LE meta event status = 1 +0ms
  hci       LE meta event data = 0001ec36f67209c01f0709534d492d4d31031900000201060f1695fe3120a10100ec36f67209c00db2 +0ms
  hci           type = 0 +1ms
  hci           address = c0:09:72:f6:36:ec +0ms
  hci           address type = random +1ms
  hci           eir = 0709534d492d4d31031900000201060f1695fe3120a10100ec36f67209c00d +0ms
  hci           rssi = -78 +1ms
  gap advertisement = {"localName":"SMI-M1","serviceData":[{"uuid":"fe95","data":{"type":"Buffer","data":[49,32,161,1,0,236,54,246,114,9,192,13]}}],"serviceUuids":[],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +2s
  hci onSocketData: 043e2702010401ec36f67209c01b07030a180100301512ff5500736f6f636172656d31c00972f636ecb2 +2ms
  hci   event type = 4 +1ms
  hci   sub event type = 62 +0ms
  hci       LE meta event type = 2 +0ms
  hci       LE meta event status = 1 +1ms
  hci       LE meta event data = 0401ec36f67209c01b07030a180100301512ff5500736f6f636172656d31c00972f636ecb2 +0ms
  hci           type = 4 +1ms
  hci           address = c0:09:72:f6:36:ec +0ms
  hci           address type = random +0ms
  hci           eir = 07030a180100301512ff5500736f6f636172656d31c00972f636ec +1ms
  hci           rssi = -78 +0ms
  gap advertisement = {"localName":"SMI-M1","manufacturerData":{"type":"Buffer","data":[85,0,115,111,111,99,97,114,101,109,49,192,9,114,246,54,236]},"serviceData":[{"uuid":"fe95","data":{"type":"Buffer","data":[49,32,161,1,0,236,54,246,114,9,192,13]}}],"serviceUuids":["180a","1","1530"],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +6ms
  App packets to send: id= health_check +5s
  App                 hex= [0d 05 75 0f da 25] (6) +3ms
  App                 dec= [13 5 117 15 -38 37] (6) +1ms
  App Warning: Trying to send packets but connection is not ready. Retrying... (5) +1ms
  App packets to send: id= health_check +1s
  App                 hex= [0d 05 75 0f da 25] (6) +1ms
  App                 dec= [13 5 117 15 -38 37] (6) +0ms
  App Warning: Trying to send packets but connection is not ready. Retrying... (4) +1ms
  App packets to send: id= health_check +1s
  App                 hex= [0d 05 75 0f da 25] (6) +1ms
  App                 dec= [13 5 117 15 -38 37] (6) +0ms
  App Warning: Trying to send packets but connection is not ready. Retrying... (3) +0ms
  App packets to send: id= health_check +1s
  App                 hex= [0d 05 75 0f da 25] (6) +2ms
  App                 dec= [13 5 117 15 -38 37] (6) +0ms
  App Warning: Trying to send packets but connection is not ready. Retrying... (2) +0ms
  App packets to send: id= health_check +1s
  App                 hex= [0d 05 75 0f da 25] (6) +2ms
  App                 dec= [13 5 117 15 -38 37] (6) +0ms
  App Warning: Trying to send packets but connection is not ready. Retrying... (1) +1ms
  App Abort +0ms
  App disconnecting... +1ms
  hci set scan enabled - writing: 010c20020001 +5s

manekinekko commented 3 years ago

I can see the correct machine and service UUID in the logs. Is your machine connected to any device? Cafy can't connect to it for some reason.

eyalcha commented 3 years ago

I am almost sure it it not connected to any device. I am able to connect to it using mobile app. (Do you have faster channel to communicate, messenger, other ?)

I see it sends packets to the device, but how do you know which device is the target device?

eyalcha commented 3 years ago

@manekinekko here is some sample data

https://drive.google.com/file/d/1ZO2evtkelPVjbTVw3bD62KK--e8O6529/view?usp=sharing

manekinekko commented 3 years ago

Thank you @eyalcha for sharing the data. Did you record the data when using Cafy? Or when you used your phone?

Can you also do another recording following these steps:

start recording with wireshark,
connect to machine with mobile phone,
wait 5 seconds,
order a coffee,
wait 5 seconds,
disconnect,
end recording.

eyalcha commented 3 years ago

It was recorded with mobile phone (hci logging option in android)
I will record the sequence and update when ready.

manekinekko commented 3 years ago

I can see the right service and characteristic, and also the 0d05750fda25 health_check value.

However, it seems that Cafy can't connect to your machine. I still need to figure this out. I will try and use a RPi in order to reproduce this issue. Maybe it's related to the OS.

manekinekko commented 3 years ago

@eyalcha could you check out the latest commit from main and run npm run inspect, then copy the logs here?

Thank you.

eyalcha commented 3 years ago

Yes, BTW, I just saw that the bluetooth setting has pin option enabled. Does it change anything? (I have disabled it and the results were the same)

eyalcha commented 3 years ago

@manekinekko this is the log (not to much)

npm run inspect

> @manekinekko/cafy@1.0.1-alpha.0 inspect
> npm run build && node dist/inspect.js

> @manekinekko/cafy@1.0.1-alpha.0 prebuild
> npm run format

> @manekinekko/cafy@1.0.1-alpha.0 format
> npx prettier --write .

.commitlintrc.json 362ms
.github/ISSUE_TEMPLATE/bug_report.md 655ms
.github/workflows/nodejs.yml 595ms
.prettierrc.json 141ms
.release-it.json 118ms
jest.config.js 121ms
package-lock.json 7062ms
package.json 829ms
README.md 2980ms
src/classes/App.ts 1984ms
src/classes/Appliance.ts 194ms
src/classes/ApplianceManager.ts 121ms
src/classes/BeanSystem.ts 162ms
src/classes/BeverageId.ts 169ms
src/classes/BeverageTasteValue.ts 90ms
src/classes/EcamMachine.ts 117ms
src/classes/EcamManager.ts 221ms
src/classes/index.ts 33ms
src/classes/MachineAlarm.ts 421ms
src/classes/MachineKey.ts 273ms
src/classes/MachineLoad.ts 111ms
src/classes/MachineSwitch.ts 262ms
src/classes/MonitorData.ts 163ms
src/classes/MonitorData2.ts 1560ms
src/classes/Parameter.ts 914ms
src/classes/ParameterModel.ts 211ms
src/classes/RecipeData.ts 104ms
src/classes/RecipeDefaults.ts 122ms
src/classes/Synchronizer.ts 231ms
src/classes/Utils.ts 499ms
src/commands.ts 163ms
src/decoder.ts 1943ms
src/index.spec.ts 135ms
src/index.ts 45ms
src/inspect.ts 485ms
tsconfig.json 188ms

> @manekinekko/cafy@1.0.1-alpha.0 build
> tsc

on -> stateChange:  { state: 'poweredOn' }
on -> scanStart

eyalcha commented 3 years ago

I see there are two address, one is public and one is random. Is it expected? To which of them the connection is performed?

 gap advertisement = {"localName":"D1533287","serviceData":[],"serviceUuids":["00035b0358e607dd021a08123a000300"],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +0ms
  hci onSocketData: 043e0c02010400a0478450a00000a6 +6ms
  hci   event type = 4 +1ms
  hci   sub event type = 62 +0ms
  hci       LE meta event type = 2 +1ms
  hci       LE meta event status = 1 +0ms
  hci       LE meta event data = 0400a0478450a00000a6 +1ms
  hci           type = 4 +1ms
  hci           address = 00:a0:50:84:47:a0 +0ms
  hci           address type = public +1ms
  hci           eir =  +0ms
  hci           rssi = -90 +1ms
  gap advertisement = {"localName":"D1533287","serviceData":[],"serviceUuids":["00035b0358e607dd021a08123a000300"],"solicitationServiceUuids":[],"serviceSolicitationUuids":[]} +8ms
  hci onSocketData: 043e2802010201e90f2147ac7b1c03039ffe17169ffe0000000000000000000000000000000000000000b7 +139ms
  hci   event type = 4 +1ms
  hci   sub event type = 62 +1ms
  hci       LE meta event type = 2 +0ms
  hci       LE meta event status = 1 +1ms
  hci       LE meta event data = 0201e90f2147ac7b1c03039ffe17169ffe0000000000000000000000000000000000000000b7 +0ms
  hci           type = 2 +1ms
  hci           address = 7b:ac:47:21:0f:e9 +0ms
  hci           address type = random +1ms
  hci           eir = 03039ffe17169ffe0000000000000000000000000000000000000000 +1ms
  hci           rssi = -73 +0ms

manekinekko commented 3 years ago

Alright! So the issue is probably coming from the underlying program that I am using: https://github.com/abandonware/noble.

Can you try the following options:

run the command using sudo npm run inspect
replace await startScanningAsync([SERVICE], false); with await startScanningAsync([], false); in this line https://github.com/manekinekko/cafy/blob/main/src/inspect.ts#L8

eyalcha commented 3 years ago

Here it is:

on -> stateChange:  { state: 'poweredOn' }
on -> scanStart
on -> discover:  {
  peripheral: Peripheral {
    _noble: Noble {
      initialized: true,
      address: 'b8:27:eb:ab:5c:c1',
      _state: 'poweredOn',
      _bindings: [NobleBindings],
      _peripherals: [Object],
      _services: [Object],
      _characteristics: [Object],
      _descriptors: [Object],
      _discoveredPeripheralUUids: [Array],
      _events: [Object: null prototype],
      _eventsCount: 6,
      _allowDuplicates: false
    },
    id: '00a0508447a0',
    uuid: '00a0508447a0',
    address: '00:a0:50:84:47:a0',
    addressType: 'public',
    connectable: true,
    advertisement: {
      localName: 'D1533287',
      txPowerLevel: undefined,
      manufacturerData: undefined,
      serviceData: [],
      serviceUuids: [Array],
      solicitationServiceUuids: [],
      serviceSolicitationUuids: []
    },
    rssi: -92,
    services: null,
    mtu: null,
    state: 'disconnected'
  }
}
on -> scanStop
on -> connect
on -> RSSI update  { rssi: -89 }
on -> peripheral services discovered  {
  services: [
    Service {
      _noble: [Noble],
      _peripheralId: '00a0508447a0',
      uuid: '1800',
      name: 'Generic Access',
      type: 'org.bluetooth.service.generic_access',
      includedServiceUuids: null,
      characteristics: null
    },
    Service {
      _noble: [Noble],
      _peripheralId: '00a0508447a0',
      uuid: '1801',
      name: 'Generic Attribute',
      type: 'org.bluetooth.service.generic_attribute',
      includedServiceUuids: null,
      characteristics: null
    },
    Service {
      _noble: [Noble],
      _peripheralId: '00a0508447a0',
      uuid: '00035b0358e607dd021a08123a000300',
      name: null,
      type: null,
      includedServiceUuids: null,
      characteristics: null
    }
  ]
}
on -> service included services discovered  { includedServiceUuids: [] }
on -> service characteristics discovered  {
  characteristics: [
    Characteristic {
      _noble: [Noble],
      _peripheralId: '00a0508447a0',
      _serviceUuid: '1800',
      uuid: '2a00',
      name: 'Device Name',
      type: 'org.bluetooth.characteristic.gap.device_name',
      properties: [Array],
      descriptors: null
    },
    Characteristic {
      _noble: [Noble],
      _peripheralId: '00a0508447a0',
      _serviceUuid: '1800',
      uuid: '2a01',
      name: 'Appearance',
      type: 'org.bluetooth.characteristic.gap.appearance',
      properties: [Array],
      descriptors: null
    },
    Characteristic {
      _noble: [Noble],
      _peripheralId: '00a0508447a0',
      _serviceUuid: '1800',
      uuid: '2a04',
      name: 'Peripheral Preferred Connection Parameters',
      type: 'org.bluetooth.characteristic.gap.peripheral_preferred_connection_parameters',
      properties: [Array],
      descriptors: null
    },
    Characteristic {
      _noble: [Noble],
      _peripheralId: '00a0508447a0',
      _serviceUuid: '1800',
      uuid: '2aa6',
      name: 'Central Address Resolution',
      type: 'org.bluetooth.characteristic.central_address_resolution',
      properties: [Array],
      descriptors: null
    }
  ]
}
on -> characteristic read { isNotification: false }
{ data: <Buffer 44 31 35 33 33 32 38 37> }
on -> characteristic write 
error? { error: undefined }
on -> disconnect

manekinekko commented 3 years ago

Oh! That's interesting. It's connecting! Did you use the sudo npm run inspect command?

eyalcha commented 3 years ago

No, I run as pi user

eyalcha commented 3 years ago

I don't know if it helps, but here is something I played with:

[bluetooth]# connect 00:A0:50:84:47:A0
Attempting to connect to 00:A0:50:84:47:A0
[CHG] Device 00:A0:50:84:47:A0 Connected: yes
Connection successful
[NEW] Primary Service
    /org/bluez/hci0/dev_00_A0_50_84_47_A0/service000a
    00001801-0000-1000-8000-00805f9b34fb
    Generic Attribute Profile
[NEW] Characteristic
    /org/bluez/hci0/dev_00_A0_50_84_47_A0/service000a/char000b
    00002a05-0000-1000-8000-00805f9b34fb
    Service Changed
[NEW] Descriptor
    /org/bluez/hci0/dev_00_A0_50_84_47_A0/service000a/char000b/desc000d
    00002902-0000-1000-8000-00805f9b34fb
    Client Characteristic Configuration
[NEW] Primary Service
    /org/bluez/hci0/dev_00_A0_50_84_47_A0/service000e
    00035b03-58e6-07dd-021a-08123a000300
    Vendor specific
[NEW] Characteristic
    /org/bluez/hci0/dev_00_A0_50_84_47_A0/service000e/char000f
    00035b03-58e6-07dd-021a-08123a000301
    Vendor specific
[NEW] Descriptor
    /org/bluez/hci0/dev_00_A0_50_84_47_A0/service000e/char000f/desc0011
    00002902-0000-1000-8000-00805f9b34fb
    Client Characteristic Configuration
[NEW] Characteristic
    /org/bluez/hci0/dev_00_A0_50_84_47_A0/service000e/char0012
    00035b03-58e6-07dd-021a-08123a0003ff
    Vendor specific
[CHG] Device 00:A0:50:84:47:A0 UUIDs: 00001800-0000-1000-8000-00805f9b34fb
[CHG] Device 00:A0:50:84:47:A0 UUIDs: 00001801-0000-1000-8000-00805f9b34fb
[CHG] Device 00:A0:50:84:47:A0 UUIDs: 00035b03-58e6-07dd-021a-08123a000300
[CHG] Device 00:A0:50:84:47:A0 ServicesResolved: yes
[D1533287]# pair 00:A0:50:84:47:A0
Attempting to pair with 00:A0:50:84:47:A0
[DEL] Device 7F:11:56:5D:63:D6 7F-11-56-5D-63-D6
[DEL] Device 44:5C:E9:A6:15:73 44-5C-E9-A6-15-73
[DEL] Device 7D:08:9A:66:7C:75 7D-08-9A-66-7C-75
[DEL] Device C0:09:72:F6:36:EC SMI-M1
[DEL] Device 46:A3:92:20:7D:32 46-A3-92-20-7D-32
[DEL] Device F0:99:19:A8:68:92 F0-99-19-A8-68-92
Failed to pair: org.bluez.Error.AuthenticationFailed
[CHG] Device 00:A0:50:84:47:A0 ServicesResolved: no
[CHG] Device 00:A0:50:84:47:A0 Connected: no
[bluetooth]# exit

Azrael-Masters commented 3 years ago

Yes, BTW, I just saw that the bluetooth setting has pin option enabled. Does it change anything? (I have disabled it and the results were the same)

Does the current implementation support PIN protected Machines? If yes, I didn't find a specific place to enter the PIN into the code files. I'm self using the ECAM 656.75 and trying to setup manekinekko's Interface in a custom Docker container (node:current-alpine) on my RaspberryPi.

manekinekko commented 3 years ago

Hi @Azrael-Masters I haven't had the time to decode the PIN activation packets. Would you mind opening a separate GitHub issue to discuss it?

Thanks btw for setting up the docker container. Is that something you are willing to contribute back to this repo? I'd be happy to merge your contribution 😃

manekinekko / cafy

Connection not ready #3