Bref New Relic Extension - Logs

[tormodmacleod]

Hello

I'm experimenting with the Bref New Relic Extension. So far it's going pretty well. I can see metrics, events and traces in the New Relic console. However, I don't see any logs. I've configured php/conf.d/newrelic-settings.ini as below

newrelic.appname = ${NEW_RELIC_APP_NAME}
newrelic.license = ${NEW_RELIC_LICENSE_KEY}
newrelic.daemon.address = ${NEW_RELIC_DAEMON_ADDRESS}

# Log to Cloud Watch
newrelic.logfile = /proc/self/fd/2

# Add config to capture infrequent requests
# https://github.com/brefphp/extra-php-extensions/issues/252#issuecomment-1020656379
newrelic.daemon.app_timeout = 120H
newrelic.daemon.app_connect_timeout = 15s

# Add super-techno debug for now
newrelic.loglevel = verbosedebug
newrelic.daemon.loglevel = debug

As you can see, I've tried to maximise my chances of getting logs through to New Relic. In index.php my colleague has added

<?php
require __DIR__ . '/vendor/autoload.php';

$logger = new \Bref\Logger\StderrLogger(\Psr\Log\LogLevel::DEBUG);
$logger->warning('Warning level log');
$logger->error('Error level log');
$logger->debug('Debug level log');
$logger->info('Info level log');
$logger->critical('Critical level log');
$logger->emergency('Emergency level log');
$logger->alert('Alert level log');
$logger->notice('Notice level log');


if (isset($_GET['exception'])) {
    throw new Exception('Exception thrown');
}

?>

We can see this in the Cloudwatch logs

2023-01-06T11:48:45.478+00:00   2023-01-06 11:48:45.477 +0000 (8 8) debug: Log Level (PSR-3): WARNING 
2023-01-06T11:48:45.478+00:00   2023-01-06 11:48:45.478 +0000 (8 8) debug: Log Forwarding Log Level (RFC5424) set to: 4 (WARNING) 
...
some lines removed for brevity
...
2023-01-06T11:48:50.164+00:00   [WARNING] Warning level log
2023-01-06T11:48:50.164+00:00   [ERROR] Error level log
2023-01-06T11:48:50.164+00:00   [DEBUG] Debug level log
2023-01-06T11:48:50.164+00:00   [INFO] Info level log
2023-01-06T11:48:50.164+00:00   [CRITICAL] Critical level log
2023-01-06T11:48:50.164+00:00   [EMERGENCY] Emergency level log
2023-01-06T11:48:50.164+00:00   [ALERT] Alert level log
2023-01-06T11:48:50.164+00:00   [NOTICE] Notice level log 

But I don't see any logs for my service in New Relic APM. I've tried looking within the New Relic Logs feature in case they're somehow not linked to the service. I've been unable to find them. Although that may be because I'm not really sure how to query for them.

It did occur to me that perhaps the extension doesn't handle logs. Or maybe I've just mis-configured something somewhere. I'd be very grateful for some advice

[starred-gijs]

Hi @tormodmacleod, I experimented with the Log Forwarder feature and it did work. However, the PHP Agent only supports this when you use Monolog, see https://docs.newrelic.com/docs/logs/logs-context/configure-logs-context-php/#automatic-logs-in-context
Your code snippet shows \Bref\Logger\StderrLogger which is a light weight replacement for Monolog if you only need to log to Cloudwatch, and the Agent does not recognise it.

FYI:
I eventually disabled Log Forwarding because the configuration options are too limited: I need multiple channels with different log levels and handlers (eg, fingers crossed). I do use https://github.com/newrelic/newrelic-monolog-logenricher-php to enrich the logs with newrelic specific data.
And from cloudwatch my logs are uploaded to NewRelic with this lambda function: https://docs.newrelic.com/docs/logs/forward-logs/aws-lambda-sending-cloudwatch-logs/

[tormodmacleod]

thanks for getting back to me @starred-gijs

we've installed monolog and newrelic log enricher. we were having no luck getting this to work in lambda so we running it in docker locally. we can see in wireguard that it's sending the logs to log-api.eu.newrelic.com but we don't receive any logs. also, although the telemetry still reaches the daemon, nothing shows up in the console

daemon.log

composer.json

{
    "require": {
        "bref/bref": "^1.7",
        "bref/extra-php-extensions": "^0.12.3",
        "bref/logger": "^1.0",
        "monolog/monolog": "^2.0",
        "newrelic/monolog-enricher": "^2.0"
    }
}

index.php

<?php
require __DIR__ . '/vendor/autoload.php';

use Monolog\Logger;
use Monolog\Handler\StreamHandler;
use Monolog\Handler\BufferHandler;
use NewRelic\Monolog\Enricher\{Handler, Processor};

