@dwsupplee @jdpedrie this issue still randomly persists.
URGENT REQUEST. We're part of the Google Cloud Startup program and launching this year... a fix would be greatly appreciated so we can move to production.
Log output:
PHP Fatal error: Uncaught Google\Cloud\Core\Exception\ServiceException: {
"message": "Socket closed",
"code": 14,
"status": "UNAVAILABLE",
"details": []
} in /[...]/Google/composer-google-cloud/vendor/google/cloud/Core/src/GrpcRequestWrapper.php:257
Stack trace:
#0 /[...]/Google/composer-google-cloud/vendor/google/cloud/Core/src/GrpcRequestWrapper.php(194): Google\Cloud\Core\GrpcRequestWrapper->convertToGoogleException(Object(Google\ApiCore\ApiException))
#1 [internal function]: Google\Cloud\Core\GrpcRequestWrapper->handleStream(Object(Google\ApiCore\ServerStream))
#2 /[...]/Google/composer-google-cloud/vendor/google/cloud/Firestore/src/SnapshotTrait.php(122): Generator->current()
#3 /[...]/Google/composer-google-clo in /[...]/Google/composer-google-cloud/vendor/google/cloud/Core/src/GrpcRequestWrapper.php on line 257
@dwsupplee firestore, not spanner
@lukasgit what version of the grpc extension do you have installed? You can find this value by running pecl list if you installed via PECL, or in the output of php -i or phpinfo().
@jdpedrie
Package Version State
grpc 1.23.1 stable
protobuf 3.10.0 stable
Thanks @lukasgit.
Does it seem to always be related to a particular service call, or does it happen randomly?
Would you be able to enable gRPC debugging and share the results relating to a failure? You can set the following environment variables to turn on debugging: GRPC_VERBOSITY=debug GRPC_TRACE=all. Please note that the debug output may include sensitive information such as access tokens, so if you'd prefer, you may send it to me via the email address on my profile.
@jdpedrie randomly, and I'm not seeing any gRPC debugging info in the php logs:
putenv('GRPC_VERBOSITY=debug');
putenv('GRPC_TRACE=all');
@lukasgit I'm sorry I was unclear. Setting those variables will cause additional logging data to be written to stderr, not to the PHP log.
@jdpedrie not seeing any gRPC debugging info to stderr.
php.ini
display_errors = stderr
@jdpedrie ^^
Hey @lukasgit sorry for not responding sooner. I'm working on this though, hope to have more by the end of the day, or tomorrow at latest.
@jdpedrie great, thanks for the update.
Are you using PHP-FPM? Make sure your configuration has catch_workers_output=yes. This should cause the workers' stderr output to be written to the server error log.
@jdpedrie still nothing... here is what I have configured:
nginx-1.17.5 (dev environment compiled with --with-debug):
error_log logs/error.log debug;
php-fpm (php-7.3.11):
catch_workers_output = yes
env[GRPC_VERBOSITY] = debug
env[GRPC_TRACE] = all
php code:
putenv('GRPC_VERBOSITY=debug');
putenv('GRPC_TRACE=all');
Hi @lukasgit, I'm sorry again for the back-and-forth. I've been trying without much success to capture the gRPC debugging data from nginx/php-fpm.
Do you have control over the system which is managing the FPM daemon? supervisord and systemd for instance? Are you able to configure php-fpm to start with an explicit pipe of stderr to file?
php-fpm 2>/var/log/php-fpm.log
Additionally, I spoke with a contact on the gRPC team, and he suggested you toggle the debug and verbosity a bit differently than what I advised earlier:
GRPC_VERBOSITY=debug
GRPC_TRACE=api,call_error,channel,client_channel_call,connectivity_state,handshaker,http,subchannel,tcp
I've opened an issue on gRPC to improve the utilities for capturing gRPC debugging information in PHP.
Hi @jdpedrie, no worries on the back-and-forth. Whatever it takes for us to resolve this issue.
I do have full control over the development system. Following your instructions, still nothing related to gRPC in /var/log/php-fpm.log :
[08-Nov-2019 21:24:18] NOTICE: fpm is running, pid 1104
[08-Nov-2019 21:24:18] NOTICE: ready to handle connections
nginx-1.17.5 (dev environment compiled with --with-debug):
error_log logs/error.log debug;
php-fpm (php-7.3.11):
catch_workers_output = yes
env[GRPC_VERBOSITY] = debug
env[GRPC_TRACE] = api,call_error,channel,client_channel_call,connectivity_state,handshaker,http,subchannel,tcp
php code:
putenv('GRPC_VERBOSITY=debug');
putenv('GRPC_TRACE=api,call_error,channel,client_channel_call,connectivity_state,handshaker,http,subchannel,tcp');
Hi @lukasgit,
@stanley-cheung, the person I've been talking to on the gRPC team, mentioned that in his tests using Apache, he found that setting the environment variables with putenv and even in the server configuration was too late and they were ineffective. In his test using docker, he set them in the Dockerfile and had better luck. Could you try setting them at the highest level possible? Perhaps etc/environment or similar.
Hi @lukasgit I am one of the maintainers of the grpc php extension.
The only thing that seems to work for me (in terms of the php-fpm + nginx setup), is to do the combination of these 2:
FROM php:7.2-fpm-stretch as a base for example)php-fpm 2>/var/log/php-fpm.log to start the service (instead of relying on the standard CMD) to redirect stderr away to my desired log fileI have tried all those catch_workers_output = yes, env[GRPC_VERBOSITY] = debug in the fpm www.conf file but none of those work. Doing putenv() in a .php script seems definitely too late.
But even with the php-fpm 2>mylog trick, the log is being outputed kind of ugly with " [pool www] child 12 said into stdout: " and lines got broken up.
So I am currently working on adding a php.ini option for the grpc extension that we can divert all those grpc logs into a separate log file, tracked in here. Will keep you updated.
But also just so I know, for the initial error, how rare / often does that happen? Are we talking about 1 every 10 request, or 1 every 10000 request? Just want to see what the scale of things is.
Hi @stanley-cheung thanks for jumping in on this issue.
I will hang tight until the php.ini option for the grpc extension is available.
As for how many times the error occurs per x requests, it varies widely. Sometimes it happens 7 times out of 50 requests. Sometimes 0 times out of 1000 requests. We haven't ran a stress test of 10,000 requests on grpc yet.
I started this PR: https://github.com/grpc/grpc/pull/20991. This works for the most part but may need some more polish. I am slightly concerned about the lack of file rotations / capping the size of the log file - as it stands, the log file will grow unbounded. There might be a need for a separate cronjob or something to monitor and regularly truncating this log file.
Hi @stanley-cheung any update on this issue? Thanks :)
@lukasgit Sorry for the late reply. We are very close to cutting a 1.26.0RC1 release candidate, which will contain that fix. Once that's done, will you be able to install that in your environment and enable the grpc log to a separate log file? You might need to monitor the file size growth if the error was not happening frequently.
@stanley-cheung since our last chat, we upgraded the composer version and only had the error happen one time (yesterday). So yeah, it's still very random. I can definitely run your next RC, just provide me with instructions when you're ready. Thanks!
@lukasgit 1.26.0RC1 should be available on PECL now. If you just do [sudo] pecl install grpc-beta, that should be the version installed.
Please add the following lines to your php.ini file:
grpc.grpc_verbosity=debug
grpc.grpc_trace=all,-timer_check
grpc.log_filename=/var/log/grpc.log
You can add more traces to ignore by adding more minus '-' sign to the grpc.grpc_trace option. See this doc for all the possible values for that option. There are potentially a few you can add to trim down the volume of the log.
i got same issue on my local
but on production working fine with same version
Have a similar issue with our local env. Every 4th request to Firestore from PHP fails with "unavailable" and an empty message. Code 14.
Test code
$ref = $firestore->collection('users');
$doc = $ref->document('someuser');
$snap = $documentReference->snapshot();
return $snap->exists();
PHP 7.2.10
grpc extension v1.26.0
google/protobuf ^v3.3.0
@digarahayu @stakable could you try enabling gRPC tracing as @stanley-cheung described above and sharing some logs from the error cases?
I think this issue is related to mine #2539.
Fatal error: Uncaught Google\Cloud\Core\Exception\ServiceException: { "message": "Empty update", "code": 14, "status": "UNAVAILABLE", "details": [] }
I'm seeing this about twice a day in production. Hundreds of other times it works fine. Using AppEngine standard, 7.3.
Same here. I recently started getting quite a few of these ... like once every 10 minutes.
PHP Fatal error: Uncaught Google\Cloud\Core\Exception\ServiceException: {
"message": "Socket closed",
"code": 14,
"status": "UNAVAILABLE",
"details": []
} in /lib/firestore/vendor/google/cloud-core/src/GrpcRequestWrapper.php:257
PHP 7.4.4 (Debian 10 x64)
Nginx 1.10.3
It's very annoying to get these in production. I understand we can try these requests with an exponential backoff ... but that is not the case as sometimes we are having requests processing card authorizations, and we cannot store all those credentials in order to re-run at a later point.
Please advise.
An update, as I can't seem to be able to edit the previous message.
This never happened on a server from another ISP (Hetzner).
On the other hand, on the servers at DigitalOcean, it happens quite often, sometimes multiple times per hour, sometimes once per day, with random methods, which don't necessarily have big payloads.
So, may it be some php-fpm config issue? Any child process killing the socket? Not sure how it works so .. I'm just throwing ideas around.
@edi are you able to try capturing some of the tracing data as described by @stanley-cheung above?
@jdpedrie @stanley-cheung we've noticed the issue persists but something of interest might be happening.
The issue seems to suddenly stop when we update the composer package google/cloud.
Is there possibly a correlation between these random "Socket closed" errors due to changes on your end that might not be compatible with a prior version of google/cloud composer package?
Do you know what the previous version of google/cloud was where the issue appeared? We'll have to look at what has changed between then and now. But do I understand correctly that the latest version of the client seems to no longer have the issue? If so, that's great news!
On the server with the issue, I have "google/cloud-core": "^1.31", which is very weird becase I've installed it myself via composer require about two weeks ago.
Regarding grpc, I have 1.27.0 installed, and I'm now upgrading to 1.28.1, hopefully it sorts it out.
This is how many times it happened for me so far, in the past 48 hours.
I've also re-installed cloud-core to 1.36.1 (given the OP's success with it), will be back tomorrow with an update.
Regards.
Thanks @edi, please do let us know.
Well gents, so far so good after updating to [email protected] š
As a sidenote, the server which didn't get a [email protected] update but only a gRPC one, still has the issues.
Another server running the same [email protected] as the one having issues, has [email protected] installed. That didn't have this kind of issues either.
So, the issue is obviously not with gRPC (1.27 or 1.28.1), but with the older version of cloud-core.
1st server -> cloud-core 1.31 gRPC 1.28.1 -> BAD
2nd server -> cloud-core 1.35 gRPC 1.27.0 -> OK
3rd server -> cloud-core 1.36.1 gRPC 1.28.1 -> OK
I may have spoken too soon. Still happens on [email protected] and [email protected]
Times when it happened today
Will try implement the logs mentioned above and come back with some more info ... it's so weird as the same exact setup on another server at another ISP and I have never had this issue.
@jdpedrie so far no errors in the last 5 days:
Using version ^0.131.0 for google/cloud
./composer.json has been created
Loading composer repositories with package information
Updating dependencies (including require-dev)
Package operations: 22 installs, 0 updates, 0 removals
- Installing google/crc32 (v0.1.0): Loading from cache
- Installing psr/cache (1.0.1): Loading from cache
- Installing psr/http-message (1.0.1): Loading from cache
- Installing ralouphie/getallheaders (3.0.3): Loading from cache
- Installing guzzlehttp/psr7 (1.6.1): Loading from cache
- Installing guzzlehttp/promises (v1.3.1): Loading from cache
- Installing guzzlehttp/guzzle (6.5.2): Loading from cache
- Installing firebase/php-jwt (v5.2.0): Downloading (100%)
- Installing google/auth (v1.8.0): Downloading (100%)
- Installing google/protobuf (v3.11.4): Downloading (100%)
- Installing google/common-protos (1.2): Downloading (100%)
- Installing grpc/grpc (1.27.0): Downloading (100%)
- Installing google/grpc-gcp (0.1.4): Loading from cache
- Installing google/gax (1.3.0): Downloading (100%)
- Installing symfony/polyfill-ctype (v1.15.0): Downloading (100%)
- Installing ramsey/collection (1.0.1): Downloading (100%)
- Installing brick/math (0.8.15): Downloading (100%)
- Installing ramsey/uuid (4.0.1): Downloading (100%)
- Installing psr/log (1.1.3): Downloading (100%)
- Installing monolog/monolog (2.0.2): Loading from cache
- Installing rize/uri-template (0.3.2): Loading from cache
- Installing google/cloud (v0.131.0): Downloading (100%)
I have decided to move on to a new Hetzner server. Just set up a new droplet on DO, basic nginx / php setup. (debian 10 x64), nothing special.
Then you'll start randomly getting those socket closed errors, with the latest binaries and SDKs.
Back on Hetzner for 3 days now, no error whatsoever.
Back on Hetzner for 3 days now, no error whatsoever.
@edi other than your setup being on a different hosting provider, was there a change in your server configuration or code ?
@jdpedrie @stanley-cheung This is not acceptable for a mission critical datastore. The random "status": "UNAVAILABLE" errors with Firestore is preventing us from going live.
Since April 22, everything has been working just fine. We thought perhaps you unknowingly figured out the problem. I left this issue open as a precaution.
As of June 6, every day we are once again receiving these random "status": "UNAVAILABLE" errors.
We upgraded the composer package today. In the upgrade we can see grpc-gcp changed from 0.1.4 to 0.1.5.
Latest upgrade on June 10 (today):
^0.133.1 for google/cloudgrpc/grpc (1.27.0)google/grpc-gcp (0.1.5)Previously installed package (since April 22):
^0.131.0 for google/cloud.grpc/grpc (1.27.0)google/grpc-gcp (0.1.4)@lukasgit Just want to clarify - these errors didn't happen between ~Apr 16-ish and Jun 6-ish?
@stanley-cheung Confirmed - these errors did not happen between ~Apr 16-ish and Jun 6-ish
2 suggestions:
And just as a guess - there are 3 main areas these errors could come from (and the fact that these errors did not happen between Apr 16 and Jun 6 didn't help much to narrow it down):
In any case, we need some more concrete things before we can really look into this:
- would you by any chance be able to pin down these versions to those as of April 22 you listed above? That way we can try to see if it's because of those packages? Coz, conceivably, even if you pin those versions back - these UNAVAILABLE errors may still happen. Then that's likely because of those packages.
Between April 6 and June 10, we were using version ^0.131.0 for google/cloud which contained google/grpc-gcp (0.1.4)
As of today, June 10, we upgrade to version ^0.133.1 for google/cloud which contains google/grpc-gcp (0.1.5)
- Are you able to capture the grpc logs as per my comment here? #2427 (comment). If we can see the grpc logs for those calls - that will help.
I will look into this again.
And just as a guess - there are 3 main areas these errors could come from (and the fact that these errors did not happen between Apr 16 and Jun 6 didn't help much to narrow it down):
- some code on the client libraries change and are responsible for it. I personally think this is unlikely. Client side changes are unlikely to cause a server to return UNAVAILABLE.
If no errors come up after we upgraded today, to the latest version ^0.133.1 for google/cloud, the probability of this being a client library issue must be considered.
- some network issues. This is the hardest to debug. This highly depends on your setup. Where are you running the clients? What are the hops between that and the Firestore servers? Are you going across regions? Anything changed in one of those hops could have caused the issues.
The client is running on a GCE Debian instance located in Zone us-east1-b. The Firestore Database location: nam5 (us-central)
- Something changed on the Firestore side or the google API serving side. Even that has many layers and possibilities.
This would imply Firestore is not production ready if multiple connection attempts are randomly denied.
In any case, we need some more concrete things before we can really look into this:
- Are there a reproducible test case? For example, if you can give us a docker image, have us replace our own credentials, run it for a few days to try to see if we can see the errors for ourselves?
As I and many others have stated in this thread, the issue is completely random. I don't believe it's a problem on our end if we're all experiencing the same issue. I filed this urgent issue back in October 2019 and we are still dealing with it as of June 2020. Furthermore, I would presume there's many others in production that aren't reporting it because their users retry when an error occurs. That is no excuse for a mission critical datastore.
- Or as mentioned above, if you can capture some logs on your side that will help.
$ cat php_error.log
[06-Jun-2020 15:22:26 UTC] PHP Fatal error: Uncaught Google\Cloud\Core\Exception\ServiceException: {
"message": "Socket closed",
"code": 14,
"status": "UNAVAILABLE",
"details": []
} in /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Core/src/GrpcRequestWrapper.php:257
Stack trace:
#0 /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Core/src/GrpcRequestWrapper.php(194): Google\Cloud\Core\GrpcRequestWrapper->convertToGoogleException(Object(Google\ApiCore\ApiException))
#1 [internal function]: Google\Cloud\Core\GrpcRequestWrapper->handleStream(Object(Google\ApiCore\ServerStream))
#2 /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Firestore/src/SnapshotTrait.php(122): Generator->current()
#3 /opt/Google/composer-google-cloud/composer-google-clo in /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Core/src/GrpcRequestWrapper.php on line 257
[09-Jun-2020 02:22:13 UTC] PHP Fatal error: Uncaught Google\Cloud\Core\Exception\ServiceException: {
"message": "Socket closed",
"code": 14,
"status": "UNAVAILABLE",
"details": []
} in /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Core/src/GrpcRequestWrapper.php:257
Stack trace:
#0 /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Core/src/GrpcRequestWrapper.php(194): Google\Cloud\Core\GrpcRequestWrapper->convertToGoogleException(Object(Google\ApiCore\ApiException))
#1 [internal function]: Google\Cloud\Core\GrpcRequestWrapper->handleStream(Object(Google\ApiCore\ServerStream))
#2 /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Firestore/src/SnapshotTrait.php(122): Generator->current()
#3 /opt/Google/composer-google-cloud/composer-google-clo in /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Core/src/GrpcRequestWrapper.php on line 257
[09-Jun-2020 21:45:28 UTC] PHP Fatal error: Uncaught Google\Cloud\Core\Exception\ServiceException: {
"message": "Socket closed",
"code": 14,
"status": "UNAVAILABLE",
"details": []
} in /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Core/src/GrpcRequestWrapper.php:257
Stack trace:
#0 /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Core/src/GrpcRequestWrapper.php(194): Google\Cloud\Core\GrpcRequestWrapper->convertToGoogleException(Object(Google\ApiCore\ApiException))
#1 [internal function]: Google\Cloud\Core\GrpcRequestWrapper->handleStream(Object(Google\ApiCore\ServerStream))
#2 /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Firestore/src/SnapshotTrait.php(122): Generator->current()
#3 /opt/Google/composer-google-cloud/composer-google-clo in /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Core/src/GrpcRequestWrapper.php on line 257
[09-Jun-2020 21:50:42 UTC] PHP Fatal error: Uncaught Google\Cloud\Core\Exception\ServiceException: {
"message": "Socket closed",
"code": 14,
"status": "UNAVAILABLE",
"details": []
} in /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Core/src/GrpcRequestWrapper.php:257
Stack trace:
#0 /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Core/src/GrpcRequestWrapper.php(194): Google\Cloud\Core\GrpcRequestWrapper->convertToGoogleException(Object(Google\ApiCore\ApiException))
#1 [internal function]: Google\Cloud\Core\GrpcRequestWrapper->handleStream(Object(Google\ApiCore\ServerStream))
#2 /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Firestore/src/SnapshotTrait.php(122): Generator->current()
#3 /opt/Google/composer-google-cloud/composer-google-clo in /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Core/src/GrpcRequestWrapper.php on line 257
[10-Jun-2020 16:00:07 UTC] PHP Fatal error: Uncaught Google\Cloud\Core\Exception\ServiceException: {
"message": "Socket closed",
"code": 14,
"status": "UNAVAILABLE",
"details": []
} in /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Core/src/GrpcRequestWrapper.php:257
Stack trace:
#0 /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Core/src/GrpcRequestWrapper.php(194): Google\Cloud\Core\GrpcRequestWrapper->convertToGoogleException(Object(Google\ApiCore\ApiException))
#1 [internal function]: Google\Cloud\Core\GrpcRequestWrapper->handleStream(Object(Google\ApiCore\ServerStream))
#2 /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Firestore/src/SnapshotTrait.php(122): Generator->current()
#3 /opt/Google/composer-google-cloud/composer-google-clo in /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Core/src/GrpcRequestWrapper.php on line 257
[10-Jun-2020 17:26:26 UTC] PHP Fatal error: Uncaught Google\Cloud\Core\Exception\ServiceException: {
"message": "Socket closed",
"code": 14,
"status": "UNAVAILABLE",
"details": []
} in /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Core/src/GrpcRequestWrapper.php:257
Stack trace:
#0 /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Core/src/GrpcRequestWrapper.php(194): Google\Cloud\Core\GrpcRequestWrapper->convertToGoogleException(Object(Google\ApiCore\ApiException))
#1 [internal function]: Google\Cloud\Core\GrpcRequestWrapper->handleStream(Object(Google\ApiCore\ServerStream))
#2 /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Firestore/src/SnapshotTrait.php(122): Generator->current()
#3 /opt/Google/composer-google-cloud/composer-google-clo in /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Core/src/GrpcRequestWrapper.php on line 257
[10-Jun-2020 17:38:45 UTC] PHP Fatal error: Uncaught Google\Cloud\Core\Exception\ServiceException: {
"message": "Socket closed",
"code": 14,
"status": "UNAVAILABLE",
"details": []
} in /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Core/src/GrpcRequestWrapper.php:257
Stack trace:
#0 /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Core/src/GrpcRequestWrapper.php(194): Google\Cloud\Core\GrpcRequestWrapper->convertToGoogleException(Object(Google\ApiCore\ApiException))
#1 [internal function]: Google\Cloud\Core\GrpcRequestWrapper->handleStream(Object(Google\ApiCore\ServerStream))
#2 /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Firestore/src/SnapshotTrait.php(122): Generator->current()
#3 /opt/Google/composer-google-cloud/composer-google-clo in /opt/Google/composer-google-cloud/composer-google-cloud-20200415/vendor/google/cloud/Core/src/GrpcRequestWrapper.php on line 257
These are just the PHP level logs. The comment I had here https://github.com/googleapis/google-cloud-php/issues/2427#issuecomment-562334183 will enable logs from the grpc C extension, which can capture more of the underlying networking layers.
By the way, can you confirm the version of the grpc extension being used? Please run
php --re grpc | head -1
Totally forgot about the extensions.... here's what is currently installed. We will update today.
Do you believe this is the underlying issue?
$ php --re grpc | head -1
Extension [ <persistent> extension #35 grpc version 1.23.1 ] {
$ php --re protobuf | head -1
Extension [ <persistent> extension #36 protobuf version 3.10.0 ] {
Could be. Version 1.23.1 is out about 10 months by now. We are currently at 1.29.1 and 1.30.0 should be coming out in a week or so. So you can try upgrading.
Protobuf I'd recommend either 3.11.4 or 3.12.2.
Actually, also, which version of Debian are you running?
This is an issue we get totally randomly as well, and have been unable to trace, following this if the rest of you manage to find some fix.
https://sentry.io/share/issue/5ede539ebefb4e18a09cf9415c9a7b9b/
I'm fighting with this issue for months. I'm running my apps in App Engine standard (7.3), and this issue basically forced us to remove firestore from various services.
@joshuaoliver @sl0wik we are hunting down the problem as this is clearly not an isolated issue.
@stanley-cheung Updated the following components. Will monitor over the next couple of days and post result.
php
$ php -v
PHP 7.4.7 (cli) (built: Jun 12 2020 04:55:45)
grpc
$ php --re grpc | head -1
Extension [ <persistent> extension #34 grpc version 1.29.1 ] {
protobuf
$ php --re protobuf | head -1
Extension [ <persistent> extension #35 protobuf version 3.12.2 ] {
Using version ^0.133.1 for google/cloud
Package operations: 25 installs, 0 updates, 0 removals
- Installing google/crc32 (v0.1.0): Loading from cache
- Installing psr/cache (1.0.1): Loading from cache
- Installing psr/http-message (1.0.1): Loading from cache
- Installing ralouphie/getallheaders (3.0.3): Loading from cache
- Installing guzzlehttp/psr7 (1.6.1): Loading from cache
- Installing guzzlehttp/promises (v1.3.1): Loading from cache
- Installing symfony/polyfill-php72 (v1.17.0): Downloading (100%)
- Installing symfony/polyfill-mbstring (v1.17.0): Downloading (100%)
- Installing symfony/polyfill-intl-idn (v1.17.0): Downloading (100%)
- Installing guzzlehttp/guzzle (6.5.4): Downloading (100%)
- Installing firebase/php-jwt (v5.2.0): Loading from cache
- Installing google/auth (v1.9.0): Downloading (100%)
- Installing google/protobuf (v3.12.2): Downloading (100%)
- Installing google/common-protos (1.2): Loading from cache
- Installing grpc/grpc (1.27.0): Loading from cache
- Installing google/grpc-gcp (0.1.5): Downloading (100%)
- Installing google/gax (1.3.1): Downloading (100%)
- Installing symfony/polyfill-ctype (v1.17.0): Downloading (100%)
- Installing ramsey/collection (1.0.1): Loading from cache
- Installing brick/math (0.8.15): Loading from cache
- Installing ramsey/uuid (4.0.1): Loading from cache
- Installing psr/log (1.1.3): Loading from cache
- Installing monolog/monolog (2.1.0): Downloading (100%)
- Installing rize/uri-template (0.3.2): Loading from cache
- Installing google/cloud (v0.133.1): Downloading (100%)
@stanley-cheung problem still persists:
[12-Jun-2020 11:02:52 UTC] PHP Fatal error: Uncaught Google\Cloud\Core\Exception\ServiceException: {
"message": "Socket closed",
"code": 14,
"status": "UNAVAILABLE",
"details": []
} in /opt/composer-google-cloud/composer-google-cloud-20200610/vendor/google/cloud/Core/src/GrpcRequestWrapper.php:257
Stack trace:
#0 /opt/composer-google-cloud/composer-google-cloud-20200610/vendor/google/cloud/Core/src/GrpcRequestWrapper.php(194): Google\Cloud\Core\GrpcRequestWrapper->convertToGoogleException()
#1 [internal function]: Google\Cloud\Core\GrpcRequestWrapper->handleStream()
#2 /opt/composer-google-cloud/composer-google-cloud-20200610/vendor/google/cloud/Firestore/src/SnapshotTrait.php(122): Generator->current()
#3 /opt/composer-google-cloud/composer-google-cloud-20200610/vendor/google/cloud/Firestore/src/SnapshotTrait.php(61): G in /opt/composer-google-cloud/composer-google-cloud-20200610/vendor/google/cloud/Core/src/GrpcRequestWrapper.php on line 257
@stanley-cheung Google is losing customers because of this issue (see comment above from @joshuaoliver):
I'm fighting with this issue for months. I'm running my apps in App Engine standard (7.3), and this issue basically forced us to remove firestore from various services.
Something is clearly wrong on Google's end. Many people are experiencing this issue.
Like I mentioned earlier, the problem went away between April 16 and June 6. We did not make any changes, yet the problem unexpectedly returned.
PLEASE TAKE THIS ISSUE SERIOUS AND URGENT.
/cc @schmidt-sebastian have we seen similar issues in other client libraries per chance? This seems like it may be network related, but we're having a hard time pin pointing it.
We've been tracking this issue since last year and had connectivity issues with various versions / combinations post grpc v1.19. We've been running the following both locally and in production (PHP72 Flex) for most of this year without issue:
"grpc/grpc": "v1.19",
"google/protobuf": "^v3.3.0",
Rolling back is not ideal but you may at the very least get a stable service running until a fix is discovered. I haven't looked at this for months but I'm pretty certain things break for us if we update grpc beyond v1.19.
@dwsupplee @stanley-cheung
Hello, I have a python grpc client and a C++ server. There is a exception appearing occasionally which tell me "Socket closed".
https://gitter.im/grpc/grpc?at=5ee236d924a3382d5d5e66cb
"error": "14 UNAVAILABLE: failed to connect to all addresses"
@lukasgit did you by any chance be able to add these entries to your php.ini to enable grpc level logs? https://github.com/googleapis/google-cloud-php/issues/2427#issuecomment-562334183.
Once you saw an UNAVAILABLE error like you mentioned, can you go clip out perhaps the logs since a few minutes before that point and send it to us?
What is the Firestore operation that triggers this? Can you give us some profile as to how this error is triggered? Something like this would help: "we are calling
@stanley-cheung yes however no grpc log is being created; still getting this error:
[12-Jun-2020 21:22:21 UTC] PHP Fatal error: Uncaught Google\Cloud\Core\Exception\ServiceException: {
"message": "Socket closed",
"code": 14,
"status": "UNAVAILABLE",
"details": []
}
@stanley-cheung we isolated where we think we can capture Firestore operations that trigger this Socket closed issue. I'll have something for you within an hour or less.
While we are at it, you mentioned that you are using "GCE Debian instance located in Zone us-east1-b", can you point us the exact image name, size of the instances, etc, so that when we try to replicate this on our end, to get as close to your setup?
@stanley-cheung reply to my email and I'll send you those details
@lukasgit - I'm also interested in the solution. I'm happy to share all my AppEngine instance information.
TL;DR: I had been looking into this in the last day or so, but I still couldn't reproduce the Socket Closed | 14 | Unavailable error. Here are the details:
I created a GCP VM and enabled the Firestore API. There are some troubles with access and permissions and service accounts and whatnot, but eventually I am able to create a fresh GCP project. The GCP VM is in us-east1-b with Debian 10 (which makes it easier to install PHP 7.3), and the Firestore database is in nam5 (us-central).
I installed the grpc pecl extension version 1.29.1 via pecl install grpc. PHP version is PHP 7.3.14-1~deb10u1 (cli) (built: Feb 16 2020 15:07:23) ( NTS ). I added extension=grpc.so to /etc/php/7.3/cli/php.ini and /etc/php/7.3/fpm/php.ini. My composer.json is extremely simple:
{
"require": {
"google/cloud-firestore": "v1.13.0"
}
}
These are all the other composer packages that got pulled in after I run composer install on that directory (from composer.lock).
"name": "brick/math", "version": "0.8.15",
"name": "firebase/php-jwt", "version": "v5.2.0",
"name": "google/auth", "version": "v1.9.0",
"name": "google/cloud-core", "version": "v1.37.1",
"name": "google/cloud-firestore", "version": "v1.13.0",
"name": "google/common-protos", "version": "1.2",
"name": "google/gax", "version": "1.3.1",
"name": "google/grpc-gcp", "version": "0.1.5",
"name": "google/protobuf", "version": "v3.12.2",
"name": "grpc/grpc", "version": "1.27.0",
"name": "guzzlehttp/guzzle", "version": "6.5.4",
"name": "guzzlehttp/promises", "version": "v1.3.1",
"name": "guzzlehttp/psr7", "version": "1.6.1",
"name": "monolog/monolog", "version": "2.1.0",
"name": "psr/cache", "version": "1.0.1",
"name": "psr/http-message", "version": "1.0.1",
"name": "psr/log", "version": "1.1.3",
"name": "ralouphie/getallheaders", "version": "3.0.3",
"name": "ramsey/collection", "version": "1.0.1",
"name": "ramsey/uuid", "version": "4.0.1",
"name": "rize/uri-template", "version": "0.3.2",
"name": "symfony/polyfill-ctype", "version": "v1.17.0",
"name": "symfony/polyfill-intl-idn", "version": "v1.17.0",
"name": "symfony/polyfill-mbstring", "version": "v1.17.0",
"name": "symfony/polyfill-php72", "version": "v1.17.0",
update-document($db); every minute just to make sure things change in a regular interval.) This script has been running for 2+ hours now with no error.<?php
require 'vendor/autoload.php';
use Google\Cloud\Firestore\FirestoreClient;
$db = new FirestoreClient([
'projectId' => '<my gcp project>'
]);
function update_document($db) {
$data = [
'name' => sprintf('document data: Los Angeles %s', date('H:i')),
'state' => 'CA',
'country' => 'USA'
];
$db->collection('cities')->document('LA')->set($data);
}
while (true) {
// call update_document($db) once every 6 loops
$docRef = $db->collection('cities')->document('LA');
$snapshot = $docRef->snapshot();
if ($snapshot->exists()) {
echo sprintf("%s \"%s\"", date('Y-m-d H:i:s'), $snapshot['name']);
} else {
echo "Failed\n";
}
sleep(10);
}
/etc/nginx/sites-available/mysite set up. And made sure I ran something like sudo systemctl restart nginx and sudo systemctl restart php7.3-fpm. server {
listen 8080;
root /var/www/html;
index index.php index.html index.htm;
server_name localhost;
location / {
try_files $uri $uri/ =404;
}
location ~ \.php$ {
include snippets/fastcgi-php.conf;
fastcgi_pass unix:/run/php/php7.3-fpm.sock;
}
}
And a /var/www/html/firestore.php script (which is extremely similar to my CLI script above) to be executed by php-fpm when that's requested by Nginx:
<?php
require '/home/stanleycheung/firestore-test/vendor/autoload.php';
use Google\Cloud\Firestore\FirestoreClient;
$db = new FirestoreClient([
'projectId' => '<my gcp project>',
'keyFile' => json_decode(file_get_contents("<path to credentials.json>"), true),
]);
$docRef = $db->collection('cities')->document('LA');
$snapshot = $docRef->snapshot();
if ($snapshot->exists()) {
echo sprintf("From Nginx/FPM: %s \"%s\"\n",
date('Y-m-d H:i:s'), $snapshot['name']);
} else {
echo "Failed\n";
}
Reason I need to add the keyFile to the constructor is just for some auth thing that because nginx / php-fpm are running as the system user so there are some complication there.
#!/bin/bash
while :
do
curl -s localhost:8080/firestore.php
sleep 10
done
So far I haven't received a single error after running the script for almost 3 hours now. I was monitoring my nginx /var/log/nginx/access.log and /var/log/nginx/error.log and there was no error.
From Nginx/FPM: 2020-06-14 06:34:55 "document data: Los Angeles 06:34"
From Nginx/FPM: 2020-06-14 06:35:05 "document data: Los Angeles 06:34"
From Nginx/FPM: 2020-06-14 06:35:16 "document data: Los Angeles 06:34"
From Nginx/FPM: 2020-06-14 06:35:26 "document data: Los Angeles 06:35"
From Nginx/FPM: 2020-06-14 06:35:36 "document data: Los Angeles 06:35"
From Nginx/FPM: 2020-06-14 06:35:46 "document data: Los Angeles 06:35"
From Nginx/FPM: 2020-06-14 06:35:56 "document data: Los Angeles 06:35"
From Nginx/FPM: 2020-06-14 06:36:06 "document data: Los Angeles 06:35"
From Nginx/FPM: 2020-06-14 06:36:16 "document data: Los Angeles 06:35"
From Nginx/FPM: 2020-06-14 06:36:27 "document data: Los Angeles 06:36"
From Nginx/FPM: 2020-06-14 06:36:37 "document data: Los Angeles 06:36"
Unless stated above - I didn't touch anything else in my GCP project, my GCP VM, my nginx / php-fpm setup, my PHP installation, my grpc extension, and the client libraries. I didn't tweak any config parameters like timeouts and stuff. I installed nginx and php-fpm straight up with sudo apt-get install php7.3 php7.3-dev php7.3-fpm nginx, and didn't do any custom compilation. I got almost everything else from the standard GCP / google cloud libraries documentations.
So that's where I am now. Current setup:
curl localhost:8080/firestore.php every 10 seconds to query the same Firestore document.tail -f on access.log, error.log, the CLI log, and the curl log to see if there's any error.I really want to be able to see the Socket Closed | 14 | Unavailable error myself, but so far I wasn't able to.
I am going to leave to script to run overnight to see if there's any error.
Update: made it thru 12 hours, 4500 requests. No errors.
So looks like we could rule out the basic stuff. I am already using a similar set up in GCP, doing a similar set of operations on the Firestore API, using the latest version of the extension and the composer packages, and using a similar (albeit a bit too simple) Nginx + PHP-FPM setup.
So there are something else that we haven't been able to identify, that the common scenarios above are missing. Anyone participating in this thread can spot something in my setup and can say "hey I am doing something different \ Or coming from the other side - can someone else try to start from scratch, like I did, in your own setup / environment? Start with a clean VM/base image, a clean composer installation, a clean PECL extension installation and see if you can reproduce the issue that way?
grpc and protobuf and enabled them in your php.ini that I should try? I wonder if there are weird interactions if I enable some extensions that I don't know about.
google/cloud version v0.133.1, instead of google/cloud-firestore version v1.13.0. Same result. No errors.
nic0, IP forwarding: Off, etc, in my VM now.
ab -c 10 -n 2000 localhost:8080/firestore.php to simulate 2000 requests with concurrency = 10. Took a minute to run these 2000 requests, that works out to about 33 requests per second. My php-fpm seems to have spawned 5 child processes to handle these requests. No errors. So it doesn't seem like a concurrency issue.
Alright - we are finally getting somewhere. I am able to get in touch with @lukasgit and asked him to enable the grpc log once again using the instructions back here and we are able to get the relevant log file for this "Socket closed" issue.
So for anyone else monitoring this thread - let me repeat the instructions here:
php.ini file. Could be /etc/php/7.3/fpm/php.ini if your PHP script is being executed by php-fpm. Add these after the extension=grpc.so line.grpc.grpc_verbosity=debug
grpc.grpc_trace=all,-timer_check
grpc.log_filename=/var/log/grpc.log
/var/log/grpc.log is writable.$ sudo touch /var/log/grpc.log
$ sudo chmod 666 /var/log/grpc.log
Restart your php-fpm sudo systemctl restart php7.3-fpm.
Monitor /var/log/grpc.log, possibly by running tail -f /var/log/grpc.log | grep -i 'Socket closed'. Whenever you receive a "Socket closed" error in your Nginx error.log, there should be something corresponding being spit out here in the grpc.log.
Yes the log file will grow pretty quickly. You may want to zero it out every X minutes depending on how fast the file grows: cp /dev/null /var/log/grpc.log if no error happens. This can be run even when the tail -f command is still running - you don't have to restart that.
Once you received a 14 UNAVAILABLE Socket Closed error, clip out the relevant section by timestamp. Each log line starts with something like I1592187671.018904062. The first part 1592187671 is the current unix timestamp. You can try to match it to the exact time when your "Socket Closed" error happen, then go back 10 seconds and then go forward 10 seconds, or something like that. That should provide us a pretty good picture of the error.
In this case, I am seeing logs like these:
I1592187671.017156449 chttp2_transport.cc:1082] transport 0x55b37dbe5910 got
goaway with last stream id 31
I1592187671.017174678 connectivity_state.cc:151] ConnectivityStateTracker
client_transport[0x55b37dbe5c40]: READY -> TRANSIENT_FAILURE (got_goaway)
I1592187794.834571065 chttp2_transport.cc:2653] ipv4:74.125.141.95:443: Complete
BDP ping err={"created":"@1592187794.833724507","description":"Endpoint read
failed","file":"/tmp/pear/temp/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2514,"occurred_during_write":0,"referenced_errors":
[{"created":"@1592187794.832794013","description":"Secure read
failed","file":"/tmp/pear/temp/grpc/src/core/lib/security/transport/secure_endpoint.cc","file_line":183,"referenced_errors":[{"created":"@1592187794.832736514","description":"Socket
closed","fd":11,"file":"/tmp/pear/temp/grpc/src/core/lib/iomgr/tcp_posix.cc","file_line":781,"grpc_status":14,"target_address":"ipv4:74.125.141.95:443"}]},
{"created":"@1592187794.832620171","description":"GOAWAY
received","file":"/tmp/pear/temp/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc"
,"file_line":1075,"grpc_status":14,"http2_error":0,"raw_bytes":"session_timed_out"}]}
This leads me a similar error with Node + Spanner: https://github.com/googleapis/nodejs-spanner/issues/620. And from there, it looks like this "GOAWAY received" error is a transient error that's retryable.
@jdpedrie @dwsupplee Can you perhaps look into this to see if this can be added to Firestore client library to handle this case?
Sorry, I was OOO on Friday.
We just submitted a change that should sync to the PHP client by tomorrow which will retry CommitRequests that fail with UNAVAILABLE. This might help here.
FWIW, we also just started retrying RunQuery requests in Node: https://github.com/googleapis/nodejs-firestore/pull/1116
From my experience, it is more fruitful to spend time on retry logic rather than trying to eliminate all network related issues.
@schmidt-sebastian Thanks for the update! I was also just pointed to an internal bug b/144734355 that's very similar to this issue.
And it eventually leads to some fixes like this in Go and this in Python. Would the PHP fix be similar to that?
Thanks!
Yes. PHP will need retry behavior on Watch RPCs, that includes setting the last resume token from the previous session. Note that even under normal operations, a Watch stream closes at least once an hour due to Auth token expiry, and as such retry is critical for these long lived stream.
Great details, thanks @schmidt-sebastian and @stanley-cheung for all your research thus far. @crwilcox does adding this retry behavior seem like a reasonable thing for us to get slated?
I think itās equally important for the end user/developer to wrap client
calls with retry behavior in their code, and have the Dev documentation and
API reference docs suggest this approach. Itās best to have it
logged/handled and retried x times rather than immediate halt due to socket
exception errors.
@lukasgit End users will not be able to retry Watch streams without incurring additional charges for document reads. Only the SDK has the ability to resume Watch streams and start where it last left off.
I understand, and absolutely the SDK must resume watch streams. However, to
account for future issues that may arise as weāve discovered, wrapping
client calls in a retry block ensure the end userās experience isnāt
interrupted by backend network issues. The cost is negligible, versus the
alternative of having upset users.
@stanley-cheung @dwsupplee @schmidt-sebastian any update yet? Seeing "Transport closed" and "Socket closed" daily again.
@lukasgit Hi, I am running C++ helloworld with client and server on different terminal and see "14: Socket closed" I see previously many folks faced this but did not see a root cause or solution, can someone help? This happens continuously for me. This is the first time am running grpc.
Why is the ball getting dropped here? I've provided ample data and we've identified the problem. Now we're waiting for a fix on your end. Numerous people across many threads and community platforms are complaining about this issue. @stanley-cheung @dwsupplee @schmidt-sebastian
I am seeing the same issue with python client running grpcio Version: 1.32.0
You may have to forcefully set up the environment variables as indicated below
putenv(āGCLOUD_PROJECT=app-idā);
putenv(āGOOGLE_APPLICATION_CREDENTIALS=path/to/service-auth-key-file.jsonā);
use Google\Cloud\Firestore\FirestoreClient;
$firestore = new FirestoreClient([
āprojectIdā => āyour-app-idā,
]);
$collectionReference = $firestore->collection(āUsersā);
$documentReference = $collectionReference->document($Userid);
$snapshot = $documentReference->snapshot();
echo āHello ā . $snapshot[ānameā];
Same problem here:

Most helpful comment
Why is the ball getting dropped here? I've provided ample data and we've identified the problem. Now we're waiting for a fix on your end. Numerous people across many threads and community platforms are complaining about this issue. @stanley-cheung @dwsupplee @schmidt-sebastian