GAE Flex PHP env better logging format

[Yao Li]

I have an app is built on GAE Flex Custom env (GCloud PHP Ngnix docker image based), I want to improve the application logging format.

How can I make the application log format better (more readable, with timestamp, POST/GET method name, status code (200), size (22 B), time (4ms), browser(chrome) in one line, put stack trace together instead of multiple lines now) like GAE logging format?

All of the following logs are from Google Cloud Platform Console, Logging page/tab.

(GAE default logging:)

15:21:23.667POST20022 B4 msChrome 56/User/isHuman

 (my application log, I want to collect following lines into one part like above default one rather than multi lines:)

15:21:27.0002017/05/25 22:21:27 [error] 23#23: *34128 FastCGI sent in stderr: "PHP message: [WARN] jsVersion does not match:3617 3623

15:21:27.000 Stack Trace:

15:21:27.000Array

15:21:27.000(

15:21:27.000[0] => Array

[Jun (Cloud Platform Support)]

Hi Yao,

You can actually write your application log entries using the psrLogger method, which will fetch a PSR-3 complaint logger, and you can have more info by looking at Writing applications logs.

- Jun

[Takashi Matsuo]

We're developing a new logging library, which is under alpha testing phase (instructoins). Please try this and let us know how it works for you.

Thanks,

--
You received this message because you are subscribed to the Google Groups "Google App Engine" group.
To unsubscribe from this group and stop receiving emails from it, send an email to google-appengi...@googlegroups.com.
To post to this group, send email to google-a...@googlegroups.com.
Visit this group at https://groups.google.com/group/google-appengine.
To view this discussion on the web visit https://groups.google.com/d/msgid/google-appengine/d8d50887-c512-451a-ac13-d91ecda235b6%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

-- Takashi

[Yao Li]

Does it make API request (Google Logging, will be slow in production) or just print to stdout/stderr (should be super fast in production)?

[Yao Li]

If it has to make API request, is there any way to write locally and also make the format pretty?

[Yao Li]

I used the code in example with logName as 'app',

$batchLogger = new PsrBatchLogger('app'); // logName `app`

But it complains about 

"NOTICE: PHP message: Failed to send log to Google: {"

" "error": {"

" "code": 400,"

" "message": "Name is missing the logs component. Expected the form projects/[PROJECT_ID]/logs/[ID]","

" "status": "INVALID_ARGUMENT""

" }"

"}"

do I need change 'app' to 'projects/my_project_id/logs/[ID]', how can I get ID or I define it by myself, like user unix timestamp?

[Takashi Matsuo]

Hi Yao,

> Does it make API request (Google Logging, will be slow in production) or just print to stdout/stderr (should be super fast in production)?

It's making API requests, but in background in batch if you're using the daemon, so it should be fast. 

> If it has to make API request, is there any way to write locally and also make the format pretty?

I think you can just use other PSR compliant logger, rather than using the PsrBatchLogger on your local machine.

> But it complains about...

Is this happening on App Engine Flex production server, or locally? I'm asking because it should just work on App Engine Flex.

Can you give me a reproducible sample?

To view this discussion on the web visit https://groups.google.com/d/msgid/google-appengine/c935b2ca-feee-47e6-9b11-7083418f1f3a%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

-- Takashi

[Takashi Matsuo]

Hi Yao,

> make the format pretty

The new logging library will automatically add some useful metadata (monitored resources, trace id, severity). They look very nice to me on the logging UI, but what do you mean exactly by making the format pretty?

--

-- Takashi

[Yao Li]

> I think you can just use other PSR compliant logger, rather than using the PsrBatchLogger on your local machine.

Could you give me some examples for other PSR compliant logger?

> Is this happening on App Engine Flex production server, or locally? ....

It's on App Engine Flex production server. (I used my project id instead of 'app', but it still complains, what's appropriate way to set the name? just 'app' or 'projects/project-id/log/ID' as suggested?

my code:

$batchLogger = new PsrBatchLogger('app'); // logName `app`, tried both 'app' and 'my-project-id'

 

$batchLogger->log(LogLevel::DEBUG, 'This is a debug log');

$batchLogger->debug('This is a debug log'); // The same thing

> The new logging library will automatically add some useful metadata (monitored resources, trace id, severity). They look very nice to me on the logging UI, but what do you mean exactly by making the format pretty?

I mean there are a lot of logging separated in multiple lines (as following example) rather than list under a request like your screenshot.

-  2017/05/31 04:19:51 [error] 51#0: *1586 FastCGI sent in stderr: "PHP message: [INFO] Array
 
-  (
 
-      [deviceId] => 0...C
 
-      [key] => 6....4
 
-      [userId] => 1602
 
-  )
   
 

[Takashi Matsuo]

Hi Yao,

On Tue, May 30, 2017 at 9:39 PM Yao Li <y...@sazze.com> wrote:

> I think you can just use other PSR compliant logger, rather than using the PsrBatchLogger on your local machine.

Could you give me some examples for other PSR compliant logger?

Monolog?

```

composer require monolog/monolog

```

```

<?php

require_once __DIR__ . '/vendor/autoload.php';

use Monolog\Logger;

use Monolog\Handler\StreamHandler;

use Monolog\Formatter\LineFormatter;

$handler = new StreamHandler('php://stdout');

$handler->setFormatter(new LineFormatter(null, null, false, true));

$logger = new Logger('LocalLogger', [$handler]);

$logger->info('test');

```

 

> Is this happening on App Engine Flex production server, or locally? ....

It's on App Engine Flex production server. (I used my project id instead of 'app', but it still complains, what's appropriate way to set the name? just 'app' or 'projects/project-id/log/ID' as suggested?

No you should be able to just set 'app', and it should just work. I can not reproduce your issue. Is it possible to somehow share your project so that i can repro?

 

my code:

$batchLogger = new PsrBatchLogger('app'); // logName `app`, tried both 'app' and 'my-project-id'

 

$batchLogger->log(LogLevel::DEBUG, 'This is a debug log');

$batchLogger->debug('This is a debug log'); // The same thing

> The new logging library will automatically add some useful metadata (monitored resources, trace id, severity). They look very nice to me on the logging UI, but what do you mean exactly by making the format pretty?

I mean there are a lot of logging separated in multiple lines (as following example) rather than list under a request like your screenshot.

I think your app is still emitting the logs to stderr, and you are seeing the logs on stderr which is not very well formatted.

Once the new logger starts working, your logs will be available in the `app` logs. Note that you need to explicitly choose `app` in the log dropdown.

-- Takashi

  

-  2017/05/31 04:19:51 [error] 51#0: *1586 FastCGI sent in stderr: "PHP message: [INFO] Array
 
-  (
 
-      [deviceId] => 0...C
 
-      [key] => 6....4
 
-      [userId] => 1602
 
-  )
   
 

On Thursday, May 25, 2017 at 3:36:25 PM UTC-7, Yao Li wrote:

I have an app is built on GAE Flex Custom env (GCloud PHP Ngnix docker image based), I want to improve the application logging format.

How can I make the application log format better (more readable, with timestamp, POST/GET method name, status code (200), size (22 B), time (4ms), browser(chrome) in one line, put stack trace together instead of multiple lines now) like GAE logging format?

All of the following logs are from Google Cloud Platform Console, Logging page/tab.

(GAE default logging:)

15:21:23.667POST20022 B4 msChrome 56/User/isHuman

 (my application log, I want to collect following lines into one part like above default one rather than multi lines:)

15:21:27.0002017/05/25 22:21:27 [error] 23#23: *34128 FastCGI sent in stderr: "PHP message: [WARN] jsVersion does not match:3617 3623

15:21:27.000 Stack Trace:

15:21:27.000Array

15:21:27.000(

15:21:27.000[0] => Array

--

You received this message because you are subscribed to the Google Groups "Google App Engine" group.
To unsubscribe from this group and stop receiving emails from it, send an email to google-appengi...@googlegroups.com.
To post to this group, send email to google-a...@googlegroups.com.
Visit this group at https://groups.google.com/group/google-appengine.

To view this discussion on the web visit https://groups.google.com/d/msgid/google-appengine/366a25f6-6fd1-47ae-b4fb-bb6f5cbe7982%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

-- Takashi

[Yao Li]

I tried Monolog and it is super fast (stdout in example), but it has logging line by line and no severity, time and status code info like original gcloud logging under one request, is there any way to achieve that with Monolog?

[Yao Li]

I fixed the project id issue for PsrBatchLogger, but it always create 499 error when make api call.

[Takashi Matsuo]

Hi Yao,

Few questions,

Is the 499 error happening on App Engine Flex?

Can you share the reproducible project (like zip files)?

Can you share the logs with me? Hopefully can you invite me to your project as a viewer so that I can check the logs?

To view this discussion on the web visit https://groups.google.com/d/msgid/google-appengine/e00aad6a-b781-448c-8f7f-191737355b97%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

-- Takashi

[Yao Li]

Hi Takashi,

1. Yes, it's happening on App Engine Flex.

2. I cannot share the project because of company's rule.
3. Some log example:

08:09:04.000 172.18.0.3 - - [01/Jun/2017:15:09:04 +0000] "POST /v0/updateDeviceID HTTP/1.1" 200 86 "-" "FS/2...31 (iPhone; iOS 10.3.1; Scale/2.00)"

08:09:04.000[01-Jun-2017 15:09:04] WARNING: [pool app] child 53 said into stderr: "NOTICE: PHP message: [INFO] Array"

08:09:04.000[01-Jun-2017 15:09:04] WARNING: [pool app] child 53 said into stderr: "("

08:09:04.000[01-Jun-2017 15:09:04] WARNING: [pool app] child 53 said into stderr: " [deviceId] => 6...1"

08:09:04.000[01-Jun-2017 15:09:04] WARNING: [pool app] child 53 said into stderr: " [userId] => 1...0"

08:09:04.000[01-Jun-2017 15:09:04] WARNING: [pool app] child 53 said into stderr: ")"

08:09:04.000[01-Jun-2017 15:09:04] WARNING: [pool app] child 53 said into stderr: ""

08:09:04.000 2017/06/01 15:09:04 [error] 51#0: *2273 FastCGI sent in stderr: "PHP message: [INFO] Array

08:09:04.000(

08:09:04.000[deviceId] => 6...1

08:09:04.000[userId] => 1...0

08:09:04.000)

 08:09:04.000

08:09:06.359 POST 200   86B   94ms FS... /v0/updateDeviceID

What I'm going to achieve is make all info print under the request (last line in logging), but it prints to multiple lines in stdout/stderr now.

[Takashi Matsuo]

Hi Yao,

I don't see any 499 errors in your logs. Is that still happening?

The logs are saying `child 53 said into stderr`, which means you are emitting the logs to stderr, but the psrBatchLogger doesn't. I don't think your configuration is correct. Can you create and deploy a simple project with the psrBatchLogger and select `nginx.request` and `app` in the log console? I attached the working sample app, so that you can just try it rather than writing it on your own. It produces the following log presentation when you expand a `nginx.request` log:

Be sure to select `app` and `nginx.request` logs as follows:

To view this discussion on the web visit https://groups.google.com/d/msgid/google-appengine/e0c9ce76-9c05-4c26-957b-ee731d39b1e0%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

-- Takashi

[Takashi Matsuo]

Sorry I forgot to attach the app. Here you are.

--

-- Takashi

[Yao Li]

1. I stop using PsrBatchLogger in framework level logging and it doesn't have 499 error.

2. The logging sample works for me, thanks.

3. I found the error for PsrBatchLogger in the current project whose runtime is custom (based on gcr.io/google_appengine/debian8, but your logging example runtime is php) :

PHP Fatal error:  Uncaught Error: Call to undefined function Google\Cloud\Core\Batch\pcntl_signal() in /app/vendor/google/cloud/src/Core/Batch/BatchDaemon.php:67

Stack trace:

#0 /app/vendor/google/cloud/src/Core/bin/google-cloud-batch(45): Google\Cloud\Core\Batch\BatchDaemon->__construct('/app/vendor/goo...')

#1 {main}

  thrown in /app/vendor/google/cloud/src/Core/Batch/BatchDaemon.php on line 67

2017-06-01 17:44:05,686 INFO exited: batch-daemon (exit status 255; not expected)

The pcntl_signal() function should be disabled, I tested adding it into google_app_engine.enable_functions in application's php.ini, but it doesn't work. I'm trying to add it into custom docker image's php.ini. (the custom docker image is based on php-nginx, like php-docker, but not exact same, cannot found the original link).

[Takashi Matsuo]

Hi Yao,

Maybe you can use one of our base image:

gcr.io/google-appengine/php71

gcr.io/google-appengine/php70

gcr.io/google-appengine/php56

They have pcntl extension enabled by default.

To view this discussion on the web visit https://groups.google.com/d/msgid/google-appengine/2cc20602-993f-4801-bd8d-9ddb8b896d8a%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

-- Takashi

[Yao Li]

1. I tested gcr.io/google-appengine/php71 and PsrBatchLogger works on production, I will test more to make sure it doesn't influence performance too much.

2. I tested Monolog as well in production and it prints very fast but not under the request call (case 1) because it outputs to stdout/stderr. Is there any way to use Monolog to achieve the format when use PsrBatchLogger? (my production site has tons of traffic, Monolog prints locally and it's perfect if it can have pretty format like case 3)

case 1 - Monolog logging:

14:30:16.000 [01-Jun-2017 21:30:16] WARNING: [pool app] child 62 said into stderr: "NOTICE: PHP message: env: 8"

14:30:16.000 [01-Jun-2017 21:30:16] WARNING: [pool app] child 62 said into stderr: "NOTICE: PHP message: dev_json: "

14:30:16.000 [01-Jun-2017 21:30:16] WARNING: [pool app] child 62 said into stderr: "NOTICE: PHP message: [INFO] php_info: 1024M"

case 2 - PsrBatchLogger logging (v1, before fix pcntl_signal issue, output to stdout/stderr) :

14:30:16.000 2017/06/01 21:30:16 [error] 54#0: *1321 FastCGI sent in stderr: "PHP message: env: 8

14:30:16.000 PHP message: dev_json:

14:30:16.000 PHP message: [INFO] php_info: 1024M

case 3 - PsrBatchLogger logging (v2, after fix pcntl_signal issue, output under the request) :

14:17:30.549 GET 200 44B 90ms Chrome 58 /TestController/Test/index

 (i) 14:17:28.998 env: 8

 (i) 14:17:28.998 dev_json:

 (i) 14:17:28.998 php_info: 1024M

[Takashi Matsuo]

Hi Yao,

On Thu, Jun 1, 2017 at 2:46 PM Yao Li <y...@sazze.com> wrote:

1. I tested gcr.io/google-appengine/php71 and PsrBatchLogger works on production, I will test more to make sure it doesn't influence performance too much.

Great to hear :)

Please feel free to ask how to configure the logger.

 

2. I tested Monolog as well in production and it prints very fast but not under the request call (case 1) because it outputs to stdout/stderr. Is there any way to use Monolog to achieve the format when use PsrBatchLogger? (my production site has tons of traffic, Monolog prints locally and it's perfect if it can have pretty format like case 3)

Unfortunately it's not possible with stdout/stderr.

Out of curiosity, how much traffic do you get (directly send me the number if you prefer it)?

-- Takashi

 

To view this discussion on the web visit https://groups.google.com/d/msgid/google-appengine/52e74371-abc9-460e-b653-8700b43a1f33%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

-- Takashi