Thanx for your help. I tried CONFIG_OVMS_HW_CAN_TX_QUEUE_SIZE=60 without success and callback crashes in can.cpp:723: 718 {719 bool loop;720 // Loop until all interrupts are handled721 do {722 bool receivedFrame;723 loop = msg.body.bus->AsynchronousInterruptHandler(&msg.body.frame, &receivedFrame);724 if (receivedFrame)725 me->IncomingFrame(&msg.body.frame);726 } while (loop);727 break; Will continue trying ... Regards Chris Am Donnerstag, den 17.09.2020, 21:35 +0200 schrieb Michael Balzer:
That looks like a bug in the MCP2515 driver.
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).
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.
The race scheme is:
- The application task (low prio) calls Write() concurrently to the "TX done" interrupt of the last frame sent being raised.
- The interrupt is sent to the CAN task (high prio), which calls AsynchronousInterruptHandler() concurrently now to the Write().
- Both Write() and AsynchronousInterruptHandler() may now get "TX buffer is free" from the MCP2515
- …Write() will then immediately fill the TX buffer with the new frame
- …and AsynchronousInterruptHandler() will concurrently fill the TX buffer with the next frame of the TX queue if any
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.
You could have had that very effect on the second time of the second message vs. the first time of the third message:
1600352233.392765 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00
1600352233.394239 3T11 291 8a aa 00 00 00 46 03 00
1600352233.394816 3CER TX_Queue T11 291 00 aa 00 00 00 46 03 00
1600352233.395680 3T11 291 8a aa 00 00 00 46 03 00
1600352233.396153 3CER TX_Queue T11 291 00 aa 00 00 00 46 03 00
1600352233.404239 3T11 291 00 aa 00 00 00 46 03 00
1600352233.404538 3CER TX_Queue T11 291 00 00 00 00 00 46 03 00
1600352233.404753 3CER TX_Queue T11 291 00 00 00 00 00 46 03 00
… TX "00 aa" done IRQ coming in here, queue has "00 00" frame ready which gets sent concurrently
→ wrong frame "00 00" is now in m_tx_frame and gets logged instead of "00 aa":
1600352233.405126 3T11 291 00 00 00 00 00 46 03 00
A second opinion on this would be good, possibly by someone else who has worked on the MCP2515 code last?
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.
On the RX side (3R11) we only see 3 times the first messages, none of the second and one of the third.
The RX log entries are the frames received from the vehicle.
Regards,
Michael
Am 17.09.20 um 17:06 schrieb Chris van der Meijden:
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 OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev
_______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev