[Ovmsdev] Polling keeps car awake (VW e-Up at least)

[Soko]

Soooo....

I've finally found time to test this again.

Basically the same behaviour as described below.

*VWUP_OFF_TICKER_THRESHOLD 5 with 4 trys.log*
Car was locked initially. Unlocked the car before line 21 (around time 
mark 60.000). Locked around time mark 80.000. Car stayed responsive 
until line 108 (time mark 100.000).
At line 130 (tm=116.814) I swap back to PollState=0. The poll for 
PollState=0 gets an immediate reply (line 131-133) and therefore I swap 
back to PollState=1.
The weird thing is that line 132 (which got a reply) is exactly the same 
as 126 (or 118 or 110) which didn't get a reply!?!? So the car has no 
idea of the poll states as the data is the same? There must be some 
issue/bug/behavior inside OVMS (maybe even in the hardware buffer) which 
gets triggered by a PollState change. Or the canlog-monitor uses somehow 
a cache and doesn't show the messages immediately.

*VWUP_OFF_TICKER_THRESHOLD 10 with 4 trys.log*
Same as below. One thing I've noticed though: Car was locked until line 
32 (tm=63.814). Then I've unlocked it and the lines 33 and 34 showed up 
immediately. This indicates a buffer/cache/etc. issue with the 
canlog-monitor as well (imho).

Soko

