Skip to content

Commit 21e69db

Browse files
benlohbenloh
authored
Merge pull request #112 from netcreateorg/dev-bl/research-log
Feature: Structure Research Logs
2 parents cec60da + 9fe13ac commit 21e69db

4 files changed

Lines changed: 105 additions & 48 deletions

File tree

‎app/unisys/common-netmessage-class.js‎

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -231,6 +231,19 @@ class NetMessage {
231231
}
232232
}
233233
/// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
234+
/** return an informational Object about the packet useful for logging
235+
* Used to provide a predictable format for Research Logging
236+
*/
237+
InfoObj(key) {
238+
switch (key) {
239+
case 'src': /* falls-through */
240+
default:
241+
return this.SourceGroupID()
242+
? { uaddr: this.SourceAddress(), group: this.SourceGroupID() }
243+
: { uaddr: this.SourceAddress(), group: undefined };
244+
}
245+
}
246+
/// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
234247
MakeNewID() {
235248
let idStr = (++m_id_counter).toString();
236249
this.id = m_id_prefix + idStr.padStart(5, '0');

‎app/unisys/server-database.js‎

Lines changed: 32 additions & 38 deletions
Original file line numberDiff line numberDiff line change
@@ -146,7 +146,7 @@ DB.InitializeDatabase = function (options = {}) {
146146
// remap duplicate NODE IDs
147147
dupeNodes.forEach(obj => {
148148
m_max_nodeID += 1;
149-
LOGGER.Write(PR, `# rewriting duplicate nodeID ${obj.id} to ${m_max_nodeID}`);
149+
LOGGER.WriteRLog({}, PR, `# rewriting duplicate nodeID ${obj.id} to ${m_max_nodeID}`);
150150
obj.id = m_max_nodeID;
151151
});
152152

@@ -580,13 +580,12 @@ DB.PKT_GetDatabase = function (pkt) {
580580
if (DBG)
581581
console.log(
582582
PR,
583-
`PKT_GetDatabase ${pkt.Info()} (loaded ${nodes.length} nodes, ${
584-
edges.length
583+
`PKT_GetDatabase ${pkt.Info()} (loaded ${nodes.length} nodes, ${edges.length
585584
} edges)`
586585
);
587586
m_MigrateNodes(nodes);
588587
m_MigrateEdges(edges);
589-
LOGGER.Write(pkt.Info(), `getdatabase`);
588+
LOGGER.WriteRLog(pkt.InfoObj(), `getdatabase`);
590589
return { d3data: { nodes, edges }, template: TEMPLATE };
591590
};
592591
/// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
@@ -606,7 +605,7 @@ DB.PKT_SetDatabase = function (pkt) {
606605
console.log(PR, `PKT_SetDatabase complete. Data available on next get.`);
607606
m_db.close();
608607
DB.InitializeDatabase();
609-
LOGGER.Write(pkt.Info(), `setdatabase`);
608+
LOGGER.WriteRLog(pkt.InfoObj(), `setdatabase`);
610609
return { OK: true };
611610
};
612611
/// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
@@ -624,7 +623,7 @@ DB.PKT_InsertDatabase = function (pkt) {
624623
console.log(PR, `PKT_InsertDatabase complete. Data available on next get.`);
625624
m_db.close();
626625
DB.InitializeDatabase();
627-
LOGGER.Write(pkt.Info(), `setdatabase`);
626+
LOGGER.WriteRLog(pkt.InfoObj(), `setdatabase`);
628627
return { OK: true };
629628
};
630629
/// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
@@ -659,7 +658,7 @@ DB.PKT_MergeDatabase = function (pkt) {
659658
m_db.saveDatabase(err => {
660659
if (err) reject(new Error('rejected'));
661660
DB.InitializeDatabase();
662-
LOGGER.Write(pkt.Info(), `mergedatabase`);
661+
LOGGER.WriteRLog(pkt.InfoObj(), `mergedatabase`);
663662
resolve({ OK: true });
664663
})
665664
);
@@ -679,7 +678,7 @@ DB.PKT_UpdateDatabase = function (pkt) {
679678
EDGES.update(edges);
680679
console.log(PR, `PKT_UpdateDatabase complete. Disk db file updated.`);
681680
m_db.saveDatabase();
682-
LOGGER.Write(pkt.Info(), `updatedatabase`);
681+
LOGGER.WriteRLog(pkt.InfoObj(), `updatedatabase`);
683682
return { OK: true };
684683
};
685684
/// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
@@ -916,16 +915,15 @@ DB.PKT_Update = function (pkt) {
916915
node.id = m_GetNewNodeID();
917916
}
918917

919-
LOGGER.Write(pkt.Info(), `insert node`, node.id, JSON.stringify(node));
918+
LOGGER.WriteRLog(pkt.InfoObj(), `insert node`, node.id, JSON.stringify(node));
920919
DB.AppendNodeLog(node, pkt); // log GroupId to node stored in database
921920
NODES.insert(node);
922921
// Return the updated record -- needed to update metadata
923922
let updatedNode = NODES.findOne({ id: node.id });
924923
if (!updatedNode)
925924
console.log(
926925
PR,
927-
`PKT_Update ${pkt.Info()} could not find node after update! This should not happen! ${
928-
node.id
926+
`PKT_Update ${pkt.Info()} could not find node after update! This should not happen! ${node.id
929927
} ${JSON.stringify(node)}`
930928
);
931929
retval = { op: 'insert', node: updatedNode };
@@ -939,7 +937,7 @@ DB.PKT_Update = function (pkt) {
939937
node
940938
)}`
941939
);
942-
LOGGER.Write(pkt.Info(), `update node`, node.id, JSON.stringify(node));
940+
LOGGER.WriteRLog(pkt.InfoObj(), `update node`, node.id, JSON.stringify(node));
943941
DB.AppendNodeLog(n, pkt); // log GroupId to node stored in database
944942
Object.assign(n, node);
945943
});
@@ -948,15 +946,14 @@ DB.PKT_Update = function (pkt) {
948946
if (!updatedNode)
949947
console.log(
950948
PR,
951-
`PKT_Update ${pkt.Info()} could not find node after update! This should not happen! ${
952-
node.id
949+
`PKT_Update ${pkt.Info()} could not find node after update! This should not happen! ${node.id
953950
} ${JSON.stringify(node)}`
954951
);
955952
retval = { op: 'update', node: updatedNode };
956953
} else {
957954
if (DBG)
958955
console.log(PR, `WARNING: multiple nodeID ${node.id} x${matches.length}`);
959-
LOGGER.Write(pkt.Info(), `ERROR`, node.id, 'duplicate node id');
956+
LOGGER.WriteRLog(pkt.InfoObj(), `ERROR`, node.id, 'duplicate node id');
960957
retval = { op: 'error-multinodeid' };
961958
}
962959
// Always update m_max_nodeID
@@ -982,16 +979,15 @@ DB.PKT_Update = function (pkt) {
982979
edge.id = m_GetNewEdgeID();
983980
}
984981

985-
LOGGER.Write(pkt.Info(), `insert edge`, edge.id, JSON.stringify(edge));
982+
LOGGER.WriteRLog(pkt.InfoObj(), `insert edge`, edge.id, JSON.stringify(edge));
986983
DB.AppendEdgeLog(edge, pkt); // log GroupId to edge stored in database
987984
EDGES.insert(edge);
988985
// Return the updated record -- needed to update metadata
989986
let updatedEdge = EDGES.findOne({ id: edge.id });
990987
if (!updatedEdge)
991988
console.log(
992989
PR,
993-
`PKT_Update ${pkt.Info()} could not find node after update! This should not happen! ${
994-
node.id
990+
`PKT_Update ${pkt.Info()} could not find node after update! This should not happen! ${node.id
995991
} ${JSON.stringify(node)}`
996992
);
997993
retval = { op: 'insert', edge: updatedEdge };
@@ -1001,11 +997,10 @@ DB.PKT_Update = function (pkt) {
1001997
if (DBG)
1002998
console.log(
1003999
PR,
1004-
`PKT_Update ${pkt.SourceGroupID()} UPDATE edgeID ${
1005-
edge.id
1000+
`PKT_Update ${pkt.SourceGroupID()} UPDATE edgeID ${edge.id
10061001
} ${JSON.stringify(edge)}`
10071002
);
1008-
LOGGER.Write(pkt.Info(), `update edge`, edge.id, JSON.stringify(edge));
1003+
LOGGER.WriteRLog(pkt.InfoObj(), `update edge`, edge.id, JSON.stringify(edge));
10091004
DB.AppendEdgeLog(e, pkt); // log GroupId to edge stored in database
10101005
Object.assign(e, edge);
10111006
});
@@ -1014,14 +1009,13 @@ DB.PKT_Update = function (pkt) {
10141009
if (!updatedEdge)
10151010
console.log(
10161011
PR,
1017-
`PKT_Update ${pkt.Info()} could not find node after update! This should not happen! ${
1018-
node.id
1012+
`PKT_Update ${pkt.Info()} could not find node after update! This should not happen! ${node.id
10191013
} ${JSON.stringify(node)}`
10201014
);
10211015
retval = { op: 'update', edge: updatedEdge };
10221016
} else {
10231017
console.log(PR, `WARNING: multiple edgeID ${edge.id} x${matches.length}`);
1024-
LOGGER.Write(pkt.Info(), `ERROR`, node.id, 'duplicate edge id');
1018+
LOGGER.WriteRLog(pkt.InfoObj(), `ERROR`, node.id, 'duplicate edge id');
10251019
retval = { op: 'error-multiedgeid' };
10261020
}
10271021
// Always update m_max_edgeID
@@ -1034,7 +1028,7 @@ DB.PKT_Update = function (pkt) {
10341028
nodeID = m_CleanID(`${pkt.Info()} nodeID`, nodeID);
10351029
if (DBG) console.log(PR, `PKT_Update ${pkt.Info()} DELETE nodeID ${nodeID}`);
10361030
// Log first so it's apparent what is triggering the edge changes
1037-
LOGGER.Write(pkt.Info(), `delete node`, nodeID);
1031+
LOGGER.WriteRLog(pkt.InfoObj(), `delete node`, nodeID);
10381032

10391033
// handle edges
10401034
let edgesToProcess = EDGES.where(e => {
@@ -1049,27 +1043,27 @@ DB.PKT_Update = function (pkt) {
10491043
if (replacementNodeID !== -1) {
10501044
// re-link edges to replacementNodeID...
10511045
EDGES.findAndUpdate({ source: nodeID }, e => {
1052-
LOGGER.Write(pkt.Info(), `relinking edge`, e.id, `to`, replacementNodeID);
1046+
LOGGER.WriteRLog(pkt.InfoObj(), `relinking edge`, e.id, `to`, replacementNodeID);
10531047
e.source = replacementNodeID;
10541048
});
10551049
EDGES.findAndUpdate({ target: nodeID }, e => {
1056-
LOGGER.Write(pkt.Info(), `relinking edge`, e.id, `to`, replacementNodeID);
1050+
LOGGER.WriteRLog(pkt.InfoObj(), `relinking edge`, e.id, `to`, replacementNodeID);
10571051
e.target = replacementNodeID;
10581052
});
10591053
} else {
10601054
// ... or delete edges completely
10611055
let sourceEdges = EDGES.find({ source: nodeID });
10621056
EDGES.findAndRemove({ source: nodeID });
10631057
if (sourceEdges.length)
1064-
LOGGER.Write(
1065-
pkt.Info(),
1058+
LOGGER.WriteRLog(
1059+
pkt.InfoObj(),
10661060
`deleting ${sourceEdges.length} sources matching ${nodeID}`
10671061
);
10681062
let targetEdges = EDGES.find({ target: nodeID });
10691063
EDGES.findAndRemove({ target: nodeID });
10701064
if (targetEdges.length)
1071-
LOGGER.Write(
1072-
pkt.Info(),
1065+
LOGGER.WriteRLog(
1066+
pkt.InfoObj(),
10731067
`deleting ${targetEdges.length} targets matching ${nodeID}`
10741068
);
10751069
}
@@ -1082,7 +1076,7 @@ DB.PKT_Update = function (pkt) {
10821076
if (edgeID !== undefined) {
10831077
edgeID = m_CleanID(`${pkt.Info()} edgeID`, edgeID);
10841078
if (DBG) console.log(PR, `PKT_Update ${pkt.Info()} DELETE edgeID ${edgeID}`);
1085-
LOGGER.Write(pkt.Info(), `delete edge`, edgeID);
1079+
LOGGER.WriteRLog(pkt.InfoObj(), `delete edge`, edgeID);
10861080
EDGES.findAndRemove({ id: edgeID });
10871081
return { op: 'delete', edgeID };
10881082
}
@@ -1409,24 +1403,24 @@ function m_MigrateEdges(edges) {
14091403
function m_CleanObjID(prompt, obj) {
14101404
if (typeof obj.id === 'string') {
14111405
let int = parseInt(obj.id, 10);
1412-
LOGGER.Write(PR, `! ${prompt} "${obj.id}" is string; converting to ${int}`);
1406+
LOGGER.WriteRLog({}, PR, `! ${prompt} "${obj.id}" is string; converting to ${int}`);
14131407
obj.id = int;
14141408
}
14151409
return obj;
14161410
}
14171411
function m_CleanEdgeEndpoints(prompt, edge) {
14181412
if (typeof edge.source === 'string') {
14191413
let int = parseInt(edge.source, 10);
1420-
LOGGER.Write(
1421-
PR,
1414+
LOGGER.WriteRLog(
1415+
{}, PR,
14221416
` edge ${prompt} source "${edge.source}" is string; converting to ${int}`
14231417
);
14241418
edge.source = int;
14251419
}
14261420
if (typeof edge.target === 'string') {
14271421
let int = parseInt(edge.target, 10);
1428-
LOGGER.Write(
1429-
PR,
1422+
LOGGER.WriteRLog(
1423+
{}, PR,
14301424
` edge ${prompt} target "${edge.target}" is string; converting to ${int}`
14311425
);
14321426
edge.target = int;
@@ -1436,7 +1430,7 @@ function m_CleanEdgeEndpoints(prompt, edge) {
14361430
function m_CleanID(prompt, id) {
14371431
if (typeof id === 'string') {
14381432
let int = parseInt(id, 10);
1439-
LOGGER.Write(PR, `! ${prompt} "${id}" is string; converting to number ${int}`);
1433+
LOGGER.WriteRLog({}, PR, `! ${prompt} "${id}" is string; converting to number ${int}`);
14401434
id = int;
14411435
}
14421436
return id;

‎app/unisys/server-logger.js‎

Lines changed: 55 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -58,10 +58,19 @@ FSE.ensureDir(dir, function (err) {
5858
var logname = str_TimeDatedFilename('log') + '.txt';
5959
var pathname = dir + '/' + logname;
6060
fs_log = FSE.createWriteStream(pathname);
61-
LogLine(
61+
62+
// Show Research Log Field Names
63+
const fieldnames = [
64+
'Date', 'Time', 'NetName', 'Addr', 'Token', 'Action', 'DataID', 'DataDetail'
65+
];
66+
let fields = fieldnames.join(LOG_DELIMITER);
67+
fields += '\n';
68+
fs_log.write(fields);
69+
70+
LogResearchLine({},
6271
`NETCREATE APPSERVER SESSION LOG for ${str_DateStamp()} ${str_TimeStamp()}`
6372
);
64-
LogLine('---');
73+
LogResearchLine({}, '---');
6574
});
6675

6776
/// LOGGING FUNCTIONS /////////////////////////////////////////////////////////
@@ -71,7 +80,8 @@ FSE.ensureDir(dir, function (err) {
7180
function LogLine(...args) {
7281
if (!fs_log) return;
7382

74-
var out = str_TimeStamp() + LOG_DELIMITER;
83+
var out = str_ShortDateStamp() + LOG_DELIMITER;
84+
out += str_TimeStamp() + LOG_DELIMITER;
7585
out += NC_CONFIG.dataset + LOG_DELIMITER;
7686
var c = args.length;
7787
// arguments are delimited
@@ -85,6 +95,30 @@ function LogLine(...args) {
8595
fs_log.write(out);
8696
}
8797

98+
/** Log a standard structured log message for research
99+
* Guarantees a predictable column order with
100+
* date, time, network, uaddr, group
101+
*/
102+
function LogResearchLine(info = { uaddr: '', group: '' }, ...args) {
103+
if (!fs_log) return;
104+
105+
var out = str_ShortDateStamp() + LOG_DELIMITER;
106+
out += str_TimeStamp() + LOG_DELIMITER;
107+
out += NC_CONFIG.dataset + LOG_DELIMITER;
108+
out += (info.uaddr || '-') + LOG_DELIMITER;
109+
out += (info.group || '-') + LOG_DELIMITER;
110+
var c = args.length;
111+
// arguments are delimited
112+
if (c) {
113+
for (let i = 0; i < c; i++) {
114+
if (i > 0) out += LOG_DELIMITER;
115+
out += args[i];
116+
}
117+
}
118+
out += '\n';
119+
fs_log.write(out);
120+
}
121+
88122
/// UTILITY FUNCTIONS /////////////////////////////////////////////////////////
89123
/// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
90124
function str_TimeStamp() {
@@ -104,6 +138,15 @@ function str_DateStamp() {
104138
return yyyy + '/' + mm + '/' + dd + ' ' + day;
105139
}
106140
/// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
141+
function str_ShortDateStamp() {
142+
var date = new Date();
143+
var mm = ('0' + (date.getMonth() + 1)).slice(-2);
144+
var dd = ('0' + date.getDate()).slice(-2);
145+
var day = e_weekday[date.getDay()];
146+
var yyyy = date.getFullYear();
147+
return yyyy + '/' + mm + '/' + dd;
148+
}
149+
/// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
107150
function str_TimeDatedFilename(...args) {
108151
// construct filename
109152
var date = new Date();
@@ -129,14 +172,22 @@ let LOG = {};
129172
*/
130173
LOG.PKT_LogEvent = function (pkt) {
131174
let { event, items } = pkt.Data();
175+
const uaddr = pkt.SourceAddress();
176+
const group = pkt.SourceGroupID(); // leave blank if empty for network events
132177
if (DBG) console.log(PR, pkt.Info(), event, ...items);
133-
LogLine(pkt.Info(), event || '-', ...items);
178+
LogResearchLine({ uaddr, group }, event || '-', ...items);
134179
return { OK: true };
135180
};
136181
/// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
137182
/** API: Write to log as delimited arguments
138183
*/
139184
LOG.Write = LogLine;
185+
/** API: Write to Researcher log as delimited arguments
186+
* Research logs alway start with date, time, network, uaddr, group
187+
*/
188+
LOG.WriteRLog = function (info = { uaddr: '', group: '' }, ...args) {
189+
LogResearchLine(info, ...args);
190+
}
140191

141192
/// EXPORT MODULE DEFINITION //////////////////////////////////////////////////
142193
/// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -

0 commit comments

Comments
 (0)