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