Michael,

I think we can do better than "tail" command. The design for printing log messages is prepared to print on all registered consoles. We have restricted the console_logger() function to just output on the async console out of concernt that sending output to the remote consoles might be too much of a burden. But if that is what's desired for a particular user's scenario, then what we should do is to add a command to direct the output to all consoles.

                                                    -- Steve

On Wed, 10 Jan 2018, Michael Balzer wrote:

Mark,

I've built a simple "tail" command to follow the file log on the telnet console.

Unfortunately -- with v2.1 -- the fflush() on the log file doesn't work as expected, the file contents will not be updated until I close the file.

Is that issue solved with v3.x?

Regards, Michael

Am 08.01.2018 um 07:28 schrieb Mark Webb-Johnson:

...

I've restructured the log commands a bit:

• The old "level <severity>" command has moved to "log level <severity>"

• A new "log file <path>" command has been added. For example "log file /sd/log.txt" will mean that anything that gets logged to the console will also get appended to /sd/log.txt as well, until reboot. You can use /sd (if SD CARD is working for you), or /store (but take care - that is system flash).

• You should be able to hook this in at the "sd.mounted" event script, to turn on logging to sd card on boot (again, if SD CARD is working for you).

Enjoy, Mark

...

Branch: refs/heads/master Home: https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3 Commit: 6947670e33823dd68d4bf76b7872518fc8398264 https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/commit/6947... Author: Mark Webb-Johnson <mark@webb-johnson.net <mailto:mark@webb-johnson.net>> Date: 2018-01-08 (Mon, 08 Jan 2018)

Changed paths: M vehicle/OVMS.V3/main/console_async.cpp M vehicle/OVMS.V3/main/ovms_command.cpp M vehicle/OVMS.V3/main/ovms_log.h M vehicle/OVMS.V3/main/ovms_main.cpp

Log Message:

Add support for "log file ..." to log to the specified vfs file

---

OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev

-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

Probably best to split this off as a separate eMail thread.

I think the implementation would be relatively simple.

Create a canlog class with a FILE* m_log member variable, and a virtual function Log() that is called with a direction (tx/rx) and frame to log. The constructor should be passed the vfs file path to log to. It should fopen the m_log file to that. The destructor should fclose the m_log file. Create a canlog_crtd class, derived from canlog, that supports Log() to log to m_log in CRTD format. Optionally create other canlog_* classes, for other logging formats that we want to support. Add a canlog* m_log member variable in canbus. Initialise m_log to NULL in the constructor. In the destructor, if m_log is not null, delete it’s object and set it to NULL. Have a command ‘can log’ like ‘can trace’ that specifies a vfs file path (remember to check it with OvmsConfig ProtectedPath) and logging format. It will then ’new’ a canlog_* style object (depending on logging format). In can::IncomingFrame, log incoming CAN messages with m_log->Log(), in the same way as m_trace is handled. In canbus::Write, log outgoing CAN messages with m_log->Log(), in the same way as m_trace is handled.

Volunteer?

Regards, Mark.

On 10 Jan 2018, at 8:07 AM, Mark Webb-Johnson <mark@webb-johnson.net> wrote:

Now SD CARD support is coming, anybody want to step forward and extend components/can to support CAN bus logging to a file (in crtd format, or perhaps support one or two popular formats)? Implementation would be in class canbus, very similar to m_trace; just need to have a FILE* m_log and appropriate commands / logging of packet write/read in the same place that trace does it.

Thanks.

I really should formally document the CRTD format properly somewhere. Anyway, here are my old notes on it, and an example:

+++++

CRTD Example:

1320724293.000 CXX OVMS Tesla Roadster cando2crtd converted log 1320724293.000 CXX OVMS Tesla roadster log: trip.20111108.csv 1320724294.072 R11 420 00 96 96 1320724294.073 R11 588 00 00 86 1320724294.073 R11 280 00 00 03 00 00 00 00 00 1320724294.073 R11 001 00 00 00 00 1320724294.073 R11 590 01 00 00 00 00 00 00 00 1320724294.113 R11 400 01 01 00 00 00 00 4C 1D

Generators should use whatever line termination the host system uses. For Unix and embedded systems that is LF. Parsers should support all CR, LF, and CRLF variants.

Generators should output hex fields in upper-case and front zero padded (for clarity). Parsers should support both upper and lower case, as well as variable length.

By convention, the .crtd extension is used for these files. It is suggested that generators prefix all crtd files with CXX lines documenting the generator, comment and source of log file.

Space-separated fields are: Timestamp (can be seconds, milliseconds, or microseconds - zero prefixed and full length padded for ms and us). Type: C*: comment CXX: general comment (rest of line is a comment) CEV: user-generated event (rest of line is event description) R11: rx standard frame R29: rx extended frame T11: tx standard frame T29: tx extended frame

Other field notes: For the R?? and T?? types, the rest of the line is hex ID followed by hex data bytes (up to 8). In the case of systems supporting multiple CAN buses, the type can be prefixed with the bus number (eg; 1R11, 2T29, etc). Messages from different CAN bus captures can be written to one shared crtd file, or individual files for each bus - entirely up to the generator.

+++++

Regards, Mark.

On 11 Jan 2018, at 8:59 PM, Michael Balzer <dexter@expeedo.de> wrote:

Mark,

I'll add the logging support along with the TX queue.

Regards, Michael

Am 10.01.2018 um 01:27 schrieb Mark Webb-Johnson:

...

Probably best to split this off as a separate eMail thread.

I think the implementation would be relatively simple.

Create a canlog class with a FILE* m_log member variable, and a virtual function Log() that is called with a direction (tx/rx) and frame to log. The constructor should be passed the vfs file path to log to. It should fopen the m_log file to that. The destructor should fclose the m_log file. Create a canlog_crtd class, derived from canlog, that supports Log() to log to m_log in CRTD format. Optionally create other canlog_* classes, for other logging formats that we want to support. Add a canlog* m_log member variable in canbus. Initialise m_log to NULL in the constructor. In the destructor, if m_log is not null, delete it’s object and set it to NULL. Have a command ‘can log’ like ‘can trace’ that specifies a vfs file path (remember to check it with OvmsConfig ProtectedPath) and logging format. It will then ’new’ a canlog_* style object (depending on logging format). In can::IncomingFrame, log incoming CAN messages with m_log->Log(), in the same way as m_trace is handled. In canbus::Write, log outgoing CAN messages with m_log->Log(), in the same way as m_trace is handled.

Volunteer?

Regards, Mark.

...

On 10 Jan 2018, at 8:07 AM, Mark Webb-Johnson <mark@webb-johnson.net <mailto:mark@webb-johnson.net>> wrote:

Now SD CARD support is coming, anybody want to step forward and extend components/can to support CAN bus logging to a file (in crtd format, or perhaps support one or two popular formats)? Implementation would be in class canbus, very similar to m_trace; just need to have a FILE* m_log and appropriate commands / logging of packet write/read in the same place that trace does it.

---

OvmsDev mailing list OvmsDev@lists.teslaclub.hk <mailto:OvmsDev@lists.teslaclub.hk> http://lists.teslaclub.hk/mailman/listinfo/ovmsdev <http://lists.teslaclub.hk/mailman/listinfo/ovmsdev>

-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

---

OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev

OK, first implementation is done & pushed. Documentation is missing, I'll add that ASAP.

Basic usage:

OVMS > can ? can1 CANx framework can2 CANx framework can3 CANx framework log CAN logging framework

OVMS > can log ? crtd ...format logging off Stop logging status Logging status trace Logging to syslog

OVMS > can log status CAN logging inactive.

OVMS > can log trace ? Usage: can log trace [filter1] [filter2] [filter3] Filter: <bus> / <id>[-<id>] / <bus>:<id>[-<id>] Example: 2:2a0-37f

OVMS > can log crtd ? Usage: can log crtd <path> [filter1] [filter2] [filter3] Filter: <bus> / <id>[-<id>] / <bus>:<id>[-<id>] Example: 2:2a0-37f

OVMS > can log trace CAN logging active: Type:trace; Path:''; Filter:off; Vehicle:; Note: info logging is done at log level debug, frame logging at verbose

OVMS > can can2 tx standard 201 12 34 56 11 22 33 44 55 E (358776) canlog: Error can2 rxpkt=0 txpkt=1 errflags=0x8000 rxerr=63 txerr=0 rxovr=0 txovr=0 txdelay=0

OVMS > can log off Closing log: Type:trace; Path:''; Filter:off; Vehicle:; CAN logging stopped.

OVMS > can log crtd /sd/test.crtd 1 2:780-7ff CAN logging active: Type:crtd; Path:'/sd/test.crtd'; Filter:1:0-ffffffff,2:780-7ff; Vehicle:; OVMS > can can1 rx standard 100 12 34 56 11 22 33 44 55 OVMS > can can1 tx standard 101 12 34 56 11 22 33 44 55 OVMS > can can2 rx standard 200 12 34 56 11 22 33 44 55 OVMS > can can2 tx standard 201 12 34 56 11 22 33 44 55 OVMS > can can2 rx standard 7d2 12 34 56 11 22 33 44 55 OVMS > can can2 tx standard 7d3 12 34 56 11 22 33 44 55 OVMS > can log off Closing log: Type:crtd; Path:'/sd/test.crtd'; Filter:1:0-ffffffff,2:780-7ff; Vehicle:; CAN logging stopped.

OVMS > vfs cat /sd/test.crtd 459.576 CXX Info Type:crtd; Path:'/sd/test.crtd'; Filter:1:0-ffffffff,2:780-7ff; Vehicle:; 476.706 1R11 100 12 34 56 11 22 33 44 55 480.366 1T11 101 12 34 56 11 22 33 44 55 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8000a6 rxerr=28 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8000a6 rxerr=28 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8000a6 rxerr=37 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8000a6 rxerr=46 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8000a6 rxerr=55 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8000a6 rxerr=64 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8000a6 rxerr=73 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8000a6 rxerr=82 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x44000 rxerr=99 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x44000 rxerr=99 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8040a6 rxerr=100 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8040a6 rxerr=109 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8040a6 rxerr=118 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8040a6 rxerr=127 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x204000 rxerr=135 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8040a6 rxerr=135 txerr=0 rxovr=0 txovr=0 txdelay=0 522.616 2R11 7D2 12 34 56 11 22 33 44 55 522.616 2CEV TX_Queue T11 7D3 12 34 56 11 22 33 44 55

Vehicle events are also logged, and if you issue "can <bus> status", the packet statistics will be logged.

The crtd logger is fast enough for the (single bus) Twizy at 500 kbit without filters. I still have no means to test multiple buses.

The current implementation limits the user to one active can logger, but that's just for ease of use and not fixed. We can add support for multiple parallel loggers, but I doubt there's an actual use case for this.

Btw, as a next logger, we could implement the pcapng format: https://wiki.wireshark.org/Development/PcapNg

Regards, Michael

Am 14.01.2018 um 18:13 schrieb Michael Balzer:

Mark,

thanks for the info, I'll add a documentation file on this.

It just turned out writing into a file is far too slow to be done inline with the frame processing… and yes, I _could_ have anticipated that ;)

Maybe idf 3.x will perform better on file I/O, but a separate logging task is better anyway.

Regards, Michael

Am 12.01.2018 um 01:44 schrieb Mark Webb-Johnson:

...

Thanks.

I really should formally document the CRTD format properly somewhere. Anyway, here are my old notes on it, and an example:

+++++

CRTD Example:

1320724293.000 CXX OVMS Tesla Roadster cando2crtd converted log
1320724293.000 CXX OVMS Tesla roadster log: trip.20111108.csv
1320724294.072 R11 420 00 96 96
1320724294.073 R11 588 00 00 86
1320724294.073 R11 280 00 00 03 00 00 00 00 00
1320724294.073 R11 001 00 00 00 00
1320724294.073 R11 590 01 00 00 00 00 00 00 00
1320724294.113 R11 400 01 01 00 00 00 00 4C 1D

Generators should use whatever line termination the host system uses. For Unix and embedded systems that is LF. Parsers should support all CR, LF, and CRLF variants.

Generators should output hex fields in upper-case and front zero padded (for clarity). Parsers should support both upper and lower case, as well as variable length.

By convention, the .crtd extension is used for these files. It is suggested that generators prefix all crtd files with CXX lines documenting the generator, comment and source of log file.

Space-separated fields are:

• Timestamp (can be seconds, milliseconds, or microseconds - zero prefixed and full length padded for ms and us).
• Type: o C*: comment + CXX: general comment (rest of line is a comment) + CEV: user-generated event (rest of line is event description) o R11: rx standard frame o R29: rx extended frame o T11: tx standard frame o T29: tx extended frame

Other field notes:

• For the R?? and T?? types, the rest of the line is hex ID followed by hex data bytes (up to 8).
• In the case of systems supporting multiple CAN buses, the type can be prefixed with the bus number (eg; 1R11, 2T29, etc). Messages from different CAN bus captures can be written to one shared crtd file, or individual files for each bus - entirely up to the generator.

+++++

Regards, Mark.

...

On 11 Jan 2018, at 8:59 PM, Michael Balzer <dexter@expeedo.de <mailto:dexter@expeedo.de>> wrote:

Mark,

I'll add the logging support along with the TX queue.

Regards, Michael

Am 10.01.2018 um 01:27 schrieb Mark Webb-Johnson:

...

Probably best to split this off as a separate eMail thread.

I think the implementation would be relatively simple.

• Create a canlog class with a FILE* m_log member variable, and a virtual function Log() that is called with a direction (tx/rx) and frame to log. o The constructor should be passed the vfs file path to log to. It should fopen the m_log file to that. o The destructor should fclose the m_log file.
• Create a canlog_crtd class, derived from canlog, that supports Log() to log to m_log in CRTD format.
• Optionally create other canlog_* classes, for other logging formats that we want to support.
• Add a canlog* m_log member variable in canbus. o Initialise m_log to NULL in the constructor. o In the destructor, if m_log is not null, delete it’s object and set it to NULL. o Have a command ‘can log’ like ‘can trace’ that specifies a vfs file path (remember to check it with OvmsConfig ProtectedPath) and logging format. It will then ’new’ a canlog_* style object (depending on logging format).
• In can::IncomingFrame, log incoming CAN messages with m_log->Log(), in the same way as m_trace is handled.
• In canbus::Write, log outgoing CAN messages with m_log->Log(), in the same way as m_trace is handled.

Volunteer?

Regards, Mark.

...

On 10 Jan 2018, at 8:07 AM, Mark Webb-Johnson <mark@webb-johnson.net <mailto:mark@webb-johnson.net>> wrote:

Now SD CARD support is coming, anybody want to step forward and extend components/can to support CAN bus logging to a file (in crtd format, or perhaps support one or two popular formats)? Implementation would be in class canbus, very similar to m_trace; just need to have a FILE* m_log and appropriate commands / logging of packet write/read in the same place that trace does it.

---

OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev

-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

---

OvmsDev mailing list OvmsDev@lists.teslaclub.hk <mailto:OvmsDev@lists.teslaclub.hk> http://lists.teslaclub.hk/mailman/listinfo/ovmsdev

---

OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev

-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

---

OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev

-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

Am 19.01.2018 um 01:55 schrieb Mark Webb-Johnson:

Looks good to me. I can at least get traces logged.

Not sure about this, though:

Note: info logging is done at log level debug, frame logging at verbose

Is that the right way around? I haven’t got a can bus connected at the moment, so all I get is the errors shown (even on rx after a failed tx).

"info logging" here is packet statistics and other bus events / comments sent to the log. My standard log level is "info", so I can see the basic system & component events. If I want to see the log events, I switch to "debug", if I want to see frame dumps as well, it's "verbose". That works well for me.

Bus errors are normal on all transceivers if not connected. can1 looks more noisy there just because it's much faster to process -- you can actually watch the rx error counter rising.

Regards, Michael

I’ll try it on a real bus, to see what it looks like there. Maybe if there are less errors, it would make more sense.

Regards, Mark.

...

On 19 Jan 2018, at 7:17 AM, Michael Balzer <dexter@expeedo.de <mailto:dexter@expeedo.de>> wrote:

OK, first implementation is done & pushed. Documentation is missing, I'll add that ASAP.

Basic usage:

OVMS > can ? can1 CANx framework can2 CANx framework can3 CANx framework log CAN logging framework

OVMS > can log ? crtd ...format logging off Stop logging status Logging status trace Logging to syslog

OVMS > can log status CAN logging inactive.

OVMS > can log trace ? Usage: can log trace [filter1] [filter2] [filter3] Filter: <bus> / <id>[-<id>] / <bus>:<id>[-<id>] Example: 2:2a0-37f

OVMS > can log crtd ? Usage: can log crtd <path> [filter1] [filter2] [filter3] Filter: <bus> / <id>[-<id>] / <bus>:<id>[-<id>] Example: 2:2a0-37f

OVMS > can log trace CAN logging active: Type:trace; Path:''; Filter:off; Vehicle:; Note: info logging is done at log level debug, frame logging at verbose

OVMS > can can2 tx standard 201 12 34 56 11 22 33 44 55 E (358776) canlog: Error can2 rxpkt=0 txpkt=1 errflags=0x8000 rxerr=63 txerr=0 rxovr=0 txovr=0 txdelay=0

OVMS > can log off Closing log: Type:trace; Path:''; Filter:off; Vehicle:; CAN logging stopped.

