Logging File log empty #3142

luizcarlospedrosogomes · 2022-12-01T22:50:17Z

package.json -> depedencies:
...
"@sap-cloud-sdk/util": "^2.11.0",
...

logger.js

const {
    unmuteLogger, createLogger, setGlobalTransports, setGlobalLogLevel,
} = require('@sap-cloud-sdk/util');
const { transports, format } = require('winston');

const consoleFormat = {
    format: format.combine(
        format.splat(),
        format.simple(),
        format.errors({ stack: true }),
    ),
    level: 'info',
    handleExceptions: true,
    json: false,
    colorize: true,
};
setGlobalLogLevel('info');
setGlobalTransports(
    new transports.File({
        name: 'info-file',
        filename: './logs/exceptions.log',
        level: 'info',
        json: false,
    }),
    new transports.Console(consoleFormat),
);
const logger = ({ name }) => createLogger(name);
module.exports = logger;

server.js
`
const myLogger = require('./logger')({ name: 'server' });
...

myLogger.info('ok5');

...
`

file log empty

The text was updated successfully, but these errors were encountered:

FrankEssenberger · 2022-12-02T09:14:11Z

Hello @luizcarlospedrosogomes,

I had a quick and compared to our test case for the logger. I experienced the behaviour, that I needed to create the logger before I set the global transport. Could you perhaps change the order in your code so that the createLogger is called before the setGlobalTransports and setGlobalLogLevel.

I guess these methods only effect existing logger. Let me know if this helps.

Best
Frank

luizcarlospedrosogomes · 2022-12-02T23:57:13Z

@FrankEssenberger thanks!
logger.js

server.js

test.log

I imagine the problem must be in the call in server.js. But I need to leave this dependency isolated in a file

FrankEssenberger · 2022-12-05T07:29:59Z

Good morning @luizcarlospedrosogomes,

I think the order is still set before creation. As you wrap the createLogger() in an arrow function the logger is created in line 20 of the server.js whereas the setGlobalTransports is executed by the require which loads the whole file. Can you try in line 9 of the logger.js to write the function like:

const logger = ({name}=>{
   const myLogger = createLogger(name);
   setGlobalTransports(fileTransport);
   return myLogger
}

Best
Frank

luizcarlospedrosogomes · 2022-12-07T03:41:51Z

Good morning @FrankEssenberger

Sorry for the delay, I followed your suggestion but I got another error

`
const fileTransport = new transports.File({
filename: 'test.log',
level: 'info',
});

const logger = ({ name }) => {
const myLogger = createLogger(name);
setGlobalTransports(fileTransport);
return myLogger;
};

module.exports = logger;
`

error

`

[email protected] start
cds run

[cds] - loading server from { file: 'srv/server.js' }
(node:796) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 error listeners added to [File]. Use emitter.setMaxListeners() to increase limit
(Use node --trace-warnings ... to show where the warning was created)
(node:796) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 unpipe listeners added to [File]. Use emitter.setMaxListeners() to increase limit
(node:796) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 drain listeners added to [File]. Use emitter.setMaxListeners() to increase limit
(node:796) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 close listeners added to [File]. Use emitter.setMaxListeners() to increase limit
(node:796) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 finish listeners added to [File]. Use emitter.setMaxListeners() to increase limit
[ERROR] write after end
at writeAfterEnd (/workspace/node_modules/readable-stream/lib/_stream_writable.js:261:12)
at PassThrough.Writable.write (/workspace/node_modules/readable-stream/lib/_stream_writable.js:305:21)
at File.log (/workspace/node_modules/winston/lib/winston/transports/file.js:185:34)
at File._write (/workspace/node_modules/winston-transport/index.js:82:19)
at doWrite (/workspace/node_modules/readable-stream/lib/_stream_writable.js:409:139)
at writeOrBuffer (/workspace/node_modules/readable-stream/lib/_stream_writable.js:398:5)
at File.Writable.write (/workspace/node_modules/readable-stream/lib/_stream_writable.js:307:11)
at DerivedLogger.ondata (/workspace/node_modules/readable-stream/lib/_stream_readable.js:681:20)
at DerivedLogger.emit (node:events:513:28)
at addChunk (/workspace/node_modules/readable-stream/lib/_stream_readable.js:298:12)
`
I haven't had time to investigate the error yet but I thought it was important to give you some feedback

FrankEssenberger · 2022-12-07T07:27:01Z

Good morning,

at least the stream seems to be considered now :-). I found an issue which seems to be also the problem here. Something with passing things as reference not value in the add()function we also use. I do not really get why it is not showing in our test. I simply get the file there. I even removed the log.

I think it would be good to simplify the situation and put the logger creation all in the same file to see where the passing around causes a problem. So first put logger creation in the server.js (just as a test). When this works step by step move the code to a function like you have and see when it breaks.

Best
Frank

