stimav4: RPC reponse arrive before RPC is completed

[pat1]

a success response is sended by station before rpc completation so we can have

• an RPC response with status OK
• the RPC is not completed

[pat1]

@digitecomg mi confermi che il problema è stato risolto ?

[digitecomg]

C'erano due diverse problematiche se ricordi e ne abbiamo parlato a voce, alla quale ne aggiungo una io adesso. La prima riguardava la non risposta di eventuali RPC messe in coda, risolta con appunto un buffer delle risposte, la seconda rimasta in sospeso sulla vera efficacia di una risposta solo al termine della RPC. Per esempio il download Dati se di lunga durata si può avere una risposta molto tardiva, oltre il tempo di validità della RPC. Questa risposta è un'assicurazione della presa in carico della richiesta. Alcune richieste come download del firmware devono interrompere il task di gestione mqtt per tornare a quello http e/o fare altre operazioni anche di lunga durata. Si deve ristabilire la connessione MQTT volutamente chiusa e/o chiusa per timeout dal server per comunicare il risultato della RPC. La risposta nella successiva connessione, se già disponibile, non fa altro che allungare i tempi dell'operatore che attende l'esecuzione della stessa e la conferma al server, unico strumento possibile di verifica dell'operatore.
Quello che aggiungo è questo: nel monitoraggio MQTT della connessione ho visto (ho fatto foto) che le pubblicazioni di RPC dal server al datalogger a volte arrivano dal server dopo il messaggio . Non dovrebbero essere la prima cosa subito dopo ? In quel caso per esempio non ho avuto risposta.
A volte invece proprio le RPC non vengono inviate ai datalogger.
Adesso per esempio non stanno andando

[pat1]

C'erano due diverse problematiche se ricordi e ne abbiamo parlato a voce, alla quale ne aggiungo una io adesso. La prima riguardava la non risposta di eventuali RPC messe in coda, risolta con appunto un buffer delle risposte, la seconda rimasta in sospeso sulla vera efficacia di una risposta solo al termine della RPC. Per esempio il download Dati se di lunga durata si può avere una risposta molto tardiva, oltre il tempo di validità della RPC. Questa risposta è un'assicurazione della presa in carico della richiesta. Alcune richieste come download del firmware devono interrompere il task di gestione mqtt per tornare a quello http e/o fare altre operazioni anche di lunga durata. Si deve ristabilire la connessione MQTT volutamente chiusa e/o chiusa per timeout dal server per comunicare il risultato della RPC. La risposta nella successiva connessione, se già disponibile, non fa altro che allungare i tempi dell'operatore che attende l'esecuzione della stessa e la conferma al server, unico strumento possibile di verifica dell'operatore.

il ritardo della conferma io non lo vedo come un problema, ma come una certezza che l'operazione è stata completata con successo. Il monitoraggio sul server non ha timeout, ma solo una procedura di manutenzione per il purge di trasazioni in sospeso. Comunque risolto il problema delle RPC senza risposta, questo lo si può ritenere un miglioramento.

Quello che aggiungo è questo: nel monitoraggio MQTT della connessione ho visto (ho fatto foto) che le pubblicazioni di RPC dal server al datalogger a volte arrivano dal server dopo il messaggio .

"dopo il messaggio" suppongo sia "dopo l'invio del primo messaggio"
credo che questo dipenda dal broker e da quando viene chiamata la funzione di aggiornamento della comunicazione con broker (nella libreria della V4 non so quale sia, in V3 era denominata loop() )

Non dovrebbero essere la prima cosa subito dopo ? In quel caso per esempio non ho avuto risposta.
A volte invece proprio le RPC non vengono inviate ai datalogger.
Adesso per esempio non stanno andando

Questo è un problema, però ora ho testato e funziona. Sto cercando di trovare una versione del broker funzionante ...
Se continua a non funzionare apri una issue dedicata.

[digitecomg]

A volte le RPC arrivano dopo il messaggio disconnect

[pat1]

https://www.hivemq.com/blog/mqtt-essentials-part-7-persistent-session-queuing-messages/
Non credo ci sia nessuna regola sulla tempistica per l'invio dei messaggi.

Alcune connessioni durano meno di 10 secondi e forse non è sufficiente per avere risposta dal DB del broker.

[2024-05-24 12:31:27] 1/maint/simcv4//1000494,4500253/agrmet/254,0,0/265,0,-,-/B01213 {"v":"conn", "s":4, "m":1}
[2024-05-24 12:31:28] 1/maint/simcv4//1000494,4500253/agrmet/254,0,0/265,0,-,-/B01213 {"t":"2024-05-24T10:30:00", "bs":"masterv4", "b":"0b0000000000000000", "c":[0,0,0,0]}
[2024-05-24 12:31:28] 1/maint/simcv4//1000494,4500253/agrmet/254,0,0/265,0,-,-/B01213 {"t":"2024-05-24T10:30:00", "bs":"module_mppt", "b":"0b0000000000000000", "c":[0,0,0,0]}
[2024-05-24 12:31:28] 1/maint/simcv4//1000494,4500253/agrmet/254,0,0/265,0,-,-/B01213 {"t":"2024-05-24T10:30:00", "bs":"module_th", "b":"0b0000000000000000", "c":[0,0,0,0]}
[2024-05-24 12:31:28] 1/maint/simcv4//1000494,4500253/agrmet/254,0,0/265,0,-,-/B01213 {"t":"2024-05-24T10:30:00", "bs":"module_rain", "b":"0b0000000000000000", "c":[0,0,0,0]}
[2024-05-24 12:31:34] 1/maint/simcv4//1000494,4500253/agrmet/254,0,0/265,0,-,-/B01213 {"v":"disconn"}