On 03.08.2020 13:10, Michael Balzer wrote:
> Soko,
>
> I don't see any obvious mistakes on a first check.
>
> Please do the tests again with CAN monitoring, so we can see what's 
> actually going on on the bus.
>
> An OBD device normally logs into the device sending a UDS diag session 
> command (0x10), then keeps that session alive by sending tester 
> present (0x3E) evers 30-60 seconds. See the UDS documentation I sent 
> you, or for an overview, see 
> https://de.wikipedia.org/wiki/Unified_Diagnostic_Services
>
> You should be able to get the session type and protocol by logging 
> what your VCDS does on the bus.
>
> Regards,
> Michael
>
>
> Am 03.08.20 um 06:19 schrieb Soko:
>>
>> Mornin,
>>
>> Source is here: 
>> https://github.com/devmarxx/Open-Vehicle-Monitoring-System-3/tree/master/vehicle/OVMS.V3/components/vehicle_vweup/src
>>
>> Attached are two logs. I haven't had the can-monitor active 
>> unfortuantely..
>>
>> *VWUP_OFF_TICKER_THRESHOLD 5 with 4 trys.log*
>> As the name says it polls every 5 seconds in PollState=1 and swaps 
>> back to PollState=0 after 5*4=20 seconds.
>> Until line 35 you see the CAN errors as the vehicle is OFF. Then I 
>> unlocked the car and in line 38 I get the first reply.
>> Around line 90 I locked the car again. It polls, but gets no reply, 
>> _but not error either_ (?!).
>> Line 118 sets the PollState=0 and suddenly a response comes in. So in 
>> Line 123 I set the PollState=1 again.
>> The the game starts again: Polls get send, no reply but no error 
>> either. After 21 CarOffTickers I switch to PollState=0 and suddenly a 
>> reply comes in...
>>
>> *VWUP_OFF_TICKER_THRESHOLD 10 with 4 trys.log
>> *Here I unlocked at line 57 and locked around line 100. After that 
>> polls get send, no reply, _but errors happen_. And the car is finally 
>> off.
>> Although I've tried the same thing later that day and the car didn't 
>> even go to sleep with Threshold=30!?!? So the behavior is not 100% 
>> reproducible (yet)...
>>
>> @gateway throttling: In VCDS (which - hopefully - does only polling 
>> too) I have a little number showing me the refresh rates of the 
>> values. It indicates ~8 refreshes per second. So with 1 second 
>> shouldn't be any throttling.
>>
>> @OBD "tester": I have no clue what this is ;) So if the polling 
>> framework doesn't do it, I don't do it. All I do is in the obd_eup.* 
>> files.
>>
>> Soko
>>
>> On 02.08.2020 20:12, Michael Balzer wrote:
>>> Soko,
>>>
>>> polling may keep the car awake, that's also an issue on the Kia 
>>> e-Niro IIRC.
>>>
>>> Changing the PollState can only affect the car indirectly via the 
>>> changed polls. Maybe you could add your code & a log?
>>>
>>> Regarding the poll replies stopping, is that also reflected in a CAN 
>>> log? Maybe the OBD gateway throttles if it sees too many requests? 
>>> (Hopefully not…)
>>>
>>> If the gateway does throttling: do you login to the OBD as a 
>>> "tester" and keep the session active by periodically sending the 
>>> "tester present" frame?
>>>
>>> Regards,
>>> Michael
>>>
>>>
>>> Am 02.08.20 um 19:30 schrieb Soko:
>>>>
>>>> Heya again,
>>>>
>>>> I'm trying to develop a detection for when the car is off/locked 
>>>> but I'm encountering a weird phenomena:
>>>>
>>>>   * Car is shut down and locked
>>>>   * OVMS connected
>>>>   * CAN poll for voltage (only one poll value active) with 30 secs
>>>>     fails with error (so far nothing weird)
>>>>   * Unlock the car via car-key remote
>>>>   * Poll succeeds and I'm switching from PollState=0 to PollState=1
>>>>     where I poll every 2 secs
>>>>   * Lock the car via car-key remote
>>>>   * _After 1 hour the polls still work and the car is active_
>>>>
>>>> Is something like this known from other vehicles? So basically my 
>>>> car never shuts down :(
>>>>
>>>> Another secondary weird thing:
>>>> When increasing the time to 5 secs for PollState=1 the polls get no 
>>>> reply and after 20 secs I swap back to PollState=0.
>>>> BUT the second the PollState changes the car replies again...
>>>> Even more weirdness: When PollState=1 time is 10 secs and I swap 
>>>> back to Pollstate=0 after 40 secs the same thing happens! 
>>>> Immediately I swap to PollState=0 the car replies again.
>>>> As if the PollState switching somehow wakes the car up??!
>>>>
>>>> Any ideas?
>>>>
>>>> Soko
>>>>
>>>>
>>>> _______________________________________________
>>>> 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
>>>
>>> _______________________________________________
>>> OvmsDev mailing list
>>> OvmsDev at lists.openvehicles.com
>>> http://lists.openvehicles.com/mailman/listinfo/ovmsdev
>>
>> _______________________________________________
>> 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
>
> _______________________________________________
> 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/20200808/6be83eb8/attachment-0001.html>
-------------- next part --------------
I (15814) simcom: State timeout, transition to 13
I (15814) simcom: State: Enter PoweredOff state
I (15814) gsm-mux: Stop MUX
I (16564) webserver: HTTP GET /shell
I (22124) webserver: HTTP POST /api/execute
I (22134) webcommand: HttpCommandStream[0x3f845768]: 3991572 bytes free, executing: . startlogging
OVMS# . startlogging
Logging level for * set to verbose
CAN logging to MONITOR active: Type:monitor Format:crtd(discard) Filter:off Vehicle:VWUP.OBD
Note: info logging is at debug log level, frame logging is at verbose, and errors as usual
I (22144) canlog-monitor: Now logging CAN messages to monitor
D (22144) canlog-monitor: 1596884094.186549 CXX OVMS CRTD
D (32814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
E (32814) can: can1: intr=113359 rxpkt=0 txpkt=0 errflags=0x8040d9 rxerr=0 txerr=128 rxovr=0 txovr=0 txdelay=1 wdgreset=0 errreset=0
V (32814) canlog-monitor: 1596884104.858690 1CER TX_Queue T11 7E5 03 22 1e 3b 00 00 00 00
E (32814) canlog-monitor: 1596884104.860077 1CER Error intr=113364 rxpkt=0 txpkt=0 errflags=0x8040d9 rxerr=0 txerr=128 rxovr=0 txovr=0 txdelay=1 wdgreset=0 errreset=0
E (48214) can: can1: intr=170776 rxpkt=0 txpkt=1 errflags=0x204c00 rxerr=0 txerr=127 rxovr=0 txovr=0 txdelay=1 wdgreset=0 errreset=0
V (48224) canlog-monitor: 1596884120.264545 1T11 7E5 03 22 1e 3b 00 00 00 00
E (48224) canlog-monitor: 1596884120.265937 1CER Error intr=170777 rxpkt=0 txpkt=1 errflags=0x204c00 rxerr=0 txerr=127 rxovr=0 txovr=0 txdelay=1 wdgreset=0 errreset=0
V (48224) canlog-monitor: 1596884120.265989 1T11 7E5 03 22 1e 3b 00 00 00 00
D (60834) script: Duktape: Compacting DukTape memory
D (63814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (63814) canlog-monitor: 1596884135.858534 1T11 7E5 03 22 1e 3b 00 00 00 00
V (63814) canlog-monitor: 1596884135.863994 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (63814) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (63814) vehicle: Receive Poll Response for 34/1e3b
D (63814) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
I (63814) vwup.obd: Setting car state to ON
V (63824) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
D (64814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (64814) vwup.obd: CarOffTicker increased to 1
V (64814) canlog-monitor: 1596884136.858635 1T11 7E5 03 22 1e 3b 00 00 00 00
V (64814) canlog-monitor: 1596884136.864339 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (64814) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (64814) vehicle: Receive Poll Response for 34/1e3b
D (64814) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
V (64814) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
V (65814) vwup.obd: CarOffTicker increased to 1
V (66814) vwup.obd: CarOffTicker increased to 2
V (67814) vwup.obd: CarOffTicker increased to 3
V (68814) vwup.obd: CarOffTicker increased to 4
V (69814) vwup.obd: CarOffTicker increased to 5
D (70814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (70814) vwup.obd: CarOffTicker increased to 6
V (70814) canlog-monitor: 1596884142.858571 1T11 7E5 03 22 1e 3b 00 00 00 00
V (70814) canlog-monitor: 1596884142.864472 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (70814) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (70814) vehicle: Receive Poll Response for 34/1e3b
D (70814) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
V (70824) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
V (71814) vwup.obd: CarOffTicker increased to 1
V (72814) vwup.obd: CarOffTicker increased to 2
V (73814) vwup.obd: CarOffTicker increased to 3
V (74814) vwup.obd: CarOffTicker increased to 4
V (75814) vwup.obd: CarOffTicker increased to 5
D (76814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (76814) vwup.obd: CarOffTicker increased to 6
V (76814) canlog-monitor: 1596884148.858623 1T11 7E5 03 22 1e 3b 00 00 00 00
V (76814) canlog-monitor: 1596884148.864647 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (76814) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (76814) vehicle: Receive Poll Response for 34/1e3b
D (76814) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
V (76824) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
V (77814) vwup.obd: CarOffTicker increased to 1
V (78814) vwup.obd: CarOffTicker increased to 2
V (79814) vwup.obd: CarOffTicker increased to 3
V (80814) vwup.obd: CarOffTicker increased to 4
V (81814) vwup.obd: CarOffTicker increased to 5
D (82814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (82814) vwup.obd: CarOffTicker increased to 6
V (82814) canlog-monitor: 1596884154.858710 1T11 7E5 03 22 1e 3b 00 00 00 00
V (82814) canlog-monitor: 1596884154.864795 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (82814) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (82814) vehicle: Receive Poll Response for 34/1e3b
D (82814) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
V (82824) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
V (83814) vwup.obd: CarOffTicker increased to 1
V (84814) vwup.obd: CarOffTicker increased to 2
V (85814) vwup.obd: CarOffTicker increased to 3
V (86814) vwup.obd: CarOffTicker increased to 4
V (87814) vwup.obd: CarOffTicker increased to 5
D (88814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (88814) vwup.obd: CarOffTicker increased to 6
V (88814) canlog-monitor: 1596884160.858754 1T11 7E5 03 22 1e 3b 00 00 00 00
V (88814) canlog-monitor: 1596884160.864923 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (88814) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (88814) vehicle: Receive Poll Response for 34/1e3b
D (88824) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
V (88824) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
V (89814) vwup.obd: CarOffTicker increased to 1
V (90814) vwup.obd: CarOffTicker increased to 2
V (91814) vwup.obd: CarOffTicker increased to 3
V (92814) vwup.obd: CarOffTicker increased to 4
V (93814) vwup.obd: CarOffTicker increased to 5
D (94814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (94814) vwup.obd: CarOffTicker increased to 6
V (94814) canlog-monitor: 1596884166.858759 1T11 7E5 03 22 1e 3b 00 00 00 00
V (94814) canlog-monitor: 1596884166.865096 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (94814) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (94824) vehicle: Receive Poll Response for 34/1e3b
D (94824) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
V (94824) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
V (95814) vwup.obd: CarOffTicker increased to 1
V (96814) vwup.obd: CarOffTicker increased to 2
V (97814) vwup.obd: CarOffTicker increased to 3
V (98814) vwup.obd: CarOffTicker increased to 4
V (99814) vwup.obd: CarOffTicker increased to 5
D (100814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (100814) vwup.obd: CarOffTicker increased to 6
V (100814) canlog-monitor: 1596884172.858831 1T11 7E5 03 22 1e 3b 00 00 00 00
V (101814) vwup.obd: CarOffTicker increased to 7
V (102814) vwup.obd: CarOffTicker increased to 8
V (103814) vwup.obd: CarOffTicker increased to 9
V (104814) vwup.obd: CarOffTicker increased to 10
V (105814) vwup.obd: CarOffTicker increased to 11
D (106814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (106814) vwup.obd: CarOffTicker increased to 12
V (106814) canlog-monitor: 1596884178.858806 1T11 7E5 03 22 1e 3b 00 00 00 00
V (107814) vwup.obd: CarOffTicker increased to 13
V (108814) vwup.obd: CarOffTicker increased to 14
V (109814) vwup.obd: CarOffTicker increased to 15
V (110814) vwup.obd: CarOffTicker increased to 16
V (111814) vwup.obd: CarOffTicker increased to 17
D (112814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (112814) vwup.obd: CarOffTicker increased to 18
V (112814) canlog-monitor: 1596884184.858897 1T11 7E5 03 22 1e 3b 00 00 00 00
V (113814) vwup.obd: CarOffTicker increased to 19
V (114814) vwup.obd: CarOffTicker increased to 20
V (115814) vwup.obd: CarOffTicker increased to 21
I (116814) vwup.obd: Setting car state to OFF
D (117814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (117814) canlog-monitor: 1596884189.858802 1T11 7E5 03 22 1e 3b 00 00 00 00
V (117824) canlog-monitor: 1596884189.865335 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (117824) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (117824) vehicle: Receive Poll Response for 34/1e3b
D (117824) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
I (117824) vwup.obd: Setting car state to ON
V (117824) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
D (118814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (118814) vwup.obd: CarOffTicker increased to 1
V (118814) canlog-monitor: 1596884190.858843 1T11 7E5 03 22 1e 3b 00 00 00 00
V (118824) canlog-monitor: 1596884190.865761 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (118824) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (118824) vehicle: Receive Poll Response for 34/1e3b
D (118824) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
V (118824) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
V (119814) vwup.obd: CarOffTicker increased to 1
V (120814) vwup.obd: CarOffTicker increased to 2
D (120834) script: Duktape: Compacting DukTape memory
V (121814) vwup.obd: CarOffTicker increased to 3
V (122814) vwup.obd: CarOffTicker increased to 4
V (123814) vwup.obd: CarOffTicker increased to 5
D (124814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (124814) vwup.obd: CarOffTicker increased to 6
V (124814) canlog-monitor: 1596884196.858497 1T11 7E5 03 22 1e 3b 00 00 00 00
V (125814) vwup.obd: CarOffTicker increased to 7
V (126814) vwup.obd: CarOffTicker increased to 8
V (127814) vwup.obd: CarOffTicker increased to 9
V (128814) vwup.obd: CarOffTicker increased to 10
V (129814) vwup.obd: CarOffTicker increased to 11
D (130814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (130814) vwup.obd: CarOffTicker increased to 12
V (130814) canlog-monitor: 1596884202.858782 1T11 7E5 03 22 1e 3b 00 00 00 00
V (131814) vwup.obd: CarOffTicker increased to 13
V (132814) vwup.obd: CarOffTicker increased to 14
V (133814) vwup.obd: CarOffTicker increased to 15
V (134814) vwup.obd: CarOffTicker increased to 16
V (135814) vwup.obd: CarOffTicker increased to 17
D (136814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (136814) vwup.obd: CarOffTicker increased to 18
V (136814) canlog-monitor: 1596884208.859129 1T11 7E5 03 22 1e 3b 00 00 00 00
V (137814) vwup.obd: CarOffTicker increased to 19
V (138814) vwup.obd: CarOffTicker increased to 20
V (139814) vwup.obd: CarOffTicker increased to 21
I (140814) vwup.obd: Setting car state to OFF
D (141814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (141814) canlog-monitor: 1596884213.859406 1T11 7E5 03 22 1e 3b 00 00 00 00
V (141824) canlog-monitor: 1596884213.866007 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (141824) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (141824) vehicle: Receive Poll Response for 34/1e3b
D (141824) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
I (141824) vwup.obd: Setting car state to ON
V (141824) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
D (142814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (142814) vwup.obd: CarOffTicker increased to 1
V (142814) canlog-monitor: 1596884214.858755 1T11 7E5 03 22 1e 3b 00 00 00 00
V (142824) canlog-monitor: 1596884214.866443 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (142824) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (142824) vehicle: Receive Poll Response for 34/1e3b
D (142824) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
V (142824) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
V (143814) vwup.obd: CarOffTicker increased to 1
V (144814) vwup.obd: CarOffTicker increased to 2
V (145814) vwup.obd: CarOffTicker increased to 3
V (146814) vwup.obd: CarOffTicker increased to 4
V (147814) vwup.obd: CarOffTicker increased to 5
D (148814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (148814) vwup.obd: CarOffTicker increased to 6
V (148814) canlog-monitor: 1596884220.858855 1T11 7E5 03 22 1e 3b 00 00 00 00
V (149814) vwup.obd: CarOffTicker increased to 7
V (150814) vwup.obd: CarOffTicker increased to 8
V (151814) vwup.obd: CarOffTicker increased to 9
V (152814) vwup.obd: CarOffTicker increased to 10
V (153814) vwup.obd: CarOffTicker increased to 11
D (154814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (154814) vwup.obd: CarOffTicker increased to 12
V (154814) canlog-monitor: 1596884226.858880 1T11 7E5 03 22 1e 3b 00 00 00 00
V (155814) vwup.obd: CarOffTicker increased to 13
V (156814) vwup.obd: CarOffTicker increased to 14
V (157814) vwup.obd: CarOffTicker increased to 15
V (158814) vwup.obd: CarOffTicker increased to 16
V (159814) vwup.obd: CarOffTicker increased to 17
D (160814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (160814) vwup.obd: CarOffTicker increased to 18
V (160814) canlog-monitor: 1596884232.858710 1T11 7E5 03 22 1e 3b 00 00 00 00
V (161814) vwup.obd: CarOffTicker increased to 19
V (162814) vwup.obd: CarOffTicker increased to 20
V (163814) vwup.obd: CarOffTicker increased to 21
I (164814) vwup.obd: Setting car state to OFF
D (165814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (165814) canlog-monitor: 1596884237.858736 1T11 7E5 03 22 1e 3b 00 00 00 00
V (165824) canlog-monitor: 1596884237.866824 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (165824) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (165824) vehicle: Receive Poll Response for 34/1e3b
D (165824) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
I (165824) vwup.obd: Setting car state to ON
V (165824) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
D (166814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (166814) vwup.obd: CarOffTicker increased to 1
V (166814) canlog-monitor: 1596884238.858681 1T11 7E5 03 22 1e 3b 00 00 00 00
V (166824) canlog-monitor: 1596884238.867172 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (166824) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (166824) vehicle: Receive Poll Response for 34/1e3b
D (166824) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
V (166824) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
V (167814) vwup.obd: CarOffTicker increased to 1
V (168814) vwup.obd: CarOffTicker increased to 2
V (169814) vwup.obd: CarOffTicker increased to 3
V (170814) vwup.obd: CarOffTicker increased to 4
V (171814) vwup.obd: CarOffTicker increased to 5
D (172814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (172814) vwup.obd: CarOffTicker increased to 6
V (172814) canlog-monitor: 1596884244.858804 1T11 7E5 03 22 1e 3b 00 00 00 00
V (173814) vwup.obd: CarOffTicker increased to 7
V (174814) vwup.obd: CarOffTicker increased to 8
V (175814) vwup.obd: CarOffTicker increased to 9
V (176814) vwup.obd: CarOffTicker increased to 10
V (177814) vwup.obd: CarOffTicker increased to 11
D (178814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (178814) vwup.obd: CarOffTicker increased to 12
V (178814) canlog-monitor: 1596884250.859183 1T11 7E5 03 22 1e 3b 00 00 00 00
V (179814) vwup.obd: CarOffTicker increased to 13
V (180814) vwup.obd: CarOffTicker increased to 14
D (180824) script: Duktape: Compacting DukTape memory
V (181814) vwup.obd: CarOffTicker increased to 15
V (182814) vwup.obd: CarOffTicker increased to 16
V (183814) vwup.obd: CarOffTicker increased to 17
D (184814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (184814) vwup.obd: CarOffTicker increased to 18
V (184814) canlog-monitor: 1596884256.858445 1T11 7E5 03 22 1e 3b 00 00 00 00
V (185814) vwup.obd: CarOffTicker increased to 19
V (186814) vwup.obd: CarOffTicker increased to 20
V (187814) vwup.obd: CarOffTicker increased to 21
I (188814) vwup.obd: Setting car state to OFF
D (189814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (189814) canlog-monitor: 1596884261.858567 1T11 7E5 03 22 1e 3b 00 00 00 00
V (189824) canlog-monitor: 1596884261.867429 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (189824) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (189824) vehicle: Receive Poll Response for 34/1e3b
D (189824) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
I (189824) vwup.obd: Setting car state to ON
V (189824) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
D (190814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (190814) vwup.obd: CarOffTicker increased to 1
V (190814) canlog-monitor: 1596884262.858660 1T11 7E5 03 22 1e 3b 00 00 00 00
V (190824) canlog-monitor: 1596884262.867925 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (190824) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (190824) vehicle: Receive Poll Response for 34/1e3b
D (190824) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
V (190824) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
V (191814) vwup.obd: CarOffTicker increased to 1
V (192814) vwup.obd: CarOffTicker increased to 2
V (193814) vwup.obd: CarOffTicker increased to 3
V (194814) vwup.obd: CarOffTicker increased to 4
V (195814) vwup.obd: CarOffTicker increased to 5
D (196814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (196814) vwup.obd: CarOffTicker increased to 6
V (196814) canlog-monitor: 1596884268.858614 1T11 7E5 03 22 1e 3b 00 00 00 00
V (197814) vwup.obd: CarOffTicker increased to 7
V (198814) vwup.obd: CarOffTicker increased to 8
V (199814) vwup.obd: CarOffTicker increased to 9
V (200814) vwup.obd: CarOffTicker increased to 10
V (201814) vwup.obd: CarOffTicker increased to 11
D (202814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (202814) vwup.obd: CarOffTicker increased to 12
V (202814) canlog-monitor: 1596884274.858657 1T11 7E5 03 22 1e 3b 00 00 00 00
V (203814) vwup.obd: CarOffTicker increased to 13
V (204814) vwup.obd: CarOffTicker increased to 14
V (205814) vwup.obd: CarOffTicker increased to 15
V (206814) vwup.obd: CarOffTicker increased to 16
V (207814) vwup.obd: CarOffTicker increased to 17
D (208814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (208814) vwup.obd: CarOffTicker increased to 18
V (208814) canlog-monitor: 1596884280.858931 1T11 7E5 03 22 1e 3b 00 00 00 00
V (209814) vwup.obd: CarOffTicker increased to 19
V (210814) vwup.obd: CarOffTicker increased to 20
V (211814) vwup.obd: CarOffTicker increased to 21
I (212814) vwup.obd: Setting car state to OFF
D (213814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
E (213814) can: can1: intr=170823 rxpkt=15 txpkt=33 errflags=0x40c00 rxerr=0 txerr=95 rxovr=0 txovr=0 txdelay=1 wdgreset=0 errreset=0
V (213814) canlog-monitor: 1596884285.858803 1T11 7E5 03 22 1e 3b 00 00 00 00
E (213814) canlog-monitor: 1596884285.859879 1CER Error intr=170823 rxpkt=15 txpkt=33 errflags=0x40c00 rxerr=0 txerr=95 rxovr=0 txovr=0 txdelay=1 wdgreset=0 errreset=0
V (213824) canlog-monitor: 1596884285.868214 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (213824) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (213824) vehicle: Receive Poll Response for 34/1e3b
D (213824) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
I (213824) vwup.obd: Setting car state to ON
V (213824) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
D (214814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (214814) vwup.obd: CarOffTicker increased to 1
V (214814) canlog-monitor: 1596884286.858778 1T11 7E5 03 22 1e 3b 00 00 00 00
V (214824) canlog-monitor: 1596884286.868651 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (214824) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (214824) vehicle: Receive Poll Response for 34/1e3b
D (214824) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
V (214824) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
V (215814) vwup.obd: CarOffTicker increased to 1
V (216814) vwup.obd: CarOffTicker increased to 2
V (217814) vwup.obd: CarOffTicker increased to 3
V (218814) vwup.obd: CarOffTicker increased to 4
V (219814) vwup.obd: CarOffTicker increased to 5
D (220814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (220814) canlog-monitor: 1596884292.858838 1T11 7E5 03 22 1e 3b 00 00 00 00
V (220814) vwup.obd: CarOffTicker increased to 6
V (221814) vwup.obd: CarOffTicker increased to 7
V (222814) vwup.obd: CarOffTicker increased to 8
V (223814) vwup.obd: CarOffTicker increased to 9
V (224814) vwup.obd: CarOffTicker increased to 10
V (225814) vwup.obd: CarOffTicker increased to 11
D (226814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (226814) vwup.obd: CarOffTicker increased to 12
V (226814) canlog-monitor: 1596884298.858879 1T11 7E5 03 22 1e 3b 00 00 00 00
V (227814) vwup.obd: CarOffTicker increased to 13
V (228814) vwup.obd: CarOffTicker increased to 14
V (229814) vwup.obd: CarOffTicker increased to 15
V (230814) vwup.obd: CarOffTicker increased to 16
V (231814) vwup.obd: CarOffTicker increased to 17
D (232814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (232814) vwup.obd: CarOffTicker increased to 18
V (232814) canlog-monitor: 1596884304.858825 1T11 7E5 03 22 1e 3b 00 00 00 00
V (233814) vwup.obd: CarOffTicker increased to 19
V (234814) vwup.obd: CarOffTicker increased to 20
V (235814) vwup.obd: CarOffTicker increased to 21
I (236814) vwup.obd: Setting car state to OFF
D (237814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (237814) canlog-monitor: 1596884309.858703 1T11 7E5 03 22 1e 3b 00 00 00 00
V (237824) canlog-monitor: 1596884309.868973 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (237824) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (237824) vehicle: Receive Poll Response for 34/1e3b
D (237824) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
I (237824) vwup.obd: Setting car state to ON
V (237824) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
D (238814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (238814) vwup.obd: CarOffTicker increased to 1
V (238814) canlog-monitor: 1596884310.858727 1T11 7E5 03 22 1e 3b 00 00 00 00
V (238824) canlog-monitor: 1596884310.870344 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (238824) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (238824) vehicle: Receive Poll Response for 34/1e3b
D (238824) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
V (238824) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
V (239814) vwup.obd: CarOffTicker increased to 1
V (240814) vwup.obd: CarOffTicker increased to 2
D (240824) script: Duktape: Compacting DukTape memory
V (241814) vwup.obd: CarOffTicker increased to 3
V (242814) vwup.obd: CarOffTicker increased to 4
V (243814) vwup.obd: CarOffTicker increased to 5
D (244814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (244814) vwup.obd: CarOffTicker increased to 6
V (244814) canlog-monitor: 1596884316.858455 1T11 7E5 03 22 1e 3b 00 00 00 00
V (245814) vwup.obd: CarOffTicker increased to 7
V (246814) vwup.obd: CarOffTicker increased to 8
V (247814) vwup.obd: CarOffTicker increased to 9
V (248814) vwup.obd: CarOffTicker increased to 10
V (249814) vwup.obd: CarOffTicker increased to 11
D (250814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (250814) vwup.obd: CarOffTicker increased to 12
V (250814) canlog-monitor: 1596884322.858614 1T11 7E5 03 22 1e 3b 00 00 00 00
V (251814) vwup.obd: CarOffTicker increased to 13
V (252814) vwup.obd: CarOffTicker increased to 14
V (253814) vwup.obd: CarOffTicker increased to 15
V (254814) vwup.obd: CarOffTicker increased to 16
V (255814) vwup.obd: CarOffTicker increased to 17
D (256814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (256814) vwup.obd: CarOffTicker increased to 18
V (256814) canlog-monitor: 1596884328.858680 1T11 7E5 03 22 1e 3b 00 00 00 00
V (257814) vwup.obd: CarOffTicker increased to 19
V (258814) vwup.obd: CarOffTicker increased to 20
V (259814) vwup.obd: CarOffTicker increased to 21
I (260814) vwup.obd: Setting car state to OFF
D (261814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (261814) canlog-monitor: 1596884333.858799 1T11 7E5 03 22 1e 3b 00 00 00 00
I (261814) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (261814) vehicle: Receive Poll Response for 34/1e3b
D (261814) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
I (261814) vwup.obd: Setting car state to ON
V (261814) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
V (261814) canlog-monitor: 1596884333.860368 1R11 7ED 05 62 1e 3b 04 fc aa aa
D (262814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (262814) vwup.obd: CarOffTicker increased to 1
V (262814) canlog-monitor: 1596884334.858830 1T11 7E5 03 22 1e 3b 00 00 00 00
I (262814) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (262814) vehicle: Receive Poll Response for 34/1e3b
D (262814) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
V (262814) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
V (262814) canlog-monitor: 1596884334.860410 1R11 7ED 05 62 1e 3b 04 fc aa aa
V (263814) vwup.obd: CarOffTicker increased to 1
V (264814) vwup.obd: CarOffTicker increased to 2
V (265814) vwup.obd: CarOffTicker increased to 3
V (266814) vwup.obd: CarOffTicker increased to 4
V (267814) vwup.obd: CarOffTicker increased to 5
D (268814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (268814) vwup.obd: CarOffTicker increased to 6
V (268814) canlog-monitor: 1596884340.858660 1T11 7E5 03 22 1e 3b 00 00 00 00
V (269814) vwup.obd: CarOffTicker increased to 7
V (270814) vwup.obd: CarOffTicker increased to 8
V (271814) vwup.obd: CarOffTicker increased to 9
V (272814) vwup.obd: CarOffTicker increased to 10
V (273814) vwup.obd: CarOffTicker increased to 11
D (274814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (274814) vwup.obd: CarOffTicker increased to 12
V (274814) canlog-monitor: 1596884346.858684 1T11 7E5 03 22 1e 3b 00 00 00 00
V (275814) vwup.obd: CarOffTicker increased to 13
V (276814) vwup.obd: CarOffTicker increased to 14
V (277814) vwup.obd: CarOffTicker increased to 15
V (278814) vwup.obd: CarOffTicker increased to 16
V (279814) vwup.obd: CarOffTicker increased to 17
D (280814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (280814) vwup.obd: CarOffTicker increased to 18
V (280814) canlog-monitor: 1596884352.858745 1T11 7E5 03 22 1e 3b 00 00 00 00
V (281814) vwup.obd: CarOffTicker increased to 19
V (282814) vwup.obd: CarOffTicker increased to 20
V (283814) vwup.obd: CarOffTicker increased to 21
I (284814) vwup.obd: Setting car state to OFF
D (285814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (285814) canlog-monitor: 1596884357.858858 1T11 7E5 03 22 1e 3b 00 00 00 00
V (285814) canlog-monitor: 1596884357.860678 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (285814) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (285814) vehicle: Receive Poll Response for 34/1e3b
D (285814) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
I (285814) vwup.obd: Setting car state to ON
V (285814) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
D (286814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (286814) vwup.obd: CarOffTicker increased to 1
V (286814) canlog-monitor: 1596884358.859177 1T11 7E5 03 22 1e 3b 00 00 00 00
I (286824) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (286824) vehicle: Receive Poll Response for 34/1e3b
D (286824) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
V (286824) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
V (286824) canlog-monitor: 1596884358.871038 1R11 7ED 05 62 1e 3b 04 fc aa aa
V (287814) vwup.obd: CarOffTicker increased to 1
V (288814) vwup.obd: CarOffTicker increased to 2
V (289814) vwup.obd: CarOffTicker increased to 3
-------------- next part --------------
 (15814) simcom: State timeout, transition to 13
I (15814) simcom: State: Enter PoweredOff state
I (15814) gsm-mux: Stop MUX
I (19634) webserver: HTTP GET /shell
I (23394) webserver: HTTP POST /api/execute
I (23404) webcommand: HttpCommandStream[0x3f845f00]: 3991032 bytes free, executing: . startlogging
I (23414) canlog-monitor: Now logging CAN messages to monitor
D (23414) canlog-monitor: 1596884658.127607 CXX OVMS CRTD
OVMS# . startlogging
Logging level for * set to verbose
CAN logging to MONITOR active: Type:monitor Format:crtd(discard) Filter:off Vehicle:VWUP.OBD
Note: info logging is at debug log level, frame logging is at verbose, and errors as usual
D (32814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
E (32814) can: can1: intr=3 rxpkt=0 txpkt=1 errflags=0x8000d9 rxerr=0 txerr=15 rxovr=0 txovr=0 txdelay=0 wdgreset=0 errreset=0
E (32814) can: can1: intr=8 rxpkt=0 txpkt=1 errflags=0x8000d9 rxerr=0 txerr=55 rxovr=0 txovr=0 txdelay=0 wdgreset=0 errreset=0
E (32814) can: can1: intr=10 rxpkt=0 txpkt=1 errflags=0x8000d9 rxerr=0 txerr=71 rxovr=0 txovr=0 txdelay=0 wdgreset=0 errreset=0
E (32814) canlog-monitor: 1596884667.531411 1CER Error intr=8 rxpkt=0 txpkt=1 errflags=0x8000d9 rxerr=0 txerr=55 rxovr=0 txovr=0 txdelay=0 wdgreset=0 errreset=0
E (32814) can: can1: intr=13 rxpkt=0 txpkt=1 errflags=0x8000d9 rxerr=0 txerr=95 rxovr=0 txovr=0 txdelay=0 wdgreset=0 errreset=0
E (32814) canlog-monitor: 1596884667.531899 1CER Error intr=10 rxpkt=0 txpkt=1 errflags=0x8000d9 rxerr=0 txerr=71 rxovr=0 txovr=0 txdelay=0 wdgreset=0 errreset=0
E (32814) can: can1: intr=15 rxpkt=0 txpkt=1 errflags=0x8040d9 rxerr=0 txerr=111 rxovr=0 txovr=0 txdelay=0 wdgreset=0 errreset=0
E (32814) canlog-monitor: 1596884667.532556 1CER Error intr=12 rxpkt=0 txpkt=1 errflags=0x8000d9 rxerr=0 txerr=87 rxovr=0 txovr=0 txdelay=0 wdgreset=0 errreset=0
E (32814) can: can1: intr=19 rxpkt=0 txpkt=1 errflags=0x204000 rxerr=0 txerr=135 rxovr=0 txovr=0 txdelay=0 wdgreset=0 errreset=0
E (32814) can: can1: intr=21 rxpkt=0 txpkt=1 errflags=0x8040d9 rxerr=0 txerr=135 rxovr=0 txovr=0 txdelay=0 wdgreset=0 errreset=0
E (32814) canlog-monitor: 1596884667.533296 1CER Error intr=15 rxpkt=0 txpkt=1 errflags=0x8040d9 rxerr=0 txerr=111 rxovr=0 txovr=0 txdelay=0 wdgreset=0 errreset=0
E (32814) canlog-monitor: 1596884667.533897 1CER Error intr=19 rxpkt=0 txpkt=1 errflags=0x204000 rxerr=0 txerr=135 rxovr=0 txovr=0 txdelay=0 wdgreset=0 errreset=0
E (32814) canlog-monitor: 1596884667.534574 1CER Error intr=21 rxpkt=0 txpkt=1 errflags=0x8040d9 rxerr=0 txerr=135 rxovr=0 txovr=0 txdelay=0 wdgreset=0 errreset=0
E (32814) canlog-monitor: 1596884667.535179 1CER Error intr=24 rxpkt=0 txpkt=1 errflags=0x8040d9 rxerr=0 txerr=135 rxovr=0 txovr=0 txdelay=0 wdgreset=0 errreset=0
D (60834) script: Duktape: Compacting DukTape memory
D (63814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (63814) canlog-monitor: 1596884698.530251 1CER TX_Queue T11 7E5 03 22 1e 3b 00 00 00 00
E (63814) can: can1: intr=115541 rxpkt=0 txpkt=1 errflags=0x8040d9 rxerr=0 txerr=135 rxovr=0 txovr=0 txdelay=1 wdgreset=0 errreset=0
E (63814) canlog-monitor: 1596884698.531818 1CER Error intr=115546 rxpkt=0 txpkt=1 errflags=0x8040d9 rxerr=0 txerr=135 rxovr=0 txovr=0 txdelay=1 wdgreset=0 errreset=0
V (71074) canlog-monitor: 1596884705.787497 1T11 7E5 03 22 1e 3b 00 00 00 00
V (71074) canlog-monitor: 1596884705.787865 1T11 7E5 03 22 1e 3b 00 00 00 00
D (94814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (94814) canlog-monitor: 1596884729.530534 1T11 7E5 03 22 1e 3b 00 00 00 00
V (94814) canlog-monitor: 1596884729.532324 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (94814) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (94814) vehicle: Receive Poll Response for 34/1e3b
D (94814) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
I (94814) vwup.obd: Setting car state to ON
V (94814) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
D (95814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (95814) vwup.obd: CarOffTicker increased to 1
V (95814) canlog-monitor: 1596884730.530230 1T11 7E5 03 22 1e 3b 00 00 00 00
I (95814) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (95814) vehicle: Receive Poll Response for 34/1e3b
D (95814) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
V (95814) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
V (95814) canlog-monitor: 1596884730.531870 1R11 7ED 05 62 1e 3b 04 fc aa aa
V (96814) vwup.obd: CarOffTicker increased to 1
V (97814) vwup.obd: CarOffTicker increased to 2
V (98814) vwup.obd: CarOffTicker increased to 3
V (99814) vwup.obd: CarOffTicker increased to 4
V (100814) vwup.obd: CarOffTicker increased to 5
V (101814) vwup.obd: CarOffTicker increased to 6
V (102814) vwup.obd: CarOffTicker increased to 7
V (103814) vwup.obd: CarOffTicker increased to 8
V (104814) vwup.obd: CarOffTicker increased to 9
V (105814) vwup.obd: CarOffTicker increased to 10
D (106814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (106814) vwup.obd: CarOffTicker increased to 11
V (106814) canlog-monitor: 1596884741.530192 1T11 7E5 03 22 1e 3b 00 00 00 00
V (106814) canlog-monitor: 1596884741.532923 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (106814) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (106814) vehicle: Receive Poll Response for 34/1e3b
D (106814) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
V (106814) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
V (107814) vwup.obd: CarOffTicker increased to 1
V (108814) vwup.obd: CarOffTicker increased to 2
V (109814) vwup.obd: CarOffTicker increased to 3
V (110814) vwup.obd: CarOffTicker increased to 4
V (111814) vwup.obd: CarOffTicker increased to 5
V (112814) vwup.obd: CarOffTicker increased to 6
V (113814) vwup.obd: CarOffTicker increased to 7
V (114814) vwup.obd: CarOffTicker increased to 8
V (115814) vwup.obd: CarOffTicker increased to 9
V (116814) vwup.obd: CarOffTicker increased to 10
D (117814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (117814) vwup.obd: CarOffTicker increased to 11
V (117814) canlog-monitor: 1596884752.530310 1T11 7E5 03 22 1e 3b 00 00 00 00
V (117814) canlog-monitor: 1596884752.532640 1R11 7ED 05 62 1e 3b 04 fc aa aa
I (117814) vehicle: Poller Rx candidate ID=7ed (expecting 7ed-7ed)
I (117814) vehicle: Receive Poll Response for 34/1e3b
D (117814) vwup.obd: IncomingPollReply(type=34, pid=1E3B, length=4, remain=0): called
V (117814) vwup.obd: StandardMetrics.ms_v_bat_voltage=319.000000
V (118814) vwup.obd: CarOffTicker increased to 1
V (119814) vwup.obd: CarOffTicker increased to 2
V (120814) vwup.obd: CarOffTicker increased to 3
D (120824) script: Duktape: Compacting DukTape memory
V (121814) vwup.obd: CarOffTicker increased to 4
V (122814) vwup.obd: CarOffTicker increased to 5
V (123814) vwup.obd: CarOffTicker increased to 6
V (124814) vwup.obd: CarOffTicker increased to 7
V (125814) vwup.obd: CarOffTicker increased to 8
V (126814) vwup.obd: CarOffTicker increased to 9
V (127814) vwup.obd: CarOffTicker increased to 10
D (128814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (128814) vwup.obd: CarOffTicker increased to 11
V (128814) canlog-monitor: 1596884763.530115 1T11 7E5 03 22 1e 3b 00 00 00 00
V (129814) vwup.obd: CarOffTicker increased to 12
V (130814) vwup.obd: CarOffTicker increased to 13
V (131814) vwup.obd: CarOffTicker increased to 14
V (132814) vwup.obd: CarOffTicker increased to 15
V (133814) vwup.obd: CarOffTicker increased to 16
V (134814) vwup.obd: CarOffTicker increased to 17
V (135814) vwup.obd: CarOffTicker increased to 18
V (136814) vwup.obd: CarOffTicker increased to 19
V (137814) vwup.obd: CarOffTicker increased to 20
V (138814) vwup.obd: CarOffTicker increased to 21
D (139814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (139814) vwup.obd: CarOffTicker increased to 22
E (139814) can: can1: intr=142629 rxpkt=4 txpkt=8 errflags=0x8040d9 rxerr=0 txerr=128 rxovr=0 txovr=0 txdelay=1 wdgreset=0 errreset=0
E (139814) canlog-monitor: 1596884774.531159 1CER Error intr=142633 rxpkt=4 txpkt=8 errflags=0x8040d9 rxerr=0 txerr=128 rxovr=0 txovr=0 txdelay=1 wdgreset=0 errreset=0
V (140814) vwup.obd: CarOffTicker increased to 23
V (141814) vwup.obd: CarOffTicker increased to 24
V (142814) vwup.obd: CarOffTicker increased to 25
V (143814) vwup.obd: CarOffTicker increased to 26
V (144814) vwup.obd: CarOffTicker increased to 27
V (145814) vwup.obd: CarOffTicker increased to 28
V (146814) vwup.obd: CarOffTicker increased to 29
V (147814) vwup.obd: CarOffTicker increased to 30
V (148814) vwup.obd: CarOffTicker increased to 31
V (149814) vwup.obd: CarOffTicker increased to 32
D (150814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (150814) canlog-monitor: 1596884785.529809 1CER TX_Queue T11 7E5 03 22 1e 3b 00 00 00 00
E (150814) can: can1: intr=183674 rxpkt=4 txpkt=8 errflags=0x8040d9 rxerr=0 txerr=128 rxovr=0 txovr=0 txdelay=2 wdgreset=0 errreset=0
E (150814) canlog-monitor: 1596884785.531159 1CER Error intr=183678 rxpkt=4 txpkt=8 errflags=0x8040d9 rxerr=0 txerr=128 rxovr=0 txovr=0 txdelay=2 wdgreset=0 errreset=0
V (150814) vwup.obd: CarOffTicker increased to 33
V (151814) vwup.obd: CarOffTicker increased to 34
V (152814) vwup.obd: CarOffTicker increased to 35
V (153814) vwup.obd: CarOffTicker increased to 36
V (154814) vwup.obd: CarOffTicker increased to 37
V (155814) vwup.obd: CarOffTicker increased to 38
V (156814) vwup.obd: CarOffTicker increased to 39
V (157814) vwup.obd: CarOffTicker increased to 40
V (158814) vwup.obd: CarOffTicker increased to 41
I (159814) vwup.obd: Setting car state to OFF
D (160814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (160814) canlog-monitor: 1596884795.529972 1CER TX_Queue T11 7E5 03 22 1e 3b 00 00 00 00
E (160814) can: can1: intr=220986 rxpkt=4 txpkt=8 errflags=0x8040d9 rxerr=0 txerr=128 rxovr=0 txovr=0 txdelay=3 wdgreset=0 errreset=0
E (160814) canlog-monitor: 1596884795.531372 1CER Error intr=220990 rxpkt=4 txpkt=8 errflags=0x8040d9 rxerr=0 txerr=128 rxovr=0 txovr=0 txdelay=3 wdgreset=0 errreset=0
D (180834) script: Duktape: Compacting DukTape memory
D (191814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (191814) canlog-monitor: 1596884826.529787 1CER TX_Queue T11 7E5 03 22 1e 3b 00 00 00 00
E (191814) can: can1: intr=336624 rxpkt=4 txpkt=8 errflags=0x8040d9 rxerr=0 txerr=128 rxovr=0 txovr=0 txdelay=4 wdgreset=0 errreset=0
E (191814) canlog-monitor: 1596884826.531185 1CER Error intr=336628 rxpkt=4 txpkt=8 errflags=0x8040d9 rxerr=0 txerr=128 rxovr=0 txovr=0 txdelay=4 wdgreset=0 errreset=0
D (222814) vehicle: Polling for 34/1e3b (expecting 7e5/7ed-7ed)
V (222814) canlog-monitor: 1596884857.529918 1CER TX_Queue T11 7E5 03 22 1e 3b 00 00 00 00
E (222814) can: can1: intr=452293 rxpkt=4 txpkt=8 errflags=0x8040d9 rxerr=0 txerr=128 rxovr=0 txovr=0 txdelay=5 wdgreset=0 errreset=0
E (222814) canlog-monitor: 1596884857.531325 1CER Error intr=452297 rxpkt=4 txpkt=8 errflags=0x8040d9 rxerr=0 txerr=128 rxovr=0 txovr=0 txdelay=5 wdgreset=0 errreset=0