Doesn't work as described in README: log.logSync(logName).write(log.entry(metadata, payload))

[chriscalo]

The behavior of log.logSync(logName).write(log.entry(metadata, payload)) doesn't match what's described in the README.

Environment details

• OS: Google App Engine Standard Environment for Node.js
• Node.js version: 16
• npm version: 8.3.1
• @google-cloud/logging version: 9.8.3

I've created a reproduction at https://github.com/chriscalo/logsync-bug and copied the full details here:

Steps:

1. Deploy to App Engine Standard environment:

gcloud app deploy app.yaml --project=<PROJECT_ID>

2. Go to console.cloud.google.com/logs/ to view output

Expected:

Here are the first two calls to log.write() in index.js:

const metadata = {
  resource: {
    type: "gae_app",
    labels: {
      module_id: process.env.GAE_SERVICE,
      version_id: process.env.GAE_VERSION,
    },
  },
};

log.write(log.entry(metadata, "A text payload"));
log.write(log.entry(metadata, { message: "A JSON payload" }));

The expected output is something like: (irrelevant details removed)

[
  {
    "textPayload": "A text payload",
    "resource": {
      "type": "gae_app",
      "labels": {
        "version_id": "logsync-bug",
        "module_id": "default",
      }
    },
    "timestamp": "2022-05-06T23:13:23.002Z",
    "logName": "projects/REDACTED_PROJECT_ID/logs/my_log"
  },
  {
    "jsonPayload": {
      "message": "A JSON payload"
    },
    "resource": {
      "type": "gae_app",
      "labels": {
        "module_id": "default",
        "version_id": "logsync-bug"
      }
    },
    "timestamp": "2022-05-06T23:13:23.004Z",
    "logName": "projects/REDACTED_PROJECT_ID/logs/my_log",
    "receiveTimestamp": "2022-05-06T23:13:23.270510336Z"
  }
]

Actual:

The actual output looks like the following: (irrelevant details removed)

[
  {
    "jsonPayload": {
      "message": "A text payload",
      "timestamp": "2022-05-06T23:13:23.002Z",
      "logName": "projects/REDACTED_PROJECT_ID/logs/my_log",
      "resource": {
        "type": "gae_app",
        "labels": {
          "module_id": "default",
          "version_id": "logsync-bug"
        }
      }
    },
    "resource": {
      "type": "gae_app",
      "labels": {
        "zone": "us3",
        "version_id": "logsync-bug",
        "module_id": "default",
        "project_id": "REDACTED_PROJECT_ID"
      }
    },
    "timestamp": "2022-05-06T23:13:23.004560Z",
    "logName": "projects/REDACTED_PROJECT_ID/logs/stdout",
  },
  {
    "jsonPayload": {
      "timestamp": "2022-05-06T23:13:23.004Z",
      "message": {
        "message": "A JSON payload"
      },
      "resource": {
        "labels": {
          "module_id": "default",
          "version_id": "logsync-bug"
        },
        "type": "gae_app"
      },
      "logName": "projects/REDACTED_PROJECT_ID/logs/my_log"
    },
    "resource": {
      "type": "gae_app",
      "labels": {
        "version_id": "logsync-bug",
        "module_id": "default",
        "project_id": "REDACTED_PROJECT_ID",
        "zone": "us3"
      }
    },
    "timestamp": "2022-05-06T23:13:23.005096Z",
    "logName": "projects/REDACTED_PROJECT_ID/logs/stdout",
  }
]

The full output can be seen in downloaded-logs-20220506-191603.json

Fix

I've followed the instructions from the README, copied below. Notice that it says to create an entry, passing metadata and a payload and then call log.write(entry):

// Optional: Create and configure a client
const logging = new Logging();
await logging.setProjectId()
await logging.setDetectedResource()

// Create a LogSync transport, defaulting to `process.stdout`
const log = logging.logSync(logname);
const meta = { /* optional field overrides here */ };
const entry = log.entry(meta, 'Your log message');
log.write(entry);

// Syntax sugar for logging at a specific severity
log.alert(entry);
log.warning(entry);

However, in calls to log.write(entry), it appears the final payload is being populated with the entire entry object passed to log.write() and therefore the entry.metadata isn't being applied at all.