delle solo Stima V4 questo è un esempio delle tempistiche di connessione di TUTTE le stazioni (a cui vanno aggiunte le stima V3:

[2024-05-24 12:30:47]   prima connessione
[2024-05-24 12:31:52]   ultima disconnessione

in circa un minuto avviene l'invio di tutti i dati di tutte le stazioni.

Era previsto un tempo random di ritardo per la connessione al server; quanto vale ?
Come soluzione posso pensare a:

• allungare i tempi di connessione delle stazioni anche in assenda di dati da inviare
• allungare il ritardo random per le connessioni

[pat1]

https://stackoverflow.com/questions/66730803/mqtt-know-when-queue-is-processed

[digitecomg]

Non mi sembra una soluzione molto informatica... però può senz'altro funzionare.
Se risponde OK dovrebbe depositare anche i messaggi in coda.
Io ho un server in UDP per esempio che si occupa di ricevere i dati dalle stazioni. Risponde OK alla conferma trasmissione dato e risponde MSG se depositato un messaggio di verifica che il datalogger va poi a processare.
Ovviamente questo stato dovrebbe essere verificato da parte del broker in avvio, prima di rispondere OK ai messaggi pubblicati.
Il tempo random è attualmente di 60 secondi e possiamo sicuramente aumentarlo.
Dimmi come preferisci procedere.

[pat1]

Non mi sembra una soluzione molto informatica... però può senz'altro funzionare.
Se risponde OK dovrebbe depositare anche i messaggi in coda.

MQTT è asincrono e da uno a molti quindi questo non è possibile ne con la versione 3 e nemmeno con la versione 5 (per quanto mi è dato si sapere).
Nessun OK viene inviato, se non l'ack del messaggio inviato o ricevuto.
Si potrebbe costruire la comunicazione in veste di RPC , ma questo complica non di poco la comunicazione, la rallenta e riduce l'utilità di MQTT. La versione 5 di MQTT migliora la capacità di eseguire RPC ma la mia proposta di implementare sulle stima tale versione è stata rifiutata da Marco Baldinetti anche con ragione in quanto scarsamente testato.

Io ho un server in UDP per esempio che si occupa di ricevere i dati dalle stazioni. Risponde OK alla conferma trasmissione dato e risponde MSG se depositato un messaggio di verifica che il datalogger va poi a processare.
Ovviamente questo stato dovrebbe essere verificato da parte del broker in avvio, prima di rispondere OK ai messaggi pubblicati

Come dicevo questo non è possibile con la logica asincrona di MQTT salvo inventare stratagemmi.

Il tempo random è attualmente di 60 secondi e possiamo sicuramente aumentarlo.
Dimmi come preferisci procedere.

Io suggerisco se non troppo onero di impostare il tempo minimo di connessione a 30 secondi.
Anche i consumi non dovrebbero risentirne troppo visto che non transitano dati. Se tutto funziona abbiamo risolto.

Solo se non funziona possiamo provare a portare il ritardo random di invio a 120 secondi.

Come ultima possibilità possiamo anche inventare un metodo più deterministico, più complesso e forse energicamente non troppo conveniente quale per ogni stazione avere un messaggio con lo stato delle RPC ma essendo anche questa una comunicazione asincrona mi pare più creatore di problemi che risolutore. Una sequenza potrebbe essere:

• server imposta con persistenza topic stato a RPC presente
• serve scrive RPC
• client aspetta di ricevere topic stato RPC
• client se RPC presente aspetta di ricevere RPC
• client ricevuta RPC imposta con persistenza topic stato a RPC assente

mi pare comunque complesso e cercherei di evitarlo; ho attualmete attivo un test che ogni minuto verifica le funzionalità delle sessioni persistenti e con un tempo di connessione di 20 secondi non ho mai messaggi persi.

[digitecomg]

Ho provato ad inserire 15 secondi come minima connessione (quando tutto funziona nella mia stazione di test ci mette 2/3 secondi ad inviare i dati). 15 secondi è un tempo abbastanza lungo di attesa per la risposta server, poi posso allungarlo.
Il problema è che non arrivano le RPC ne prima ne dopo, attualmente sembra proprio bloccato il server MQTT.

[pat1]

Segnalo di aver consigliato 30 secondi e non 15 come tempo minimo di connessione, con possibilità di ridurlo successivamente. Questo perchè 30 secondi sono testati continuamente: dimezzare il tempo non è la stessa cosa.
Forse mi manca qualche motivazione a sostegno dell'affermazione "15 secondi è un tempo abbastanza lungo di attesa per la risposta server".
Per il resto relativamente alle RPC non inviate non riesco a trovare l'eventuale problema.
Queste le ultime RPC inviate:

2024-05-29 20:18:59 - root - INFO - RPC: admin {'fdownload': True} True submitted admin {'fdownload': True}
2024-05-29 20:18:59 - root - INFO - publish topic: 1/rpc/simcv4//1120006,4449614/agrmet/com payload: {"jsonrpc": "2.0", "method": "admin", "params": {"fdownload": true}, "id": 5}
2024-05-29 20:18:59 - root - INFO - wait for: 15
2024-05-29 20:19:14 - root - INFO - time: 2024-05-29 20:19:15
2024-05-29 20:19:14 - root - INFO - RPC: admin {'fdownload': True} True submitted admin {'fdownload': True}
2024-05-29 20:19:14 - root - INFO - publish topic: 1/rpc/simcv4//1016786,4500695/agrmet/com payload: {"jsonrpc": "2.0", "method": "admin", "params": {"fdownload": true}, "id": 5}
2024-05-29 20:19:14 - root - INFO - wait for: 15
2024-05-29 20:19:29 - root - INFO - time: 2024-05-29 20:19:30
2024-05-29 20:19:29 - root - INFO - RPC: admin {'fdownload': True} True submitted admin {'fdownload': True}
2024-05-29 20:19:29 - root - INFO - publish topic: 1/rpc/simcv4//1100357,4450354/locali/com payload: {"jsonrpc": "2.0", "method": "admin", "params": {"fdownload": true}, "id": 3}
2024-05-29 20:19:29 - root - INFO - wait for: 15
2024-05-29 20:19:44 - root - INFO - time: 2024-05-29 20:19:45
2024-05-29 20:19:44 - root - INFO - RPC: admin {'fdownload': True} True submitted admin {'fdownload': True}
2024-05-29 20:19:44 - root - INFO - publish topic: 1/rpc/simcv4//1250050,4403456/agrmet/com payload: {"jsonrpc": "2.0", "method": "admin", "params": {"fdownload": true}, "id": 4}
2024-05-29 20:19:45 - root - INFO - wait for: 14
2024-05-29 20:19:59 - root - INFO - time: 2024-05-29 20:20:00
2024-05-29 20:19:59 - root - INFO - RPC: admin {'fdownload': True} True submitted admin {'fdownload': True}
2024-05-29 20:19:59 - root - INFO - publish topic: 1/rpc/simcv4//1174639,4474656/agrmet/com payload: {"jsonrpc": "2.0", "method": "admin", "params": {"fdownload": true}, "id": 3}
2024-05-29 20:19:59 - root - INFO - wait for: 15
2024-05-29 20:20:14 - root - INFO - time: 2024-05-29 20:20:15
2024-05-29 20:20:14 - root - INFO - RPC: admin {'fdownload': True} True submitted admin {'fdownload': True}
2024-05-29 20:20:14 - root - INFO - publish topic: 1/rpc/simcv4//1175408,4441953/agrmet/com payload: {"jsonrpc": "2.0", "method": "admin", "params": {"fdownload": true}, "id": 3}
2024-05-29 20:20:14 - root - INFO - wait for: 15
2024-05-29 20:20:29 - root - INFO - time: 2024-05-29 20:20:30
2024-05-29 20:20:29 - root - INFO - RPC: admin {'fdownload': True} True submitted admin {'fdownload': True}
2024-05-29 20:20:29 - root - INFO - publish topic: 1/rpc/simcv4//1124125,4443967/locali/com payload: {"jsonrpc": "2.0", "method": "admin", "params": {"fdownload": true}, "id": 5}

e queste una serie di risposte:

2024-05-29 20:31:10 - root - INFO - user=simcv4 ident= lon=11.74639 lat=44.74656 network=agrmet prefix=rpc
2024-05-29 20:31:10 - root - INFO - try to save in django 
2024-05-29 20:31:14 - root - INFO - time: 2024-05-29 20:31:15
2024-05-29 20:31:14 - root - INFO - wait for: 15
2024-05-29 20:31:25 - root - INFO - user=simcv4 ident= lon=11.75408 lat=44.41953 network=agrmet prefix=rpc
2024-05-29 20:31:25 - root - INFO - try to save in django 
2024-05-29 20:31:29 - root - INFO - time: 2024-05-29 20:31:30
2024-05-29 20:31:29 - root - INFO - wait for: 15
2024-05-29 20:31:39 - root - INFO - user=simcv4 ident= lon=10.16786 lat=45.00695 network=agrmet prefix=rpc
2024-05-29 20:31:39 - root - INFO - try to save in django 
2024-05-29 20:31:43 - root - INFO - user=simcv4 ident= lon=11.20006 lat=44.49614 network=agrmet prefix=rpc
2024-05-29 20:31:43 - root - INFO - try to save in django 
2024-05-29 20:31:44 - root - INFO - time: 2024-05-29 20:31:45
2024-05-29 20:31:44 - root - INFO - wait for: 15
2024-05-29 20:31:46 - root - INFO - user=simcv4 ident= lon=11.24125 lat=44.43967 network=locali prefix=rpc
2024-05-29 20:31:46 - root - INFO - try to save in django 

Se vogliamo risolvere il problema la segnalazione ricevuta non è sufficiente.
Come minimo servono:

• ora di invio RPC
• stazione destinataria
• cosa ci si attendeva e cosa invece è successo

Qui riporto un semplice scrip bash per effettuare un test del broker mqtt

cat check_broker

export HOME=/tmp
USER=$1
PASSWORD=$2
TOPIC=$3

/usr/bin/mosquitto_sub -E -c    -u $USER -P $PASSWORD -q 1 -V 311 -i monit_sub -t $TOPIC
/usr/bin/mosquitto_pub          -u $USER -P $PASSWORD -q 1 -V 311 -i monit_pub -t $TOPIC -m check
/usr/bin/mosquitto_sub -W 20 -c -u $USER -P $PASSWORD -q 1 -V 311 -i monit_sub -t $TOPIC |grep -q check

eseguire:
check_broker USERNAME PASSWORD TOPIC

ovviamente tutti i parametri devono essere corretti

se lo script torna $? == 0 tutto ha funzionato

[pat1]

aggiungo tutte le RPC inviate il giorno 29 e ricevute tramite il broker:

[2024-05-29 19:45:33] 1/rpc/simcv4//1140259,4449920/agrmet/com {"jsonrpc": "2.0", "method": "admin", "params": {"sdinit": true}, "id": 2}
[2024-05-29 19:48:29] 1/rpc/simcv4//1140259,4449920/agrmet/com {"jsonrpc": "2.0", "method": "admin", "params": {"sdinit": true}, "id": 3}
[2024-05-29 19:52:44] 1/rpc/simcv4//1140259,4449920/agrmet/com {"jsonrpc": "2.0", "method": "admin", "params": {"fdownload": true}, "id": 4}
[2024-05-29 20:06:44] 1/rpc/simcv4//1140259,4449920/agrmet/com {"jsonrpc": "2.0", "method": "admin", "params": {"sdinit": true}, "id": 5}
[2024-05-29 20:11:29] 1/rpc/simcv4//1140259,4449920/agrmet/com {"jsonrpc": "2.0", "method": "admin", "params": {"sdinit": true}, "id": 6}
[2024-05-29 20:20:44] 1/rpc/simcv4//1140259,4449920/agrmet/com {"jsonrpc": "2.0", "method": "admin", "params": {"sdinit": true}, "id": 7}
[2024-05-29 20:22:44] 1/rpc/simcv4//1140259,4449920/agrmet/com {"jsonrpc": "2.0", "method": "admin", "params": {"sdinit": true}, "id": 8}
[2024-05-29 20:26:29] 1/rpc/simcv4//1140259,4449920/agrmet/com {"jsonrpc": "2.0", "method": "admin", "params": {"fdownload": true}, "id": 9}
[2024-05-29 20:40:15] 1/rpc/simcv4//1095670,4470214/agrmet/com {"jsonrpc": "2.0", "method": "admin", "params": {"pgcalib": true}, "id": 3}
[2024-05-29 20:40:59] 1/rpc/simcv4//1051062,4468953/agrmet/com {"jsonrpc": "2.0", "method": "admin", "params": {"pgcalib": true}, "id": 3}
[2024-05-29 22:18:59] 1/rpc/simcv4//1120006,4449614/agrmet/com {"jsonrpc": "2.0", "method": "admin", "params": {"fdownload": true}, "id": 5}
[2024-05-29 22:19:14] 1/rpc/simcv4//1016786,4500695/agrmet/com {"jsonrpc": "2.0", "method": "admin", "params": {"fdownload": true}, "id": 5}
[2024-05-29 22:19:29] 1/rpc/simcv4//1100357,4450354/locali/com {"jsonrpc": "2.0", "method": "admin", "params": {"fdownload": true}, "id": 3}
[2024-05-29 22:19:45] 1/rpc/simcv4//1250050,4403456/agrmet/com {"jsonrpc": "2.0", "method": "admin", "params": {"fdownload": true}, "id": 4}
[2024-05-29 22:19:59] 1/rpc/simcv4//1174639,4474656/agrmet/com {"jsonrpc": "2.0", "method": "admin", "params": {"fdownload": true}, "id": 3}
[2024-05-29 22:20:14] 1/rpc/simcv4//1175408,4441953/agrmet/com {"jsonrpc": "2.0", "method": "admin", "params": {"fdownload": true}, "id": 3}
[2024-05-29 22:20:29] 1/rpc/simcv4//1124125,4443967/locali/com {"jsonrpc": "2.0", "method": "admin", "params": {"fdownload": true}, "id": 5}

e queste le risposte sempre del giorno 29:

[2024-05-29 20:24:17] 1/rpc/simcv4//1140259,4449920/agrmet/res {"jsonrpc":"2.0","id":8,"result":{"state":"done"}}
[2024-05-29 20:27:09] 1/rpc/simcv4//1140259,4449920/agrmet/res {"jsonrpc":"2.0","id":9,"result":{"state":"done"}}
[2024-05-29 20:46:01] 1/rpc/simcv4//1051062,4468953/agrmet/res {"jsonrpc":"2.0","id":3,"result":{"state":"done"}}
[2024-05-29 20:46:10] 1/rpc/simcv4//1095670,4470214/agrmet/res {"jsonrpc":"2.0","id":3,"result":{"state":"done"}}
[2024-05-29 22:31:10] 1/rpc/simcv4//1174639,4474656/agrmet/res {"jsonrpc":"2.0","id":3,"result":{"state":"done"}}
[2024-05-29 22:31:25] 1/rpc/simcv4//1175408,4441953/agrmet/res {"jsonrpc":"2.0","id":3,"result":{"state":"done"}}
[2024-05-29 22:31:39] 1/rpc/simcv4//1016786,4500695/agrmet/res {"jsonrpc":"2.0","id":5,"result":{"state":"done"}}
[2024-05-29 22:31:43] 1/rpc/simcv4//1120006,4449614/agrmet/res {"jsonrpc":"2.0","id":5,"result":{"state":"done"}}
[2024-05-29 22:31:46] 1/rpc/simcv4//1124125,4443967/locali/res {"jsonrpc":"2.0","id":5,"result":{"state":"done"}}

[digitecomg]

Le prime che ho mandato erano senza consegna del messaggio (ero anche in ascolto su monitor MQTT), poi ad un certo punto poco dopo che ho inviato il messaggio su GitHub circa 10' (il messaggio dei 15 secondi), è arrivata la prima RPC (37 secondi dopo la connessione), avevo impostato 40 per fare vari tentativi.
Successivamente hanno iniziato ad arrivare puntuali al momento della connessione.
Onestamente non so se 15 secondi o 30 fanno differenza, forse sì ma il problema sembrava proprio un'altro.
Poi se dici di mettere 30 secondi lo faccio subito.

[pat1]

Non mi pare correlato ma ho rimosso un limite che imponeva un massimo di 2 messaggi accodati per ogni stazione.

[digitecomg]

OK