Google-cloud-php: Long running PHP PubSub process that eats all cpu exactly 1h into processing

[udAL]

This is more of a plea for help than a bug report..

• OS: Dockerized Ubuntu 16.04.6 (Modified gcr.io/google-appengine/php72)
  
  
  
  • PHP version: 7.2.22
  
  
  • Package name and version:
    
    google/cloud-pubsub 1.11.0
    
    google/cloud-core 1.27.0
    
    (outdated because of compatibility reasons)
  
  

We have been using PubSub for a while for managing background tasks. We have a GCE vm that has supervisord with two long running php processes that check for new messages and process whatever. It looks something like this:

use Google\Cloud\PubSub\PubSubClient;
$pubSub = new PubSubClient([
    'keyFilePath' => 'includes/secret.json'
]);
$subscription = $pubSub->subscription('workers');
while(true)
{
    $message = false;
    try
    {
        foreach ($subscription->pull([
            'maxMessages' => 1
        ]) as $pullMessage)
        {
            $message = $pullMessage;
        }
    }
    catch( Exception $e)
    {
        // Nothing
    }
    if($message)
    {
        // Do stuff
        $subscription->acknowledge($message);
    }
}

As discussed on https://github.com/googleapis/google-cloud-php/issues/1986, since we started we saw this errors popping up every hour:

[19-Sep-2019 16:30:30 Europe/Madrid] PHP Fatal error:  Uncaught Google\Cloud\Core\Exception\ServiceException: cURL error 35: gnutls_handshake()$
Stack trace:
#0 /app/vendor/google/cloud-core/src/RequestWrapper.php(189): Google\Cloud\Core\RequestWrapper->convertToGoogleException(Object(GuzzleHttp\Exce$
#1 /app/vendor/google/cloud-core/src/RestTrait.php(95): Google\Cloud\Core\RequestWrapper->send(Object(GuzzleHttp\Psr7\Request), Array)
#2 /app/vendor/google/cloud-pubsub/src/Connection/Rest.php(193): Google\Cloud\PubSub\Connection\Rest->send('subscriptions', 'pull', Array)
#3 /app/vendor/google/cloud-pubsub/src/Subscription.php(409): Google\Cloud\PubSub\Connection\Rest->pull(Array)
#4 /app/worker.php(77): Google\Cloud\PubSub\Subscription->pull(Array)
#5 {main}
  thrown in /app/vendor/google/cloud-core/src/RequestWrapper.php on line 336

It wasn't a big deal for us since we had our supervisord to keep the processes open. It wasn't till a few days ago when we updated our docker (which we do frequently). Suddenly our worker vm's were constantly at 100% cpu, even though there wasn't anything to process on PubSub and no task processing. We could restart the processes and they would work fine for exactly one hour, then they'll pop to 100% cpu without apparent reason. We're stuck with an essential server that needs restarting every 60 min.

We have done a lot of debugging and the only difference we found between the old and new machines it's that ubuntu package libcurl3-gnutls was updated from <7.47.0-1ubuntu2.12> to <7.47.0-1ubuntu2.14>. We haven't found a way to downgrade.

We have tried to force Guzzle to use TLS 1.1. PubSub allows to pass parameters to it like this:

$subscription->pull([
    'maxMessages' => 1,
    'restOptions' => [
        'curl' => [
            CURLOPT_SSLVERSION => CURL_SSLVERSION_TLSv1_0
        ]
    ]
])

But it hasn't work... Not with CURL_SSLVERSION_TLSv1 neither with CURL_SSLVERSION_TLSv1_0 or CURL_SSLVERSION_TLSv1_2
I know this is a complex error, probably has nothing to do with google/cloud-pubsub, and this is an outdated version. Maybe it's a TLS incompatibility with google pubsub service. Maybe an outdated library in an updated os. I really don't know, but we'll take any suggestion you can give us... Any ideas?

Tomorrow i'll try with a clean project with updated packages and will post.

[dwsupplee]

@udAL that sounds really frustrating, 🙁. We'll definitely take a look to see where/how we can help. Do you have the protobuf/gRPC extensions enabled? If so, would you be able to share versions of each?

As an aside, would you be able to share the comparability issues you're experiencing? Maybe there's something we can do there to help as well.

[udAL]

Hi @dwsupplee
I understand you're referring to google/protobuf and grpc/grpc composer packages. We did have them installed:

• grpc/grpc 1.19.0
• google/protobuf v3.7.1

Our compatibility issues come mainly from requirements of package kreait/firebase-php. If I uninstall it and update I can get:

• google/cloud-core v1.33.0 (latest)
• google/cloud-pubsub v1.17.0 (latest)
• google/protobuf v3.9.1 (latest)
• grpc/grpc 1.22.0 (latest)

I'll do some tests to see if this was part of the problem.
Thanks

[udAL]

With last versions of the packages the result it's the same, 100% cpu after 1h into the script.
I'm sure this is related to libcurl and cURL error 35: gnutls_handshake() since this error used to pop up at 1h and has been replaced with this 100% spikes at 1h, so I'll get into that. Following the cURL error 35 I found suggestions to force cURL to use TLS1.0, do you know if my code it's correct when passing parameters to Guzzle? Any ideas on what else I could try?

[udAL]

To the best of my knowledge the connection to PubSub freezes 1h into it. Don't know how or why, but since PubSub it's usually used on long running processes, isn't that something that should be taken into account?

To hotfix the problem, we had installed cron and restarted the process every 50 min but that has it's own problems since a task could be cough in the middle and, not being acknowledged, would be reprocessed. I have put a timer in the script to destroy and create the PubSub object to reconnect and this should hotfix the problem for now.

[udAL]

This occurred also on google-cloud-python around Dec 2017:
https://github.com/googleapis/google-cloud-python/issues/4600
It was fixed by requiring python package grpcio >= 1.8.2:
https://github.com/googleapis/google-cloud-python/pull/4642

Does that help?

[udAL]

Is there anything being done to solve this?
Otherwise, how should I proceed?
Can you help?

[illambo]

About cURL error 35: gnutls_handshake() we experience a similar issue in one app hosted on flexible engine php (see screenshot), and we use a supervisord in order to maintain stable the worker.

Another thing, for this application we have different envs each in a different project, currently we find this problem only in one of the three projects, maybe try to redistribute in a new project, maybe the problem is for specific network zone.

• google/cloud-pubsub: v1.17.0
• google/cloud-core: v1.33.0
• google/protobuf: v3.9.1
• grpc/grpc: 1.22.0

[dwsupplee]

I understand you're referring to google/protobuf and grpc/grpc composer packages.

Actually, I was wondering about the extensions available on PECL (protobuf/grpc) :).

I have some time set aside next week to help look in to this, my apologies for the delay. We've had a team summit this week.

[udAL]

I did not have protobuf nor grpc extensions installed.
I have added those and it seems this solves the issue. I'll keep testing to be sure.

• ext-protobuf: 3.7.0
• ext-grpc: 1.19.0

Shouldn't this extensions be required on the google/cloud-core?

EDIT: False 'all is good' alarm. It still pops up to 100% CPU

[dwsupplee]

Shouldn't this extensions be required on the google/cloud-core?

Not all our libraries which depend on core require the extensions, and often times users may find themselves on something like shared hosting where the extensions aren't even an option. As a result we've worked to make sure they aren't hard requirements.

False 'all is good' alarm. It still pops up to 100% CPU

Gah, sorry to hear that. I'm setting up an environment to do some testing here soon.

[udAL]

Any news?

[dwsupplee]

@udAL I've been working on reproducing. Would you be able to share the modified dockerfile you're using?

[jdpedrie]

@udAL are you able to share this additional info? :)

[udAL]

Hi, sorry for the delay.
For some reason the package libcurl3-gnutls falled back on it's own to 7.47.0-1ubuntu2.12 (instead of 7.47.0-1ubuntu2.14) so right now we don't have the 100% CPU problem and we have the good old cURL error 35: gnutls_handshake().

Here you can find a project that can reproduce the error.

It requires:

• PubSub json key file at includes/pubsub_secret.json
• PubSub topic with pull subscription named workers_test (in my case with no expiration and 7 days message retention)

To deploy:

• Build and push to Container registry
• Deploy a GCE instance with this image

To reproduce:

• SSH into machine
• docker container ls (copy first contianer id)
• docker exec -it [ID] bash
• Wait 1h
• Take a look at app/worker.err.log

You don't need to send any message to workers_test.
Be aware that the process will auto reset because of supervisord.

Thanks

[udAL]

Any progress?

[udAL]

@jdpedrie Could you reproduce the error?

[udAL]

Hello there!
It's me again!
Is there going to be any action done? Should we stop waiting and look at other options? Anything?

[jdpedrie]

Hi @udAL,

I'm really sorry for the lengthy delay. I'm looking into this now.

[jdpedrie]

How many messages, on average, does the worker generally process before the CPU usage spikes? I've been running your sample application for quite some time (nearly 90 minutes) without seeing any sign of unusually high CPU usage. :-/