So either the README is wrong or there's a bug here. To fix this it seems would require either:

1. updating the README to show how to correctly create and write to a log.logSync(), or
2. fixing the behavior to match what's in the README.

[kladnik]

I also encountered the same issue.
Can't have textPayload and jsonPayload when using logSync.

[losalex]

Thanks @chriscalo for opening this issue! It seems that there are multiple issues here, feel free to correct me if I am wrong:

1. I believe that having extra "message" field in jsonPayload is related to recently fixed 1301 - we added an ability to eliminate extra "message" field when LogSync is used to output structured logs.
2. As for textPayload, I believe we only have an ability today to have text in "message" field inside jsonPayload. I am going to follow up on this to see how it behaves when I print raw console logs which has "textPayload" field and will get back to you.
3. As for metadata, the logic to retrieve LogEntry specific fields can be followed here.

Please let me know if my observations make sense and please comment if you have more questions.

[NeverwinterMoon]

@losalex
I am having the same problem when using @google-cloud/logging version 10.1.1.

With LogSync, the logName is nested inside jsonPayload after being processed (by google-fluentd?). With Log (async version), it works as documented and the logName is hoisted to the top level. But according to https://cloud.google.com/nodejs/docs/reference/logging/latest/logging/logsync, LogSync is "Recommended for Serverless environment logging", which is what we are using.

With logName not properly hoisted, we can't get our log sinks to work - as the routing is based on the logName. It's a pretty severe issue, in my opinion.