luizcarlospedrosogomes · 2022-12-08T14:03:41Z

server.js
`
const { transports } = require('winston');
const { createLogger, setGlobalTransports } = require('@sap-cloud-sdk/util');

...
const fileTransport = new transports.File({
filename: 'test.log',
level: 'info',
});

setGlobalTransports(fileTransport);
const myLogger = createLogger('server');
...
`
log on start

[cds] - loading server from { file: 'srv/server.js' } [2022-12-08T13:56:24.495Z] INFO (server): CDS API Boostrap from /srv/server.js (node:2744) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 unpipe listeners added to [File]. Use emitter.setMaxListeners() to increase limit (Usenode --trace-warnings ...` to show where the warning was created)
(node:2744) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 error listeners added to [File]. Use emitter.setMaxListeners() to increase limit
(node:2744) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 drain listeners added to [File]. Use emitter.setMaxListeners() to increase limit
(node:2744) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 close listeners added to [File]. Use emitter.setMaxListeners() to increase limit
(node:2744) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 finish listeners added to [File]. Use emitter.setMaxListeners() to increase limit
[cov2ap] - [HPM] Proxy created: / -> http://localhost:4004
[cov2ap] - [HPM] Proxy rewrite rule created: "^/v2" ~> ""
[cov2ap] - [HPM] Proxy created: / -> http://localhost:4004
[cov2ap] - [HPM] Proxy rewrite rule created: "^/v2" ~> ""
[cds] - loaded model from 6 file(s):

db/schema.cds
srv/index.cds
db/data/model.cds
srv/src/models/solicitation-service.cds
db/data/views.cds
db/data/views_expand.cds
`
test.log
�[90m[2022-12-08T13:56:14.701Z]�[39m �[32mINFO�[39m �[34m(server)�[39m: CDS API Boostrap from /srv/server.js

That way, despite the log indicating the need for some intention, it worked, but now how to make it work in isolation?

luizcarlospedrosogomes · 2022-12-08T14:33:36Z

winstonjs/winston#1573 (comment)

I followed this comment fully, implemented the code that is as an example. It worked I have the log files too. But the sap package, this package, was left out.

FrankEssenberger · 2022-12-08T16:28:33Z

hm, I do not know. This is issue is strange and I can not reproduce it. I think there must be some problem with calling things by reference creating shallow copies if you adjust a logger after creation. This is what we do when calling setGlobalTransports. In the example the logger is created correctly right away. Perhaps you can try putting everything inside the function scope:

export const loggerBuilder = (name: string): Logger => {
  const myLogger = createLogger(name);
  const fileTransport = new transports.File({
    filename: 'test.log',
    level: 'info'
  });
  setGlobalTransports(fileTransport);
  return myLogger;
};

If this also does not help I, I would perhaps use the code sample you found. @marikaner do you have an idea on this issue?

Best
Frank

marikaner · 2023-10-09T08:38:41Z

@luizcarlospedrosogomes, it has been a long time since this issue was discussed. Were you able to solve or work around it since then?

luizcarlospedrosogomes · 2023-10-22T00:50:10Z

@luizcarlospedrosogomes, it has been a long time since this issue was discussed. Were you able to solve or work around it since then?

It was implemented as per the guidance, I didn't return to the scenario again.

I must return soon

luizcarlospedrosogomes added the bug Something isn't working label Dec 1, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Logging File log empty #3142

Logging File log empty #3142

luizcarlospedrosogomes commented Dec 1, 2022 •

edited

FrankEssenberger commented Dec 2, 2022

luizcarlospedrosogomes commented Dec 2, 2022

FrankEssenberger commented Dec 5, 2022

luizcarlospedrosogomes commented Dec 7, 2022 •

edited

FrankEssenberger commented Dec 7, 2022

luizcarlospedrosogomes commented Dec 8, 2022

luizcarlospedrosogomes commented Dec 8, 2022

FrankEssenberger commented Dec 8, 2022

marikaner commented Oct 9, 2023

luizcarlospedrosogomes commented Oct 22, 2023

Logging File log empty #3142

Logging File log empty #3142

Comments

luizcarlospedrosogomes commented Dec 1, 2022 • edited

FrankEssenberger commented Dec 2, 2022

luizcarlospedrosogomes commented Dec 2, 2022

FrankEssenberger commented Dec 5, 2022

luizcarlospedrosogomes commented Dec 7, 2022 • edited

FrankEssenberger commented Dec 7, 2022

luizcarlospedrosogomes commented Dec 8, 2022

luizcarlospedrosogomes commented Dec 8, 2022

FrankEssenberger commented Dec 8, 2022

marikaner commented Oct 9, 2023

luizcarlospedrosogomes commented Oct 22, 2023

luizcarlospedrosogomes commented Dec 1, 2022 •

edited

luizcarlospedrosogomes commented Dec 7, 2022 •

edited