@google-cloud/logging-winston not logging from NodeJS after some time inside a GCE instance

1,169 views
Skip to first unread message

Jophin Joseph

unread,
Sep 5, 2019, 8:03:19 AM9/5/19
to Google Stackdriver Discussion Forum

Node: 10.16.0

@google-cloud/logging-winston: 2.0.0

Server: GCE VM Instance


I'm logging to stackdriver from my node process running an a GCE instance. I'm adding the following object to my winston transports as mentioned here


new require("@google-cloud/logging-winston").LoggingWinston({
  projectId: "my-google-project-id"
})


After deployment to GCP and starting the node process, I'm getting the logs in GCP Logs Viewer. So far so good. After a couple of hours(or in some cases minutes), I stop getting any logs in the Log Viewer. When I check the node process on my VM Instance, it is still running and writing logs to the console. But the google-cloud transport does not work at all. If I stop the node process and restart it, I start getting logs on the Logs Viewer again. But again it stops logging after some time. I tried downgrading from @google-cloud/logging...@2.0.0 to 1.1.1, but still the same. Could it be that I'm hitting some quotas? Or could it be because there is some uncaught error and @google-cloud/logging-winston fails from thereon?


In the logging agent trouble shooting page, I read that if logrotate is enabled, there will be issues with the agent. Is this also applicable for the @google-cloud/logging-winston library that I use from nodejs? I'm running my nodejs server using pm2 and there is logrotate enabled for pm2.


Igor Peshansky

unread,
Sep 5, 2019, 8:32:44 AM9/5/19
to Jophin Joseph, Google Stackdriver Discussion Forum
Hi,

The behavior you describe makes me suspect that there's indeed some uncaught exception that's preventing the Winston google-cloud transport from sending more logs. Do you see any backtrace on the console?

The fact that it resumes writing after a restart makes it unlikely that you're running into quota issues, unless your program produces a whole lot of logs in a burst and makes the google-cloud transport hit the QPS limit (which would be quite impressive, as that limit is 1000 QPS). You can always check your quota to see your current usage, see https://cloud.google.com/logging/quotas.

The logging agent logrotate issue does not apply as winston does not read from files, but rather sends events from your program directly to the Stackdriver Logging API.

On a side note, this list is human-moderated, so it takes a bit of time for your messages to get through the moderation queue. Don't be alarmed if your response does not show up on the list right away.
        Igor
-- sent from a mobile device, please excuse tyops and omissns

--
© 2016 Google Inc. 1600 Amphitheatre Parkway, Mountain View, CA 94043
 
Email preferences: You received this email because you signed up for the Google Stackdriver Discussion Google Group (google-stackdr...@googlegroups.com) to participate in discussions with other members of the GoogleStackdriver community.
---
You received this message because you are subscribed to the Google Groups "Google Stackdriver Discussion Forum" group.
To unsubscribe from this group and stop receiving emails from it, send an email to google-stackdriver-d...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/google-stackdriver-discussion/242bc260-67b8-4971-a996-0ac52cf03063%40googlegroups.com.

Jophin Joseph

unread,
Sep 6, 2019, 7:25:58 AM9/6/19
to Google Stackdriver Discussion Forum
Hi Igor,

I'm getting this error from the grpc library which I think is the cause of the issue. 

You have triggered an unhandledRejection, you may have forgotten to catch a Promise rejection: Error: Log entry with size 376.0K exceeds maximum size of 256.0K at Http2CallStream.call.on (/home/deploy/release-app/current/node_modules/@grpc/grpc-js/build/src/client.js:96:45) at Http2CallStream.emit (events.js:203:15) at Http2CallStream.EventEmitter.emit (domain.js:448:20) at process.nextTick (/home/deploy/release-app/current/node_modules/@grpc/grpc-js/build/src/call-stream.js:71:22) at process._tickCallback (internal/process/next_tick.js:61:11)

I saw other complaining about the same in the googleapis/node-logging library also. Any idea how I can handle and recover from this issue?


On Thursday, September 5, 2019 at 6:02:44 PM UTC+5:30, Igor Peshansky wrote:
Hi,