OVMS > can log crtd /sd/test.crtd 1 2:780-7ff CAN logging active: Type:crtd; Path:'/sd/test.crtd'; Filter:1:0-ffffffff,2:780-7ff; Vehicle:; OVMS > can can1 rx standard 100 12 34 56 11 22 33 44 55 OVMS > can can1 tx standard 101 12 34 56 11 22 33 44 55 OVMS > can can2 rx standard 200 12 34 56 11 22 33 44 55 OVMS > can can2 tx standard 201 12 34 56 11 22 33 44 55 OVMS > can can2 rx standard 7d2 12 34 56 11 22 33 44 55 OVMS > can can2 tx standard 7d3 12 34 56 11 22 33 44 55 OVMS > can log off Closing log: Type:crtd; Path:'/sd/test.crtd'; Filter:1:0-ffffffff,2:780-7ff; Vehicle:; CAN logging stopped.

OVMS > vfs cat /sd/test.crtd 459.576 CXX Info Type:crtd; Path:'/sd/test.crtd'; Filter:1:0-ffffffff,2:780-7ff; Vehicle:; 476.706 1R11 100 12 34 56 11 22 33 44 55 480.366 1T11 101 12 34 56 11 22 33 44 55 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8000a6 rxerr=28 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8000a6 rxerr=28 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8000a6 rxerr=37 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8000a6 rxerr=46 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8000a6 rxerr=55 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8000a6 rxerr=64 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8000a6 rxerr=73 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8000a6 rxerr=82 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x44000 rxerr=99 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x44000 rxerr=99 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8040a6 rxerr=100 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8040a6 rxerr=109 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8040a6 rxerr=118 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8040a6 rxerr=127 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x204000 rxerr=135 txerr=0 rxovr=0 txovr=0 txdelay=0 480.366 1CEV Error rxpkt=1 txpkt=1 errflags=0x8040a6 rxerr=135 txerr=0 rxovr=0 txovr=0 txdelay=0 522.616 2R11 7D2 12 34 56 11 22 33 44 55 522.616 2CEV TX_Queue T11 7D3 12 34 56 11 22 33 44 55

Vehicle events are also logged, and if you issue "can <bus> status", the packet statistics will be logged.

The crtd logger is fast enough for the (single bus) Twizy at 500 kbit without filters. I still have no means to test multiple buses.

The current implementation limits the user to one active can logger, but that's just for ease of use and not fixed. We can add support for multiple parallel loggers, but I doubt there's an actual use case for this.

Btw, as a next logger, we could implement the pcapng format: https://wiki.wireshark.org/Development/PcapNg

Regards, Michael

Am 14.01.2018 um 18:13 schrieb Michael Balzer:

...

Mark,

thanks for the info, I'll add a documentation file on this.

It just turned out writing into a file is far too slow to be done inline with the frame processing… and yes, I _could_ have anticipated that ;)

Maybe idf 3.x will perform better on file I/O, but a separate logging task is better anyway.

Regards, Michael

Am 12.01.2018 um 01:44 schrieb Mark Webb-Johnson:

...

Thanks.

I really should formally document the CRTD format properly somewhere. Anyway, here are my old notes on it, and an example:

+++++

CRTD Example:

1320724293.000 CXX OVMS Tesla Roadster cando2crtd converted log
1320724293.000 CXX OVMS Tesla roadster log: trip.20111108.csv
1320724294.072 R11 420 00 96 96
1320724294.073 R11 588 00 00 86
1320724294.073 R11 280 00 00 03 00 00 00 00 00
1320724294.073 R11 001 00 00 00 00
1320724294.073 R11 590 01 00 00 00 00 00 00 00
1320724294.113 R11 400 01 01 00 00 00 00 4C 1D

Generators should use whatever line termination the host system uses. For Unix and embedded systems that is LF. Parsers should support all CR, LF, and CRLF variants.

Generators should output hex fields in upper-case and front zero padded (for clarity). Parsers should support both upper and lower case, as well as variable length.

By convention, the .crtd extension is used for these files. It is suggested that generators prefix all crtd files with CXX lines documenting the generator, comment and source of log file.

Space-separated fields are:

• Timestamp (can be seconds, milliseconds, or microseconds - zero prefixed and full length padded for ms and us).
• Type: o C*: comment + CXX: general comment (rest of line is a comment) + CEV: user-generated event (rest of line is event description) o R11: rx standard frame o R29: rx extended frame o T11: tx standard frame o T29: tx extended frame

Other field notes:

• For the R?? and T?? types, the rest of the line is hex ID followed by hex data bytes (up to 8).
• In the case of systems supporting multiple CAN buses, the type can be prefixed with the bus number (eg; 1R11, 2T29, etc). Messages from different CAN bus captures can be written to one shared crtd file, or individual files for each bus - entirely up to the generator.

+++++

Regards, Mark.

...