$logger = new Logger('newrelic');
$logger->pushHandler(new StreamHandler('php://stderr', Logger::DEBUG));
$logger->pushProcessor(new Processor());
$logger->pushHandler(new BufferHandler(new Handler));
$logger->warning('Warning level log');
$logger->error('Error level log');
$logger->debug('Debug level log');
$logger->info('Info level log');
$logger->critical('Critical level log');
$logger->emergency('Emergency level log');
$logger->alert('Alert level log');
$logger->notice('Notice level log');


if (isset($_GET['exception'])) {
    throw new Exception('Exception thrown');
}

?>
<!DOCTYPE html>
<html lang="en">
<head>
    <meta name="viewport" content="width=device-width, initial-scale=1, shrink-to-fit=no">
    <title>Welcome!</title>
    <link href="https://fonts.googleapis.com/css?family=Dosis:300&display=swap" rel="stylesheet">
    <link href="https://unpkg.com/tailwindcss@^1.0/dist/tailwind.min.css" rel="stylesheet">
</head>
<body class="flex h-screen">
    <div class="rounded-full mx-auto self-center relative" style="height: 400px; width: 400px; background: linear-gradient(123.19deg, #266488 3.98%, #258ECB 94.36%)">
        <h1 class="font-light absolute w-full text-center text-blue-200" style="font-family: Dosis; font-size: 45px; top: 35%">Hello there,</h1>
        <div class="w-full relative absolute" style="top: 60%; height: 50%">
            <div class="absolute inset-x-0 bg-white" style="bottom: 0; height: 55%"></div>
            <svg viewBox="0 0 1280 311" fill="none" xmlns="http://www.w3.org/2000/svg"><g clip-path="url(#clip0)"><path d="M1214 177L1110.5 215.5L943.295 108.5L807.5 168.5L666 66.5L581 116L517 49.5L288.5 184L163.5 148L-34.5 264.5V311H1317V258.5L1214 177Z" fill="white"/><path d="M1214 177L1110.5 215.5L943.295 108.5L807.5 168.5L666 66.5L581 116L517 49.5L288.5 184L163.5 148L-34.5 264.5L163.5 161L275 194L230.5 281.5L311 189L517 61L628 215.5L600 132.5L666 77L943.295 295L833 184L9
43.295 116L1172 275L1121 227L1214 189L1298 248L1317 258.5L1214 177Z" fill="#DCEFFA"/></g><defs><clipPath id="clip0"><rect width="1280" height="311" fill="white"/></clipPath></defs></svg>
        </div>
    </div>
</body>
</html>

[starred-gijs]

Sorry to hear it's not working, that must be frustrating. You mention you switched to local docker for testing purposes. What is the local setup? Do you use the bref docker dev image? I dont have any experience with that one. I suggest to take 1 step at the time. You want to run this on lambda eventually, so start with that setup. Initially you mentioned APM worked, so that is a great first step.
Now decide how you want to ship your logs to newrelic. Via the daemon or via Cloudwatch.

https://docs.newrelic.com/docs/logs/logs-context/configure-logs-context-php/

Deamon:
Verify agent version at least 10.3.0
Verify daemon version at least 10.3.0
REMOVE newrelic/monolog-enricher
Configure ini

newrelic.application_logging.enabled = true
newrelic.application_logging.metrics.enabled = true
newrelic.application_logging.forwarding.enabled = true
newrelic.application_logging.forwarding.log_level = info 

Cloudwatch
Verify agent version at least 10.3.0
Verify daemon version at least 10.3.0
Install + configure newrelic/monolog-enricher
configure monolog to write to stdout
enable distributed tracing
Configure ini to disable log forwarding:

newrelic.application_logging.enabled = false
newrelic.application_logging.forwarding.enabled = false

Log some stuff and look into your cloudwatch log groups for newrelic added data like span.id and trace.id

if all of this fails, contact NR support.

[tormodmacleod]

@starred-gijs thanks very much for your help. it is now working beautifully 🤌

the problem had been that we'd installed the log enricher

to your point about whether to use the daemon or cloudwatch to get the logs to new relic... i was thinking that the daemon would be easier in that i'm going to be configuring my functions to talk to the daemon anyway. so long as they can access the daemon for sending telemetry, they'll also be able to send the logs. however, on inspection, it appears that the agent send the logs directly to log-api.eu.newrelic.com. i guess the advantage of scraping cloudwatch for the logs and forwarding them to new relic would be that you might get more verbose logs? i'd be interested to get your thoughts