The behavior you describe makes me suspect that there's indeed some uncaught exception that's preventing the Winston google-cloud transport from sending more logs. Do you see any backtrace on the console?

The fact that it resumes writing after a restart makes it unlikely that you're running into quota issues, unless your program produces a whole lot of logs in a burst and makes the google-cloud transport hit the QPS limit (which would be quite impressive, as that limit is 1000 QPS). You can always check your quota to see your current usage, see https://cloud.google.com/logging/quotas.

The logging agent logrotate issue does not apply as winston does not read from files, but rather sends events from your program directly to the Stackdriver Logging API.

On a side note, this list is human-moderated, so it takes a bit of time for your messages to get through the moderation queue. Don't be alarmed if your response does not show up on the list right away.
        Igor
-- sent from a mobile device, please excuse tyops and omissns

On Thu, Sep 5, 2019, 8:03 AM Jophin Joseph <jop...@kubric.io> wrote:

Node: 10.16.0

@google-cloud/logging-winston: 2.0.0

Server: GCE VM Instance


I'm logging to stackdriver from my node process running an a GCE instance. I'm adding the following object to my winston transports as mentioned here


new require("@google-cloud/logging-winston").LoggingWinston({
  projectId: "my-google-project-id"
})


After deployment to GCP and starting the node process, I'm getting the logs in GCP Logs Viewer. So far so good. After a couple of hours(or in some cases minutes), I stop getting any logs in the Log Viewer. When I check the node process on my VM Instance, it is still running and writing logs to the console. But the google-cloud transport does not work at all. If I stop the node process and restart it, I start getting logs on the Logs Viewer again. But again it stops logging after some time. I tried downgrading from @google-cloud/logging-winston@2.0.0 to 1.1.1, but still the same. Could it be that I'm hitting some quotas? Or could it be because there is some uncaught error and @google-cloud/logging-winston fails from thereon?


In the logging agent trouble shooting page, I read that if logrotate is enabled, there will be issues with the agent. Is this also applicable for the @google-cloud/logging-winston library that I use from nodejs? I'm running my nodejs server using pm2 and there is logrotate enabled for pm2.


--
© 2016 Google Inc. 1600 Amphitheatre Parkway, Mountain View, CA 94043
 
Email preferences: You received this email because you signed up for the Google Stackdriver Discussion Google Group (google-stackdriver-discu...@googlegroups.com) to participate in discussions with other members of the GoogleStackdriver community.

---
You received this message because you are subscribed to the Google Groups "Google Stackdriver Discussion Forum" group.
To unsubscribe from this group and stop receiving emails from it, send an email to google-stackdriver-discussion+unsub...@googlegroups.com.

Igor Peshansky

unread,
Sep 6, 2019, 10:29:28 AM9/6/19
to Jophin Joseph, Rory Petty, Google Stackdriver Discussion Forum
Yep, this error definitely seems to be related — the API is rejecting the log entry that's too large. As documented at https://cloud.google.com/logging/quotas#log-limits, the maximum supported entry size is 256kiB. If the logging library didn't enable partial success responses, the whole request will be rejected. Worse, if the library retries the request before sending more logs, all logging may become stuck.