On 11 Jan 2018, at 8:59 PM, Michael Balzer <dexter@expeedo.de <mailto:dexter@expeedo.de>> wrote:

Mark,

I'll add the logging support along with the TX queue.

Regards, Michael

Am 10.01.2018 um 01:27 schrieb Mark Webb-Johnson:

...

Probably best to split this off as a separate eMail thread.

I think the implementation would be relatively simple.

• Create a canlog class with a FILE* m_log member variable, and a virtual function Log() that is called with a direction (tx/rx) and frame to log. o The constructor should be passed the vfs file path to log to. It should fopen the m_log file to that. o The destructor should fclose the m_log file.
• Create a canlog_crtd class, derived from canlog, that supports Log() to log to m_log in CRTD format.
• Optionally create other canlog_* classes, for other logging formats that we want to support.
• Add a canlog* m_log member variable in canbus. o Initialise m_log to NULL in the constructor. o In the destructor, if m_log is not null, delete it’s object and set it to NULL. o Have a command ‘can log’ like ‘can trace’ that specifies a vfs file path (remember to check it with OvmsConfig ProtectedPath) and logging format. It will then ’new’ a canlog_* style object (depending on logging format).
• In can::IncomingFrame, log incoming CAN messages with m_log->Log(), in the same way as m_trace is handled.
• In canbus::Write, log outgoing CAN messages with m_log->Log(), in the same way as m_trace is handled.

Volunteer?

Regards, Mark.

> On 10 Jan 2018, at 8:07 AM, Mark Webb-Johnson <mark@webb-johnson.net <mailto:mark@webb-johnson.net>> wrote: > > Now SD CARD support is coming, anybody want to step forward and extend components/can to support CAN bus logging to a file (in crtd > format, or perhaps support one or two popular formats)? Implementation would be in class canbus, very similar to m_trace; just need to > have a FILE* m_log and appropriate commands / logging of packet write/read in the same place that trace does it.

---

OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev

-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

---

OvmsDev mailing list OvmsDev@lists.teslaclub.hk <mailto:OvmsDev@lists.teslaclub.hk> http://lists.teslaclub.hk/mailman/listinfo/ovmsdev

---

OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev

-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

---

OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev

-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

---

OvmsDev mailing list OvmsDev@lists.teslaclub.hk <mailto:OvmsDev@lists.teslaclub.hk> http://lists.teslaclub.hk/mailman/listinfo/ovmsdev

---

OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev

-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

Mark, Steve,

thanks for the test & workaround.

Yes, the syslog can better be distributed internally by the console system. The "tail" command is also intended for general debugging/monitoring of files. I thought it would be straight forward to implement, but another issue/idea turned up we should discuss -- I'll follow up on that after work.

Regards, Michael

Am 10.01.2018 um 01:07 schrieb Mark Webb-Johnson:

Nope:

Here is /store:

OVMS > log file /store/log.txt
...
I (37670) simcom: State: Enter PoweringOn state
I (37670) simcom: Power Cycle
OVMS > vfs stat /store/log.txt
File /store/log.txt size is 0 and digest d41d8cd98f00b204e9800998ecf8427e
OVMS > log file
Closed log file
OVMS > vfs stat /store/log.txt
File /store/log.txt size is 1176 and digest b15515a15edeb75d04a2767ba66a721d

And here is /sd:

OVMS > log file /sd/log.txt
I (15494) simcom: State timeout, transition to 1
I (15494) simcom: State: Enter CheckPowerOff state
OVMS > vfs stat /sd/log.txt
File /sd/log.txt size is 0 and digest d41d8cd98f00b204e9800998ecf8427e
OVMS > log file
Closed log file
OVMS > vfs stat /sd/log.txt
File /sd/log.txt size is 122 and digest ae18d2d2ed63b5dd2381b5bf11d1779d

Seems to be the FAT filesystem itself.

The vfs layer only seems to support a fsync operation, but no fflush. I’m guessing fflush just flushes the FILE buffers, but doesn’t actually sync that to disk. Adding 'fsync(fileno(ovms_log_file));’ after 'fflush(ovms_log_file);’ in ConsoleAsync::ConsoleLogger of main/console_async.cpp seems to resolve this:

OVMS > log file /store/log.txt
OVMS > vfs stat /store/log.txt
File /store/log.txt size is 1176 and digest b15515a15edeb75d04a2767ba66a721d
I (15450) simcom: State timeout, transition to 13
I (15620) simcom: State: Enter PoweredOff state
OVMS > vfs stat /store/log.txt
File /store/log.txt size is 1296 and digest 96221e6daf7258b6e2c0d9eb4a92cad3

