I have implemented a logging method in my code that works most of the time but i know its very bad. ie i call it on ever log and write to card.
Anyone suggest a methodology to use?
I’m using Queue() object to store logs but is an array more efficient. I’m thinking to log to an object and have another thread send it out to the cloud or sdcard?
Any thoughts?
The approach I use is to create a series of files of one day of logging each. Log records are written as BSON and flushed immediately (so that I can reliably capture things even in a power failure). The advantage of using BSON is that you can capture data, events and all sorts of information in a single logging stream, and it is far more compact than xml or json.
Each file starts with a signature word and length, and each record starts with a signature value and length, again, so it is easy to recover corrupted data. Each record also has a timestamp and GUID identifier to aid in syncing records.
Then, to upload, I use one of two methods : either a thread that periodically and opportunistically (i.e., when the network is up) pushes data to a service (local server or cloud); or a local server periodically contacts each netmf device and downloads data over an http connection.
Log files are either removed on a time schedule; when storage is low; or when an upload completes and is confirmed - which method I choose depends on the application
The key elements here : BSON storage; robust filesystem interactions; opportunistic transfer of data (that is, remote data transfer is not a critical path element in logging).
I can provide the BSON code and the filesystem logging code, if anyone is interested, but it’s too large to post inline.
Would love to see you code? I learnt about bson through mongodb.
Ok - the json/bson serializer is in nuget (but I need to push an update to fix some known errors - don’t grab it just yet).
Here’s the data logger that I use (it is structured to work in the Verdant Service framework, but that is only evident in the Start/Stop methods):
using System;
using System.Collections;
using System.IO;
using System.Text;
using PervasiveDigital.Json;
using ProjectController.Common;
using ProjectController.Core.Utilities;
using Verdant.Node.Common;
namespace ProjectController.Core.Services
{
public class DataLoggerService : IService, IDataLogger
{
private const int MaxDays = 30;
private const UInt32 FileMarker = 0xDEADC0ED;
private const UInt32 RecordMarker = 0xBAADBEEF;
private readonly object _sync = new object();
private IMassStorageDriver _storage;
private FileStream _file;
private DateTime _lastDataWritten = DateTime.MinValue;
private DateTime _currentFileDate = DateTime.MinValue;
private UInt32 _offset;
public void Start()
{
_storage = (IMassStorageDriver)DiContainer.Instance.Resolve(typeof(IMassStorageDriver));
_storage.Insert += _storage_Insert;
_storage.Eject += _storage_Eject;
DiContainer.Instance.Register(typeof(IDataLogger), () => this);
if (_storage.GetSdCard(false) != null)
InitializeLogStorage();
}
public string Name { get { return "Data logger"; } }
public void Stop()
{
_file.Close();
_offset = 0;
_file = null;
}
public void LogEvent(string eventClass, object eventData)
{
lock (_sync)
{
var now = DateTime.UtcNow;
if (now.Year != _lastDataWritten.Year ||
now.Month != _lastDataWritten.Month ||
now.Day != _lastDataWritten.Day)
{
// roll over to new log file
InitializeLogStorage();
}
if (_file == null)
return;
var eventTree = JsonConverter.Serialize(eventData);
var wrapper = new JObject();
wrapper.Add("timestamp", new JValue(DateTimeExtensions.ToIso8601(now)));
wrapper.Add("classname", new JValue(eventData.GetType().FullName));
wrapper.Add("evclass", new JValue(eventClass));
wrapper.Add("evid", new JValue(Guid.NewGuid().ToString()));
wrapper.Add("data", eventTree);
var bson = wrapper.ToBson();
var length = bson.Length + 8;
var buffer = new byte[length];
int offset = 0;
SerializationUtilities.Marshall(buffer, ref offset, RecordMarker);
SerializationUtilities.Marshall(buffer, ref offset, (UInt32)length);
Array.Copy(bson, 0, buffer, offset, bson.Length);
// write record
_file.Seek(_offset, SeekOrigin.Begin);
_file.Write(buffer, 0, length);
// update file header with new offset
offset = 0;
SerializationUtilities.Marshall(buffer, ref offset, (UInt32)(_offset + length));
_file.Seek(4, SeekOrigin.Begin);
_file.Write(buffer, 0, 4);
_file.Flush();
_offset += (UInt32)length;
_storage.GetSdCard().FlushAll();
}
}
public IJToken[] GetEvents(DateTime start, int count)
{
lock (_sync)
{
ArrayList result = new ArrayList();
FileStream file = null;
UInt32 bookmark = 0;
do
{
// Get a file to work with
do
{
var compare = new DateTime(start.Year, start.Month, start.Day);
if (compare > _currentFileDate)
return (IJToken[])result.ToArray(typeof(IJToken));
if (file != null && file != _file)
file.Close();
file = GetFileFor(start);
if (file == null)
{
start = new DateTime(start.Year, start.Month, start.Day);
start = start.AddDays(1.0);
}
} while (file == null);
var record = GetFirstRecord(file, ref bookmark);
do
{
if (record is JObject)
{
try
{
var jobj = (JObject)record;
var value = (JValue)jobj["timestamp"].Value;
var timestamp = DateTimeExtensions.FromIso8601(value.Value.ToString());
if (timestamp > start)
{
result.Add(record);
--count;
}
}
catch
{
// timestamp might have been bad
//TODO: ??
}
}
// collect records until count==0 or end of file
record = GetNextRecord(file, ref bookmark);
if (record == null)
{
// move on to the next day
start = new DateTime(start.Year, start.Month, start.Day);
start = start.AddDays(1.0);
}
} while (count > 0 && record != null);
} while (count > 0);
if (file != _file)
file.Close();
return (IJToken[])result.ToArray(typeof(IJToken));
}
}
public IJToken[] GetEvents(DateTime fileDate, ref UInt32 bookmark, int count)
{
if (bookmark == 0)
bookmark = 8;
// normalize to midnight
fileDate = new DateTime(fileDate.Year, fileDate.Month, fileDate.Day);
if (fileDate > _currentFileDate)
throw new Exception("no data");
lock (_sync)
{
ArrayList result = new ArrayList();
FileStream file = GetFileFor(fileDate);
if (file == null)
throw new Exception("no data");
var record = GetNextRecord(file, ref bookmark);
if (record != null)
{
do
{
result.Add(record);
--count;
// collect records until count==0 or end of file
record = GetNextRecord(file, ref bookmark);
if (record == null)
break;
} while (count > 0 && record != null);
}
if (file != _file)
file.Close();
return (IJToken[])result.ToArray(typeof(IJToken));
}
}
public IJToken[] GetFiles()
{
var list = new ArrayList();
var rootDir = _storage.GetSdCard().RootDirectory;
var files = Directory.GetFiles(rootDir);
foreach (var file in files)
{
var filename = Path.GetFileName(file);
if (filename.StartsWith("log-") && filename.EndsWith(".dat"))
{
list.Add(new JValue(filename));
}
}
return (IJToken[])list.ToArray(typeof(IJToken));
}
private FileStream GetFileFor(DateTime date)
{
if (date.Year == _currentFileDate.Year &&
date.Month == _currentFileDate.Month &&
date.Day == _currentFileDate.Day)
return _file;
FileStream result = null;
var rootDir = _storage.GetSdCard().RootDirectory;
// Opening files takes time - make sure it is there first
var files = Directory.GetFiles(rootDir);
foreach (var file in files)
{
var filename = Path.GetFileName(file);
if (filename.StartsWith("log-") && filename.EndsWith(".dat"))
{
var year = int.Parse(filename.Substring(4, 4));
var month = int.Parse(filename.Substring(8, 2));
var day = int.Parse(filename.Substring(10, 2));
var fileDate = new DateTime(year, month, day);
if (fileDate.Year == date.Year &&
fileDate.Month == date.Month &&
fileDate.Day == date.Day)
{
try
{
var name = GetLogFileName(date);
result = File.Open(Path.Combine(rootDir, name), FileMode.Open, FileAccess.Read, FileShare.None);
}
catch
{
result = null;
}
return result;
}
}
}
return null;
}
private JToken GetFirstRecord(FileStream file, ref UInt32 cursor)
{
if (file.Length < 16)
return null;
var buffer = new byte[8];
int offset = 0;
file.Seek(0, SeekOrigin.Begin);
file.Read(buffer, 0, 8);
var fileMarker = (UInt32)SerializationUtilities.Unmarshall(buffer, ref offset, TypeCode.UInt32);
if (fileMarker != FileMarker)
return null;
var nextRecord = (UInt32)SerializationUtilities.Unmarshall(buffer, ref offset, TypeCode.UInt32);
file.Seek(8, SeekOrigin.Begin);
file.Read(buffer, 0, 8);
offset = 0;
var recordMarker = (UInt32)SerializationUtilities.Unmarshall(buffer, ref offset, TypeCode.UInt32);
if (recordMarker != RecordMarker)
return null;
var length = (UInt32)SerializationUtilities.Unmarshall(buffer, ref offset, TypeCode.UInt32);
var dataBuffer = new byte[length - 8];
if (file.Read(dataBuffer, 0, (int)(length - 8)) != length - 8)
return null;
var result = JsonConverter.FromBson(dataBuffer);
((JObject)result).Add("locn", new JValue(cursor));
((JObject)result).Add("next", new JValue(cursor + length));
cursor = 8 + length;
return result;
}
private JToken GetNextRecord(FileStream file, ref UInt32 cursor)
{
if (file.Length <= cursor)
return null;
var buffer = new byte[8];
int offset = 0;
file.Seek(cursor, SeekOrigin.Begin);
if (file.Read(buffer, 0, 8)!=8)
return null;
var recordMarker = (UInt32)SerializationUtilities.Unmarshall(buffer, ref offset, TypeCode.UInt32);
if (recordMarker != RecordMarker)
return null;
var length = (UInt32)SerializationUtilities.Unmarshall(buffer, ref offset, TypeCode.UInt32);
var dataBuffer = new byte[length - 8];
if (file.Read(dataBuffer, 0, (int)(length - 8)) != length - 8)
return null;
var result = JsonConverter.FromBson(dataBuffer);
((JObject)result).Add("locn", new JValue(cursor));
((JObject)result).Add("next", new JValue(cursor+length));
cursor = cursor + length;
return result;
}
private void InitializeLogStorage()
{
lock (_sync)
{
try
{
if (_file != null)
{
_file.Close();
_file = null;
_offset = 0;
}
var rootDir = _storage.GetSdCard().RootDirectory;
var now = DateTime.UtcNow;
CleanUp(rootDir, now);
_file = File.Open(Path.Combine(rootDir, GetLogFileName(now)), FileMode.OpenOrCreate, FileAccess.ReadWrite, FileShare.None);
_currentFileDate = new DateTime(now.Year, now.Month, now.Day);
InitializeLogFile();
_lastDataWritten = now;
}
catch
{
_file = null;
_offset = 0;
}
}
}
private void CleanUp(string root, DateTime today)
{
try
{
// remove old files
var files = Directory.GetFiles(root);
foreach (var file in files)
{
var filename = Path.GetFileName(file);
if (filename.StartsWith("log-") && filename.EndsWith(".dat"))
{
var year = int.Parse(filename.Substring(4, 4));
var month = int.Parse(filename.Substring(8, 2));
var day = int.Parse(filename.Substring(10, 2));
var fileDate = new DateTime(year, month, day);
if (today - fileDate > TimeSpan.FromTicks(TimeSpan.TicksPerHour * 24 * MaxDays))
{
try
{
File.Delete(file);
}
catch
{
// don't let this stop cleanup attempts
}
}
}
}
}
catch
{
// failure to clean up is not fatal, though the effect could accumulate
}
}
private void InitializeLogFile()
{
var buffer = new byte[8];
int offset = 0;
if (_file.Length < 8)
{
InitializeEmptyFile(_file);
_offset = 8;
return;
}
_file.Seek(0, SeekOrigin.Begin);
_file.Read(buffer, 0, 8);
var marker = (UInt32)SerializationUtilities.Unmarshall(buffer, ref offset, TypeCode.UInt32);
var nextRecord = (UInt32)SerializationUtilities.Unmarshall(buffer, ref offset, TypeCode.UInt32);
if (marker != FileMarker || nextRecord < 8)
{
InitializeEmptyFile(_file);
_offset = 8;
return;
}
_offset = nextRecord;
}
private void InitializeEmptyFile(FileStream file)
{
var buffer = new byte[8];
int offset = 0;
SerializationUtilities.Marshall(buffer, ref offset, FileMarker);
SerializationUtilities.Marshall(buffer, ref offset, (UInt32)8);
file.Seek(0, SeekOrigin.Begin);
file.Write(buffer, 0, 8);
file.Flush();
}
private string GetLogFileName(DateTime dt)
{
string timestamp = dt.Year.ToString("D4") + dt.Month.ToString("D2") + dt.Day.ToString("D2");
return "log-" + timestamp + ".dat";
}
void _storage_Insert(object sender, Microsoft.SPOT.IO.MediaEventArgs e)
{
if (e.Volume.Name == "SD")
InitializeLogStorage();
}
void _storage_Eject(object sender, Microsoft.SPOT.IO.MediaEventArgs e)
{
if (e.Volume.Name == "SD")
{
_file = null;
_offset = 0;
}
}
}
public class DataLoggerEvent
{
public int recordType;
public string recordSubType;
public long timestamp;
}
}
And here is an example of walking a log to turn BSON into JSON for transmitting over HTTP: (in this case, a web request came in with either a date and a count, or a date and a file offset or ‘cursor’)
IJToken[] records;
if (uiCursor == UInt32.MaxValue)
records = _logger.GetEvents(dtStart, iCount);
else
records = _logger.GetEvents(dtStart, ref uiCursor, iCount);
var result = new JArray(records);
SendResponse(ctx, HttpStatusCode.OK, result.ToString());
thanks…i make use of your code and share my version as well…using mqtt i can change the log levels that are sent to the cloud, sdcard and console…anyway thanks for sharing… ;D
Whatever floats yer code 
@mcalsyn
Thanks for the posted code.
I’m just trying to implement your SD-Card logger and logging already works. However I have difficulties to get the deserialization methods working.
The records are read back to an array of IJToken but I cannot find the declaration of the type IJToken.
It would be helpful to have this declaration.
In the GetNextRecord method JsonConverter.FromBson now the demands besides buffer for two additional parameter:
public static object FromBson(byte[] buffer, Type resultType, InstanceFactory factory = null)
I don’t know, what to take as resultType and InstanceFactory.
It would help if you could give me an example.
Thanks in in advance
RoSchmi
I don’t have example code at hand, but I can tell you this… If you provide a non-null value for resultType, then the library will instantiate an populate that type. If your type contains arrays, due to a bug in netmf, you also need to provide an InstanceFactory. The bug in netmf is that for an array of elements, reflection/introspection does not return a valid Type for the members of the array, so the Json/Bson library cannot dynamically identify and create the necessary arrays.
To work around that, I introduced the InstanceFactory. If you pass null for the resultType, and a method for ‘factory’ then every time the library needs to create an instance, it will call your function and pass the json path to the element that it is trying to create, the member name, and a cardinality (array size). A cardinality of -1 means that it just needs a simple object, 0 or more means that it needs an array of that cardinality. You can build a function that uses the path and member name to determine what part of your json is being deserialized and use that information to to ‘new’ the correct simple, object, or array type.
If you are deserializing an object with no arrays in it, then you can ignore InstanceFactory and just fill in ‘resultType’ with the type of object that you are deserializing.
Yes, this is all complicated, but chalk that up to the lack of generics and an introspection bug in netmf. The introspection bug was filed with netmf some time ago and remains open. I looked at it a bit myself, but it’s in a fairly nasty bit of code in the interpreter and I never got to the bottom of it.
If this doesn’t help you out, I will dig up some example code and post it when I return from vacation next week. Taking a look at the code starting at line 67 here might help.
Additional note: The InstanceFactory is only used if resultType is null. So: Simple objects without arrays : provide resultType. Objects with arrays : provide a value for ‘factory’.
Thanks for your detailed informations. I think that now I have understood the used mechanisms of serialization and deserialization. Still not clear to me is the type IJToken. An array of this type is returned by the getevents method but I couldn’t find a declaration of this type. From the labelling I assume that it is an interface that might represent the data and additions like timestamp and GUID. This is not yet clear to me.
Got the SD-Card logging working with this Class as IJToken and little modifications of the code in this thread.
public class IJToken
{
public string classname;
public string timestamp;
public string evclass;
public LogContent data;
public string evid;
}
and as an example this Class as the data to be logged:
public class LogContent
{
public string logReason;
public string logLabel;
public int logNumber;
}
I’m not sure that it was intended to be done this way
I just got back home today, so I took a look at the original code, and I see the source of the confusion. The logger code that I provided is relying on an updated version of jsonnetmf that I never pushed to github. The updated version has JToken inheriting from IJToken, whose definition is shown below.
What I need to do is update the github source and the nuget package. I’ll get to that after I finish the current work on getting the Open-Source Gadgeteer release done. You should not be extending IJToken with domain-specific fields. Yes, it will work, but that’s not actually the intended pattern. I am happy you got it to work of course, and I will update the json package and maybe release the logger as a separate nuget package just to keep everything in sync a bit better.
(Note that use of the name ProjectController in the previous and below snippets was merely to obscure the original project name - Those will change in the github/nuget releases).
using System;
using System.Text;
namespace ProjectController.Common
{
public interface IJToken
{
byte[] ToBson();
}
}Thank you, hope you had a good flight.
I’m looking forward to see your new code but it has time.
For now it works for me sufficiently, the only disadvantage is that I can not use exchangeable Classes for the content to be logged.
Another question is: Which application can be used to inspect the log-files on the PC. I didn’t find a ready solution with text-editors, Excel or a browser to inspect the record files in a table-like manner. I’m just writing a little Windows Forms App for this. Do you have a ready-to-use solution?
The files are not text, so they are not viewable in text editors. I do have a command-line program that can extract the data into flat logfile formats and I will push that to github as well.
Note that there’s another level of complexity to this whole thing, if you care to go that deep… The system really is designed just to store the essential varying information in each log message. Consider messages like “Program started”; “network changed” etc., There’s no point in storing the string information. For “Program started”, you might just store a message ID. For “network changed” you would store a message ID and maybe an IP address.
Originally I used a program that would parse attributes/comments in your source code and create messages from those. The invariant information would be stripped out into a file that could be used on a PC to decode the messages. The data actually stored on the NETMF device would then be very, very compact.
The missing piece here is that the attribute/comment parser is quite complex and I was not quite ready to open source it at the time I wrote it. Now, the winds have shifted a bit and I may go ahead and release it, but it’s probably overkill for all but the largest and most complex of industrial projects.
This model of “compressed messages that use an external resource to re-hydrate” is exactly the same model as used by the Microsoft MC.exe message compiler and the event-viewer, eventvwr.exe. I just chose to put the message data inline in the program rather than in a separate xxxxx.mc file.
For now I write the content of the log-files to a DataTable in a Windows Forms App and show it in a DataGridWiew. So I can sort the the records in dependence of the content of the different columns. That’s in the moment all what I need. Thanks a lot for your code and instructions.