<!DOCTYPE html>
<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
</head>
<body>
Chris, Michael,<br>
<br>
by "regular status ping" I meant testing the car status while off by
sending a request every few seconds. The "off" state for the Leaf is
state 0, none of the polls has an interval in that slot. So while
the Leaf is considered "off" by the module, there should be no new
(!) requests.<br>
<br>
If a final round of the BMS polls would have been kept in the queue,
that would only contain at most one entry for each of the polls,
i.e. four TX in total, with PIDs 0x01, 0x02, 0x06, 0x04 (with 0x04
only being polled every 5 minutes). The first TX_Fail would then
remove the poll from the queue.<br>
<br>
But your log shows repeated TX failures for 0x01, 0x02 & 0x06.
So no, that's not normal.<br>
<br>
That can only happen, if either the Leaf code has a bug with
detecting the correct vehicle state (and with announcing that by
some log / event, would need to be "on" or "charging" according to
the polling scheme)…<br>
<br>
…or the new poller has a bug, that leads to keeping or re-entering a
wrong poll state. The latter could affect other vehicles as well.<br>
<br>
<blockquote type="cite">
<div><span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738275829.012407
CXX OVMS CRTD</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738275829.012407
CVR 3.1</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738275829.020355
1CXX Info Type:vfs Format:crtd(discard) Vehicle:NL
Path:/sd/can4.crtd</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;"><b>1738275879</b>.419663
1CER TX_Fail T11 79B 02 21 <b>01</b> 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738275880.419598
1CER TX_Fail T11 79B 02 21 <b>02</b> 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738275881.419606
1CER TX_Fail T11 79B 02 21 <b>06</b> 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;"><b>1738275942</b>.419724
1CER TX_Fail T11 79B 02 21 <b>01</b> 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738275943.419618
1CER TX_Fail T11 79B 02 21 <b>02</b> 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738275944.419611
1CER TX_Fail T11 79B 02 21 <b>06</b> 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;"><b>1738276005</b>.419663
1CER TX_Fail T11 79B 02 21 <b>01</b> 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738276006.419606
1CER TX_Fail T11 79B 02 21 <b>02</b> 55 55 55 55 55</span></div>
</blockquote>
<br>
From the timestamps, that's the 60 seconds interval (63 due to the
error/timeout), so that must have been poll state 1 (on) or 3
(charging).<br>
<br>
You need to check the poll state transitions. These get logged by
the poller (log tag "vehicle-poll"), which needs to be set to log
level "debug" for this.<br>
<br>
You should then see log entries "Pollers: Queue SetState" for the
state change request & "Pollers:
PollState(<state>[,<bus>])" for the actual state change.<br>
<br>
A log entry "Pollers[SetState]: Task Queue Overflow" (btw, that's
currently at "info" level, should be "error") indicates a state
change request got lost. That should not happen.<br>
<br>
<br>
@Michael: the poller currently allows state changes to get lost. I
think that's a problem. Not properly transitioning the poll state
could cause mayhem, as the wrong polls can cause damage, either by
putting the vehicle in a fault mode, or simply by not letting the
ECUs go to sleep, causing the 12V battery to drain.<br>
<br>
I think state changes must not get lost, if that happens, that's
rather a reason for `abort()` if it cannot be handled otherwise. The
same applies to all poll list management commands. Maybe it's an
option to make these queue requests blocking? Or to introduce a
secondary queue for poller control commands?<br>
<br>
Any additional ideas for Chris on how to investigate this further?<br>
<br>
Regards,<br>
Michael<br>
<br>
<br>
<div class="moz-cite-prefix">Am 02.02.25 um 13:58 schrieb Chris Box:<br>
</div>
<blockquote type="cite"
cite="mid:010b0194c6bd947c-dea76337-fc80-4070-9df9-28b92d94506f-000000@eu-west-2.amazonses.com">
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
<p id="reply-intro">Hi everyone,</p>
<p>On 2025-01-28 19:12, Michael Balzer wrote:</p>
<blockquote type="cite"
style="padding: 0 0.4em; border-left: #1010ff 2px solid; margin: 0">
<div>Reading the Leaf code, I don't see any regular status ping
polling,</div>
<div> </div>
</blockquote>
<div> </div>
<div>Actually there is some defined polling of BMS:</div>
<div> </div>
<div><span
style="font-family: 'courier new', courier, monospace; font-size: 8pt;">static
const OvmsPoller::poll_pid_t obdii_polls[] =</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 8pt;">
{</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 8pt;">
// BUS 2</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 8pt;">
{ CHARGER_TXID, CHARGER_RXID, VEHICLE_POLL_TYPE_OBDIIGROUP,
VIN_PID, { 0, 900, 0, 0 }, 2, ISOTP_STD }, // VIN
[19]</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 8pt;">
{ CHARGER_TXID, CHARGER_RXID,
VEHICLE_POLL_TYPE_OBDIIEXTENDED, QC_COUNT_PID, { 0, 900, 0, 0
}, 2, ISOTP_STD }, // QC [2]</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 8pt;">
{ CHARGER_TXID, CHARGER_RXID,
VEHICLE_POLL_TYPE_OBDIIEXTENDED, L1L2_COUNT_PID, { 0, 900, 0,
0 }, 2, ISOTP_STD }, // L0/L1/L2 [2]</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 8pt;">
// BUS 1</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 8pt;">
{ BMS_TXID, BMS_RXID, VEHICLE_POLL_TYPE_OBDIIGROUP, 0x01, {
0, 60, 0, 60 }, 1, ISOTP_STD }, // bat [39/41]</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 8pt;">
{ BMS_TXID, BMS_RXID, VEHICLE_POLL_TYPE_OBDIIGROUP, 0x02, {
0, 60, 0, 60 }, 1, ISOTP_STD }, // battery voltages [196]</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 8pt;">
{ BMS_TXID, BMS_RXID, VEHICLE_POLL_TYPE_OBDIIGROUP, 0x06, {
0, 60, 0, 60 }, 1, ISOTP_STD }, // battery shunts [96]</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 8pt;">
{ BMS_TXID, BMS_RXID, VEHICLE_POLL_TYPE_OBDIIGROUP, 0x04, {
0, 300, 0, 300 }, 1, ISOTP_STD }, // battery temperatures
[14]</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 8pt;">
POLL_LIST_END</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 8pt;">
};</span></div>
<div> </div>
<div>BMS_TXID is 0x79B, and this is mostly what I see appearing in
CRTD overnight:</div>
<div> </div>
<div><span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738275829.012407
CXX OVMS CRTD</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738275829.012407
CVR 3.1</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738275829.020355
1CXX Info Type:vfs Format:crtd(discard) Vehicle:NL
Path:/sd/can4.crtd</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738275879.419663
1CER TX_Fail T11 79B 02 21 01 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738275880.419598
1CER TX_Fail T11 79B 02 21 02 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738275881.419606
1CER TX_Fail T11 79B 02 21 06 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738275942.419724
1CER TX_Fail T11 79B 02 21 01 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738275943.419618
1CER TX_Fail T11 79B 02 21 02 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738275944.419611
1CER TX_Fail T11 79B 02 21 06 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738276005.419663
1CER TX_Fail T11 79B 02 21 01 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738276006.419606
1CER TX_Fail T11 79B 02 21 02 55 55 55 55 55</span></div>
<div> </div>
<div>The first night, that was everything I saw until a charge
pilot event woke the car up at 05:50.</div>
<div> </div>
<div>The second night, at 03:46 there were two records of
apparently successful transmits, which coincides with errors
being logged.</div>
<div> </div>
<div><span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738381606.559723
1CER TX_Fail T11 79B 02 21 01 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738381607.560118
1CER TX_Fail T11 79B 02 21 02 55 55 55 55 55</span></div>
<div><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738381607.561672
1CER Error intr=32898937 rxpkt=32886195 txpkt=4872
errflags=0x204c00 rxerr=0 txerr=127 rxinval=0 rxovr=3 txovr=0
txdelay=213 txfail=5411 wdgreset=0 errreset=5 txqueue=0</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738381607.561766
<strong>1T11 79B 02 21 02 55 55 55 55 55</strong></span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738381607.561816
1CST Status intr=32898937 rxpkt=32886195 txpkt=4873
errflags=0x204c00 rxerr=0 txerr=127 rxinval=0 rxovr=3 txovr=0
txdelay=213 txfail=5411 wdgreset=0 errreset=5 txqueue=0</span></div>
<div><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738381608.559656
1CER TX_Fail T11 79B 02 21 06 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738381608.559819
1CST Status intr=32898940 rxpkt=32886195 txpkt=4873
errflags=0x8048d9 rxerr=0 txerr=135 rxinval=0 rxovr=3 txovr=0
txdelay=213 txfail=5412 wdgreset=0 errreset=5 txqueue=0</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738381608.561065
1CER Error intr=32898943 rxpkt=32886195 txpkt=4873
errflags=0x8048d9 rxerr=0 txerr=134 rxinval=0 rxovr=3 txovr=0
txdelay=213 txfail=5412 wdgreset=0 errreset=5 txqueue=0</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738381608.561163
<strong>1T11 79B 02 21 06 55 55 55 55 55</strong></span></div>
<div><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738381669.559719
1CER TX_Fail T11 79B 02 21 01 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738381670.559655
1CER TX_Fail T11 79B 02 21 02 55 55 55 55 55</span></div>
<div> </div>
<div>The above activity is what creates records in the
otherwise-quiet system log:</div>
<div>2025-02-01 03:46:48.272 GMT E (189607402) can: can1:
intr=32898936 rxpkt=32886195 txpkt=4872 errflags=0x8048d9
rxerr=0 txerr=128 rxinval=0 rxovr=3 txovr=0 txdelay=213
txfail=5411 wdgreset=0 er<br>
rreset=5 txqueue=0<br>
2025-02-01 03:46:49.272 GMT E (189608402) can: can1:
intr=32898940 rxpkt=32886195 txpkt=4873 errflags=0x8048d9
rxerr=0 txerr=135 rxinval=0 rxovr=3 txovr=0 txdelay=213
txfail=5412 wdgreset=0 er<br>
rreset=5 txqueue=0</div>
<div> </div>
<div>It fits well with your description below, although in these
nights I didn't see any queuing. Just a small probability of
thinking it can send a frame on a bus that's off.</div>
<div> </div>
<blockquote type="cite"
style="padding: 0 0.4em; border-left: #1010ff 2px solid; margin: 0">
<div id="replybody1">On my UpMiiGo (which switches off the bus),
the ESP32CAN most of the time recognizes an immediate failure
for a TX with the vehicle being off. That means the TX buffer
(in the controller) gets cleared immediately, with an
immediate "TX_Fail" result for the frame. Ideally that would
be the case always while the bus is off.<br>
<br>
But the ESP32CAN controller sometimes tries to send the frame,
waiting for an ack, repeating the transmission and then ending
up in the frame being stuck in the TX buffer. Then the TX
queue (software) gets filled with the status ping request
frame from there, up to the 30 frames capacity of the TX
queue, then counting TX overflows.<br>
<br>
This continues until the ESP32CAN, due to unknown reasons,
thinks it could send the frame. The TX queue then gets flushed
immediately, with the frames appearing as being sent
successfully (although there is no ECU active, the bus is
still off).<br>
<br>
After the queue has been cleared, this loop starts over.<br>
<br>
So it may happen, that the TX queue gets filled, and the
ESP32CAN thinks it can send frames, even while the bus is shut
off.<br>
<br>
</div>
</blockquote>
<div> </div>
<div>On the third night the crtd log says it tried to send BMS
polls at 23:37, 23:39, 00:00 and 00:02.</div>
<div> </div>
<div><span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738452975.674976
1CER TX_Fail T11 79B 02 21 06 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738453036.675613
1CER TX_Fail T11 79B 02 21 01 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738453036.677195
1CER Error intr=41628672 rxpkt=41612603 txpkt=6073
errflags=0x8048d9 rxerr=0 txerr=128 rxinval=0 rxovr=3 txovr=0
txdelay=259 txfail=6847 wdgreset=0 errreset=7 txqueue=0</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738453036.686582
<strong>1T11 79B 02 21 01 55 55 55 55 55</strong></span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738453036.686690
1CST Status intr=41628708 rxpkt=41612603 txpkt=6074
errflags=0x204c00 rxerr=0 txerr=127 rxinval=0 rxovr=3 txovr=0
txdelay=259 txfail=6847 wdgreset=0 errreset=7 txqueue=0</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738453037.674988
1CER TX_Fail T11 79B 02 21 02 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738453037.675148
1CST Status intr=41628711 rxpkt=41612603 txpkt=6074
errflags=0x8048d9 rxerr=0 txerr=135 rxinval=0 rxovr=3 txovr=0
txdelay=259 txfail=6848 wdgreset=0 errreset=7 txqueue=0</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738453037.676306
1CER Error intr=41628714 rxpkt=41612603 txpkt=6074
errflags=0x8048d9 rxerr=0 txerr=134 rxinval=0 rxovr=3 txovr=0
txdelay=259 txfail=6848 wdgreset=0 errreset=7 txqueue=0</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738453037.676389
<strong>1T11 79B 02 21 02 55 55 55 55 55</strong></span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738453038.674985
1CER TX_Fail T11 79B 02 21 06 55 55 55 55 55</span></div>
<div> </div>
<div><span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738453164.675494
1CER TX_Fail T11 79B 02 21 02 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738453164.676968
1CER Error intr=41628729 rxpkt=41612603 txpkt=6075
errflags=0x8048d9 rxerr=0 txerr=133 rxinval=0 rxovr=3 txovr=0
txdelay=259 txfail=6855 wdgreset=0 errreset=7 txqueue=0</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738453164.677076
<strong>1T11 79B 02 21 02 55 55 55 55 55</strong></span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738453165.675001
1CER TX_Fail T11 79B 02 21 06 55 55 55 55 55</span></div>
<div> </div>
<div><span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738454366.674962
1CER TX_Fail T11 79B 02 21 04 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738454427.675572
1CER TX_Fail T11 79B 02 21 01 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738454427.677047
1CER Error intr=41628861 rxpkt=41612603 txpkt=6076
errflags=0x8048d9 rxerr=0 txerr=133 rxinval=0 rxovr=3 txovr=0
txdelay=259 txfail=6918 wdgreset=0 errreset=7 txqueue=0</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738454427.686539
<strong>1T11 79B 02 21 01 55 55 55 55 55</strong></span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738454428.674962
1CER TX_Fail T11 79B 02 21 02 55 55 55 55 55</span></div>
<div> </div>
<div><span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738454555.679243
1CER TX_Fail T11 79B 02 21 06 55 55 55 55 55</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738454555.680668
1CER Error intr=41628916 rxpkt=41612603 txpkt=6077
errflags=0x8048d9 rxerr=0 txerr=131 rxinval=0 rxovr=3 txovr=0
txdelay=259 txfail=6926 wdgreset=0 errreset=7 txqueue=0</span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738454555.680756
<strong>1T11 79B 02 21 06 55 55 55 55 55</strong></span><br>
<span
style="font-family: 'courier new', courier, monospace; font-size: 9pt;">1738454616.678795
1CER TX_Fail T11 79B 02 21 01 55 55 55 55 55</span></div>
<div> </div>
<div><span
style="font-family: verdana, geneva, sans-serif; font-size: 10pt;">So
far I haven't seen any errors with a non-zero txqueue value,
but I'll continue to keep a lookout for any issues. Until
then, this seems to be its normal behaviour. I haven't
explored the Leaf modules' BMS polling code, but I'm wondering
if some changes there would help, e.g. not polling when the
car is off.</span></div>
<div> </div>
<div><span
style="font-family: verdana, geneva, sans-serif; font-size: 10pt;">Chris</span></div>
</blockquote>
<br>
<pre class="moz-signature" cols="72">--
Michael Balzer * Am Rahmen 5 * D-58313 Herdecke
Fon 02330 9104094 * Handy 0176 20698926</pre>
</body>
</html>