There is also a separate issue of multi-line messages not being logged correctly (LF -> “|" translation). I’ve pushed both fixes to the remotes/origin/for-v3.0 branch Steve and I are working on for v3.0. Haven’t tested in 2.1 master, but it will probably work there if you want to merge back to master.

All that said, I think Steve is correct. A tail function (although useful) is not the best way of doing this particular thing. Better to have a ‘log monitor yes/no’ command that sets a flag on the current console (presumably in OvmsWriter like the m_issecure flag). If set, then log messages are shown on that console. Perhaps default to ‘yes’ for async console, and ‘no’ for the others.

Now SD CARD support is coming, anybody want to step forward and extend components/can to support CAN bus logging to a file (in crtd format, or perhaps support one or two popular formats)? Implementation would be in class canbus, very similar to m_trace; just need to have a FILE* m_log and appropriate commands / logging of packet write/read in the same place that trace does it.

Regards, Mark.

...

On 10 Jan 2018, at 7:28 AM, Stephen Casner <casner@acm.org <mailto:casner@acm.org>> wrote:

Michael,

I think we can do better than "tail" command. The design for printing log messages is prepared to print on all registered consoles. We have restricted the console_logger() function to just output on the async console out of concernt that sending output to the remote consoles might be too much of a burden. But if that is what's desired for a particular user's scenario, then what we should do is to add a command to direct the output to all consoles.

                                                   -- Steve

On Wed, 10 Jan 2018, Michael Balzer wrote:

...

Mark,

I've built a simple "tail" command to follow the file log on the telnet console.

Unfortunately -- with v2.1 -- the fflush() on the log file doesn't work as expected, the file contents will not be updated until I close the file.

Is that issue solved with v3.x?

Regards, Michael

Am 08.01.2018 um 07:28 schrieb Mark Webb-Johnson:

...

I've restructured the log commands a bit:

• The old "level <severity>" command has moved to "log level <severity>"

• A new "log file <path>" command has been added. For example "log file /sd/log.txt" will mean that anything that gets logged to the console will also get appended to /sd/log.txt as well, until reboot. You can use /sd (if SD CARD is working for you), or /store (but take care - that is system flash).

• You should be able to hook this in at the "sd.mounted" event script, to turn on logging to sd card on boot (again, if SD CARD is working for you).

Enjoy, Mark

-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

Thanks, Steve.

Mark, backporting the workaround isn't possible / simple, fsync() isn't available in idf-2.1, there's only a stub in newlib.h.

For the followup on my issue with the "tail" implementation, I've pushed my proposal as branch "prop-cmdtask".

Background: the tail command shall be interruptable / terminatable as usual by pressing Ctrl-C. The same applies to other possibly long running commands, i.e. the CANopen scanner. Of course a background process can be used for execution (like wifi scan does), but requires returning results by watching logs, doing a push notification or issuing a "get results" type subcommand.

So I set up a simple task command wrapper class "OvmsCommandTask" based on TaskBase and the console's insert callback API.

A command simply subclasses the wrapper and implements the Service() method. The Service() loop then polls IsTerminated() and exits as indicated.

That makes adding an interruptable command very neat, simple and straight forward, no more code than with a standard command:

https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/compare/pro...

This all works nicely, but maybe I'm crossing some already existing plans with this approach.

Possible issues:

1. Is it too short-sighted to implement the termination detection outside the OvmsShell? Another approach could hook into OvmsShell::ProcessChar, but would require a registration of termination callbacks on top of the insert callback. I like the idea of keeping the shell as simple as possible, but this can of course be seen as a task for the shell.

2. Is it OK to implement just the simple termination signal using a bool and polling instead of using FreeRTOS event groups or task notifications? Using RTOS signals would enable to terminate a running command from another terminal by some "kill" command sending the signal to the command task. It would also provide commands being able to wait for signals instead of poll them. Do we actually need/want this already?

3. Is it OK to use the key listener just for termination for now, or should the class provide keyboard input support as well?

Of course the OvmsCommandTask class implementation can be changed later on to implement a more sophisticated approach on any or all of these points, so maybe we can get back to the refinement later.

This is also in no hurry, there are more important todos. The tail command seemed to be a simple under-the-week-thing at the beginning ;)

Regards, Michael

Am 10.01.2018 um 17:34 schrieb Stephen Casner:

Michael,

I will implement the optional syslog distribution to all consoles.

                                                    -- Steve

On Wed, 10 Jan 2018, Michael Balzer wrote:

