diff --git a/controller/comms/messages/Messages.ts b/controller/comms/messages/Messages.ts index 98d22665..c979d362 100755 --- a/controller/comms/messages/Messages.ts +++ b/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; } } diff --git a/controller/nixie/NixieEquipment.ts b/controller/nixie/NixieEquipment.ts index 3510cff5..5cf438e1 100644 --- a/controller/nixie/NixieEquipment.ts +++ b/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 { + public static async putDeviceService(uuid: string, url: string, data?: any): Promise { 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); diff --git a/controller/nixie/chemistry/ChemController.ts b/controller/nixie/chemistry/ChemController.ts index 40f154c1..16e362df 100644 --- a/controller/nixie/chemistry/ChemController.ts +++ b/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; } diff --git a/defaultConfig.json b/defaultConfig.json index 8438a678..2c6f2c41 100755 --- a/defaultConfig.json +++ b/defaultConfig.json @@ -229,7 +229,8 @@ "app": { "enabled": true, "level": "info", - "captureForReplay": false + "captureForReplay": false, + "logToFile": false } }, "appVersion": "0.0.1" diff --git a/logger/Logger.ts b/logger/Logger.ts index f90db1b2..a42c3271 100755 --- a/logger/Logger.ts +++ b/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.`); diff --git a/web/Server.ts b/web/Server.ts index 5ba6ec95..4aec4ec4 100755 --- a/web/Server.ts +++ b/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 { diff --git a/web/interfaces/httpInterface.ts b/web/interfaces/httpInterface.ts index cf5c0a9d..7c6826d9 100644 --- a/web/interfaces/httpInterface.ts +++ b/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') {