This is the output of LogSync write (project ID not defined just for this example, in real case it's correctly inserted):

{
  "timestamp": "2022-07-20T08:23:26.143Z",
  "logging.googleapis.com/labels": {
    "deviceID": "device-1234567890123456"
  },
  "logging.googleapis.com/insertId": "..........trV63Y01O.1fQXCoha3S2w",
  "message": {
    "some": "thing"
  },
  "logName": "projects/{{projectId}}/logs/hyperloop-telemetry"
}

This is how that log would look over at Cloud Logging console:

{
  insertId: 'SOME ID'
  jsonPayload: {
    logName: 'projects/{{projectId}}/logs/hyperloop-telemetry'
    message: {
      some: "thing"
    }
    resource: {}
    timestamp: '2022-07-20T08:31:05.121Z'
  }
  labels: {
    deviceID: 'device-1234567890123456'
    execution_id: 'SOME ID'
    instance_id: 'SOME ID'
  }
  logName: 'projects/{{projectId}}/logs/cloudfunctions.googleapis.com%2Fcloud-functions'
  receiveTimestamp: '2022-07-20T08:31:05.265952769Z'
  timestamp: '2022-07-20T08:31:05.121123Z'
  trace: 'SOME TRACE'
}

Here is an example of using Log instead (async version) with exactly the same code (entry creation with metadata):

const metadata = {
  labels: {
    deviceID: 'device-1234567890123456'
  }
}

const message = {
  some: 'thing'
}

const entry = entry(metadata, message)


log.write(entry)

{
  insertId: "SOME ID"
  jsonPayload: {
    some: "thing"
  }
  labels: {
    deviceID: "device-1234567890123456"
  }
  logName: "projects/{{projectId}}/logs/hyperloop-telemetry"
  receiveTimestamp: "2022-07-14T06:52:32.018287296Z"
  resource: {}
  timestamp: "2022-07-14T06:52:31.779000043Z"
}

Note that

• logName at the top level is the one passed to log('name') (same was done with logSync('name')
• jsonPayload does not contain "message" but has just the payload without the extra stuff like when using LogSync

Edit

Oh, I've just realized that #1301 is not a part of the latest release (10.1.1), so maybe it does indeed alleviate the problem.

[NeverwinterMoon]

Actually, my bad on that edit: the mentioned change (#1301) was released, so I've tried setting useMessageField to false.

It's still not behaving the same way as async Log does, as the end result is this:

{
  insertId: "INSERT ID"
  jsonPayload: {
    data: {16}
    logName: "projects/{{RETRACTED}}/logs/hyperloop-telemetry"
    resource: {2}
    timestamp: "2022-07-20T11:27:36.726Z"
    type: "BatteryStatusUpdate"
  }
  labels: {3}
  logName: "projects/{{RETRACTED}}/logs/cloudfunctions.googleapis.com%2Fcloud-functions"
  receiveTimestamp: "2022-07-20T11:27:36.839152437Z"
  resource: {2}
  timestamp: "2022-07-20T11:27:36.726459Z"
  trace: "SOME TRACE"
}

As you can see from the above: logName, timestamp and resource are still stuck under jsonPayload. This is clearly a bug (and is not according to the docs): at least the logName should actual set the value to top level, otherwise what's the point... The only thing it changed for better: message is no longer wrapping the data (jsonPayload#message).

[losalex]

Thanks @NeverwinterMoon for providing more context! Below are some points with respect of your observations:

1. When running in serverless environments like Cloud Functions (CF), the logName and resource fields are always overriden by the environment when stdout-based output is used. See more explanation in Structured logging in Google Cloud blog under How to write logs section. I filed an issue with CF team to provide an ability to override the logName, so for now we embedding this into jsonPayload field so it could be searched at least. As for resource, I believe it is mandatory field and expected to be in specific format which is described here.
2. I will follow up regarding the timestamp field - based on explanation here it should be picked up correctly from the output, but seems it might be some issues.

[losalex]

Downgrading priority for now until we clarify this issue with product teams

[losalex]

@chriscalo and @NeverwinterMoon , I was thinking to close this issue - the timestamp issue was fixed and as for logName, it might take time to fix - I filed a feature request for our product team and it will be tracked separately.
Please let me know if you have any other questions - thanks!

[chriscalo]

I might be misunderstanding something, but I think the original problem still stands that the docs and the behavior don't align. This would suggest that we shouldn't close this issue unless (a) there's a flaw in my original interpretation, (b) the behavior is fixed to match the docs, or (c) the docs are updated to match the behavior.

So either the README is wrong or there's a bug here. To fix this it seems would require either:

1. updating the README to show how to correctly create and write to a log.logSync(), or
2. fixing the behavior to match what's in the README.

[cindy-peng]

Hi @chriscalo, when the logging agent pick up the logs from stdout written by LogSync, it is expected that the Logging agent then sends the structured logs to Cloud Logging as the jsonPayload of the LogEntry structure. textPayload will be extracted to LogEntry parent level in very few cases, more details can be found here: https://cloud.google.com/logging/docs/structured-logging

However, in calls to log.write(entry), it appears the final payload is being populated with the entire entry object passed to >log.write() and therefore the entry.metadata isn't being applied at all.

In your case, entry.metadata is actually still being extracted in LogEntry.resource into an extended fashion:

Since by default the logging agent will rename LogName when sending to Cloud Logging API, we will still want to keep logName under jsonPayload so it is searchable, before CF team provide an ability to override the logName.

I understand this is causing confusions since the logging behavior is inconsistent with log async. I will update the document to explain the expected behavior. Thank you!

[chriscalo]

I am nearly certain that the original issue as I stated it is incorrect behavior.

We might be talking past each other. Where do we think the disconnect is coming from? What more can I provide to convince the team that this behavior (or the README) is wrong?

Shouldn't the following be true for the log.entry() method?

• it should be possible to pass a string for the payload parameter and have that end up in the log entry as a textPayload
• nothing from the metadata parameter should end up in the jsonPayload

[jordanebelanger]

@chriscalo
I am also having trouble understanding LogSync and its intended purpose.

The default behaviour of the logging object returned by logSynch is non-sensical and doesn't work in practice afaik.

The logging object must be instantiated with the useMessageField: false options for it generate actual logging agent/cloudrun parsable output

i.e

const log = logging.logSync('test', process.stdout, {useMessageField: false})
const messageEntry = log.entry({ name: 'jordan', lastname: 'belanger', message: 'test' })
log.info(messageEntry)

this outputs:

{"timestamp":{"seconds":1706553658,"nanos":496999979},"severity":"INFO","logging.googleapis.com/insertId":"..........5JOwBw0ahDMel9EK68WV0y","name":"jordan","lastname":"belanger","message":"test","logName":"projects/test/logs/test"}

which will be parsed correctly and let you attach metadata along with your log message under cloudrun, other managed environments and when using the logging agent manually.