Have you tried using a specific tag of the gcr.io/google-appengine/php72 image, rather than latest? Perhaps pinning to a version released before the issue appeared may help, or at least give us a hint as to the source of the problem.

[udAL]

The error I'm getting now it's the cURL error 35: gnutls_handshake() not the high CPU usage as stated here:

For some reason the package libcurl3-gnutls falled back on it's own to 7.47.0-1ubuntu2.12 (instead of 7.47.0-1ubuntu2.14) so right now we don't have the 100% CPU problem and we have the good old cURL error 35: gnutls_handshake().

It pops up exactly at 60 minutes. Have you seen the error on app/worker.err.log ?

It doesn't seem to depend on how many messages it processes. On tests the error showed without processing any messages.

Have you tried using a specific tag of the gcr.io/google-appengine/php72 image, rather than latest? Perhaps pinning to a version released before the issue appeared may help, or at least give us a hint as to the source of the problem.

I could, but what version should I use? I don't know any that has worked.
It looks to me that there's a deep bug embedded on whatever library you're using to send requests, something that's sensible to cUrl versions. I could obviously try each version of cUrl to explore if one works but isn't that a that a lame workaround? Should I be stuck with an old cUrl version forever?

Online I've found other cURL error 35: gnutls_handshake() errors with various google/cloud-core libraries. I can't point to what is it since I don't know the inner workings of google-cloud-php library, that's why I come to you in search of help. All the 'fixes' I have found require to tinker with cUrl parameters on the request, something that's not available to us from outside google/cloud-core.

[jdpedrie]

Have you tried running the container outside of GCE? Does the error still happen? If you've not tried, please confirm that. If it works outside GCE, I'll see about having a member of the network team investigate.

[udAL]

I've just tested both local and GCE.
Confirmed it works outside GCE and still fails inside GCE.
Good call! I'll wait for updates

[jdpedrie]

Thank you for checking. Let me pass this information along to our team and we'll try to see what the next steps are. Thank you again for your patience, I absolutely know how frustrating this kind of thing can be.

[jdpedrie]

Looks like #2562 may be related.

[kamalaboulhosn]

@udAL would you be able to reach out to Google Cloud Support and provide your project ID and the name of your GCE VM that was exhibiting the issue? You can reference this GitHub issue and that the Pub/Sub team asked you to provide this information for debugging. Thanks!

[udAL]

@kamalaboulhosn Absolutely! Sorry if this it's obvious, where should I contact them? I can't find an email or form to send.

[kamalaboulhosn]

@udAL You can reach support from the Cloud console.

[udAL]

@kamalaboulhosn I've been digging on it. To the best of my knowledge, I can only send issues on GCP by purchasing a Support Plan (at least 100$/month user). With the basic plan I can only send billing issues, not technical ones. I would like not to purchase this to send you debugging data.
Is there another option?

[udAL]

@kamalaboulhosn, @jdpedrie is there another option to send the debugging data to the Google Cloud Support team?

[kamalaboulhosn]

@udAL I am now able to reproduce the error in my own docker image with the instructions provided. I can provide the information for my instance for further debugging. Will update if we have or need further information.

[udAL]

I did test it recently in my local machine and couldn't reproduce the error. Don't know why is that.
So this means back to square one?

[kamalaboulhosn]

I had actually deleted the comment where I said I could reproduce it locally. It turns out that was a different issue.

[udAL]

Any news?

[udAL]

Hi,
We've been with this issue since September (6 months) and there has been no news for a month.
Can you update me on this?
Is this being worked on?
Is there an estimate to solve this?

[kamalaboulhosn]

The issue is with the networking team currently. Awaiting an update from them.

[dpassola]

Hi @kamalaboulhosn , i'm David, coworker of udAL. He is not working with us from this April.
Do you have any news about this issue?
Thank you in advance

[kamalaboulhosn]

Hi, @dpassola, the network team looked at it and believes it is likely an issue in the client making the requests to the server. The team who owns the infrastructure that the Pub/Sub client library builds on is now investigating the issue.

[meredithslota]

Internal tracking issue b/148449576.

[dpassola]

Hi @meredithslota and @kamalaboulhosn, is there any news about this issue?

Thank's

[dpassola]

Internal tracking issue b/148449576.

Hi @meredithslota and @kamalaboulhosn, is there any news about this issue?

Thank's

[dpassola]

Hi @meredithslota and @kamalaboulhosn , do you have any news?

We stay more than one year with this issue :(

[dpassola]

Hi @jdpedrie, do you have any news?

[meredithslota]

Hello @dpassola — I checked the internal bug and it has not yet been fixed but I will ping some folks internally and see if we can get it moving. Thanks for checking back. :)