...

Mark, Steve,

thanks for the test & workaround.

Yes, the syslog can better be distributed internally by the console system. The "tail" command is also intended for general debugging/monitoring of files. I thought it would be straight forward to implement, but another issue/idea turned up we should discuss -- I'll follow up on that after work.

Regards, Michael

Am 10.01.2018 um 01:07 schrieb Mark Webb-Johnson:

...

Nope:

Here is /store:

OVMS > log file /store/log.txt
...
I (37670) simcom: State: Enter PoweringOn state
I (37670) simcom: Power Cycle
OVMS > vfs stat /store/log.txt
File /store/log.txt size is 0 and digest d41d8cd98f00b204e9800998ecf8427e
OVMS > log file
Closed log file
OVMS > vfs stat /store/log.txt
File /store/log.txt size is 1176 and digest b15515a15edeb75d04a2767ba66a721d

And here is /sd:

OVMS > log file /sd/log.txt
I (15494) simcom: State timeout, transition to 1
I (15494) simcom: State: Enter CheckPowerOff state
OVMS > vfs stat /sd/log.txt
File /sd/log.txt size is 0 and digest d41d8cd98f00b204e9800998ecf8427e
OVMS > log file
Closed log file
OVMS > vfs stat /sd/log.txt
File /sd/log.txt size is 122 and digest ae18d2d2ed63b5dd2381b5bf11d1779d

Seems to be the FAT filesystem itself.

The vfs layer only seems to support a fsync operation, but no fflush. I'm guessing fflush just flushes the FILE buffers, but doesn't actually sync that to disk. Adding 'fsync(fileno(ovms_log_file));' after 'fflush(ovms_log_file);' in ConsoleAsync::ConsoleLogger of main/console_async.cpp seems to resolve this:

OVMS > log file /store/log.txt
OVMS > vfs stat /store/log.txt
File /store/log.txt size is 1176 and digest b15515a15edeb75d04a2767ba66a721d
I (15450) simcom: State timeout, transition to 13
I (15620) simcom: State: Enter PoweredOff state
OVMS > vfs stat /store/log.txt
File /store/log.txt size is 1296 and digest 96221e6daf7258b6e2c0d9eb4a92cad3

There is also a separate issue of multi-line messages not being logged correctly (LF -> "|" translation). I've pushed both fixes to the remotes/origin/for-v3.0 branch Steve and I are working on for v3.0. Haven't tested in 2.1 master, but it will probably work there if you want to merge back to master.

All that said, I think Steve is correct. A tail function (although useful) is not the best way of doing this particular thing. Better to have a 'log monitor yes/no' command that sets a flag on the current console (presumably in OvmsWriter like the m_issecure flag). If set, then log messages are shown on that console. Perhaps default to 'yes' for async console, and 'no' for the others.

Now SD CARD support is coming, anybody want to step forward and extend components/can to support CAN bus logging to a file (in crtd format, or perhaps support one or two popular formats)? Implementation would be in class canbus, very similar to m_trace; just need to have a FILE* m_log and appropriate commands / logging of packet write/read in the same place that trace does it.

Regards, Mark.

...

On 10 Jan 2018, at 7:28 AM, Stephen Casner <casner@acm.org <mailto:casner@acm.org>> wrote:

Michael,

I think we can do better than "tail" command. The design for printing log messages is prepared to print on all registered consoles. We have restricted the console_logger() function to just output on the async console out of concernt that sending output to the remote consoles might be too much of a burden. But if that is what's desired for a particular user's scenario, then what we should do is to add a command to direct the output to all consoles.

                                                   -- Steve

On Wed, 10 Jan 2018, Michael Balzer wrote:

...

Mark,

I've built a simple "tail" command to follow the file log on the telnet console.

Unfortunately -- with v2.1 -- the fflush() on the log file doesn't work as expected, the file contents will not be updated until I close the file.

Is that issue solved with v3.x?

Regards, Michael

Am 08.01.2018 um 07:28 schrieb Mark Webb-Johnson:

...

I've restructured the log commands a bit:

• The old "level <severity>" command has moved to "log level <severity>"

• A new "log file <path>" command has been added. For example "log file /sd/log.txt" will mean that anything that gets logged to the console will also get appended to /sd/log.txt as well, until reboot. You can use /sd (if SD CARD is working for you), or /store (but take care - that is system flash).

• You should be able to hook this in at the "sd.mounted" event script, to turn on logging to sd card on boot (again, if SD CARD is working for you).

Enjoy, Mark

Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

---

OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev

-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26