cafy icon indicating copy to clipboard operation
cafy copied to clipboard

Connection not ready

Open eyalcha opened this issue 5 years ago • 20 comments

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

eyalcha avatar Nov 24 '20 12:11 eyalcha

  • 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.

manekinekko avatar Nov 24 '20 12:11 manekinekko

I have only one machine :-).

eyalcha avatar Nov 24 '20 12:11 eyalcha

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

eyalcha avatar Nov 24 '20 12:11 eyalcha

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.

manekinekko avatar Nov 24 '20 12:11 manekinekko

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 avatar Nov 24 '20 13:11 eyalcha

@manekinekko here is some sample data

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

eyalcha avatar Nov 26 '20 07:11 eyalcha

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.

manekinekko avatar Nov 26 '20 14:11 manekinekko

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

eyalcha avatar Nov 26 '20 15:11 eyalcha

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

image

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 avatar Nov 26 '20 18:11 manekinekko

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

Thank you.

manekinekko avatar Nov 26 '20 19:11 manekinekko

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 avatar Nov 26 '20 19:11 eyalcha

@manekinekko this is the log (not to much)

npm run inspect

> @manekinekko/[email protected] inspect
> npm run build && node dist/inspect.js


> @manekinekko/[email protected] prebuild
> npm run format


> @manekinekko/[email protected] 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/[email protected] build
> tsc

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

eyalcha avatar Nov 26 '20 19:11 eyalcha

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

eyalcha avatar Nov 26 '20 19:11 eyalcha

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:

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

manekinekko avatar Nov 26 '20 21:11 manekinekko

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

eyalcha avatar Nov 26 '20 21:11 eyalcha

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

manekinekko avatar Nov 26 '20 23:11 manekinekko

No, I run as pi user

eyalcha avatar Nov 26 '20 23:11 eyalcha

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

eyalcha avatar Nov 26 '20 23:11 eyalcha

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.

Azrael-Masters avatar Jan 13 '21 08:01 Azrael-Masters

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 avatar Jan 13 '21 13:01 manekinekko