one other thing i'm interested in is how people typically deploy the daemon? i've currently got it deployed to ecs within the same vpc as my function and that works fine. however, i'd like to deploy it to ecs behind a load balancer and have all of my functions configured to connect to a single daemon. the idea being to have a single daemon deployment that i can scale rather than have to maintain a daemon per vpc. i'd also like to avoid having to deploy all of my functions within vpc's. i'm not sure whether you can load balance the traffic to more than one instance of the daemon. but even if i had to have a single instance of the daemon and scale it vertically i think this would still be better than having to maintain a daemon per project / aws account.

i did have some initial success with putting the daemon behind an nlb but now i'm getting an error in cloudwatch

2023-01-31 10:13:44.102 +0000 (10 10) verbosedebug: daemon connect(fd=10 host=DNS_NAME_OF_THE_LOAD_BALANCER, port=31339) returned -1 errno=EALREADY
2023-01-31 10:13:42.162 +0000 (10 10) verbosedebug: Waiting for TTL to elapse to resolve IP address for a TCP connection: host=DNS_NAME_OF_THE_LOAD_BALANCER, port=31339
2023-01-31 10:13:42.162 +0000 (10 10) debug: unable to begin transaction: no daemon connection 

i'm using the dns name directly from ecs which is an A record with a 60 second ttl. i'm not sure why it would wait for the ttl to elapse before resolving the ip 🤷‍♂️

[starred-gijs]

i guess the advantage of scraping cloudwatch for the logs and forwarding them to new relic would be that you might get more verbose logs? i'd be interested to get your thoughts

We choose cloudwatch for 2 reasons:

1. Occasionally the lambda can't connect to the ECS hosted daemon (connect via private IP), so the ARM data is not shipped to NR, but that is not a big deal. But when I need to check the logs to verify some processing flow, and I cant know if they are missing, that is bad. Plus we have other log groups (php logs, nginx logs, ELB logs) that are also in cloudwatch and shipped via a separate log-forwarder.
2. We use many Monolog channels with various log level messages, and I found the config of the agent too limited.

one other thing i'm interested in is how people typically deploy the daemon

We run the official docker image in ECS within the same VPC as our other ECS containers and lambdas, and we directly connect on private IP address
Its possible the NS lookup takes too long, look at newrelic.daemon.app_connect_timeout ini setting, we have it at 2s

[tormodmacleod]

@starred-gijs i realised that my lambda was in a vpc subnet with no route to the internet 😞

since i corrected that it's working 🙂

i did notice that some invocations do not show up in the console. i see them established on the daemon

2023/02/14 16:57:39.110859 (13) Info: app 'lambda-newrelic-bref' connected with run id 'BWL19d3nZs5tADPCSx1G14Jj673UAAMBACdHIQEAAAANAgQbb_uXeGjbvnoG6a9hmD6mcsjEhD88W0skhwFJ4CWo7ibfynEDAAoxMC40LjAuMzE2AA4xNjkuMjU0LjcwLjIwOQAYc3czLWxhbWJkYS1uZXdyZWxpYy1icmVm'

but no data shows up. it's usually the first interaction. ie if my lambda is invoked, i'll see it connect to the daemon but there'll be no logs or metrics in new relic. however, if i wait a couple of minutes and invoke the lambda again, these invocations will show up in new relic.

i started playing about with newrelic.daemon.app_connect_timeout as per your previous message and also newrelic.daemon.app_timeout as per this issue. the way i understand the documentation, if i set as below...

newrelic.daemon.app_connect_timeout = "15s"
newrelic.daemon.app_timeout = "1h20m"

...this config should

1. tell the agent to wait up to 15s in order to establish a connection to the daemon
2. tell the daemon to maintain connections from an agent for 1 hour and 20 minutes

however, no matter what i set newrelic.daemon.app_timeout as i see

2023/02/14 17:22:38.226893 (13) Info: removing "lambda-newrelic-bref" with run id "Ba2IvQTOKARvADPCSx1Gnrtj68FYAAMBACdHIQEAAAANAgQbb_uXeGjbvnoG6a9hmD6mcsjEhD88W0skhwFJ4CWo7ibfynEDAAoxMC40LjAuMzE2AA0xNjkuMjU0LjE5Ljg1ABhzdzMtbGFtYmRhLW5ld3JlbGljLWJyZWY" for lack of activity within 10m0s

because subsequent invocations within ten minutes of the initial one are showing up in new relic i'm making the assumption that this newrelic.daemon.app_timeout setting is not being applied somehow. but this may be a misunderstanding on my part.

i should add that i am very grateful for all of the help that you've given me so far and am at the stage where i've got something working and am not too concerned about missing telemetry for the odd invocation here and there. i suspect i've probably not quite got my settings right somewhere but i thought i'd post here anyway in case it was obvious to you.

[starred-gijs]

Good to hear you got it working! Im not sure what the exact settings should be to fix those timeouts, we run the lamdbas at a higher volume, so those timeouts do not happen.