search

bphermansson / EspSparsnasGateway

Reads data from Ikea Sparsnäs energy meter and publish via Mqtt.
MIT License
39 stars 27 forks source link

MQTT is not stable, many missed packets. #30

Closed dogmatic69 closed 5 years ago

dogmatic69 commented 5 years ago

After running for a while this is my logs, you can see many missed pakets. The Sparsnas is sending around every 15 seconds (seen in the serial debugger), but the MQTT subscriber is only getting a fraction of what is sent.

Look at the seq below, this is what MQTT is actually processing.

EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":43362,"watt":2792.727,"total":205.451,"pulse":"205451","battery":100,"rssi":"-101","power":"1320"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":43384,"watt":2378.323,"total":205.702,"pulse":"205702","battery":100,"rssi":"-86","power":"1550"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":43558,"watt":2963.344,"total":207.677,"pulse":"207677","battery":100,"rssi":"-85","power":"1244"}
EspSparsnasGateway/values {"seq":43564,"watt":3056.716,"total":207.753,"pulse":"207753","battery":100,"rssi":"-93","power":"1206"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":43608,"watt":1253.025,"total":208.207,"pulse":"208207","battery":100,"rssi":"-84","power":"2942"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":43652,"watt":1466.348,"total":208.467,"pulse":"208467","battery":100,"rssi":"-94","power":"2514"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":43677,"watt":701.3699,"total":208.602,"pulse":"208602","battery":100,"rssi":"-86","power":"5256"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":43788,"watt":607.7151,"total":208.878,"pulse":"208878","battery":100,"rssi":"-82","power":"6066"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":43793,"watt":920.6793,"total":208.892,"pulse":"208892","battery":100,"rssi":"-91","power":"4004"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":43840,"watt":1044.602,"total":209.011,"pulse":"209011","battery":100,"rssi":"-90","power":"3529"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":43882,"watt":7200,"total":209.107,"pulse":"209107","battery":100,"rssi":"-88","power":"512"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":43935,"watt":641.3361,"total":209.275,"pulse":"209275","battery":100,"rssi":"-87","power":"5748"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":43939,"watt":560.7545,"total":209.285,"pulse":"209285","battery":100,"rssi":"-86","power":"6574"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":43972,"watt":457.0295,"total":209.371,"pulse":"209371","battery":100,"rssi":"-85","power":"8066"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44011,"watt":1142.715,"total":209.579,"pulse":"209579","battery":100,"rssi":"-88","power":"3226"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44126,"watt":996.3243,"total":210.235,"pulse":"210235","battery":100,"rssi":"-90","power":"3700"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44171,"watt":3145.393,"total":210.74,"pulse":"210740","battery":100,"rssi":"-85","power":"1172"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44199,"watt":3432.402,"total":211.139,"pulse":"211139","battery":100,"rssi":"-85","power":"1074"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44371,"watt":6083.168,"total":212.872,"pulse":"212872","battery":100,"rssi":"-82","power":"606"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44381,"watt":3824.066,"total":213.062,"pulse":"213062","battery":100,"rssi":"-87","power":"964"}
EspSparsnasGateway/values {"seq":44382,"watt":4015.686,"total":213.078,"pulse":"213078","battery":100,"rssi":"-94","power":"918"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44399,"watt":5008.696,"total":213.4,"pulse":"213400","battery":100,"rssi":"-91","power":"736"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44410,"watt":4596.509,"total":213.623,"pulse":"213623","battery":100,"rssi":"-89","power":"802"}
EspSparsnasGateway/values {"seq":44411,"watt":4585.075,"total":213.642,"pulse":"213642","battery":100,"rssi":"-82","power":"804"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44425,"watt":2949.12,"total":213.838,"pulse":"213838","battery":100,"rssi":"-88","power":"1250"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44462,"watt":4738.303,"total":214.514,"pulse":"214514","battery":100,"rssi":"-83","power":"778"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44488,"watt":4517.647,"total":215.11,"pulse":"215110","battery":100,"rssi":"-90","power":"816"}
EspSparsnasGateway/values {"seq":44489,"watt":4506.602,"total":215.129,"pulse":"215129","battery":100,"rssi":"-81","power":"818"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44495,"watt":4619.549,"total":215.243,"pulse":"215243","battery":100,"rssi":"-87","power":"798"}
EspSparsnasGateway/values {"seq":44496,"watt":4573.697,"total":215.263,"pulse":"215263","battery":100,"rssi":"-88","power":"806"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44511,"watt":3963.871,"total":215.495,"pulse":"215495","battery":100,"rssi":"-89","power":"930"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44573,"watt":2972.903,"total":216.365,"pulse":"216365","battery":100,"rssi":"-85","power":"1240"}
EspSparsnasGateway/values {"seq":44574,"watt":3006.852,"total":216.377,"pulse":"216377","battery":100,"rssi":"-85","power":"1226"}
EspSparsnasGateway/values {"seq":44575,"watt":3006.852,"total":216.39,"pulse":"216390","battery":100,"rssi":"-88","power":"1226"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44578,"watt":2963.344,"total":216.427,"pulse":"216427","battery":100,"rssi":"-82","power":"1244"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44583,"watt":3245.07,"total":216.493,"pulse":"216493","battery":100,"rssi":"-95","power":"1136"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44607,"watt":4837.795,"total":216.847,"pulse":"216847","battery":100,"rssi":"-83","power":"762"}
EspSparsnasGateway/values {"seq":44608,"watt":4775.129,"total":216.869,"pulse":"216869","battery":100,"rssi":"-84","power":"772"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44614,"watt":3194.454,"total":216.978,"pulse":"216978","battery":100,"rssi":"-88","power":"1154"}
EspSparsnasGateway/values {"seq":44615,"watt":3188.927,"total":216.991,"pulse":"216991","battery":100,"rssi":"-91","power":"1156"}
EspSparsnasGateway/values {"seq":44616,"watt":3245.07,"total":217.005,"pulse":"217005","battery":100,"rssi":"-89","power":"1136"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44619,"watt":4726.154,"total":217.05,"pulse":"217050","battery":100,"rssi":"-83","power":"780"}
EspSparsnasGateway/values {"seq":44620,"watt":3092.617,"total":217.066,"pulse":"217066","battery":100,"rssi":"-88","power":"1192"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44639,"watt":3309.156,"total":217.207,"pulse":"217207","battery":100,"rssi":"-82","power":"1114"}
EspSparsnasGateway/values {"seq":44640,"watt":3256.537,"total":217.221,"pulse":"217221","battery":100,"rssi":"-94","power":"1132"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44648,"watt":3504.183,"total":217.334,"pulse":"217334","battery":100,"rssi":"-82","power":"1052"}
EspSparsnasGateway/values {"seq":44649,"watt":1647.185,"total":217.343,"pulse":"217343","battery":100,"rssi":"-89","power":"2238"}
EspSparsnasGateway/values {"seq":44650,"watt":1482.864,"total":217.349,"pulse":"217349","battery":100,"rssi":"-101","power":"2486"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44655,"watt":1647.185,"total":217.384,"pulse":"217384","battery":100,"rssi":"-88","power":"2238"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44657,"watt":1590.337,"total":217.397,"pulse":"217397","battery":100,"rssi":"-84","power":"2318"}
EspSparsnasGateway/values {"seq":44658,"watt":1628.269,"total":217.405,"pulse":"217405","battery":100,"rssi":"-90","power":"2264"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44660,"watt":1615.425,"total":217.419,"pulse":"217419","battery":100,"rssi":"-92","power":"2282"}
EspSparsnasGateway/values {"seq":44661,"watt":1641.318,"total":217.426,"pulse":"217426","battery":100,"rssi":"-98","power":"2246"}
EspSparsnasGateway/values {"seq":44662,"watt":1635.492,"total":217.433,"pulse":"217433","battery":100,"rssi":"-90","power":"2254"}
EspSparsnasGateway/values {"seq":44663,"watt":1598.612,"total":217.439,"pulse":"217439","battery":100,"rssi":"-94","power":"2306"}
EspSparsnasGateway/values {"seq":44664,"watt":1644.246,"total":217.446,"pulse":"217446","battery":100,"rssi":"-92","power":"2242"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44676,"watt":3369.653,"total":217.533,"pulse":"217533","battery":100,"rssi":"-87","power":"1094"}
EspSparsnasGateway/values {"seq":44677,"watt":3382.018,"total":217.547,"pulse":"217547","battery":100,"rssi":"-93","power":"1090"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44708,"watt":1594.464,"total":217.809,"pulse":"217809","battery":100,"rssi":"-93","power":"2312"}
EspSparsnasGateway/debug {"status":"Connected to Mqtt broker as EspSparsnasGateway"}
EspSparsnasGateway/values {"seq":44713,"watt":2944.409,"total":217.841,"pulse":"217841","battery":100,"rssi":"-84","power":"1252"}

Messages are sent much more frequently...

16:54:18.081 -> Attempting MQTT connection...Data here????
16:54:18.114 -> Connected to Mqtt broker as EspSparsnasGateway
16:54:21.280 -> Got rf data
16:54:26.681 -> Got rf data
16:54:32.314 -> Got rf data
16:54:32.781 -> Got rf data
16:54:32.781 -> Memory usage: 36256
16:54:32.781 -> Sending to mqtt: {"seq":44814,"watt":1265.065,"total":218.368,"pulse":"218368","battery":100,"rssi":"-84","power":"2914"}
16:54:36.599 -> Got rf data
16:54:39.397 -> Got rf data
16:54:39.530 -> Attempting MQTT connection...Data here????
16:54:39.564 -> Connected to Mqtt broker as EspSparsnasGateway
16:54:42.492 -> Got rf data
16:54:47.752 -> Got rf data
16:54:47.752 -> Memory usage: 36256
16:54:47.785 -> Sending to mqtt: {"seq":44815,"watt":1249.627,"total":218.373,"pulse":"218373","battery":100,"rssi":"-81","power":"2950"}
16:54:55.417 -> Got rf data
16:54:57.651 -> Got rf data
16:55:01.526 -> Attempting MQTT connection...Data here????
16:55:01.560 -> Connected to Mqtt broker as EspSparsnasGateway
16:55:02.767 -> Got rf data
16:55:02.767 -> Memory usage: 37600
16:55:02.767 -> Sending to mqtt: {"seq":44816,"watt":1237.878,"total":218.379,"pulse":"218379","battery":100,"rssi":"-85","power":"2978"}
dogmatic69 commented 5 years ago

I have debugged the pubsub package and the code is run all the way to at least the below line, and the result is true as I added some code to debug that.

rc = _client->write(buf+(MQTT_MAX_HEADER_SIZE-hlen),length+hlen);

dogmatic69 commented 5 years ago

After more debugging last night it started "working" and every single message was sent to MQTT.

Tonight I recompiled the same code and nothing is getting sent again. There is something really strange going on.

dogmatic69 commented 5 years ago

Seems to be stable now. Not seen any issues after weeks and many restarts