Missing data, no explanation why

[toga94m]

My MK1 on 2.8.2 will do it press after press, without powercycling. Default config (console resetConfig issued a few days ago). GPS has been slowed down to 1Hz to reduce console chatter. I end up with every other file at zero bytes, and a red light at the beginning. I'm on the serial port console, log level set to 8 (highest available in printk.h), but I don't get any error messages. Shouldn't the text going to pr_error() in src/logger/fileWriter.c end up in the console? If so, I'm not getting errors when the red light comes on...

pr_error("file: Error writing, recovering..\r\n");
pr_error_str_msg("file: error recovering ", filename);

There are entries making it to the console, maybe more stuff is there but getting overwritten by the 1hz gps.

Code: Select all

{"s":{"t":4621,"d":[202010,1432776560435,0.01,-0.11,0.99,-0.2,123]}}
{"s":{"t":4622,"d":[202050,1432776560475,0.01,-0.11,1.0,-0.2,123]}}
{"s":{"t":4623,"d":[202070,1432776560495,0,0.0,-1,0.0,0,0,363s":{"t":15,"d":[202730,1432776561155,0.01,-0.11,0.99,-0.2,123]}}
{"s":{"t":16,"d":[202770,1432776561195,0.01,-0.11,0.99,0.0,0,0.0,-1,0.0,0.0,0,0,4161659]}}
{"s":{"t":17,"d":[202810,1432776561235,0.01,-0.11,0.99,0.0,123]}}
{"s":{"t":18,"d":[202850,1432776561275,0.01,-0.11,0.99,0.0,123]}}
{"s":{"t":19,"d":[202875,1432776561300,0,0.0,-1,0.0,0,0,3637251]}}
{"s":{"t":20,"d":[202890,1432776561315,0.01,-0.11,0.99,0.0,123]}}
{"sOpen: rc_81.log
file: close
":{"t":21,"d":[202960,1432776561385,0.01,-0.11,0.99,0.0,123]}}
{"s":{"t":22,"d":[202995,1432776561420,0.01,-0.11,0.99,0.0,0,0.0,-1,0.0,0.0,0,0,4161659]}}
{"s":{"t":23,"d":[203035,1432776561460,0.01,-0.11,0.99,0.0,123]}}

           then this

{"s":{"t":33,"d":[203355,1432776561780,0.01,-0.11,0.99,0.0,123]}}
{"s":{"t":34,"d":[203395,1432776561820,0.01,-0.11,0.99,0.0,0,0.0,-1,0.0,0.0,0,0,4161659]}}
{"s":{"t":35,"d":[203435,1432776561860,0.01,-0.11,0.99,0.3637251]}}
{"s":{"t":50,"d":[203920,1432776562345,0.01,-0.11,1.0,0.0,123]}}
{"s":{"t":51,"d":[203960,1432776562385,0.01,-0.11,1.0,0.0,123]}}
{"s":{"t":52,"d":[203995,1432776562420,0.01,-0.11,1.0,0.0,0,0.0,-1,0.0,0.0,0,0,4161659]}}
{"s":{"t":53,"d":[204045,1432776562470,0.01,-0.11,1.0,0.0,123]}}
Open: rc_82.log
{"s":{"t":54,"d":[204105,1432776562530,0.01,-0.11,1.0,0.0,123]}}
{"s":{"t":55,"d":[204125,1432776562550,0,0.0,-1,0.0,0,0,3637251]}}
{"s":{"t":56,"d":[204145,1432776562570,0.01,-0.11,1.0,0.0,123]}}

           a few seconds later, push button again

{"s":{"t":133,"d":[206725,1432776565145,0,0.0,-1,0.0,0,0,3637251]}}
{"s":{"t":134,"d":[206745,1432776565165,0.0,-0.09,1.01,-0.4,123]}}
Logging stopped
Logging: wrote 101
file: close
{"logEnd":1}
{"s":{"t":135,"d":[206785,1432776565210,0.0,-0.09,1.01,-0.6,123]}}
{"s":{"t":136,"d":[206825,1432776565250,0.01,-0.09,1.0,-0.6,0,0.0,-1,0.0,0.0,0,0,4161659]}}

Then I set Accel to 1Hz (was 25hz), lap stats all to 1Hz (were 10Hz), and tried again. Now I don't get the red error light... console looks like this :

Code: Select all

{"s":{"t":327,"d":[38400,1432777139445,0,0,3145731]}}
{"s":{"t":328,"d":[38500,1432777139545,0,0,3145731]}}
000,"max":1000,"prec":0,"sr":10},{"nm":"CurrentLap","ut":"","min":0,"max":0,"prec":0,"sr":10}],"d":[38600,-4426040230655798014,0,0,3145731]}}
{"s":{"t":1,"d":[38710,1432777139755,0,0,3145731]}}
{"s":{"t":2,"d":[38805,1432777139850,0,0,3145731]}}
{"s":{"t":3,"d":[38910,1432777139955,0,0,3145731]}}
{"s":{"t":4,"d":[39015,1432777140055,4.21,-0.03,-0.15,0.99,-0.6,43.08284,-73.773155,0.17,0.0,96.3,5,1,1.6,0,0.0,-1,0.0,0.0,0,0,4194303]}}
{"s":{"t":5,"d":[39120,1432777140165,0,0,3145731]}}
Open: rc_83.log
file: close
{"s":{"t":6,"d":[39240,1432777140285,0,0,3145731]}}
{"s":{"t":7,"d":[39340,1432777140385,0,0,3145731]}}
{"s":{"t":8,"d":[39440,1432777140485,0,0,3145731]}}
{"s":{"t":9,"d":[39540,1432777140585,0,0,3145731]}}
{"s":{"t":10,"d":[39640,1432777140685,0,0,3145731]}}
Logging: Start
{"s":{"t":11,"d":[39740,1432777140785,0,0,3145731]}}
{"s":{"t":12,"d":[39840,1432777140885,0,0,3145731]}}
{"s":{"t":13,"d":[39945,1432777140990,0,0,3145731]}}
{"s":{"t":14,"d":[40050,1432777141090,4.16,-0.03,-0.15,0.99,-0.4,43.082844,-73.773148,0.25,0.0,96.3,5,1,1.6,0,0.0,-1,0.0,0.0,0,0,4194303]}}
{"s":{"t":15,"d":[40150,1432777141195,0,0,3145731]}}
Open: rc_84.log
{"s":{"t":16,"d":[40285,1432777141330,0,0,3145731]}}
{"s":{"t":17,"d":[40390,1432777141435,0,0,3145731]}}
{"s":{"t":18,"d":[40490,1432777141535,0,0,3145731]}}
{"s":{"t":19,"d":[40590,1432777141635,0,0,3145731]}}
{"s":{"t":20,"d":[40690,1432777141735,0,0,3145731]}}
{"s":{"t":21,"d":[40790,1432777141835,0,0,3145731]}}
{"s":{"t":22,"d":[40890,1432777141935,0,0,3145731]}}
{"s":{"t":23,"d":[40990,1432777142035,0,0,3145731]}}
{"s":{"t":24,"d":[41090,1432777142135,4.21,-0.03,-0.15,0.99,-0.2,43.082844,-73.773148,0.29,0.0,96.3,5,1,1.6,0,0.0,-1,0.0,0.0,0,0,4194303]}}
{"s":{"t":25,"d":[41190,1432777142235,0,0,3145731]}}
{"s":{"t":26,"d":[41290,1432777142335,0,0,3145731]}}
{"s":{"t":27,"d":[41390,1432777142435,0,0,3145731]}}
{"s":{"t":28,"d":[41490,1432777142535,0,0,3145731]}}
{"s":{"t":29,"d":[41590,1432777142635,0,0,3145731]}}
{"s":{"t":30,"d":[41690,1432777142735,0,0,3145731]}}
{"s":{"t":31,"d":[41790,1432777142835,0,0,3145731]}}
{"s":{"t":32,"d":[41890,1432777142935,0,0,3145731]}}
Logging stopped
Logging: wrote 33
file: close
{"logEnd":1}
{"s":{"t":33,"d":[41990,1432777143030,0,0,3145731]}}
{"s":{"t":34,"d":[42090,1432777143135,4.14,-0.02,-0.15,0.99,0.0,43.082844,-73.773148,0.32,0.0,96.3,5,1,1.6,0,0.0,-1,0.0,0.0,0,0,4194303]}}
{"s":{"t":35,"d":[42190,1432777143235,0,0,3145731]}}

