[Ovmsdev] Double updates - Normal?

Fri Jan 31 08:15:09 HKT 2020

I put some telemetry on this and see (for the first ten seconds of boot):

I (43) events: Initialising EVENTS (1200)
I (612) events: SignalEvent: event 'config.mounted' queued (0 waiting, 20 free)
I (682) ovms_main: Starting HOUSEKEEPING...
I (682) housekeeping: Initialising HOUSEKEEPING Framework...
I (842) events: SignalEvent: event 'housekeeping.init' queued (1 waiting, 19 free)
I (1022) housekeeping: Executing on CPU core 1
I (1022) housekeeping: reset_reason: cpu0=12, cpu1=12
I (1022) housekeeping: Initialising WATCHDOG...
I (1022) housekeeping: Starting PERIPHERALS...
I (1262) events: SignalEvent: event 'egpio.output.1.low' queued (1 waiting, 19 free)
I (1262) housekeeping: Auto init max7317 (free: 193092 bytes)
I (1272) housekeeping: Auto init ext12v (free: 193092 bytes)
I (1282) housekeeping: Auto init dbc (free: 193092 bytes)
I (1282) housekeeping: Auto init wifi (free: 193092 bytes)
I (1462) housekeeping: Auto init modem (free: 149952 bytes)
I (1472) housekeeping: Auto init vehicle (free: 149656 bytes)
I (1482) events: SignalEvent: event 'power.can1.on' queued (4 waiting, 16 free)
I (1492) events: SignalEvent: event 'egpio.output.2.low' queued (5 waiting, 15 free)
I (1502) housekeeping: Auto init obd2ecu (free: 141484 bytes)
I (1502) housekeeping: Auto init server v2 (free: 141484 bytes)
I (1512) housekeeping: Auto init server v3 (free: 141484 bytes)
I (1522) housekeeping: Auto init javascript (free: 141484 bytes)
I (1522) housekeeping: Auto init done (free: 141484 bytes)
I (1532) housekeeping: Starting USB console...
Firmware: 3.2.008-125-g1fca0362-dirty/factoents: 
SignalEvent: event 'system.start' queued (7 waiting, 13 free)
I (2022) events: SignalEvent: event 'ticker.1' queued (8 waiting, 12 free)
I (2202) simcom: State: Enter CheckPowerOff state
I (2202) events: SignalEvent: event 'egpio.output.3.low' queued (1 waiting, 19 free)
I (2202) events: SignalEvent: event 'egpio.output.0.low' queued (2 waiting, 18 free)
I (3022) events: SignalEvent: event 'ticker.1' queued (1 waiting, 19 free)
I (4022) events: SignalEvent: event 'ticker.1' queued (1 waiting, 19 free)
I (5022) events: SignalEvent: event 'ticker.1' queued (1 waiting, 19 free)
I (6022) events: SignalEvent: event 'ticker.1' queued (1 waiting, 19 free)
I (6022) sdcard: SD CARD has been inserted
I (6022) events: SignalEvent: event 'sd.insert' queued (1 waiting, 19 free)
I (7022) events: SignalEvent: event 'ticker.1' queued (1 waiting, 19 free)
I (8022) events: SignalEvent: event 'ticker.1' queued (1 waiting, 19 free)
I (8022) events: SignalEvent: event 'sd.mounted' queued (1 waiting, 19 free)
I (9022) events: SignalEvent: event 'ticker.1' queued (1 waiting, 19 free)
I (10022) events: SignalEvent: event 'ticker.1' queued (1 waiting, 19 free)
I (11022) events: SignalEvent: event 'ticker.1' queued (1 waiting, 19 free)
I (11022) events: SignalEvent: event 'ticker.10' queued (1 waiting, 19 free)

(that doesn’t include scheduled events, only the ones from OvmsEvents::SignalEvent)

I think the issue was most likely triggered by the egpio events introduced a while back. Agree with Thomas that this is most likely just a simple queue overflow. Perhaps EGPIO is flapping at startup, causing a flurry of these egpio events? I am guessing that this is aggravated in Greg’s case as he is doing some egpio and power work for HUD control.

I’ve increased the OVMS_HW_EVENT_QUEUE_SIZE to 40 on my test build, and just released that to the production server (for edge). As this sdkconfig file is not included in github, I recommend all developers do the same for their local builds.

@Michael can you set the same on your production build server?

