<html><head>
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
</head>
<body><div>Thanx for your help.</div><div><br></div><div>I tried CONFIG_OVMS_HW_CAN_TX_QUEUE_SIZE=60 without success and callback crashes in can.cpp:723:</div><div><br></div><div>718 {</div><div>719 bool loop;</div><div>720 // Loop until all interrupts are handled</div><div>721 do {</div><div>722 bool receivedFrame;</div><div>723 loop = msg.body.bus->AsynchronousInterruptHandler(&msg.body.frame, &receivedFrame);</div><div>724 if (receivedFrame)</div><div>725 me->IncomingFrame(&msg.body.frame);</div><div>726 } while (loop);</div><div>727 break;</div><div></div><div><br></div><div>Will continue trying ...</div><div><br></div><div>Regards</div><div><br></div><div>Chris</div><div><br></div><div>Am Donnerstag, den 17.09.2020, 21:35 +0200 schrieb Michael Balzer:</div><blockquote type="cite">
That looks like a bug in the MCP2515 driver.<br>
<br>
<blockquote type="cite">
<pre class="moz-quote-pre" wrap="">The TX that come to the bus (3T11) we see 15 times the first messages
(that is right), one time the second messages (wrong, should be two)
and 6 times the third messages (wrong, should be 5).</pre>
</blockquote>
<br>
I haven't fully analyzed the code path yet, but my impression so far
is we have a race condition between mcp2515::Write() and
mcp2515::AsynchronousInterruptHandler(). If I'm right, that could
lead to wrong TX log entries and even to lost or out of sequence
frame transmissions in a situation like yours, when many frames get
sent in series without any delay.<br>
<br>
The race scheme is:<br>
<br>
- The application task (low prio) calls Write() concurrently to the
"TX done" interrupt of the last frame sent being raised.<br>
- The interrupt is sent to the CAN task (high prio), which calls
AsynchronousInterruptHandler() concurrently now to the Write().<br>
- Both Write() and AsynchronousInterruptHandler() may now get "TX
buffer is free" from the MCP2515<br>
- …Write() will then immediately fill the TX buffer with the new
frame<br>
- …and AsynchronousInterruptHandler() will concurrently fill the TX
buffer with the next frame of the TX queue if any<br>
<br>
As the SPI bus has a lock, both writes may succeed, but m_tx_frame
will contain only the last of the two frames, so the next log entry
will be wrong. The m_tx_frame container (originating from PR 259)
has been designed under the assumption of stricly sequential frame
transmissions.<br>
<br>
You could have had that very effect on the second time of the second
message vs. the first time of the third message:<br>
<br>
<tt>1600352233.392765 3CER TX_Queue T11 291 <b>8a</b><b> aa</b> 00
00 00 46 03 00</tt><tt><br>
</tt><tt>1600352233.394239 3T11 291 <b>8a</b><b> aa</b> 00 00 00 46
03 00</tt><tt><br>
</tt><tt>1600352233.394816 3CER TX_Queue T11 291 <b>00</b><b> aa</b>
00 00 00 46 03 00</tt><tt><br>
</tt><tt>1600352233.395680 3T11 291 <b>8a</b><b> aa</b> 00 00 00 46
03 00</tt><tt><br>
</tt><tt>1600352233.396153 3CER TX_Queue T11 291 <b>00</b><b> aa</b>
00 00 00 46 03 00</tt><tt><br>
</tt><tt>1600352233.404239 3T11 291 <b>00</b><b> aa</b> 00 00 00 46
03 00<br>
</tt><tt>1600352233.404538 3CER TX_Queue T11 291 <b>00 00</b> 00 00
00 46 03 00<br>
1600352233.404753 3CER TX_Queue T11 291 <b>00 00</b> 00 00 00 46
03 00<br>
</tt><tt><tt><tt>… </tt><tt>TX "00 aa" done IRQ coming in here,
queue has "00 00" frame ready which gets sent concurrently<br>
→ wrong frame "00 00" is now in m_tx_frame and gets logged
instead of "00 aa":<br>
</tt></tt>1600352233.405126 3T11 291 <b>00 00</b> 00 00 00 46
03 00<br>
<br>
</tt><br>
A second opinion on this would be good, possibly by someone else who
has worked on the MCP2515 code last?<br>
<br>
Chris, while we're thinking about this, you could try serialising
the frames by sending them one by one using the TX callback. The TX
queue is meant to handle bulk transmissions, but you may need to
raise the queue size (sdkconfig:
CONFIG_OVMS_HW_CAN_TX_QUEUE_SIZE=20) in that case.<br>
<br>
<blockquote type="cite">
<pre class="moz-quote-pre" wrap="">On the RX side (3R11) we only see 3 times the first messages, none of
the second and one of the third.
</pre>
</blockquote>
<br>
The RX log entries are the frames received from the vehicle.<br>
<br>
Regards,<br>
Michael<br>
<br>
<br>
<br>
<div class="moz-cite-prefix">Am 17.09.20 um 17:06 schrieb Chris van
der Meijden:<br>
</div>
<blockquote type="cite" cite="mid:1600355177.27369.1.camel@arachnon.de">
<pre class="moz-quote-pre" wrap="">Hi all
I'm trying to make the Lock/Unlock function work for the VW e-UP on
T26A.
I found the right messages and got it working once, not knowing why.
What I need to do is sending 22 messages in a row. My code for that is:
// Send 0x291 messages
for (k=0;k<15;k++)
{
data[0] = 0x8A;
data[1] = 0xAA;
data[2] = 0x00;
data[3] = 0x00;
data[4] = 0x00;
data[5] = 0x46;
data[6] = 0x03;
data[7] = 0x00;
if (vwup_enable_write && !dev_mode)
comfBus->WriteStandard(0x291, length, data);
}
for (k=0;k<2;k++)
{
data[0] = 0x00;
data[1] = 0xAA;
data[2] = 0x00;
data[3] = 0x00;
data[4] = 0x00;
data[5] = 0x46;
data[6] = 0x03;
data[7] = 0x00;
if (vwup_enable_write && !dev_mode)
comfBus->WriteStandard(0x291, length, data);
}
for (k=0;k<5;k++)
{
data[0] = 0x00;
data[1] = 0x00;
data[2] = 0x00;
data[3] = 0x00;
data[4] = 0x00;
data[5] = 0x46;
data[6] = 0x03;
data[7] = 0x00;
if (vwup_enable_write && !dev_mode)
comfBus->WriteStandard(0x291, length, data);
}
This is what I get in the logging:
V (96275) canlog-monitor: 1600352233.355713 3T11 291 8a aa 00 00 00 46
03 00
V (96275) canlog-monitor: 1600352233.357066 3CER TX_Queue T11 291 8a aa
00 00 00 46 03 00
V (96275) canlog-monitor: 1600352233.357673 3T11 291 8a aa 00 00 00 46
03 00
V (96275) canlog-monitor: 1600352233.358156 3CER TX_Queue T11 291 8a aa
00 00 00 46 03 00
E (96285) mcp2515: AsynchronousInterruptHandler: error while sending
frame. msgId 0x291
V (96285) canlog-monitor: 1600352233.364241 3T11 291 8a aa 00 00 00 46
03 00
E (96285) can: can3: intr=8 rxpkt=0 txpkt=4 errflags=0x85050101 rxerr=0
txerr=107 rxovr=0 txovr=0 txdelay=6 wdgreset=0 errreset=0
V (96285) canlog-monitor: 1600352233.364745 3CER TX_Queue T11 291 8a aa
00 00 00 46 03 00
W (96285) mcp2515: can3 EFLG: TX_Err_Warn EWARN
V (96285) canlog-monitor: 1600352233.364965 3CER TX_Queue T11 291 8a aa
00 00 00 46 03 00
E (96285) can: can3: intr=8 rxpkt=1 txpkt=5 errflags=0x4050104 rxerr=0
txerr=107 rxovr=0 txovr=0 txdelay=6 wdgreset=0 errreset=0
E (96285) canlog-monitor: 1600352233.366305 3CER Error intr=8 rxpkt=0
txpkt=4 errflags=0x85050101 rxerr=0 txerr=107 rxovr=0 txovr=0 txdelay=6
wdgreset=0 errreset=0
V (96285) canlog-monitor: 1600352233.367035 3R11 291 8a aa 00 00 00 46
03 00
V (96285) canlog-monitor: 1600352233.367620 3T11 291 8a aa 00 00 00 46
03 00
V (96295) canlog-monitor: 1600352233.367647 3CER TX_Fail T11 291 8a aa
00 00 00 46 03 00
E (96295) canlog-monitor: 1600352233.368350 3CER Error intr=8 rxpkt=1
txpkt=5 errflags=0x4050104 rxerr=0 txerr=107 rxovr=0 txovr=0 txdelay=6
wdgreset=0 errreset=0
V (96295) canlog-monitor: 1600352233.368403 3T11 291 8a aa 00 00 00 46
03 00
V (96295) canlog-monitor: 1600352233.369064 3T11 291 8a aa 00 00 00 46
03 00
V (96295) canlog-monitor: 1600352233.370243 3R11 470 40 00 00 00 00 00
00 14
V (96295) canlog-monitor: 1600352233.371859 3CER TX_Queue T11 291 8a aa
00 00 00 46 03 00
V (96295) canlog-monitor: 1600352233.374239 3T11 291 8a aa 00 00 00 46
03 00
V (96295) canlog-monitor: 1600352233.374827 3CER TX_Queue T11 291 8a aa
00 00 00 46 03 00
V (96295) canlog-monitor: 1600352233.375507 3T11 291 8a aa 00 00 00 46
03 00
V (96295) canlog-monitor: 1600352233.375976 3CER TX_Queue T11 291 8a aa
00 00 00 46 03 00
V (96305) canlog-monitor: 1600352233.384241 3T11 291 8a aa 00 00 00 46
03 00
V (96305) canlog-monitor: 1600352233.384985 3CER TX_Queue T11 291 8a aa
00 00 00 46 03 00
V (96305) canlog-monitor: 1600352233.385602 3CER TX_Queue T11 291 8a aa
00 00 00 46 03 00
E (96305) can: can3: intr=14 rxpkt=2 txpkt=10 errflags=0x27450501
rxerr=0 txerr=100 rxovr=0 txovr=0 txdelay=12 wdgreset=0 errreset=0
V (96305) canlog-monitor: 1600352233.386140 3CER TX_Queue T11 291 8a aa
00 00 00 46 03 00
W (96305) mcp2515: can3 EFLG: TX_Err_Warn EWARN
E (96305) canlog-monitor: 1600352233.387010 3CER Error intr=14 rxpkt=2
txpkt=10 errflags=0x27450501 rxerr=0 txerr=100 rxovr=0 txovr=0
txdelay=12 wdgreset=0 errreset=0
V (96305) canlog-monitor: 1600352233.387820 3R11 291 8a aa 00 00 00 46
03 00
V (96315) canlog-monitor: 1600352233.388508 3R11 291 8a aa 00 00 00 46
03 00
V (96315) canlog-monitor: 1600352233.388548 3T11 291 8a aa 00 00 00 46
03 00
V (96315) canlog-monitor: 1600352233.388586 3T11 291 8a aa 00 00 00 46
03 00
V (96315) canlog-monitor: 1600352233.390509 3T11 291 8a aa 00 00 00 46
03 00
V (96315) canlog-monitor: 1600352233.391040 3R11 359 ff 89 ff 00 10 6b
80 00
V (96315) canlog-monitor: 1600352233.392246 3T11 291 8a aa 00 00 00 46
03 00
V (96315) canlog-monitor: 1600352233.392765 3CER TX_Queue T11 291 8a aa
00 00 00 46 03 00
V (96315) canlog-monitor: 1600352233.394239 3T11 291 8a aa 00 00 00 46
03 00
V (96315) canlog-monitor: 1600352233.394816 3CER TX_Queue T11 291 00 aa
00 00 00 46 03 00
V (96315) canlog-monitor: 1600352233.395680 3T11 291 8a aa 00 00 00 46
03 00
V (96315) canlog-monitor: 1600352233.396153 3CER TX_Queue T11 291 00 aa
00 00 00 46 03 00
V (96325) canlog-monitor: 1600352233.404239 3T11 291 00 aa 00 00 00 46
03 00
V (96325) canlog-monitor: 1600352233.404538 3CER TX_Queue T11 291 00 00
00 00 00 46 03 00
V (96325) canlog-monitor: 1600352233.404753 3CER TX_Queue T11 291 00 00
00 00 00 46 03 00
V (96325) canlog-monitor: 1600352233.404791 3R11 291 00 00 00 00 00 46
03 00
V (96325) canlog-monitor: 1600352233.405089 3R11 457 00 47 00
V (96325) canlog-monitor: 1600352233.405126 3T11 291 00 00 00 00 00 46
03 00
V (96325) canlog-monitor: 1600352233.406203 3T11 291 00 00 00 00 00 46
03 00
V (96325) canlog-monitor: 1600352233.407538 3T11 291 00 00 00 00 00 46
03 00
V (96325) canlog-monitor: 1600352233.408701 3CER TX_Queue T11 291 00 00
00 00 00 46 03 00
V (96335) canlog-monitor: 1600352233.414259 3T11 291 00 00 00 00 00 46
03 00
E (96335) can: can3: intr=25 rxpkt=7 txpkt=21 errflags=0x27400501
rxerr=0 txerr=90 rxovr=0 txovr=0 txdelay=18 wdgreset=0 errreset=0
E (96335) canlog-monitor: 1600352233.416398 3CER Error intr=25 rxpkt=7
txpkt=21 errflags=0x27400501 rxerr=0 txerr=90 rxovr=0 txovr=0
txdelay=18 wdgreset=0 errreset=0
V (96335) canlog-monitor: 1600352233.416729 3R11 320 01 00 00 01 00 02
00 80
V (96335) canlog-monitor: 1600352233.417216 3R11 575 00 00 00 00
V (96335) canlog-monitor: 1600352233.417255 3T11 291 00 00 00 00 00 46
03 00
V (96335) canlog-monitor: 1600352233.417283 3T11 291 00 00 00 00 00 46
03 00
I (96335) ovms-server-v2: Send MP-0 c22,0
I see some weird stuff here ...
The TX that come to the bus (3T11) we see 15 times the first messages
(that is right), one time the second messages (wrong, should be two)
and 6 times the third messages (wrong, should be 5).
On the RX side (3R11) we only see 3 times the first messages, none of
the second and one of the third.
To unlock the doors we need on 3R11 (???) 15 times first, 5 times
second and two times third.
I don't understand enough from the can communication within OVMS to
solve this on my own. Could someone help me out here?
Thanx!
Regards
Chris
_______________________________________________
OvmsDev mailing list
<a class="moz-txt-link-abbreviated" href="mailto:OvmsDev@lists.openvehicles.com">OvmsDev@lists.openvehicles.com</a>
<a class="moz-txt-link-freetext" href="http://lists.openvehicles.com/mailman/listinfo/ovmsdev">http://lists.openvehicles.com/mailman/listinfo/ovmsdev</a>
</pre>
</blockquote>
<br>
<pre>_______________________________________________
OvmsDev mailing list
<a href="mailto:OvmsDev@lists.openvehicles.com">OvmsDev@lists.openvehicles.com</a>
<a href="http://lists.openvehicles.com/mailman/listinfo/ovmsdev">http://lists.openvehicles.com/mailman/listinfo/ovmsdev</a>
</pre></blockquote></body></html>