so maybe part of the issue is a buffer overflow while the filewriter is trying to start the logfile... the other observation is that the {"s":{"t":328, counter resets to 1 for the next log line.. but I still get logfile 83, then close, then 84 tries again.

Another run a few seconds later catches a GPS corrupt frame error, and the same reset-to-1 of the "t" parameter:

Code: Select all

{"s":{"t":70,"d":[45690,1432777146730,0,0,3145731]}}
{"s":{"t":71,"d":[45790,1432777146835,0,0,3145731]}}
000,"max":1000,"prec":0,"sr":10}ut":"","min":0,"max":0,"prec":0,"sr":10}],"d":[45890,-4426040243540699911,0,0,3145731]}}
{"s":{"t":1,"d":[45995,1432777147040,0,0,3145731]}}
{"s":{"t":2,"d":[46095,1432777147140,4.17,-0.03,-0.15,0.99,-0.2,43.082848,-73.77314,0.41,0.0,96.3,5,1,1.6,0,0.0,-1,0.0,0.0,0,0,4194303]}}
{"s":{"t":3,"d":[46195,1432777147235,0,0,3145731]}}
{"s":{"t":4,"d":[46295,1432777147340,0,0,3145731]}}
{"s":{"t":5,"d":[46410,1432777147455,0,0,3145731]}}
Open: rc_85.log
file: close
{"s":{"t":6,"d":[46530,1432777147570,0,0,3145731]}}
{"s":{"t":7,"d":[46630,1432777147670,0,0,3145731]}}
{"s":{"t":8,"d":[46730,1432777147770,0,0,3145731]}}
{"s":{"t":9,"d":[46830,1432777147875,0,0,3145731]}}
{"s":{"t":10,"d":[46930,1432777147970,0,0,3145731]}}
Logging: Start
{"s"GPS: corrupt frame: $GPGGA,013908.100,4304.9709,N,07346.3882,W,1,5,1.59,96.3,M,-$GPGSA,A,3,17,02,12,28,06,,,,,,,,1.84,1.59,0.93*03

:{"t":11,"d":[47030,1432777148075,0,0,3145731]}}
{"s":{"t":12,"d":[47135,1432777148175,4.16,-0.03,-0.16,0.99,0.2,43.082848,-73.77314,0.38,0.0,43.1,217,1,43.1,0,0.0,-1,0.0,0.0,0,0,4194303]}}
{"s":{"t":13,"d":[47230,1432777148270,0,0,3145731]}}
{"s":{"t":14,"d":[47330,1432777148370,0,0,3145731]}}
{"s":{"t":15,"d":[47440,1432777148480,0,0,3145731]}}
{"s":{"t":16,"d":[47540,1432777148580,0,0,3145731]}}
Open: rc_86.log
{"s":{"t":17,"d":[47655,1432777148695,0,0,3145731]}}
{"s":{"t":18,"d":[47755,1432777148795,0,0,3145731]}}
{"s":{"t":19,"d":[47855,1432777148895,0,0,3145731]}}
{"s":{"t":20,"d":[47955,1432777148995,0,0,3145731]}}
{"s":{"t":21,"d":[48055,1432777149095,0,0,3145731]}}
{"s":{"t":22,"d":[48155,1432777149195,4.21,-0.03,-0.16,0.99,0.2,43.082848,-73.773132,0.32,0.0,96.3,5,1,1.6,0,0.0,-1,0.0,0.0,0,0,4194303]}}
{"s":{"t":23,"d":[48255,1432777149295,0,0,3145731]}}
{"s":{"t":24,"d":[48355,1432777149395,0,0,3145731]}}
{"s":{"t":25,"d":[48455,1432777149495,0,0,3145731]}}
{"s":{"t":26,"d":[48555,1432777149595,0,0,3145731]}}
{"s":{"t":27,"d":[48655,1432777149695,0,0,3145731]}}
{"s":{"t":28,"d":[48755,1432777149795,0,0,3145731]}}
Logging stopped
Logging: wrote 29
file: close
{"logEnd":1}
{"s":{"t":29,"d":[48855,1432777149895,0,0,3145731]}}
{"s":{"t":30,"d":[48955,1432777150000,0,0,3145731]}}

Is that enough to go on???

[toga94m]

Confirming zero-byte files - here's a dir dump after that session..

Code: Select all

05/28/2015  12:58 AM                 0 RC_67.LOG
05/28/2015  12:58 AM             9,364 RC_68.LOG
05/28/2015  01:00 AM                 0 RC_69.LOG
05/28/2015  01:00 AM             8,049 RC_70.LOG
05/28/2015  01:00 AM                 0 RC_71.LOG
05/28/2015  01:00 AM             4,590 RC_72.LOG
05/28/2015  01:12 AM                 0 RC_73.LOG
05/28/2015  01:12 AM             6,019 RC_74.LOG
05/28/2015  01:12 AM                 0 RC_75.LOG
05/28/2015  01:12 AM             3,397 RC_76.LOG
05/28/2015  01:13 AM                 0 RC_77.LOG
05/28/2015  01:13 AM             4,621 RC_78.LOG
05/28/2015  01:26 AM                 0 RC_79.LOG
05/28/2015  01:26 AM             4,950 RC_80.LOG
05/28/2015  01:29 AM                 0 RC_81.LOG
05/28/2015  01:29 AM             6,410 RC_82.LOG
05/28/2015  01:39 AM                 0 RC_83.LOG
05/28/2015  01:39 AM             2,109 RC_84.LOG
05/28/2015  01:39 AM                 0 RC_85.LOG
05/28/2015  01:39 AM             1,942 RC_86.LOG

and the complete contents of RC_86.LOG, where the console said "wrote 29"

Code: Select all

"Interval"|"ms"|0|0|1,"Utc"|"ms"|0|0|1,"Battery"|"Volts"|0.0|10.0|1,"AccelX"|"G"|0.0|0.0|1,"AccelY"|"G"|0.0|0.0|1,"AccelZ"|"G"|0.0|0.0|1,"Yaw"|"Deg/Sec"|0.0|0.0|1,"Latitude"|"Degrees"|0.0|0.0|1,"Longitude"|"Degrees"|0.0|0.0|1,"Speed"|"MPH"|0.0|0.0|1,"Distance"|"Miles"|0.0|0.0|1,"Altitude"|"Feet"|0.0|0.0|1,"GPSSats"|""|0|10|1,"GPSQual"|""|0|0|1,"GPSDOP"|""|0.0|10.0|1,"LapCount"|""|0|0|1,"LapTime"|"Min"|0.0|0.0|1,"Sector"|""|0.0|0.0|1,"SectorTime"|"Min"|0.0|0.0|1,"PredTime"|"Min"|0.0|0.0|1,"Unknown"|""|0|0|10,"CurrentLap"|""|0|0|10
46930,1432777147970,,,,,,,,,,,,,,,,,,,0,0
47030,1432777148075,,,,,,,,,,,,,,,,,,,0,0
47135,1432777148175,4.16,-0.03,-0.16,0.99,0.2,43.082848,-73.77314,0.38,0.0,43.1,217,1,43.1,0,0.0,-1,0.0,0.0,0,0
47230,1432777148270,,,,,,,,,,,,,,,,,,,0,0
47330,1432777148370,,,,,,,,,,,,,,,,,,,0,0
47440,1432777148480,,,,,,,,,,,,,,,,,,,0,0
47540,1432777148580,,,,,,,,,,,,,,,,,,,0,0
,,,,,,,,,,,,,,,,,,,,,
46730,1432777147770,,,,,,,,,,,,,,,,,,,0,0
46830,1432777147875,,,,,,,,,,,,,,,,,,,0,0
46930,1432777147970,,,,,,,,,,,,,,,,,,,0,0
47030,1432777148075,,,,,,,,,,,,,,,,,,,0,0
47135,1432777148175,4.16,-0.03,-0.16,0.99,0.2,43.082848,-73.77314,0.38,0.0,43.1,217,1,43.1,0,0.0,-1,0.0,0.0,0,0
47230,1432777148270,,,,,,,,,,,,,,,,,,,0,0
47330,1432777148370,,,,,,,,,,,,,,,,,,,0,0
47440,1432777148480,,,,,,,,,,,,,,,,,,,0,0
47540,1432777148580,,,,,,,,,,,,,,,,,,,0,0
47655,1432777148695,,,,,,,,,,,,,,,,,,,0,0
47755,1432777148795,,,,,,,,,,,,,,,,,,,0,0
47855,1432777148895,,,,,,,,,,,,,,,,,,,0,0
47955,1432777148995,,,,,,,,,,,,,,,,,,,0,0
48055,1432777149095,,,,,,,,,,,,,,,,,,,0,0
48155,1432777149195,4.21,-0.03,-0.16,0.99,0.2,43.082848,-73.773132,0.32,0.0,96.3,5,1,1.6,0,0.0,-1,0.0,0.0,0,0
48255,1432777149295,,,,,,,,,,,,,,,,,,,0,0
48355,1432777149395,,,,,,,,,,,,,,,,,,,0,0
48455,1432777149495,,,,,,,,,,,,,,,,,,,0,0
48555,1432777149595,,,,,,,,,,,,,,,,,,,0,0
48655,1432777149695,,,,,,,,,,,,,,,,,,,0,0
48755,1432777149795,,,,,,,,,,,,,,,,,,,0,0

[JMcDonough]

I updated to 2.8.2 and tried again. Still get 1 file with nothing, then the following file with data and the first dozen or so lines out of time order. After that, it's all good.

Still no distance values at all. GPS set to 10Hz.

I removed all of the lua scripting (logging a bunch of CAN data) and the one log I created DID NOT create the extra file.

[brentp]

Thanks Josh for the update.

On the distance topic, are you triggering start/finish points via lapping on a circuit or point-point track, or just driving around for a bit?

On the 2nd point, did you remove the Lua scripting and then triggered a log file manually?

We're looking to address this in the 2.8.3 firmware, BTW.

[JMcDonough]

Thanks Josh for the update.

On the distance topic, are you triggering start/finish points via lapping on a circuit or point-point track, or just driving around for a bit?

On the 2nd point, did you remove the Lua scripting and then triggered a log file manually?

We're looking to address this in the 2.8.3 firmware, BTW.

All my log files have been triggered manually. No start/finish points established. My (wrong?) assumption was that it would start recording distance as soon as the log file starts.

[brentp]

Gotcha. So you're saying - if you disable your Lua scripting, you don't see the empty initial files upon triggering?

The distance behavior changed when we re-worked the lap timing algorithm in a recent release. Also looking at restoring the default behavior in 2.8.3 as well.

[Copper280z]

Got a chance to play with this some. Updated to 2.8.2 and 1.3.4 app.

Starting logging with the button, at first I could not get any data out of it. Terminal output:

Logging started
Open: rc_14.log
file: close
*Wait several seconds and hit button again*
Logging stopped
Logging: wrote 0
*Wait several seconds and hit button again*
Logging started
Open: rc_15.log
file: close
*Wait several seconds and hit button again*
Logging stopped
Logging: wrote 0

I did a config reset and turned GPS off, otherwise the base config. Now I'm getting an empty file, followed by a file with some data. I haven't let it run for long yet, just a few seconds. Here is the output from the terminal:

Logging started
Open: rc_5.log
file: close
Open: rc_6.log
*wait several seconds and hit the button again*
Logging stopped
Logging: wrote 886
file: close

Here's another button press, this time it closed on it's own before I hit the button, unless I accidentally bounced the button.

Logging started
Open: rc_9.log
file: close
Logging stopped
Open: rc_10.log
Logging: wrote 1
file: close

I've got several hours longer on the way to an event, I'm going to play with it some more.

edit: I've tried both configs now and the difference seems to be in the difference between the configs.

Edit2: I deleted the lua script in the 'not_working' config, now the rcp will start that second log file just like the 'working' config was.

[brentp]

Thanks for the report, working on fixing that for 2.8.3!

-Brent

[JMcDonough]

Gotcha. So you're saying - if you disable your Lua scripting, you don't see the empty initial files upon triggering?

The distance behavior changed when we re-worked the lap timing algorithm in a recent release. Also looking at restoring the default behavior in 2.8.3 as well.

To close the loop on this I did a bit more testing today. I was able to get the empty file behavior with and without Lua scripting flashed in the RCP.

[Copper280z]

Hey Brent, any updates on this? It's been a few weeks now and several races where I'd really like to have run data have passed. As it sits the RCP is pretty much useless to me.

Any advice on how to get it to work somewhat reliably? Revert firmware back a ways? Different SD card?

[JMcDonough]

Hey Copper, have you tried logging in different configurations to see if you can get any data? Without lua script? Different memory card? Different power source? CAN not connected?

Happy to send you a config file that works on my RCP if it would be of any use.

[Copper280z]

I've got it to work without the Lua script, but the steering and throttle position data(which I get via CAN) is 70% of what I'm interested in.

I've been meaning to try another SD card, but haven't yet. I'd love to see another configuration, especially if it works with a script.

[brentp]

2.8.4 firmware coming soon will have a fix for this issue (and many others!). Thanks for your patience!

[toga94m]

Fixed my MK1 with 2.8.4!

My last race event of the season was Sunday, and before each run I'd push the button, get the red light, then a second or two later the red would go out and it'd start logging. Pulling logfiles later, I could see every other file was 0 bytes (failed attempt with red light) then the real data would start. The top of the logfile had a few hiccups/blank lines and restarts, then logging was smooth.

Today with 2.8.4 on the arm of the chair, each push has a delay but then it starts logging, no more every-other-filename-has-0-bytes either.

tom

[brentp]

Thanks Tom for the report, that's fantastic to hear! We put a ton of work into this release, it's gratifying to hear the results in the field.