@Greg can you check your existing firmware boot (via usb) and check for 'queue overflow, event '%s’ dropped’ style messages on startup (probably around the time is says ’Starting USB console…’.

@Greg please try the edge 3.2.008-126-g0291d03 firmware. Update to it, reboot, and see if ‘metric list version’ shows the version correctly. Hopefully this resolves (or works around) the issue.

Regards, Mark.

> On 30 Jan 2020, at 8:07 PM, Michael Balzer <dexter at expeedo.de> wrote:
> 
> Maybe OVMS_HW_EVENT_QUEUE_SIZE is just too small now, with the added events during boot and async event processing?
> 
> Regards,
> Michael
> 
> 
> Am 30.01.20 um 13:00 schrieb Tamás Kovács:
>> Some time the m.version not set on Mitsubishi i-Miev .
>> 
>> 2020. január 30., csütörtök dátummal Thomas Heuer <egon at heuer-humfeld.de <mailto:egon at heuer-humfeld.de>> ezt írta:
>> The issue was on boot, the events: SignalEvent: queue overflow, event 'system.start' dropped in some case.
>> 
>>  
>> the problem was the egpio settings in OvmsVehicleSmartED::ConfigChanged(OvmsConfigParam* param)
>> 
>>  
>> https://github.com/Dimitrie78/Open-Vehicle-Monitoring-System-3/commit/21e1a0339c029adf5c746dfd6fecddbc9455a947#diff-9106f33dff1f6160884b2e78d145607fL155-L160 <https://github.com/Dimitrie78/Open-Vehicle-Monitoring-System-3/commit/21e1a0339c029adf5c746dfd6fecddbc9455a947#diff-9106f33dff1f6160884b2e78d145607fL155-L160>
>> line 155 – 160
>> 
>>  
>> Von: OvmsDev <ovmsdev-bounces at lists.openvehicles.com <mailto:ovmsdev-bounces at lists.openvehicles.com>> Im Auftrag von Mark Webb-Johnson
>> Gesendet: Donnerstag, 30. Januar 2020 11:35
>> An: OVMS Developers <ovmsdev at lists.openvehicles.com <mailto:ovmsdev at lists.openvehicles.com>>
>> Betreff: Re: [Ovmsdev] Double updates - Normal?
>> 
>>  
>> Just had a thought.
>> 
>>  
>> Events used to be synchronous, but we switched to deliver in a different task. Maybe the startup sequence relies on that in some way.
>> 
>> 
>> 
>> 
>> On 30 Jan 2020, at 6:32 PM, Mark Webb-Johnson <mark at webb-johnson.net <mailto:mark at webb-johnson.net>> wrote:
>> 
>> 
>> 
>> Seems identical. The changes don’t seem to affect the dispatch of the system.start event.
>> 
>>  
>> I think it must be a race condition.
>> 
>>  
>> Mark
>> 
>> 
>> 
>> 
>> On 30 Jan 2020, at 5:56 PM, Michael Balzer <dexter at expeedo.de <mailto:dexter at expeedo.de>> wrote:
>> 
>> 
>> 
>> Mark,
>> 
>> a similar issue was happening on some Smart ED and fixed by Dimitrie later on:
>> 
>> https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/issues/293 <https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/issues/293>
>> 
>> I thought that was a Smart specific issue, maybe I was wrong.
>> 
>> Regards,
>> Michael
>> 
>> 
>> Am 30.01.20 um 06:17 schrieb Mark Webb-Johnson:
>> 
>> Still stumped…
>> 
>>  
>> The OTA code doesn’t call GetOVMSVersion(), but instead just looks at StandardMetrics.ms_m_version (which we know is blank). That is why this is happening.
>> 
>>  
>> But why is StandardMetrics.ms_m_version empty (as is the hardware value as well).
>> 
>>  
>> The ovms_version code hooks into ’system.start’ event, and sets the version and hardware metrics. So, obviously that is not being called. That event is raised just after ’Starting USB console…”. The event is also listened to be ovms_time, ovms_mdns, and swcan.
>> 
>>  
>> MDNS outputs “Starting MDNS” when it sees that. The ovms_time sets the environment variable TZ. Your car is showing:
>> 
>>  
>> ovms> time status
>> 
>> ...
>> 
>> Vehicle Response:
>> 
>>   Time Zone:  Not defined
>> 
>>   UTC Time:   2020-01-30 05:00:53 UTC
>> 
>>   Local Time: 2020-01-30 05:00:53 GMT
>> 
>>   Provider:   None
>> 
>>  
>> So looks like TZ is not being set. Presumably that means the call is not happening. I had a look at the ovms_events code, but can’t find anything obvious.
>> 
>>  
>> So, tried a hacky test:
>> 
>>  
>> ovms> metric list version
>> 
>> ...
>> 
>> Vehicle Response:
>> 
>>   m.version
>> 
>>  
>> ovms> event raise system.start
>> 
>> ...
>> 
>> Vehicle Response:
>> 
>>   Raising event: system.start
>> 
>>  
>> ovms> metric list version
>> 
>> ...
>> 
>> Vehicle Response:
>> 
>>   m.version                                3.2.008-121-g4c6c9fe/ota_0/edge (build idf v3.3-beta3-775-gdc1ca69 Jan 29 2020 00:00:52)
>> 
>>  
>> ovms> ota status
>> 
>> ...
>> 
>> Vehicle Response:
>> 
>>   Firmware:          3.2.008-121-g4c6c9fe/ota_0/edge (build idf v3.3-beta3-775-gdc1ca69 Jan 29 2020 00:00:52)
>> 
>>   Running partition: ota_0
>> 
>>   Boot partition:    ota_0
>> 
>>   Factory image:     3.1.001
>> 
>>   OTA_O image:       3.2.008-121-g4c6c9fe
>> 
>>   OTA_1 image:       3.2.008-121-g4c6c9fe
>> 
>>   Server Available:  3.2.008-121-g4c6c9fe (no update required)
>> 
>>  
>> 🤢
>> 
>>  
>> Can you try to boot from USB (module reset) and provide the serial boot log? Particularly around the lines ’Starting USB console’.
>> 
>>  
>> Maybe a race condition at startup, or some other issue delivering events early on?
>> 
>>  
>> Only other thing I see are some scripts on /store/events regarding vehicle on/off - perhaps you can try disabling those to see if they trigger the issue? I tried recreating them on my box, but couldn’t repeat your problem.
>> 
>>  
>> Regards, Mark.
>> 
>> 
>> 
>> 
>> On 30 Jan 2020, at 11:55 AM, Mark Webb-Johnson <mark at webb-johnson.net <mailto:mark at webb-johnson.net>> wrote:
>> 
>>  
>> Greg,
>> 
>>  
>> It seems your car can’t pickup currently running firmware version:
>> 
>>  
>> ovms> open ROADSTER834B
>> 
>> Connected and logged in to ROADSTER834B
>> 
>> ovms> metric list version
>> 
>> ...
>> 
>> Vehicle Response:
>> 
>>   m.version
>> 
>>  
>> By comparison, here’s mine:
>> 
>>  
>> ovms> metric list version
>> 
>> ...
>> 
>> Vehicle Response:
>> 
>>   m.version                                3.2.008-121-g4c6c9fe/ota_1/edge (build idf v3.3-beta3-775-gdc1ca69 Jan 29 2020 00:00:52)
>> 
>> ovms> ota status
>> 
>> ...
>> 
>> Vehicle Response:
>> 
>>   Firmware:          3.2.008-121-g4c6c9fe/ota_1/edge (build idf v3.3-beta3-775-gdc1ca69 Jan 29 2020 00:00:52)
>> 
>>   Running partition: ota_1
>> 
>>   Boot partition:    ota_1
>> 
>>   Factory image:     3.2.002
>> 
>>   OTA_O image:       3.2.008-120-gcfb7864
>> 
>>   OTA_1 image:       3.2.008-121-g4c6c9fe
>> 
>>  
>> Your m.hardware metric is also blank.
>> 
>>  
>> I’ll keep looking, but at the moment this seems bizarre.
>> 
>>  
>> Regards, Mark.
>> 
>> 
>> 
>> 
>> On 30 Jan 2020, at 11:21 AM, Greg D. <gregd2350 at gmail.com <mailto:gregd2350 at gmail.com>> wrote:
>> 
>>  
>> Hi Mark, Michael,
>> 
>> Seems like what is happening is that the module keeps thinking a new
>> update is available.  Today was especially active for some reason. 
>> Screenshot of the Android application's log screen, attached.  All
>> versions appear to be the same.  The car has simply been sitting in the
>> garage on WiFi; no transitions of network access.
>> 
>> Output of 'ota status' attached as well.
>> 
>> Sorry, but I don't appear to have logging enabled. What specifically
>> would you like logged?
>> 
>> Greg
>> 
>> 
>> Mark Webb-Johnson wrote:
>> 
>> 
>> Not normal. Can you send us the logs. Also the output of ‘ota status’ would be helpful.
>> 
>> Are you sure this isn't just a notification of the update, and is the update itself? Perhaps a screenshot of the double notifications you receive?
>> 
>> Regards, Mark.
>> 
>> 
>> 
>> On 25 Jan 2020, at 11:35 AM, Greg D. <gregd2350 at gmail.com <mailto:gregd2350 at gmail.com>> wrote:
>> 
>> Hi folks,
>> 
>> I moved my car's OVMSv3 to the Edge firmware a bit ago, and notice that
>> every update seems to be doubled.  Besides being a bit annoying, it ends
>> up without a previous version to fall back to since both partitions end
>> up being the same.
>> 
>> Is this behavior normal?  Can it be prevented?
>> 
>> I'm only on Edge because of the bug in obd2ecu, and will probably move
>> to EAP after we get an EAP build with the fix in it.  Is the behavior
>> the same there?
>> 
>> I used to be on Main, and all seemed fine there.
>> 
>> Thanks,
>> 
>> Greg
>> 
>> _______________________________________________
>> OvmsDev mailing list
>> OvmsDev at lists.openvehicles.com <mailto:OvmsDev at lists.openvehicles.com>
>> http://lists.openvehicles.com/mailman/listinfo/ovmsdev <http://lists.openvehicles.com/mailman/listinfo/ovmsdev>
>> _______________________________________________
>> OvmsDev mailing list
>> OvmsDev at lists.openvehicles.com <mailto:OvmsDev at lists.openvehicles.com>
>> http://lists.openvehicles.com/mailman/listinfo/ovmsdev <http://lists.openvehicles.com/mailman/listinfo/ovmsdev>
>> 
>> <Repeated updates.png><Repeated updates ota status output.txt>_______________________________________________
>> OvmsDev mailing list
>> OvmsDev at lists.openvehicles.com <mailto:OvmsDev at lists.openvehicles.com>
>> http://lists.openvehicles.com/mailman/listinfo/ovmsdev <http://lists.openvehicles.com/mailman/listinfo/ovmsdev>
>>  
>>  
>> 
>> 
>> 
>> _______________________________________________
>> OvmsDev mailing list
>> OvmsDev at lists.openvehicles.com <mailto:OvmsDev at lists.openvehicles.com>
>> http://lists.openvehicles.com/mailman/listinfo/ovmsdev <http://lists.openvehicles.com/mailman/listinfo/ovmsdev>
>> 
>> 
>> 
>> -- 
>> Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal <https://www.google.com/maps/search/Helkenberger+Weg+9+*+D-58256+Ennepetal?entry=gmail&source=g>
>> Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
>> _______________________________________________
>> OvmsDev mailing list
>> OvmsDev at lists.openvehicles.com <mailto:OvmsDev at lists.openvehicles.com>
>> http://lists.openvehicles.com/mailman/listinfo/ovmsdev <http://lists.openvehicles.com/mailman/listinfo/ovmsdev>
>> _______________________________________________
>> OvmsDev mailing list
>> OvmsDev at lists.openvehicles.com <mailto:OvmsDev at lists.openvehicles.com>
>> http://lists.openvehicles.com/mailman/listinfo/ovmsdev <http://lists.openvehicles.com/mailman/listinfo/ovmsdev>
>> 
>> -- 
>> Üdvözlettel:
>> Kovács Tamás
>> 
>> 
>> 
>> 
>> _______________________________________________
>> OvmsDev mailing list
>> OvmsDev at lists.openvehicles.com <mailto:OvmsDev at lists.openvehicles.com>
>> http://lists.openvehicles.com/mailman/listinfo/ovmsdev <http://lists.openvehicles.com/mailman/listinfo/ovmsdev>
> 
> 
> -- 
> Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal
> Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
> _______________________________________________
> OvmsDev mailing list
> OvmsDev at lists.openvehicles.com
> http://lists.openvehicles.com/mailman/listinfo/ovmsdev

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openvehicles.com/pipermail/ovmsdev/attachments/20200131/65baa9dd/attachment.htm>