Added copious logging for chemController and created an option to log…

… the console to a file.

controller/comms/messages/Messages.ts

@@ -355,7 +355,7 @@ export class Inbound extends Message {
                 if (this.header.length < 6) {
                     // We actually don't have a complete header yet so just return.
                     // we will pick it up next go around.
-                    logger.verbose(`We have an incoming message but the serial port hasn't given a complete header. [${this.padding}][${this.preamble}][${this.header}]`);
+                    logger.debug(`We have an incoming message but the serial port hasn't given a complete header. [${this.padding}][${this.preamble}][${this.header}]`);
                     this.preamble = [];
                     this.header = [];
                     return ndxHeader;
@@ -368,7 +368,7 @@ export class Inbound extends Message {
                 else if (this.source == 12 || this.dest == 12) this.protocol = Protocol.IntelliValve;
                 if (this.datalen > 75) {
                     //this.isValid = false;
-                    logger.verbose(`Broadcast length ${this.datalen} exceeded 75bytes for ${this.protocol} message. Message rewound ${this.header}`);
+                    logger.debug(`Broadcast length ${this.datalen} exceeded 75bytes for ${this.protocol} message. Message rewound ${this.header}`);
                     this.padding.push(...this.preamble);
                     this.padding.push(...this.header.slice(0, 1));
                     this.preamble = [];
@@ -389,7 +389,7 @@ export class Inbound extends Message {
                 if (this.header.length < 4) {
                     // We actually don't have a complete header yet so just return.
                     // we will pick it up next go around.
-                    logger.verbose(`We have an incoming chlorinator message but the serial port hasn't given a complete header. [${this.padding}][${this.preamble}][${this.header}]`);
+                    logger.debug(`We have an incoming chlorinator message but the serial port hasn't given a complete header. [${this.padding}][${this.preamble}][${this.header}]`);
                     this.preamble = [];
                     this.header = [];
                     return ndxHeader;
@@ -432,7 +432,7 @@ export class Inbound extends Message {
                     this.payload.push(bytes[ndx++]);
                     if (this.payload.length > 25) {
                         this.isValid = false; // We have a runaway packet.  Some collision occurred so lets preserve future packets.
-                        logger.verbose(`Chlorinator message marked as invalid after not finding 16,3 in payload after ${this.payload.length} bytes`);
+                        logger.debug(`Chlorinator message marked as invalid after not finding 16,3 in payload after ${this.payload.length} bytes`);
                         break;
                     }
                 }

controller/nixie/NixieEquipment.ts

@@ -10,12 +10,15 @@ export class NixieEquipment {
     constructor(ncp: INixieControlPanel) { this._pmap['ncp'] = ncp; }
     public get controlPanel(): INixieControlPanel { return this._pmap['ncp']; }
     public get id(): number { return -1; }
-    public static async putDeviceService(uuid: string, url: string, data?:any): Promise<any> {
+    public static async putDeviceService(uuid: string, url: string, data?: any): Promise<InterfaceServerResponse> {
         try {
             let result: InterfaceServerResponse;
             let server = webApp.findServerByGuid(uuid);
             if (typeof server === 'undefined') return Promise.reject(new Error(`Error sending device command: Server [${uuid}] not found.`));
-            if (!server.isConnected) return Promise.reject(new Error(`Error sending device command: [${server.name}] not connected.`));
+            if (!server.isConnected) {
+                logger.warn(`Cannot send PUT ${url} to ${server.name} server is not connected.`);
+                return Promise.reject(new Error(`Error sending device command: [${server.name}] not connected.`));
+            }
             if (server.type === 'rem') {
                 let rem = server as REMInterfaceServer;
                 result = await rem.putApiService(url, data);

controller/nixie/chemistry/ChemController.ts

@@ -427,6 +427,10 @@ class NixieChemical extends NixieChildEquipment {
                 // Reflect any changes to the configuration.
                 this.currentMix.time = this.chemical.mixingTime;
                 schem.mixTimeRemaining = this.currentMix.timeRemaining;
+                logger.verbose(`Chem mixing remaining: ${utils.formatDuration(schem.mixTimeRemaining)}`);
+            }
+            else {
+                logger.verbose(`Chem mixing paused because body is not on.`);
             }
             this.currentMix.lastChecked = dt;
             if (schem.mixTimeRemaining === 0) {
@@ -558,8 +562,10 @@ export class NixieChemPump extends NixieChildEquipment {
             let type = sys.board.valueMaps.chemPumpTypes.getName(this.pump.type);
             if (type === 'none') {
                 // We aren't going to do anything.
+                logger.verbose(`Chem pump dose ignore pump ${type}`);
             }
             else if (type === 'relay') {
+
                 // We are a relay pump so we need to turn on the pump for a timed interval
                 // then check it on each iteration.  If the pump does not receive a request
                 // from us then the relay will turn off.
@@ -573,7 +579,8 @@ export class NixieChemPump extends NixieChildEquipment {
                     delay = Math.max(0, ((this.chemical.chemical.startDelay * 60) * 1000) - timeElapsed);
                     dosage.schem.delayTimeRemaining = Math.round(delay/1000);
                     if (delay > 0) {
-                        if (!dosage.schem.flowDelay) logger.info(`Chem Controller delay dosing for ${utils.formatDuration(delay/1000)}`)
+                        if (!dosage.schem.flowDelay) logger.info(`Chem Controller delay dosing for ${utils.formatDuration(delay / 1000)}`)
+                        else logger.verbose(`Chem pump delay dosing for ${utils.formatDuration(delay / 1000)}`);
                         dosage.schem.flowDelay = true;
                     }
                     else {
@@ -585,18 +592,28 @@ export class NixieChemPump extends NixieChildEquipment {
                 //console.log({ status: dosage.schem.dosingStatus, time: dosage.time, timeDosed: dosage.timeDosed / 1000, volume: dosage.volume, volumeDosed: dosage.volumeDosed });
                 if (!isBodyOn) {
                     // Make sure the pump is off.
+                    logger.verbose(`Chem pump flow not detected. Body is not running.`);
                     await NixieEquipment.putDeviceService(this.pump.connectionId, `/state/device/${this.pump.deviceBinding}`, { state: false });
                     dosage.schem.pump.isDosing = this.isOn = false;
                 }
                 else if (dosage.schem.tank.level <= 0 || dosage.timeRemaining <= 0 || dosage.volumeRemaining <= 0) {
                     // If we ran the tank dry or we completed the dose. Start mixing.
+                    logger.verbose(`Chem tank ran dry with ${dosage.volumeRemaining}mL remaining`);
                     await NixieEquipment.putDeviceService(this.pump.connectionId, `/state/device/${this.pump.deviceBinding}`, { state: false });
                     dosage.schem.dosingStatus = 2;
                 }
                 else if (dosage.timeRemaining > 0 && dosage.volumeRemaining > 0) {
                     if (delay <= 0) {
+                        logger.verbose(`Sending command to activate chem pump...`);
                         let res = await NixieEquipment.putDeviceService(this.pump.connectionId, `/state/device/${this.pump.deviceBinding}`, { state: true, latch: 3000 });
+                        if (typeof res.status === 'undefined' || res.status.code !== 200) {
+                            let status = res.status || { code: res.status.code, message: res.status.message };
+                            logger.error(`Chem pump could not activate relay ${status.code}: ${status.message}`);
+                        }
                         let relay = res.obj;
+                        try {
+                            logger.verbose(`Chem pump response ${JSON.stringify(relay)}`);
+                        } catch (err) { logger.error(`Invalid chem pump response`); }
                         if (typeof dosage.lastLatchTime !== 'undefined') {
                             let time = new Date().getTime() - dosage.lastLatchTime;
                             // Run our math out to 7 sig figs to keep in the ballpark for very slow pumps.
@@ -611,8 +628,9 @@ export class NixieChemPump extends NixieChildEquipment {
                         logger.info(`Chem Controller dosed ${dosage.volumeDosed.toFixed(2)}mL of ${dosage.volume}mL ${utils.formatDuration(dosage.timeRemaining)} remaining`);
                         dosage.schem.pump.isDosing = this.isOn = relay.state;
                     }
-                    else 
+                    else {
                         dosage.schem.pump.isDosing = this.isOn = false;
+                    }
 
                     // Set the volume and time remaining to the second and 4 sig figs.
                     dosage.schem.dosingVolumeRemaining = dosage.volumeRemaining;
@@ -758,6 +776,7 @@ export class NixieChemicalPh extends NixieChemical {
                     if (chem.body === 2 || chem.body === 32) totalGallons += sys.bodies.getItemById(2).capacity;
                     if (chem.body === 3) totalGallons += sys.bodies.getItemById(3).capacity;
                     if (chem.body === 4) totalGallons += sys.bodies.getItemById(4).capacity;
+                    logger.verbose(`Chem begin calculating dose current: ${sph.level} setpoint: ${this.ph.setpoint} body: ${totalGallons}`);
                     //let pv = utils.convert.volume.convertUnits(totalGallons, 'gal', 'L');
                     let chg = this.ph.setpoint - sph.level;
                     let delta = chg * totalGallons;
@@ -778,6 +797,7 @@ export class NixieChemicalPh extends NixieChemical {
                             let demand = dose = Math.round(utils.convert.volume.convertUnits((delta / -240.15 * at.dosingFactor) + (extra / -240.15 * at.dosingFactor), 'oz', 'mL'));
                             let time = typeof pump.ratedFlow === 'undefined' || pump.ratedFlow <= 0 ? 0: Math.round(dose / (pump.ratedFlow / 60));
                             let meth = sys.board.valueMaps.chemDosingMethods.getName(this.ph.dosingMethod);
+                            logger.verbose(`Chem acid demand calculated ${demand}mL for ${utils.formatDuration(time)} Tank Level: ${sph.tank.level}`);
                             // Now that we know our acid demand we need to adjust this dose based upon the limits provided in the setup.
                             switch (meth) {
                                 case 'time':
@@ -806,8 +826,9 @@ export class NixieChemicalPh extends NixieChemical {
                                     }
                                     break;
                             }
+                            logger.verbose(`Chem acid dosing maximums applied ${dose}mL for ${utils.formatDuration(time)}`);
                             let dosage: NixieChemDose = typeof this.currentDose === 'undefined' || status === 'monitoring' ? new NixieChemDose() : this.currentDose;
-                            dosage.set({startDate:new Date(), schem: sph, method: meth, setpoint: this.ph.setpoint, level: sph.level, volume: dose, time: time, maxVolume: Math.max(meth.indexOf('vol') !== -1 ? this.ph.maxDosingVolume : dose), maxTime: Math.max(meth.indexOf('time') !== -1 ? this.ph.maxDosingTime : time) });
+                            dosage.set({ startDate: new Date(), schem: sph, method: meth, setpoint: this.ph.setpoint, level: sph.level, volume: dose, time: time, maxVolume: Math.max(meth.indexOf('vol') !== -1 ? this.ph.maxDosingVolume : dose), maxTime: time });
                             sph.doseTime = dosage.time;
                             sph.doseVolume = dosage.volume;
                             if (typeof this.currentDose === 'undefined') {
@@ -823,6 +844,7 @@ export class NixieChemicalPh extends NixieChemical {
                             }
                             // Now let's determine what we need to do with our pump to satisfy our acid demand.
                             if (sph.tank.level > 0) {
+                                logger.verbose(`Chem acid dose activate pump ${this.pump.pump.ratedFlow}mL/min`);
                                 await this.pump.dose(dosage);
                                 this.currentDose = dosage;
                             }

defaultConfig.json

@@ -229,7 +229,8 @@
     "app": {
       "enabled": true,
       "level": "info",
-      "captureForReplay": false
+      "captureForReplay": false,
+      "logToFile":  false
     }
   },
   "appVersion": "0.0.1"

logger/Logger.ts

@@ -18,6 +18,7 @@ import * as path from 'path';
 import * as fs from 'fs';
 import * as winston from 'winston';
 import * as os from 'os';
+import { utils } from "../controller/Constants";
 import { Message } from '../controller/comms/messages/Messages';
 import { config } from '../config/Config';
 import { webApp } from '../web/Server';
@@ -36,9 +37,9 @@ class Logger {
     private pkts: Message[];
     private pktPath: string;
     private consoleToFilePath: string;
-    private transports: {console:winston.transports.ConsoleTransportInstance, file?:winston.transports.FileTransportInstance} = {
-        console: new winston.transports.Console({level:'silly'})
-    }
+    private transports: { console: winston.transports.ConsoleTransportInstance, file?: winston.transports.FileTransportInstance, consoleFile?: winston.transports.FileTransportInstance } = {
+        console: new winston.transports.Console({ level: 'silly' })
+    };
     private captureForReplayBaseDir: string;
     private captureForReplayPath: string;
     private pktTimer: NodeJS.Timeout;
@@ -71,11 +72,28 @@ class Logger {
         });
         this.transports.console.level = this.cfg.app.level;
         if (this.cfg.app.captureForReplay) this.startCaptureForReplay(false);
+        if (this.cfg.app.logToFile) {
+            this.transports.consoleFile = new winston.transports.File({
+                filename: path.join(process.cwd(), '/logs', this.getConsoleToFilePath()),
+                level: 'silly',
+                format: winston.format.combine(winston.format.splat(), winston.format.uncolorize(), this.myFormat)
+            });
+            this.transports.consoleFile.level = this.cfg.app.level;
+            this._logger.add(this.transports.consoleFile);
+        }
     }
     public async stopAsync() {
+        this.info(`Stopping logger.`);
         if (this.cfg.app.captureForReplay) {
             return this.stopCaptureForReplayAsync();
         }
+        // Free up the file handles.  This is yet another goofiness with winston.  Not sure why they
+        // need to exclusively lock the file handles when the process always appends.  Just stupid.
+        if (typeof this.transports.consoleFile !== 'undefined') {
+            this._logger.remove(this.transports.consoleFile);
+            this.transports.consoleFile.close();
+            this.transports.consoleFile = undefined;
+        }
     }
     public get options(): any { return this.cfg; }
     public info(...args: any[]) { logger._logger.info.apply(logger._logger, arguments); }
@@ -190,9 +208,26 @@ class Logger {
                 c[prop] = opts[prop];
         }
         config.setSection('log', this.cfg);
-        for (let [key,transport] of Object.entries(this.transports)){
-           transport.level = this.cfg.app.level; 
-       } 
+        if (utils.makeBool(this.cfg.app.logToFile)) {
+            if (typeof this.transports.consoleFile === 'undefined') {
+                this.transports.consoleFile = new winston.transports.File({
+                    filename: path.join(process.cwd(), '/logs', this.getConsoleToFilePath()),
+                    level: 'silly',
+                    format: winston.format.combine(winston.format.splat(), winston.format.uncolorize(), this.myFormat)
+                });
+                this._logger.add(this.transports.consoleFile);
+            }
+        }
+        else {
+            if (typeof this.transports.consoleFile !== 'undefined') {
+                this._logger.remove(this.transports.consoleFile);
+                this.transports.consoleFile.close();
+                this.transports.consoleFile = undefined;
+            }
+        }
+        for (let [key, transport] of Object.entries(this.transports)) {
+            if(typeof transport !== 'undefined') transport.level = this.cfg.app.level;
+        }
     }
     public startCaptureForReplay(bResetLogs:boolean) {
         logger.info(`Starting Replay Capture.`);

web/Server.ts

@@ -824,6 +824,7 @@ export class REMInterfaceServer extends ProtoServer {
             opts.method = method || 'GET';
             ret.data = '';
             opts.agent = this.agent;
+            logger.verbose(`REM server request initiated. ${opts.method} ${opts.path} ${sbody}`);
             await new Promise((resolve, reject) => {
                 let req: http.ClientRequest;
 
@@ -851,7 +852,7 @@ export class REMInterfaceServer extends ProtoServer {
                 req.on('error', (err, req, res) => { logger.error(`Error sending Request: ${opts.method} ${url} ${err.message}`); ret.error = err; });
                 req.on('abort', () => { logger.warn('Request Aborted'); reject(new Error('Request Aborted.')); });
                 req.end(sbody);
-            }).catch((err) => { ret = new InterfaceServerResponse(); });
+            }).catch((err) => { logger.error(`Error initializing REM Request: ${opts.method} ${url} ${err.message}`); ret.error = err; });
             if (ret.status.code > 200) {
                 // We have an http error so let's parse it up.
                 try {

web/interfaces/httpInterface.ts

@@ -92,7 +92,7 @@ export class HttpInterfaceBindings extends BaseInterfaceBindings {
                     }
                     if (typeof opts.path !== 'undefined') opts.path = encodeURI(opts.path); // Encode the data just in case we have spaces.
                     // opts.headers["CONTENT-LENGTH"] = Buffer.byteLength(sbody || '');
-                    logger.verbose(`Sending [${evt}] request to ${this.cfg.name}: ${JSON.stringify(opts)}`);
+                    logger.debug(`Sending [${evt}] request to ${this.cfg.name}: ${JSON.stringify(opts)}`);
                     let req: http.ClientRequest;
                     // We should now have all the tokens.  Put together the request.
                     if (typeof sbody !== 'undefined') {