Ludovic, Am 02.12.22 um 23:31 schrieb Ludovic LANGE:
Hi Michael,
Thanks for your encouraging feedback !
A few points:
I assume "vfs-auto" will set another config instance to enable continuation after a crash/reboot? In fact not at the moment :-) Based on the discussion we had in https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/issues/766 , I settled on the attachment to `sd.*` events to start/stop the log. It's working OK for the moment and starts as soon as the system is up and SC card mounted.
Of course you need to listen to the SD events, but you wouldn't want the user having to take care of adding & removing scripts to events to manage the CAN logger, a simple command should be sufficient. You could provide a scheme to let "vfs-auto" create & delete event scripts, but that would be risky, as scripts may be altered by the user as well. The system file logger works similary, it starts automatically when a path is configured. It also listens for config changes, so you can start it simply by setting the path, which enables very simple web control. The system file logger can be started without persistence from the "log file" command, or with persistence by setting the config. The "log file" command could be extended by e.g. an option "-p" to make it set the config as well. For consistency, this usage pattern should apply to the CAN file logger as well. To provide this scheme for the CAN logger you'll need to capture the actual vfs-auto logging configuration in config instances (might simply be the argument vector or shell full command).
Please avoid "_" on event names. Any technical reason for that ? Or is it for consistency ? Should I replace with '-' or just have `can.log.rotatefiles` ?
It's for consistency, we generally only use group/level separators (dots). See the list of system events for reference, it's e.g. "system.shuttingdown", not "system.shutting_down".
Maybe you should raise e.g. "can.log.rotate.pre" synchronously before the actual rotation, so handlers can add some last info to the file, and "can.log.rotate.post" after. Interesting. How could we ensure that all handlers have finished handling the event ? Waiting for some time ? I'm a little bit concerned of having to introduce delay in the rotation itself, not wanting to drop events.
Synchronous events are implemented using the `event_signal_done_fn callback` on `SignalEvent()`. The "done" callback executes after all event handlers have been called. A more recent example of this is in my fix for issue #702, see `OvmsConfig::Restore()`: // Signal & wait for components to shutdown: { OvmsSemaphore eventdone; auto callback = [](const char* event, void* data) { ((OvmsSemaphore*)data)->Give(); }; MyEvents.SignalEvent("config.restore", &eventdone, callback); eventdone.Take(); } This code pattern can be applied if the current task simply needs to (and can) pause execution until all event handlers have finished execution. If you need to continue processing in the task emitting the event, you'll implement a separate callback. See the system shutdown procedure in `ovms_boot` for this pattern: m_shutdown_timer = 60; // Give them 60 seconds to shutdown MyEvents.SignalEvent("system.shuttingdown", NULL, boot_shuttingdown_done); Here, the separate `boot_shuttingdown_done()` function will be called when all "system.shuttingdown" handlers have been processed.
Adding a status dump before closing a file would be good so you can see if there were drops Yes, that's useful to close the file with a dump of stats and counters. (And you're right about clearing them)
A command to log arbitrary comments would also make sense, that could be used by users and scripts. Indeed. Maybe as a broadcast to all open logs, and/or having the option to send the comments to a specific log.
As a broadcast, same pattern as for the "can status" log entry, but possibly generally sending to all buses (i.e. command "can log comment").
Do you feel we should have all those features (pre/post events, status dump, log comment, your previous suggestion of file logging sync period) ready for a first PR candidate ? Or would you prefer that we try to polish the first functionality (some docs are needed, event naming), create a first PR, and then add incrementally those features as PRs ?
These are improvement options, the initial PR only needs to be consistent and functional. Regards, Michael
Regards, Ludovic
Le 02/12/2022 à 20:15, Michael Balzer a écrit :
Ludovic,
this is far more than I ever needed for my vehicle CAN logging, but I can see this making sense in vehicle or ECU development, and in gathering initial data for reverse engineering from users in the field. With this, users can easily collect data over a couple of days taking photos & notes, and then send the collected data to the developer. That's currently hard to do, as users would need to monitor & manage the continuous logging.
Your config scheme looks appropriate. I assume "vfs-auto" will set another config instance to enable continuation after a crash/reboot?
Please avoid "_" on event names. Maybe you should raise e.g. "can.log.rotate.pre" synchronously before the actual rotation, so handlers can add some last info to the file, and "can.log.rotate.post" after.
Adding a status dump before closing a file would be good so you can see if there were drops. That currently needs a "can canX status" to be triggered. Maybe clearing the counters on transition to the next file then also makes sense.
A command to log arbitrary comments would also make sense, that could be used by users and scripts.
Regards, Michael
Am 26.11.22 um 23:31 schrieb Ludovic LANGE:
Hi,
To follow on this previous idea, I'd like to share a Proof Of Concept of my proposal in the `748-split-can-log-files` branch for comments - you can see the diff here https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/compare/mas...
It does not (yet !) include all the suggestions received - notably absent is the proposal of file logging sync period from Michael below - but I'll try to take them into account.
There is an open issue https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/issues/748 to gather public comments regarding the code if you prefer to do it on GitHub.
(When talking of automatic naming, I mean in fact automatic file name rotation based on different criterion)
Here it is:
* A new command is introduced `can log start vfs-auto` which is exactly like `can log start vfs` but, you guessed it, with automatic file name rotation o The parameter to this command is not a file name any more, but a `prefix` (see below)
* New configuration items are introduced: o `[can] log.file.maxsize_kb` : if the log file size exceeds this number, the file will be rotated o `[can] log.file.maxduration_s` : if the log file has logged for more than (this number) seconds, the file will be rotated o `[can] log.file.keep_empty` : in case a rotation would have created an empty file (no messages), should we rotate nevertheless (`true`) or not (`false`) ? o `[can] log.file.pattern` : this describes how to name the file with some variables (see below)
* A new event `can.log.rotate_files` is introduced to allow one to force a file name rotation
The file name (`log.file.pattern`) can be configured with (combination of) the following elements:
* `strftime` format conversion specification (like`%Y` `%H` ...) * `{vehicleid}` will be replaced by the configured vehicle id * `{session}` will be replaced by the counter of restarts of the module (always incrementing) (See https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/pull/779 for a discussion, will certainly evolve) * `{prefix}` is the argument to the log command `can log start vfs-auto <format> <prefix>`, so that you can configure multiple logs in parallel and have them log to different files (by varying `prefix`) * `{splits}` is a counter of the number of cycles that occurred to this very log file * `{extension}` is the preferred extension for the chosen log format
(Any non-existing directory will be created on the go during file rotation)
The default for these variables are: ``` OVMS# con lis can can (readable writeable) log.file.keep_empty: false log.file.maxduration_s: 1800 log.file.maxsize_kb: 1024 log.file.pattern: /sd/log/{vehicleid}/{session}/{prefix}/{splits}-%Y%m%d-%H%M%S{extension} ```
To illustrate a sequence of file name rotation, here is an excerpt with smaller values (maxduration: 120s / maxsize : 2kb), started by the command `can log start vfs-auto crtd essai`.
The first two renames occur because of maxduration (>= 120s) while the third rename occur because the log file exceeded 2048 bytes. (In addition, SNTP synchro occurred just before the first rename, so you see that the first file segment is dated 1970... while the second one has proper date and time)
``` ... I (119937) canlog-vfs: canlog_vfs_autonaming::OutputMsg() size:172, log duration: 120s I (119957) canlog-vfs: Closed vfs log '/sd/log/ovms-vehicle/00000390/essai/00000001-19700101-010008.crtd': Size:172 Messages:2 Dropped:0 Filtered:0 Rate:0.0% I (119967) canlog-vfs: Changing file name from '/sd/log/ovms-vehicle/00000390/essai/00000001-19700101-010008.crtd' to '/sd/log/ovms-vehicle/00000390/essai/00000002-20221126-155952.crtd' I (119977) canlog-vfs: Now logging CAN messages to '/sd/log/ovms-vehicle/00000390/essai/00000002-20221126-155952.crtd'
I (239967) canlog-vfs: canlog_vfs_autonaming::OutputMsg() size:1943, log duration: 120s I (239987) canlog-vfs: Closed vfs log '/sd/log/ovms-vehicle/00000390/essai/00000002-20221126-155952.crtd': Size:1.9k Messages:22 Dropped:0 Filtered:0 Rate:0.0% I (239997) canlog-vfs: Changing file name from '/sd/log/ovms-vehicle/00000390/essai/00000002-20221126-155952.crtd' to '/sd/log/ovms-vehicle/00000390/essai/00000003-20221126-160152.crtd' I (240007) canlog-vfs: Now logging CAN messages to '/sd/log/ovms-vehicle/00000390/essai/00000003-20221126-160152.crtd'
I (334967) canlog-vfs: canlog_vfs_autonaming::OutputMsg() size:2111, log duration: 95s I (334987) canlog-vfs: Closed vfs log '/sd/log/ovms-vehicle/00000390/essai/00000003-20221126-160152.crtd': Size:2.1k Messages:24 Dropped:0 Filtered:0 Rate:0.0% I (334997) canlog-vfs: Changing file name from '/sd/log/ovms-vehicle/00000390/essai/00000003-20221126-160152.crtd' to '/sd/log/ovms-vehicle/00000390/essai/00000004-20221126-160327.crtd' I (335007) canlog-vfs: Now logging CAN messages to '/sd/log/ovms-vehicle/00000390/essai/00000004-20221126-160327.crtd' ...
OVMS# vfs rls /sd/log/ovms-vehicle/00000390/essai/ 172 26-Nov-2022 15:59 /sd/log/ovms-vehicle/00000390/essai/00000001-19700101-010008.crtd 1.9k 26-Nov-2022 16:01 /sd/log/ovms-vehicle/00000390/essai/00000002-20221126-155952.crtd 2.1k 26-Nov-2022 16:03 /sd/log/ovms-vehicle/00000390/essai/00000003-20221126-160152.crtd 0 30-Nov-1979 00:00 /sd/log/ovms-vehicle/00000390/essai/00000004-20221126-160327.crtd
```
Notes:
* maxsize comparisons are done after writing, which means that you will have files slightly bigger than maxsize - not under maxsize. (for maxduration however it should be OK as the comparison is done before writing)
* While the comparison of maxsize is done on the real number of bytes written, the concept of empty file (for `[can] log.file.keep_empty`) is based on the number of messages logged to the file. This, because most of the files will have a header written even if no messages are written ; which I considered to be nevertheless an empty file. Those "empty" files with no messages will not be rotated in that case (and kept open for logging).
Let me know what you think of this, if you have some remarks, and even if you feel it has no interest whatsoever.
Regards,
Ludovic
_______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev
-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26