Aws-sam-cli: sam logs output mangled

[davidjohnmaccallum]

Description

When I use sam logs to view my lambda function logs from the console (OSX terminal) my log messages are mangled. Note, I don't expect them to be pretty printed, but the output below is mangled.

2019/08/22/[$LATEST]57ae4b1bd8bf448d8e674d8231cc1970 2019-08-22T08:08:49.231000 START RequestId: ce26f5df-b0d9-4347-882a-cd89ccfc8160 Version: $LATEST
      "body": "SiteCode=TSTSTE0001&TransactionId=7e1ea8de-c4a8-4a4e-b7d1-9d29e191bc46&TransactionReference=ABC123&Amount=100.99&Status=Complete&Optional1=&Optional2=&Optional3=&Optional4=&Optional5=&CurrencyCode=ZAR&IsTes    "body": "SiteCode=TSTSTE0001&TransactionId=7e1ea8de-c4a8-4a4e-b7d1-9d29e191bc46&TransactionReference=ABC123&Amount=100.99&Status=Complete&Optional1=&Optional2=&Optional3=&Optional4=&Optional5=&CurrencyCode=ZAR&IsTest=} } "awsRequestId": "ce26f5df-b0d9-4347-882a-cd89ccfc8160"090357:function:centbee-ozow-api-OzowCallback",a5af86f6fec0b2c15e5df12f5f4b98084bcb5b621032e88a08b962d3a98ac226f84f9b748e"
} } "Hash": "28f7ebe65d84d2737cada8bbe31bc314430d00fd0d4ca726efd523a5af86f6fec0b2c15e5df12f5f4b98084bcb5b621032e88a08b962d3a98ac226f84f9b748e"fc8160    DEBUG   {
   '28f7ebe65d84d2737cada8bbe31bc314430d00fd0d4ca726efd523a5af86f6fec0b2c15e5df12f5f4b98084bcb5b621032e88a08b962d3a98ac226f84f9b748e' }-cd89ccfc8160    ERROR   { message: 'Ozow callback hash check failed',
2019/08/22/[$LATEST]57ae4b1bd8bf448d8e674d8231cc1970 2019-08-22T08:08:49.943000 2019-08-22T08:08:49.943Z        ce26f5df-b0d9-4347-882a-cd89ccfc8160    ERROR   Hash check failed
2019/08/22/[$LATEST]57ae4b1bd8bf448d8e674d8231cc1970 2019-08-22T08:08:49.983000 END RequestId: ce26f5df-b0d9-4347-882a-cd89ccfc8160
2019/08/22/[$LATEST]57ae4b1bd8bf448d8e674d8231cc1970 2019-08-22T08:08:49.983000 REPORT RequestId: ce26f5df-b0d9-4347-882a-cd89ccfc8160  Duration: 751.81 ms     Billed Duration: 800 ms         Memory Size: 128 MB     Max Memory Used: 96 MB

Here is the view from CloudWatch Management Console:

Steps to reproduce

I am producing these log messages like this (Node 10.x):

console.debug(JSON.stringify({ ozowResponse }, null, 2));

Observed result

See description above.

Expected result

I printed four log messages. Two console.debugs and two console.errors. I expect to see these four log messages as in the sam logs output.

Additional environment details (Ex: Windows, Mac, Amazon Linux etc)

1. OS: OSX
2. sam --version: 0.17.0

Add --debug flag to command you are running

[sanathkr]

I have to dig into this more. But I think this is a bug where multiline logs aren't handled well.

[davidjohnmaccallum]

Thanks @sanathkr, I managed to fix the problem using the eol library. Newlines were coming through as carriage returns (\r) which was confusing my bash shell. Converting them to new lines (\n) did the trick.

[einnjo]

@sanathkr I'm also observing this issue in SAM CLI, version 0.19.0, OSX, Node.js 10.x I'm logging a javascript object and the output is mangled, it does seem to be an issue with multiline logs since logs output by our logging library (JSON delimited by NL) seem to output correctly.

[daveykane]

Also experiencing this issue since upgrading to 0.21.0 with Node.js 10.x

I have been using console.dir for now which seems to be ok.

[wmonk]

I've used this to make it work properly on mac:

sam .... 2>&1 | tr "^M" \\n

[wmonk]

To add to this, it is also an issue when using sam local.

[daveykane]

thanks @wmonk very helpful. For some reason that didn't quite work for me but I did adapt it to the below and it seems to have sorted the issue with multiline logs (particularly logging large nested objects):

sam ... 2>&1 | tr "\r" "\n"

[wmonk]

Yep sorry should have mentioned, to get ^M you need to do ctrl+v ctrl+m.

[S-Cardenas]

Is there a permanent fix for this yet. I'm seeing the same behavior in SAM CLI, version 0.22.0? It's unfortunate to have to append 2>&1 | tr "\r" "\n" to every call to sam invoke when using nodejs10.x, especially since the node community and AWS will disable the creation and update of lambda functions running nodejs8.10 in Februrary 2020.

[mhart]

This is due to some unfortunate internal changes in the runtimes where console.log is overwritten by a function that transforms all newlines to \r. I assume this somehow makes it easier for Cloudwatch Logs, but it definitely messes with the readability and is potentially destructive (if you had a mixture of \r and \n in your output that you wanted to keep... now you can never get that back)

It's always been docker-lambda's policy to make as minimal changes as possible to the runtimes so that the docker images are as close to production as possible – and this extends to the logging.

Workarounds are just writing straight to process.stdout instead of console.log, using a logging library that does this for you, or transforming the output yourself

[mhart]

Ok, you know what – after some thinking about it, I decided to fix this issue by changing docker-lambda's behaviour.

I now transform \r into \n for all the output from the runtimes UNLESS the DOCKER_LAMBDA_NO_MODIFY_LOGS environment variable is set and passed into the container.

So basically, your logs should look fine now. If you're outputting \r deliberately and you want to keep them, then set DOCKER_LAMBDA_NO_MODIFY_LOGS=1, otherwise they'll be transformed into \n

@sanathkr you can probably consider this issue closed unless you want to do something on the aws-sam-cli end

[sanathkr]

@mhart Thanks for jumping on this and fixing. I will close the issue.

[code-is-art]

I am having this issue with version 1.13.2 using local invoke. I have not tested it with logs yet. This issue was not there with the previous version I was using which was 1.3.0.

[code-is-art]

I take it back. I just downgraded to 1.3.0 and the issue is there. Anything with JSON.stringify will get mangled using local invoke. Can only see the fist line and the last line. So anything with \n or \r will not work. For example.

console.log('line one\rline two\rline three\nline four\nline five')

will output

START RequestId: ac1ef293-d504-16a9-6b21-20a04c7f98e6 Version: $LATEST
line fiveeT14:12:51.527Z ac1ef293-d504-16a9-6b21-20a04c7f98e6 INFO line one
END RequestId: ac1ef293-d504-16a9-6b21-20a04c7f98e6

Should I start a new issue for this or can this issue be re-opened?

Edit:
sam local invoke 2>&1 | tr "\r" "\n" will work with no other code change
process.stdout.write() will also work but one must change every console.log call

@mhart the above code will work but this is still a bug and should be re-opened.

[mhart]

@code-is-art SAM CLI no longer uses the docker-lambda containers where this issue was originally fixed.

Might want to open an issue over at https://github.com/aws/aws-lambda-runtime-interface-emulator

[code-is-art]

Thank you