The fact that you have a large single log entry is unfortunate, but the fact that this entry being rejected by the server stops further log processing seems like a bug in the Node logging libraries. They should enable partial success so the rest of the request gets accepted, drop the erroneous entry, and continue sending other logs. Unfortunately, the Node logging libraries are not maintained by Stackdriver, so, as far as I know, your best bet at the moment is to file an issue with this recommendation in the open-source repo (or reopen the one you've referenced). +Rory Petty may have a better suggestion, though.

        Igor
-- sent from a mobile device, please excuse tyops and omissns
On Fri, Sep 6, 2019, 7:26 AM Jophin Joseph <jop...@kubric.io> wrote:
Hi Igor,

I'm getting this error from the grpc library which I think is the cause of the issue. 

You have triggered an unhandledRejection, you may have forgotten to catch a Promise rejection: Error: Log entry with size 376.0K exceeds maximum size of 256.0K at Http2CallStream.call.on (/home/deploy/release-app/current/node_modules/@grpc/grpc-js/build/src/client.js:96:45) at Http2CallStream.emit (events.js:203:15) at Http2CallStream.EventEmitter.emit (domain.js:448:20) at process.nextTick (/home/deploy/release-app/current/node_modules/@grpc/grpc-js/build/src/call-stream.js:71:22) at process._tickCallback (internal/process/next_tick.js:61:11)

I saw other complaining about the same in the googleapis/node-logging library also. Any idea how I can handle and recover from this issue?

On Thursday, September 5, 2019 at 6:02:44 PM UTC+5:30, Igor Peshansky wrote:
Hi,

The behavior you describe makes me suspect that there's indeed some uncaught exception that's preventing the Winston google-cloud transport from sending more logs. Do you see any backtrace on the console?

The fact that it resumes writing after a restart makes it unlikely that you're running into quota issues, unless your program produces a whole lot of logs in a burst and makes the google-cloud transport hit the QPS limit (which would be quite impressive, as that limit is 1000 QPS). You can always check your quota to see your current usage, see https://cloud.google.com/logging/quotas.

The logging agent logrotate issue does not apply as winston does not read from files, but rather sends events from your program directly to the Stackdriver Logging API.

On a side note, this list is human-moderated, so it takes a bit of time for your messages to get through the moderation queue. Don't be alarmed if your response does not show up on the list right away.
        Igor
-- sent from a mobile device, please excuse tyops and omissns

On Thu, Sep 5, 2019, 8:03 AM Jophin Joseph <jop...@kubric.io> wrote:

Node: 10.16.0

@google-cloud/logging-winston: 2.0.0

Server: GCE VM Instance


I'm logging to stackdriver from my node process running an a GCE instance. I'm adding the following object to my winston transports as mentioned here


new require("@google-cloud/logging-winston").LoggingWinston({
  projectId: "my-google-project-id"
})


After deployment to GCP and starting the node process, I'm getting the logs in GCP Logs Viewer. So far so good. After a couple of hours(or in some cases minutes), I stop getting any logs in the Log Viewer. When I check the node process on my VM Instance, it is still running and writing logs to the console. But the google-cloud transport does not work at all. If I stop the node process and restart it, I start getting logs on the Logs Viewer again. But again it stops logging after some time. I tried downgrading from @google-cloud/logging...@2.0.0 to 1.1.1, but still the same. Could it be that I'm hitting some quotas? Or could it be because there is some uncaught error and @google-cloud/logging-winston fails from thereon?


In the logging agent trouble shooting page, I read that if logrotate is enabled, there will be issues with the agent. Is this also applicable for the @google-cloud/logging-winston library that I use from nodejs? I'm running my nodejs server using pm2 and there is logrotate enabled for pm2.


--
© 2016 Google Inc. 1600 Amphitheatre Parkway, Mountain View, CA 94043
 
Email preferences: You received this email because you signed up for the Google Stackdriver Discussion Google Group (google-stackdr...@googlegroups.com) to participate in discussions with other members of the GoogleStackdriver community.

---
You received this message because you are subscribed to the Google Groups "Google Stackdriver Discussion Forum" group.
To unsubscribe from this group and stop receiving emails from it, send an email to google-stackdriver-d...@googlegroups.com.

--
© 2016 Google Inc. 1600 Amphitheatre Parkway, Mountain View, CA 94043
 
Email preferences: You received this email because you signed up for the Google Stackdriver Discussion Google Group (google-stackdr...@googlegroups.com) to participate in discussions with other members of the GoogleStackdriver community.

---
You received this message because you are subscribed to the Google Groups "Google Stackdriver Discussion Forum" group.
To unsubscribe from this group and stop receiving emails from it, send an email to google-stackdriver-d...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/google-stackdriver-discussion/498dda09-000d-4c25-8f18-5082595db29e%40googlegroups.com.
Reply all
Reply to author
Forward
0 new messages