Trying to send backgroundTransaction (on Heroku)

[pesseyjulien]

Hi,

I have been following the doc (https://scoutapm.com/docs/php/advanced-features#custom-instrumentation) in order to send a backgroundTransaction :

        $ret = $this->scout->enabled();
        var_dump($ret);

        $this->scout->backgroundTransaction($this->getName(), function(){

           ...
        });

        $this->scout->send();

Injecting private Scoutapm\ScoutApmAgent $scout in the command __construct.

But I'm getting the following error :

{"message":"[Scout] Failed to connect to socket on address \"tcp://127.0.0.1:6590\", previous message: socket_connect(): unable to connect [111]: Connection refused","context":{},"level":400,"level_name":"ERROR","channel":"app","datetime":"2022-01-31T21:59:41.168531+00:00","extra":{}}
21:59:41 ERROR     [app] [Scout] Failed to connect to socket on address "tcp://127.0.0.1:6590", previous message: socket_connect(): unable to connect [111]: Connection refused

Any idea why ?

Thanks in advance,
Julien

[asgrim]

@pesseyjulien

The error occurs because the scout-apm-symfony-bundle library cannot connect to something called core-agent. The core-agent, with the default configuration, is automatically downloaded and launched on the first request to $agent->connect(). The core-agent is a binary socket server that collects events from the Scout libraries (in any supported language, not just PHP), and sends batches of collected events to Scout periodically.

My default, the Scout integration for Symfony will subscribe to the the onKernelRequest event to call $agent->connect(). This will kick off the download & launch process the first time.

There are a few reasons I can think of why this might not be happening:

• If you are running this in a CLI or long-running process, perhaps the onKernelRequest event is not triggered, so Scout will not "start". I think this is most likely scenario. Once, before the transaction, and before any main "loop" you might have for long-running processes), you should call $this->scout->connect().
• The Scout Bundle was not correctly set up, and so the onKernelRequest is never triggered (or something else is stopping Scout from receiving that kernel event).
• You have configured Scout to not automatically download & launch the core-agent, but have not started it another way (for example, in a Docker container
• You have changed the configuration for Scout to connect to the core-agent and does not match the settings that the core-agent was launched with.

If the first point does not help you, would you be able to share your Scout configuration please; this should be output earlier in the logs, for example:

[Scout] Configuration: {"monitor":true,"name":"Agent Integration Test","key":"<redacted>","log_level":"debug","log_payload_content":false,"api_version":"1.0","ignore":[],"application_root":null,"scm_subdirectory":null,"revision_sha":null,"hostname":null,"disabled_instruments":null,"core_agent_log_level":"DEBUG","core_agent_log_file":"\/tmp\/scout-core-agent.log","core_agent_config_file":null,"core_agent_socket_path":"tcp:\/\/127.0.0.1:6590","core_agent_dir":"\/tmp\/scout_apm_core","core_agent_full_name":"scout_apm_core-v1.4.0-x86_64-unknown-linux-musl","core_agent_download_url":"https:\/\/s3-us-west-1.amazonaws.com\/scout-public-downloads\/apm_core_agent\/release","core_agent_launch":true,"core_agent_download":true,"core_agent_version":"v1.4.0","core_agent_triple":"x86_64-unknown-linux-musl","core_agent_permissions":511,"uri_reporting":"path","uri_filtered_params":["access","access_token","api_key","apikey","auth","auth_token","card","certificate","credentials","crypt","key","mysql_pwd","otp","passwd","password","private","protected","salt","secret","ssn","stripetoken","token"],"errors_enabled":true,"errors_ignored_exceptions":[],"errors_host":"https:\/\/errors.scoutapm.com","errors_batch_size":5,"errors_filtered_params":["password","s3-key","scout_key"]}

Or alternatively, the contents of your config/packages/scoutapm.xml and .env files (BUT IF YOU DO THIS, BE SURE TO REMOVE THE API KEY BEFOREHAND PLEASE!), for example:

<?xml version="1.0" ?>

<container xmlns="http://symfony.com/schema/dic/services"
    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xmlns:scoutapm="http://example.org/schema/dic/scout_apm"
    xsi:schemaLocation="http://symfony.com/schema/dic/services https://symfony.com/schema/dic/services/services-1.0.xsd">

    <scoutapm:config>
        <scoutapm:scoutapm
            name="%env(SCOUT_NAME)%"
            key="%env(SCOUT_KEY)%"
            monitor="true"
            errors_enabled="true"
        />
    </scoutapm:config>
</container>

and

SCOUT_KEY=<redacted>
SCOUT_NAME="My Symfony App"

[pesseyjulien]

Hi @asgrim,

Thanks a bunch for the detailed answer !

I'm now getting 'true' (and no error anymore) on $this->scout->send(); after adding : $this->scout->connect(); but I don't see anything on the dashboard :/

Could it be an issue because I'm using the heroku integration ?

Also, on the dashboard it says 'Background jobs are not yet supported for PHP apps.' but meaning automatically right ? It supposed to work if we manually add it using backgroundTransaction ?

Best,
Julien

[asgrim]

@pesseyjulien would you be able to provide that configuration that should be displayed in the log output please, as that should help us determine if the messages are getting sent to the core agent? I know the data can take a few minutes to reach the dashboard sometimes, and I think the dashboard only displays requests over a certain request length, e.g. slow requests (@jrothrock may be able to confirm that)

[pesseyjulien]

I'm sorry but it seems there is no way to see this kind of log on Heroku :/

But I revert the SCOUT_LOG_LEVEL to DEBUG and got :

18:29:10 WARNING [app] [Scout] Failed to connect to socket on address "tcp://127.0.0.1:6590", previous message: socket_connect(): unable to connect [111]: Connection refused

[asgrim]

I'm sorry but it seems there is no way to see this kind of log on Heroku :/

But I revert the SCOUT_LOG_LEVEL to DEBUG and got :

18:29:10 WARNING [app] [Scout] Failed to connect to socket on address "tcp://127.0.0.1:6590", previous message: socket_connect(): unable to connect [111]: Connection refused

Is that the only log message you see with [Scout] in it? The log message with the configuration is sent by the same logging mechanism, so it should be somewhere before that particular message.

[pesseyjulien]

Unfortunately it's :/

Heroku works in a weird way for cli commands, it provision a new container for each run.

Like if I run my command, I won't even see the logs on the app log but only where I ran the command (see enclosed). I don't know if I make myself clear enough :/

[pesseyjulien]

I finally go them logs ! They appear if the command throws an exception..

{"message":"[Scout] Configuration: {\"monitor\":true,\"name\":\"back-dev\",\"key\":\"<redacted>\",\"log_level\":\"DEBUG\",\"log_payload_content\":false,\"api_version\":\"1.0\",\"ignore\":[],\"application_root\":null,\"scm_subdirectory\":null,\"revision_sha\":null,\"hostname\":null,\"disabled_instruments\":null,\"core_agent_log_level\":null,\"core_agent_log_file\":null,\"core_agent_config_file\":null,\"core_agent_socket_path\":\"tcp:\\/\\/127.0.0.1:6590\",\"core_agent_dir\":\"\\/tmp\\/scout_apm_core\",\"core_agent_full_name\":\"scout_apm_core-v1.4.0-x86_64-unknown-linux-musl\",\"core_agent_download_url\":\"https:\\/\\/s3-us-west-1.amazonaws.com\\/scout-public-downloads\\/apm_core_agent\\/release\",\"core_agent_launch\":true,\"core_agent_download\":true,\"core_agent_version\":\"v1.4.0\",\"core_agent_triple\":\"x86_64-unknown-linux-musl\",\"core_agent_permissions\":511,\"uri_reporting\":\"path\",\"uri_filtered_params\":[\"access\",\"access_token\",\"api_key\",\"apikey\",\"auth\",\"auth_token\",\"card\",\"certificate\",\"credentials\",\"crypt\",\"key\",\"mysql_pwd\",\"otp\",\"passwd\",\"password\",\"private\",\"protected\",\"salt\",\"secret\",\"ssn\",\"stripetoken\",\"token\"],\"errors_enabled\":false,\"errors_ignored_exceptions\":[],\"errors_host\":\"https:\\/\\/errors.scoutapm.com\",\"errors_batch_size\":5,\"errors_filtered_params\":[\"password\",\"s3-key\",\"scout_key\"]}","context":{},"level":100,"level_name":"DEBUG","channel":"app","datetime":"2022-02-02T20:58:06.209647+00:00","extra":{}}
{"message":"[Scout] Scout Core Agent (app=back-dev, ext=n/a) not connected yet, attempting to start","context":{},"level":200,"level_name":"INFO","channel":"app","datetime":"2022-02-02T20:58:06.209687+00:00","extra":{}}
{"message":"[Scout] Parsing Core Agent Manifest at \"/tmp/scout_apm_core/scout_apm_core-v1.4.0-x86_64-unknown-linux-musl/manifest.json\"","context":{},"level":200,"level_name":"INFO","channel":"app","datetime":"2022-02-02T20:58:06.210902+00:00","extra":{}}
{"message":"[Scout] Exception raised whilst parsing manifest: The file \"/tmp/scout_apm_core/scout_apm_core-v1.4.0-x86_64-unknown-linux-musl/manifest.json\" does not exist.","context":{"exception":{"class":"Webmozart\\Assert\\InvalidArgumentException","message":"The file \"/tmp/scout_apm_core/scout_apm_core-v1.4.0-x86_64-unknown-linux-musl/manifest.json\" does not exist.","code":0,"file":"/app/vendor/webmozart/assert/src/Assert.php:2060"}},"level":100,"level_name":"DEBUG","channel":"app","datetime":"2022-02-02T20:58:06.210998+00:00","extra":{}}
{"message":"[Scout] Core Agent verification failed: Manifest is not valid.","context":{},"level":100,"level_name":"DEBUG","channel":"app","datetime":"2022-02-02T20:58:06.211006+00:00","extra":{}}
{"message":"[Scout] Lock path \"/tmp/scout_apm_core/scout_apm_core-v1.4.0-x86_64-unknown-linux-musl/download.lock\" did not exist, nothing to clean","context":{},"level":100,"level_name":"DEBUG","channel":"app","datetime":"2022-02-02T20:58:06.211101+00:00","extra":{}}
{"message":"[Scout] Downloading package from \"https://s3-us-west-1.amazonaws.com/scout-public-downloads/apm_core_agent/release/scout_apm_core-v1.4.0-x86_64-unknown-linux-musl.tgz\" to \"/tmp/scout_apm_core/scout_apm_core-v1.4.0-x86_64-unknown-linux-musl/scout_apm_core-v1_4_0-x86_64-unknown-linux-musl.tgz\"","context":{},"level":100,"level_name":"DEBUG","channel":"app","datetime":"2022-02-02T20:58:06.211136+00:00","extra":{}}
{"message":"[Scout] Decompressing archive \"/tmp/scout_apm_core/scout_apm_core-v1.4.0-x86_64-unknown-linux-musl/scout_apm_core-v1_4_0-x86_64-unknown-linux-musl.tgz\" to \"/tmp/scout_apm_core/scout_apm_core-v1.4.0-x86_64-unknown-linux-musl/scout_apm_core-v1_4_0-x86_64-unknown-linux-musl.tar\"","context":{},"level":100,"level_name":"DEBUG","channel":"app","datetime":"2022-02-02T20:58:09.112399+00:00","extra":{}}
{"message":"[Scout] Extracting \"/tmp/scout_apm_core/scout_apm_core-v1.4.0-x86_64-unknown-linux-musl/scout_apm_core-v1_4_0-x86_64-unknown-linux-musl.tar\" to path \"/tmp/scout_apm_core/scout_apm_core-v1.4.0-x86_64-unknown-linux-musl\"","context":{},"level":100,"level_name":"DEBUG","channel":"app","datetime":"2022-02-02T20:58:09.306522+00:00","extra":{}}
{"message":"[Scout] Parsing Core Agent Manifest at \"/tmp/scout_apm_core/scout_apm_core-v1.4.0-x86_64-unknown-linux-musl/manifest.json\"","context":{},"level":200,"level_name":"INFO","channel":"app","datetime":"2022-02-02T20:58:09.328110+00:00","extra":{}}
{"message":"[Scout] exec is available","context":{},"level":100,"level_name":"DEBUG","channel":"app","datetime":"2022-02-02T20:58:09.483462+00:00","extra":{}}
{"message":"[Scout] Core Agent Launch in Progress","context":{},"level":100,"level_name":"DEBUG","channel":"app","datetime":"2022-02-02T20:58:09.483490+00:00","extra":{}}
{"message":"[Scout] Launching core agent with command: '/tmp/scout_apm_core/scout_apm_core-v1.4.0-x86_64-unknown-linux-musl/core-agent' 'start' '--daemonize' 'true' '--log-file' '/dev/null' '--tcp' '127.0.0.1:6590'","context":{},"level":100,"level_name":"DEBUG","channel":"app","datetime":"2022-02-02T20:58:09.483534+00:00","extra":{}}
{"message":"[Scout] Connected to connector.","context":{},"level":100,"level_name":"DEBUG","channel":"app","datetime":"2022-02-02T20:58:09.492321+00:00","extra":{}}

What I have gathered from my investigation :

• No minimal duration to send the transaction
• If the command is run using "heroku run" or using heroku scheduler, it does not work
• If the command is run inside the container after "heroku run bash" -> it works !

So I think the heroku way of handling commands is the issue !

[asgrim]

Thanks @pesseyjulien - I'll try and reproduce this as soon as I can.

[asgrim]

I can confirm that I can reproduce the behaviour you're seeing. I created a small isolated repository test case that is deployable to Heroku, with a "long-running process" and a "short process" (i.e. a fire-once type command). I believe your report pertains specifically to the latter (a fire-once job that exits after completed), so I shall focus on that.

In both cases, Scout must download and run the core-agent, which it does so. The warning seen in the logs can be ignored; this happens because it takes a moment to start the core-agent and the PHP library is too eager in trying to connect:

$ heroku run php short-process.php
--- some logs snipped ---
[2022-02-04T09:19:09.313544+00:00] application.WARNING: [Scout] Failed to connect to socket on address "tcp://127.0.0.1:6590", previous message: socket_connect(): unable to connect [111]: Connection refused [] []
[2022-02-04T09:19:09.313611+00:00] application.DEBUG: STARTING: HerokuSingleTransaction-2022-02-04-09-19-09 [] []
[2022-02-04T09:19:12.314892+00:00] application.DEBUG: [Scout] Connected to connector whilst sending. [] []
[2022-02-04T09:19:12.767109+00:00] application.DEBUG: [Scout] Sending metrics from 1 collected spans. [] []
[2022-02-04T09:19:12.806240+00:00] application.DEBUG: [Scout] Sent whole payload successfully to core agent. [] []
[2022-02-04T09:19:12.806391+00:00] application.DEBUG: FINISHED: HerokuSingleTransaction-2022-02-04-09-19-09 [] []

The above transaction never made it into the dashboard.

$ heroku run bash
 ›   Warning: heroku update available from 7.59.1 to 7.59.2.
Running bash on ⬢ <redacted>... up, run.3134 (Free)
~ $ php short-process.php 
--- some logs snipped ---
[2022-02-04T09:19:29.357210+00:00] application.WARNING: [Scout] Failed to connect to socket on address "tcp://127.0.0.1:6590", previous message: socket_connect(): unable to connect [111]: Connection refused [] []
[2022-02-04T09:19:29.357264+00:00] application.DEBUG: STARTING: HerokuSingleTransaction-2022-02-04-09-19-29 [] []
[2022-02-04T09:19:32.358596+00:00] application.DEBUG: [Scout] Connected to connector whilst sending. [] []
[2022-02-04T09:19:32.815329+00:00] application.DEBUG: [Scout] Sending metrics from 1 collected spans. [] []
[2022-02-04T09:19:32.860163+00:00] application.DEBUG: [Scout] Sent whole payload successfully to core agent. [] []
[2022-02-04T09:19:32.860409+00:00] application.DEBUG: FINISHED: HerokuSingleTransaction-2022-02-04-09-19-29 [] []
~ $ 

In this case, I left the session open. After a while I saw the transaction appear in the dashboard.

The most likely explanation for this is that the core-agent does not immediately send payloads to Scout. The core-agent collects several transactions, and periodically sends the data to Scout APM. In the first example, the script runs and immediately exits; when this happens, Heroku kills the runner, including the core-agent, which in most cases will not have been able to send the payload collected to Scout. The second example works because the Heroku runner is left running, giving the running core-agent a chance to send its payload.

I will discuss this with the Scout team and see what recommendations we have.

I know it isn't ideal, but as a temporary workaround, you could add a sleep(120); at the end of your script; I can't remember exactly how often core-agent sends payloads to Scout off my head (again, I'd have to ask), but that should be plenty.

[asgrim]

Moved issue to scout-apm-php as it is a general issue, not specific to scout-apm-symfony-bundle.

[pesseyjulien]

Hi,

Thanks for your investigation !

I can't wait for a better solution :) I think what could be ideal is being able to make te core-agent send the transaction directly. For example on $this>scout->send(true) (adding the bool would make an immediate trigger on the core-agent).

Let me know when you have sorted this one out.

Thanks again,
Julien