2

I am deploying a nodejs server (graphql) application on GCloud AppEngine standard environment and occasionally the first requests fail but the subsequent ones (within 5s) work . I am using the following configuration: 

runtime: nodejs10
instance_class: F2
service: ...
env_variables:
  ...
  ...

and the logs are as follows (see last few lines for the 404s): 

OPTIONS 204 310 B 4.1 s Chrome 71 /graphql OPTIONS 204 310 B 4.1 s Chrome 71 
OPTIONS 204 310 B 4.1 s Chrome 71 /graphql OPTIONS 204 310 B 4.1 s Chrome 71 
[start] 2019/01/18 20:46:21.506468 no entrypoint specified, using default entrypoint: /serve 
[start] 2019/01/18 20:46:21.511900 no entrypoint specified, using default entrypoint: /serve 
[start] 2019/01/18 20:46:21.539860 starting app 
[start] 2019/01/18 20:46:21.540272 Executing: /bin/sh -c exec /serve 
[start] 2019/01/18 20:46:21.540122 starting app 
[start] 2019/01/18 20:46:21.540403 Executing: /bin/sh -c exec /serve 
[start] 2019/01/18 20:46:21.560976 waiting for network connection open. subject:"app/invalid" Address:127.0.0.1:8080 
[start] 2019/01/18 20:46:21.561742 waiting for network connection open. subject:"app/valid" Address:127.0.0.1:8081 
[start] 2019/01/18 20:46:21.561786 waiting for network connection open. subject:"app/invalid" Address:127.0.0.1:8080 
[start] 2019/01/18 20:46:21.562055 waiting for network connection open. subject:"app/valid" Address:127.0.0.1:8081 
[serve] 2019/01/18 20:46:21.586374 serve started 
[serve] 2019/01/18 20:46:21.586831 args: {runtimeName:nodejs10 memoryMB:256 positional:[]} 
[serve] 2019/01/18 20:46:21.587680 serve started 
[serve] 2019/01/18 20:46:21.588167 args: {runtimeName:nodejs10 memoryMB:256 positional:[]} 
[serve] 2019/01/18 20:46:21.593780 execing to: /bin/sh -c exec node ./dist/index.js 
[serve] 2019/01/18 20:46:21.594081 execing to: /bin/sh -c exec node ./dist/index.js 
[start] 2019/01/18 20:46:25.122334 wait successful. subject:"app/valid" Address:127.0.0.1:8081 attempts:701 elapsed:3.560382686s 
[start] 2019/01/18 20:46:25.122604 starting nginx 
Go to http://localhost:8081/graphql to run queries! 
[start] 2019/01/18 20:46:25.127939 wait successful. subject:"app/valid" Address:127.0.0.1:8081 attempts:687 elapsed:3.56541476s 
[start] 2019/01/18 20:46:25.128135 starting nginx 
[start] 2019/01/18 20:46:25.128836 waiting for network connection open. subject:"nginx" Address:127.0.0.1:8080 
Go to http://localhost:8081/graphql to run queries! 
[start] 2019/01/18 20:46:25.163712 waiting for network connection open. subject:"nginx" Address:127.0.0.1:8080 
[start] 2019/01/18 20:46:25.179456 wait successful. subject:"nginx" Address:127.0.0.1:8080 attempts:6 elapsed:50.397788ms 
[start] 2019/01/18 20:46:25.184531 wait successful. subject:"nginx" Address:127.0.0.1:8080 attempts:4 elapsed:20.559325ms 
2019/01/18 20:46:25 [alert] 33#33: prctl(PR_SET_DUMPABLE) failed (22: Invalid argument) 
2019/01/18 20:46:25 [alert] 33#33: prctl(PR_SET_DUMPABLE) failed (22: Invalid argument) 
POST 404 505 B 176 ms Chrome 71 /graphql POST 404 505 B 176 ms Chrome 71 
POST 404 505 B 185 ms Chrome 71 /graphql POST 404 505 B 185 ms Chrome 71 
OPTIONS 204 310 B 4 ms Chrome 71 /graphql OPTIONS 204 310 B 4 ms Chrome 71 
POST 200 679 B 73 ms Chrome 71 /graphql POST 200 679 B 73 ms Chrome 71 
OPTIONS 204 310 B 3 ms Chrome 71 /graphql OPTIONS 204 310 B 3 ms Chrome 71 
POST 200 651 B 61 ms Chrome 71 /graphql POST 200 651 B 61 ms Chrome 71 
OPTIONS 204 310 B 4 ms Chrome 71 /graphql OPTIONS 204 310 B 4 ms Chrome 71 
OPTIONS 204 310 B 2 ms Chrome 71 /graphql OPTIONS 204 310 B 2 ms Chrome 71 
POST 200 677 B 131 ms Chrome 71 /graphql POST 200 677 B 131 ms Chrome 71 
POST 200 653 B 127 ms Chrome 71 /graphql POST 200 653 B 127 ms Chrome 71

Anyone know what could be going wrong? Thanks

skay-
  • 1,546
  • 3
  • 16
  • 26

1 Answers1

0

I suppose you are referring to below log entries. you say this happens occasionally, is there some pattern of occurence? What are your queries made of? From the logs, it looks like these two requests are the first ones after deploy, maybe they fail as the app is not fully serving, or the traffic still redirecting from previous version. Do you encounter these errors while the app is already deployed or only after a new deployment?

POST 404 505 B 176 ms Chrome 71 /graphql POST 404 505 B 176 ms Chrome 71 
POST 404 505 B 185 ms Chrome 71 /graphql POST 404 505 B 185 ms Chrome 71
alp
  • 642
  • 5
  • 13
  • 1
    The pattern is that they appear after the app is scaled down to 0 instances and it needs to scale up when it receives the first request. So its part of Standard Environment instance management. – skay- Jan 30 '19 at 19:32
  • ok so it's normal warming artefacts, you can get around this by keeping 1 instance running at all times, or scale up before traffic is on. – alp Jan 31 '19 at 08:14