[Ovmsdev] Automatic naming of CAN log files
Michael Balzer
dexter at expeedo.de
Sat Dec 3 15:56:48 HKT 2022
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/master...llange:Open-Vehicle-Monitoring-System-3:748-split-can-log-files
>>>
>>> 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 at 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openvehicles.com/pipermail/ovmsdev/attachments/20221203/d2817cf8/attachment-0001.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: OpenPGP_signature
Type: application/pgp-signature
Size: 203 bytes
Desc: OpenPGP digital signature
URL: <http://lists.openvehicles.com/pipermail/ovmsdev/attachments/20221203/d2817cf8/attachment-0001.sig>
More information about the OvmsDev
mailing list