Reading cloud logs using bn logs

The binaris cloud logs standard output and error of each function invocation. Let’s tweak the hello function to see logging in action.

def handler(body, req):
    qs = req.query.get('name')
    body = body.get('name')
    name = qs or body or 'World'

    print('Query string is {}'.format(qs))
    print('Body is         {}'.format(body))
    print('Name is set to  {}'.format(name))

    return 'Hello {}!'.format(name)

The function logs its parameter, which helps us understand a specific name is returned.

Deploy, invoke and log

# Deploy the updated code
$ bn deploy hello

# Invoke the function
$ bn invoke hello --data '{"name": "firstName"}'
"Hello firstName!"

# Read the logs
$ bn logs hello

[2018-04-29T13:48:57.474923Z] Function invocation took 288.010 us
[2018-04-29T14:49:22.408467Z] Function invocation took 46.968 us
[2018-04-29T14:57:38.239214Z] Function invocation took 58.174 us
[2018-04-29T15:43:39.046819Z] Query string is None
[2018-04-29T15:43:39.046962Z] Body is         firstName
[2018-04-29T15:43:39.047082Z] Name is set to  firstName
[2018-04-29T15:43:39.047178Z] Function invocation took 599.146 us

The last four lines were generated by our invocation. As expected, we logged a None query string, a firstName body, and a firstName name.

The last log line with the 599.146 us duration measurement is autogenerated per invocation. The first log lines in the bn logs output were genrated by your first calls to hello during the previous chapters of this tutorial.

Live logs

bn logs can show logs in real time, in a way similar to tail -f on a local file. To try it out, let’s split our terminal or open a new tab or window.

In the first terminal window, type:

$ bn logs hello --tail

In a separate terminal window, invoke the function a few times:

$ bn invoke hello --data '{"name": "secondName"}'
"Hello secondName!"
$ bn invoke hello --data '{"name": "thirdName"}'
"Hello thirdName!"

The first terminal shows the log shortly after each invocation:

$ bn logs hello --tail
[2018-04-29T16:12:23.296957Z] Query string is None
[2018-04-29T16:12:23.297096Z] Body is         secondName
[2018-04-29T16:12:23.297213Z] Name is set to  secondName
[2018-04-29T16:12:23.297300Z] Function invocation took 545.025 us
[2018-04-29T16:12:57.638662Z] Query string is None
[2018-04-29T16:12:57.638806Z] Body is         thirdName
[2018-04-29T16:12:57.638924Z] Name is set to  thirdName
[2018-04-29T16:12:57.639015Z] Function invocation took 576.973 us

What next?