[Glass] Nginx , FastCGI and GLASS problem

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
25 messages Options
12
Reply | Threaded
Open this post in threaded view
|

[Glass] Nginx , FastCGI and GLASS problem

Mariano Martinez Peck
HI guys. This is the first time I am trying to use FastCGI. For some reason, i have a timeout with fastCGI.
I started the Gems either with:


WAGemStoneRunSeasideGems default
        name: 'FastCGI';
        adaptorClass: WAFastCGIAdaptor;
        ports: #(9001 9002 9003).
WAGemStoneRunSeasideGems restartGems.

(from GemTools) or from command line:

./startSeaside_FastCGI 9001

In either case, what happens is that I can browse my app http:localhost:9001/dp (and 9002 and 9003). But when I do a request to the server trough my FastCGI, it takes ONE MINUTE to load the page. I am using Nginx in the backend with this configuration:

    upstream seaside 
      {
        server localhost:9001;
        server localhost:9002;
        server localhost:9003;
      }
 
      server
      {
 
listen 33300;
server_name localhost; 
        root /var/www/glass/;


   access_log  /var/log/nginx/fastCGI.log;
   error_log  /var/log/nginx/error.log info;
 
        location /
        { 
            try_files $uri @seaside;
 #  error_page 403 404 = @seaside;
        }
     
        location @seaside
        {
          include fastcgi_params;
          fastcgi_pass seaside;
        }
      }


Using the webtools of the browser, I see that each time I go to a page, there is either a GET or a POST that takes exactly 1 minute. I mean...nothing happens, until one minute passes and then the page is rendered. The requests are small.  And in fact, browsing directly to 9001/2/3 works perfectly. So I guess this is a one minute timeout of something.

For what I can see, it could be related to the 

 keepalive_timeout  65;

And in nginx error.log I see something like:

2013/11/25 17:38:18 [error] 22835#0: *73 upstream timed out (60: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request: "GET /dp HTTP/1.1", upstream: "fastcgi://127.0.0.1:9001", host: "localhost:33300"
2013/11/25 17:38:18 [info] 22835#0: *73 kevent() reported that client 127.0.0.1 closed keepalive connection

Any ideas what could be wrong?


Thanks!

--
Mariano
http://marianopeck.wordpress.com

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Reply | Threaded
Open this post in threaded view
|

Re: [Glass] Nginx , FastCGI and GLASS problem

Mariano Martinez Peck
Also, when I see that 1-minute request in the browser development tools, it appears like 2ms receiving, 1 minute waiting...weird!


On Mon, Nov 25, 2013 at 8:26 PM, Mariano Martinez Peck <[hidden email]> wrote:
HI guys. This is the first time I am trying to use FastCGI. For some reason, i have a timeout with fastCGI.
I started the Gems either with:


WAGemStoneRunSeasideGems default
        name: 'FastCGI';
        adaptorClass: WAFastCGIAdaptor;
        ports: #(9001 9002 9003).
WAGemStoneRunSeasideGems restartGems.

(from GemTools) or from command line:

./startSeaside_FastCGI 9001

In either case, what happens is that I can browse my app http:localhost:9001/dp (and 9002 and 9003). But when I do a request to the server trough my FastCGI, it takes ONE MINUTE to load the page. I am using Nginx in the backend with this configuration:

    upstream seaside 
      {
        server localhost:9001;
        server localhost:9002;
        server localhost:9003;
      }
 
      server
      {
 
listen 33300;
server_name localhost; 
        root /var/www/glass/;


   access_log  /var/log/nginx/fastCGI.log;
   error_log  /var/log/nginx/error.log info;
 
        location /
        { 
            try_files $uri @seaside;
 #  error_page 403 404 = @seaside;
        }
     
        location @seaside
        {
          include fastcgi_params;
          fastcgi_pass seaside;
        }
      }


Using the webtools of the browser, I see that each time I go to a page, there is either a GET or a POST that takes exactly 1 minute. I mean...nothing happens, until one minute passes and then the page is rendered. The requests are small.  And in fact, browsing directly to 9001/2/3 works perfectly. So I guess this is a one minute timeout of something.

For what I can see, it could be related to the 

 keepalive_timeout  65;

And in nginx error.log I see something like:

2013/11/25 17:38:18 [error] 22835#0: *73 upstream timed out (60: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request: "GET /dp HTTP/1.1", upstream: "fastcgi://127.0.0.1:9001", host: "localhost:33300"
2013/11/25 17:38:18 [info] 22835#0: *73 kevent() reported that client 127.0.0.1 closed keepalive connection

Any ideas what could be wrong?


Thanks!

--
Mariano
http://marianopeck.wordpress.com



--
Mariano
http://marianopeck.wordpress.com

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Reply | Threaded
Open this post in threaded view
|

Re: [Glass] Nginx , FastCGI and GLASS problem

Mariano Martinez Peck
HI john,

Thanks for the suggestion. I have commented those lines but still same problem :(

I attach an screenshot of the web developer. As you can see, there is a GET and a POST. The post takes always 1 minute. 

Sometimes the delay is in a GET, not a POST....




On Mon, Nov 25, 2013 at 10:02 PM, John McIntosh <[hidden email]> wrote:

Ok well maybe it's the compression bug? 


WAFastCGIAdaptor>>responseFrom: ....

-- comment out the Content-length attribute... 

"*** FastCGI 2.4.4 and 2.4.6 have a bug in which Content-length for compressed data 
is reported at the uncompressed length. This often causes significant delays while
the client browser waits to get the remaining data. Although content-length should
be supplied by the HTTP server to the client, the FastCGI solution is to drop it!
nextPutAll: 'Content-length: ';
nextPutAll: contents size printString;
nextPutAll: crlf;"



On Mon, Nov 25, 2013 at 6:33 PM, Mariano Martinez Peck <[hidden email]> wrote:
Also, when I see that 1-minute request in the browser development tools, it appears like 2ms receiving, 1 minute waiting...weird!


On Mon, Nov 25, 2013 at 8:26 PM, Mariano Martinez Peck <[hidden email]> wrote:
HI guys. This is the first time I am trying to use FastCGI. For some reason, i have a timeout with fastCGI.
I started the Gems either with:


WAGemStoneRunSeasideGems default
        name: 'FastCGI';
        adaptorClass: WAFastCGIAdaptor;
        ports: #(9001 9002 9003).
WAGemStoneRunSeasideGems restartGems.

(from GemTools) or from command line:

./startSeaside_FastCGI 9001

In either case, what happens is that I can browse my app http:localhost:9001/dp (and 9002 and 9003). But when I do a request to the server trough my FastCGI, it takes ONE MINUTE to load the page. I am using Nginx in the backend with this configuration:

    upstream seaside 
      {
        server localhost:9001;
        server localhost:9002;
        server localhost:9003;
      }
 
      server
      {
 
listen 33300;
server_name localhost; 
        root /var/www/glass/;


   access_log  /var/log/nginx/fastCGI.log;
   error_log  /var/log/nginx/error.log info;
 
        location /
        { 
            try_files $uri @seaside;
 #  error_page 403 404 = @seaside;
        }
     
        location @seaside
        {
          include fastcgi_params;
          fastcgi_pass seaside;
        }
      }


Using the webtools of the browser, I see that each time I go to a page, there is either a GET or a POST that takes exactly 1 minute. I mean...nothing happens, until one minute passes and then the page is rendered. The requests are small.  And in fact, browsing directly to 9001/2/3 works perfectly. So I guess this is a one minute timeout of something.

For what I can see, it could be related to the 

 keepalive_timeout  65;

And in nginx error.log I see something like:

2013/11/25 17:38:18 [error] 22835#0: *73 upstream timed out (60: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request: "GET /dp HTTP/1.1", upstream: "fastcgi://127.0.0.1:9001", host: "localhost:33300"
2013/11/25 17:38:18 [info] 22835#0: *73 kevent() reported that client 127.0.0.1 closed keepalive connection

Any ideas what could be wrong?


Thanks!

--
Mariano
http://marianopeck.wordpress.com



--
Mariano
http://marianopeck.wordpress.com

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass




--
===========================================================================
John M. McIntosh <[hidden email]>
Corporate Smalltalk Consulting Ltd. Twitter: squeaker68882
===========================================================================




--
Mariano
http://marianopeck.wordpress.com

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass

Screen Shot 2013-11-25 at 10.36.15 PM.png (69K) Download Attachment
Screen Shot 2013-11-25 at 10.32.54 PM.png (67K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: [Glass] Nginx , FastCGI and GLASS problem

Mariano Martinez Peck
Thanks John,

Yes, I saw his post. I am using a similar configuration. Just a few minutes ago, I shut down GemStone, start everything again from scratch and somehow it seems to work correct now.
So I don't know what happened hahhaa.

btw... I noticed these lines:

        location ~* ^.+\.(css|js|jpg|jpeg|gif|png|ico|svg)$ {
                add_header Access-Control-Allow-Origin "*"; 
                expires max;
                add_header Cache-Control "public, must-revalidate, proxy-revalidate";
                add_header Pragma public;
        }


I wanted to add that but there is a problem...if the file (say a css) is not found in the server (try_files failes), then the request is not forwarded to fast_cgi so the file is not loaded at all. 

Is there a way to fallback to /files and use FileLibraries in case those fails?  or is it better for production systems to remove the app under /files and be sure everything is served by the web server?

Thanks!







On Mon, Nov 25, 2013 at 11:18 PM, John McIntosh <[hidden email]> wrote:
Ok well Paul had this which is different from your setup.
I've an apache setup, but going to migrate to nginx as we use it everywhere else. 


upstream seaside {
         server localhost:9001;
         server localhost:9002;
         server localhost:9003;
}


server {
       listen 80 default_server;
       server_name www.example.com example.com;
       root /var/www/www.example.com;

        gzip on;
        gzip_disable "msie6";
        gzip_static on;
        gzip_vary on;
        gzip_proxied any;
        gzip_comp_level 6;
        gzip_buffers 16 8k;
        gzip_http_version 1.1;
        gzip_types text/plain text/css application/json application/x-javascript text/xml application/xml application/xml+rss text/javascript image/svg+xml;



       location @fastCgi {
           include fastcgi_params;
           fastcgi_pass seaside;
        }

        location / {
                 try_files $uri @fastCgi;
        }

        location ~* ^.+\.(css|js|jpg|jpeg|gif|png|ico|svg)$ {
                add_header Access-Control-Allow-Origin http://www.example.com ;
                expires max;
                add_header Cache-Control "public, must-revalidate, proxy-revalidate";
                add_header Pragma public;
        }
}


On Mon, Nov 25, 2013 at 8:46 PM, Mariano Martinez Peck <[hidden email]> wrote:
HI john,

Thanks for the suggestion. I have commented those lines but still same problem :(

I attach an screenshot of the web developer. As you can see, there is a GET and a POST. The post takes always 1 minute. 

Sometimes the delay is in a GET, not a POST....




On Mon, Nov 25, 2013 at 10:02 PM, John McIntosh <[hidden email]> wrote:

Ok well maybe it's the compression bug? 


WAFastCGIAdaptor>>responseFrom: ....

-- comment out the Content-length attribute... 

"*** FastCGI 2.4.4 and 2.4.6 have a bug in which Content-length for compressed data 
is reported at the uncompressed length. This often causes significant delays while
the client browser waits to get the remaining data. Although content-length should
be supplied by the HTTP server to the client, the FastCGI solution is to drop it!
nextPutAll: 'Content-length: ';
nextPutAll: contents size printString;
nextPutAll: crlf;"



On Mon, Nov 25, 2013 at 6:33 PM, Mariano Martinez Peck <[hidden email]> wrote:
Also, when I see that 1-minute request in the browser development tools, it appears like 2ms receiving, 1 minute waiting...weird!


On Mon, Nov 25, 2013 at 8:26 PM, Mariano Martinez Peck <[hidden email]> wrote:
HI guys. This is the first time I am trying to use FastCGI. For some reason, i have a timeout with fastCGI.
I started the Gems either with:


WAGemStoneRunSeasideGems default
        name: 'FastCGI';
        adaptorClass: WAFastCGIAdaptor;
        ports: #(9001 9002 9003).
WAGemStoneRunSeasideGems restartGems.

(from GemTools) or from command line:

./startSeaside_FastCGI 9001

In either case, what happens is that I can browse my app http:localhost:9001/dp (and 9002 and 9003). But when I do a request to the server trough my FastCGI, it takes ONE MINUTE to load the page. I am using Nginx in the backend with this configuration:

    upstream seaside 
      {
        server localhost:9001;
        server localhost:9002;
        server localhost:9003;
      }
 
      server
      {
 
listen 33300;
server_name localhost; 
        root /var/www/glass/;


   access_log  /var/log/nginx/fastCGI.log;
   error_log  /var/log/nginx/error.log info;
 
        location /
        { 
            try_files $uri @seaside;
 #  error_page 403 404 = @seaside;
        }
     
        location @seaside
        {
          include fastcgi_params;
          fastcgi_pass seaside;
        }
      }


Using the webtools of the browser, I see that each time I go to a page, there is either a GET or a POST that takes exactly 1 minute. I mean...nothing happens, until one minute passes and then the page is rendered. The requests are small.  And in fact, browsing directly to 9001/2/3 works perfectly. So I guess this is a one minute timeout of something.

For what I can see, it could be related to the 

 keepalive_timeout  65;

And in nginx error.log I see something like:

2013/11/25 17:38:18 [error] 22835#0: *73 upstream timed out (60: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request: "GET /dp HTTP/1.1", upstream: "fastcgi://127.0.0.1:9001", host: "localhost:33300"
2013/11/25 17:38:18 [info] 22835#0: *73 kevent() reported that client 127.0.0.1 closed keepalive connection

Any ideas what could be wrong?


Thanks!

--
Mariano
http://marianopeck.wordpress.com



--
Mariano
http://marianopeck.wordpress.com

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass




--
===========================================================================
John M. McIntosh <[hidden email]>
Corporate Smalltalk Consulting Ltd. Twitter: squeaker68882
===========================================================================




--
Mariano
http://marianopeck.wordpress.com



--
===========================================================================
John M. McIntosh <[hidden email]>
Corporate Smalltalk Consulting Ltd. Twitter: squeaker68882
===========================================================================




--
Mariano
http://marianopeck.wordpress.com

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Reply | Threaded
Open this post in threaded view
|

Re: [Glass] Nginx , FastCGI and GLASS problem

Paul DeBruicker
Those lines from the config just add expiration headers to the files with extensions in the list.  

I wonder if you change your try_files line to

try_files $uri files/$uri @seaside;

it will do what you want.  Maybe you'll need /files/$uri instead of files/$uri .  From the docs [1] I'm not sure if nginx will let you prefix the $uri parameter.  

http://nginx.org/en/docs/http/ngx_http_core_module.html#try_files



Hope this helps

Paul

Mariano Martinez Peck wrote
Thanks John,

Yes, I saw his post. I am using a similar configuration. Just a few minutes
ago, I shut down GemStone, start everything again from scratch and somehow
it seems to work correct now.
So I don't know what happened hahhaa.

btw... I noticed these lines:

        location ~* ^.+\.(css|js|jpg|jpeg|gif|png|ico|svg)$ {
                add_header Access-Control-Allow-Origin "*";
                expires max;
                add_header Cache-Control "public, must-revalidate,
proxy-revalidate";
                add_header Pragma public;
        }


I wanted to add that but there is a problem...if the file (say a css) is
not found in the server (try_files failes), then the request is not
forwarded to fast_cgi so the file is not loaded at all.

Is there a way to fallback to /files and use FileLibraries in case those
fails?  or is it better for production systems to remove the app under
/files and be sure everything is served by the web server?

Thanks!
Reply | Threaded
Open this post in threaded view
|

Re: [Glass] Nginx , FastCGI and GLASS problem

Johan Brichau-3
In reply to this post by Mariano Martinez Peck
Mariano,

I would guess not all fastcgi gems are running correctly on all ports.
There is a default timeout of 60s in nginx before it will pass a fastcgi request to another port in the upstream configuration. 

The reason you see the delay with the post and not with the following get might be because nginx is doing a round-trip load balance over the fastcgi backends and one request goes to a working port but the next is not (or vice-versa).

You might want to experiment by limiting the nginx conf to a single fastcgi backend and/or change the default timeout and put some logging code in your app when the request gets to seaside. That would at least allow to find on what to focus.

Johan

On 26 Nov 2013, at 00:33, Mariano Martinez Peck <[hidden email]> wrote:

Also, when I see that 1-minute request in the browser development tools, it appears like 2ms receiving, 1 minute waiting...weird!


On Mon, Nov 25, 2013 at 8:26 PM, Mariano Martinez Peck <[hidden email]> wrote:
HI guys. This is the first time I am trying to use FastCGI. For some reason, i have a timeout with fastCGI.
I started the Gems either with:


WAGemStoneRunSeasideGems default
        name: 'FastCGI';
        adaptorClass: WAFastCGIAdaptor;
        ports: #(9001 9002 9003).
WAGemStoneRunSeasideGems restartGems.

(from GemTools) or from command line:

./startSeaside_FastCGI 9001

In either case, what happens is that I can browse my app http:localhost:9001/dp (and 9002 and 9003). But when I do a request to the server trough my FastCGI, it takes ONE MINUTE to load the page. I am using Nginx in the backend with this configuration:

    upstream seaside 
      {
        server localhost:9001;
        server localhost:9002;
        server localhost:9003;
      }
 
      server
      {
 
listen 33300;
server_name localhost; 
        root /var/www/glass/;


   access_log  /var/log/nginx/fastCGI.log;
   error_log  /var/log/nginx/error.log info;
 
        location /
        { 
            try_files $uri @seaside;
 #  error_page 403 404 = @seaside;
        }
     
        location @seaside
        {
          include fastcgi_params;
          fastcgi_pass seaside;
        }
      }


Using the webtools of the browser, I see that each time I go to a page, there is either a GET or a POST that takes exactly 1 minute. I mean...nothing happens, until one minute passes and then the page is rendered. The requests are small.  And in fact, browsing directly to 9001/2/3 works perfectly. So I guess this is a one minute timeout of something.

For what I can see, it could be related to the 

 keepalive_timeout  65;

And in nginx error.log I see something like:

2013/11/25 17:38:18 [error] 22835#0: *73 upstream timed out (60: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request: "GET /dp HTTP/1.1", upstream: "fastcgi://127.0.0.1:9001", host: "localhost:33300"
2013/11/25 17:38:18 [info] 22835#0: *73 kevent() reported that client 127.0.0.1 closed keepalive connection

Any ideas what could be wrong?


Thanks!

--
Mariano
http://marianopeck.wordpress.com



--
Mariano
http://marianopeck.wordpress.com
_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Reply | Threaded
Open this post in threaded view
|

Re: [Glass] Nginx , FastCGI and GLASS problem

Johan Brichau-3
Reading through your email again, since you say the fastcgi's are running correctly: can you leave out the try_files and make the / location pass on to the fastcgi directly?

I wonder if that would change anything.

Johan

On 26 Nov 2013, at 07:22, Johan Brichau <[hidden email]> wrote:

> Mariano,
>
> I would guess not all fastcgi gems are running correctly on all ports.
> There is a default timeout of 60s in nginx before it will pass a fastcgi request to another port in the upstream configuration.
>
> The reason you see the delay with the post and not with the following get might be because nginx is doing a round-trip load balance over the fastcgi backends and one request goes to a working port but the next is not (or vice-versa).
>
> You might want to experiment by limiting the nginx conf to a single fastcgi backend and/or change the default timeout and put some logging code in your app when the request gets to seaside. That would at least allow to find on what to focus.
>
> Johan
>
> On 26 Nov 2013, at 00:33, Mariano Martinez Peck <[hidden email]> wrote:
>
>> Also, when I see that 1-minute request in the browser development tools, it appears like 2ms receiving, 1 minute waiting...weird!
>>
>>
>> On Mon, Nov 25, 2013 at 8:26 PM, Mariano Martinez Peck <[hidden email]> wrote:
>> HI guys. This is the first time I am trying to use FastCGI. For some reason, i have a timeout with fastCGI.
>> I started the Gems either with:
>>
>>
>> WAGemStoneRunSeasideGems default
>>         name: 'FastCGI';
>>         adaptorClass: WAFastCGIAdaptor;
>>         ports: #(9001 9002 9003).
>> WAGemStoneRunSeasideGems restartGems.
>>
>> (from GemTools) or from command line:
>>
>> ./startSeaside_FastCGI 9001
>>
>> In either case, what happens is that I can browse my app http:localhost:9001/dp (and 9002 and 9003). But when I do a request to the server trough my FastCGI, it takes ONE MINUTE to load the page. I am using Nginx in the backend with this configuration:
>>
>>     upstream seaside
>>       {
>>         server localhost:9001;
>>         server localhost:9002;
>>         server localhost:9003;
>>       }
>>  
>>       server
>>       {
>>  
>> listen 33300;
>> server_name localhost;
>>         root /var/www/glass/;
>>
>>
>>    access_log  /var/log/nginx/fastCGI.log;
>>    error_log  /var/log/nginx/error.log info;
>>  
>>         location /
>>         {
>>             try_files $uri @seaside;
>>  #  error_page 403 404 = @seaside;
>>         }
>>      
>>         location @seaside
>>         {
>>           include fastcgi_params;
>>           fastcgi_pass seaside;
>>         }
>>       }
>>
>>
>> Using the webtools of the browser, I see that each time I go to a page, there is either a GET or a POST that takes exactly 1 minute. I mean...nothing happens, until one minute passes and then the page is rendered. The requests are small.  And in fact, browsing directly to 9001/2/3 works perfectly. So I guess this is a one minute timeout of something.
>>
>> For what I can see, it could be related to the
>>
>>  keepalive_timeout  65;
>>
>> And in nginx error.log I see something like:
>>
>> 2013/11/25 17:38:18 [error] 22835#0: *73 upstream timed out (60: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request: "GET /dp HTTP/1.1", upstream: "fastcgi://127.0.0.1:9001", host: "localhost:33300"
>> 2013/11/25 17:38:18 [info] 22835#0: *73 kevent() reported that client 127.0.0.1 closed keepalive connection
>>
>> Any ideas what could be wrong?
>>
>>
>> Thanks!
>>
>> --
>> Mariano
>> http://marianopeck.wordpress.com
>>
>>
>>
>> --
>> Mariano
>> http://marianopeck.wordpress.com
>> _______________________________________________
>> Glass mailing list
>> [hidden email]
>> http://lists.gemtalksystems.com/mailman/listinfo/glass

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Reply | Threaded
Open this post in threaded view
|

Re: [Glass] Nginx , FastCGI and GLASS problem

Mariano Martinez Peck
In reply to this post by Johan Brichau-3



On Tue, Nov 26, 2013 at 3:22 AM, Johan Brichau <[hidden email]> wrote:
Mariano,

I would guess not all fastcgi gems are running correctly on all ports.
There is a default timeout of 60s in nginx before it will pass a fastcgi request to another port in the upstream configuration. 

The reason you see the delay with the post and not with the following get might be because nginx is doing a round-trip load balance over the fastcgi backends and one request goes to a working port but the next is not (or vice-versa).

You might want to experiment by limiting the nginx conf to a single fastcgi backend and/or change the default timeout and put some logging code in your app when the request gets to seaside. That would at least allow to find on what to focus.



Thanks Johan, that was indeed the problem. This is the second time that happened to me. If I restart everything, it will probably be "fixed". But I don't want to do that to really fix the problem. So 9001 is answering correct, yet, 9002 yields timeone and 9003 yields could not connect after 1 minute.... I tried by doing:


So...the thing is how to know what the hell is happening that some of my gems (or  FastCGI adaptors) go down for some reason.
I have checked all my gemstone logs. 2 things look suspicious. FastCGI_server-9003.log shows that I have a button that updates my app code in GemStone which is causing this:

a RepositoryViewLost occurred (notification 3031), When running outside
of a transaction the session failed to respond quickly enough to a
request from Stone to abort.  All object caches have been cleared.
nil

Then,there are some:  ----------- Commit failure - retrying LOG ENTRY: aSymbolDictionary-----------

Here is the pieces of logs I could rescue. Maybe someone could help me figure out what is happening!

Thanks in advance!!


seaside_2485pcmon.log

[12/04/13 02:17:21.210 EST]: Client died: Slot   12, PID    2743, LostOtFlags    0, Name FastCGI-11-DataCurator
[12/04/13 02:17:21.210 EST]: Starting crashed client recovery: Slot 12, PID 2743, Name FastCGI-11-DataCurator
    Cleaned up locked/pinned frame 550 for crashed process 2743
    Cleaned up locked/pinned frame 11545 for crashed process 2743
    Cleaned up locked/pinned frame 3929 for crashed process 2743
    Cleaned up locked/pinned frame 11407 for crashed process 2743
    Disposing free frame cache from slot 12:  4 of 4 frames recovered.
[12/04/13 02:17:23.451 EST]: Finished crashed client recovery: Slot 12, PID 2743, Name FastCGI-11-DataCurator


FastCGI_server-9001.log  (which is the only gem/adaptor that seems to be working)

paz 1> topaz 1> topaz 1> topaz 1> FastCGI Server started on port 9001
-----------  Unreportable ERROR Encountered: 2013-12-03T22:52:06.46091294288635-08:00UserDefinedError: send(16,0x7f352f6ebba8,7416,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2013-12-03T22:53:06.45396900177002-08:00UserDefinedError: send(17,0x7f352f786110,7416,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2013-12-03T23:05:07.57434701919556-08:00UserDefinedError: send(14,0x7f352f65e6c0,2673,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2013-12-03T23:05:31.43626189231873-08:00UserDefinedError: send(15,0x7f352f6bed60,2673,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2013-12-03T23:14:13.39595103263855-08:00UserDefinedError: send(16,0x7f352f71f7e0,2673,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2013-12-03T23:15:13.47269105911255-08:00UserDefinedError: send(17,0x7f352f77ff90,2673,0) failed with errno=107,ENOTCONN, Socket is not connected-----------


FastCGI_server-9002.log

failure
Read-Write Conflicts...
Write-Write Conflicts...
    383168257
Write-Dependency Conflicts...
Write-ReadLock Conflicts...
Write-WriteLock Conflicts...
Rc-Write-Write Conflicts...
Synchronized-Commit Conflicts...
----------- Commit failure - retrying LOG ENTRY: aSymbolDictionary-----------
failure
Read-Write Conflicts...
Write-Write Conflicts...
    383168257
Write-Dependency Conflicts...
Write-ReadLock Conflicts...
Write-WriteLock Conflicts...
Rc-Write-Write Conflicts...
Synchronized-Commit Conflicts...
----------- Commit failure - retrying LOG ENTRY: aSymbolDictionary-----------
-----------  Unreportable ERROR Encountered: 2013-12-04T04:36:49.04186797142029-08:00UserDefinedError: send(16,0x7f21f9462268,2673,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2013-12-04T04:36:49.0669538974762-08:00UserDefinedError: send(17,0x7f21f94ed6c8,2673,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2013-12-04T04:36:49.10030889511108-08:00UserDefinedError: send(18,0x7f21f9551ae8,2673,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2013-12-04T04:36:49.11388611793518-08:00UserDefinedError: send(14,0x7f21f95b2918,2673,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2013-12-04T04:36:49.12687110900879-08:00UserDefinedError: send(19,0x7f21f96184e8,2673,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2013-12-04T04:36:49.12758493423462-08:00UserDefinedError: Incorrect FCGI version. Expected: 1 Received: 71-----------
-----------  Unreportable ERROR Encountered: 2013-12-04T04:36:49.15798401832581-08:00UserDefinedError: send(15,0x7f21f968f7d8,2673,0) failed with errno=107,ENOTCONN, Socket is not connected-----------



FastCGI_server-9003.log


--transcript--'...finished 1.4-baseline'
failure
Read-Write Conflicts...
Write-Write Conflicts...
    288128769
    294245633
Write-Dependency Conflicts...
Write-ReadLock Conflicts...
Write-WriteLock Conflicts...
Rc-Write-Write Conflicts...
Synchronized-Commit Conflicts...
----------- Commit failure - retrying LOG ENTRY: aSymbolDictionary-----------
-----------------------------------------------------
GemStone: Error         Nonfatal
a RepositoryViewLost occurred (notification 3031), When running outside
of a transaction the session failed to respond quickly enough to a
request from Stone to abort.  All object caches have been cleared.
nil
Error Category: 231169 [GemStone] Number: 3031  Arg Count: 1 Context : 318063361 exception : 318063105
Arg 1: [20 sz:0 cls: 76289 UndefinedObject] nil
topaz > exec iferr 1 : where
==> 1 AbstractException >> _signalWith:             (envId 0) @6 line 25   [methId 4496129]
2 [] in  AbstractException >> _signalAsync      (envId 0) @2 line 19   [methId 4605185]
3 ExecBlock >> ensure:                          (envId 0) @2 line 12   [methId 3709185]
4 AbstractException >> _signalAsync             (envId 0) @6 line 21   [methId 4600321]
5 ProcessorScheduler >> _reapEvents:            (envId 0) @96 line 86   [methId 4810241]
6 ProcessorScheduler >> _findReadyProcess:      (envId 0) @2 line 8   [methId 4815105]
7 ProcessorScheduler >> _reschedule             (envId 0) @3 line 8   [methId 4805121]
8 GsProcess >> _wait                            (envId 0) @3 line 3   [methId 4486145]
9 Delay >> _wait:                               (envId 0) @26 line 26   [methId 13285377]
10 Delay >> wait                                 (envId 0) @3 line 5   [methId 13307905]
11 [] in  Executed Code                          (envId 0) @3 line 32   [methId 318074625]
12 GsProcess >> _start                           (envId 0) @7 line 16   [methId 4467969]
13 GsNMethod class >> _gsReturnToC               (envId 0) @1 line 1   [methId 4461825]
  [GsProcess 318063361]
topaz 1> topaz 1> [268 sz:0 cls: 68097 Boolean] true






 
Johan

On 26 Nov 2013, at 00:33, Mariano Martinez Peck <[hidden email]> wrote:

Also, when I see that 1-minute request in the browser development tools, it appears like 2ms receiving, 1 minute waiting...weird!


On Mon, Nov 25, 2013 at 8:26 PM, Mariano Martinez Peck <[hidden email]> wrote:
HI guys. This is the first time I am trying to use FastCGI. For some reason, i have a timeout with fastCGI.
I started the Gems either with:


WAGemStoneRunSeasideGems default
        name: 'FastCGI';
        adaptorClass: WAFastCGIAdaptor;
        ports: #(9001 9002 9003).
WAGemStoneRunSeasideGems restartGems.

(from GemTools) or from command line:

./startSeaside_FastCGI 9001

In either case, what happens is that I can browse my app http:localhost:9001/dp (and 9002 and 9003). But when I do a request to the server trough my FastCGI, it takes ONE MINUTE to load the page. I am using Nginx in the backend with this configuration:

    upstream seaside 
      {
        server localhost:9001;
        server localhost:9002;
        server localhost:9003;
      }
 
      server
      {
 
listen 33300;
server_name localhost; 
        root /var/www/glass/;


   access_log  /var/log/nginx/fastCGI.log;
   error_log  /var/log/nginx/error.log info;
 
        location /
        { 
            try_files $uri @seaside;
 #  error_page 403 404 = @seaside;
        }
     
        location @seaside
        {
          include fastcgi_params;
          fastcgi_pass seaside;
        }
      }


Using the webtools of the browser, I see that each time I go to a page, there is either a GET or a POST that takes exactly 1 minute. I mean...nothing happens, until one minute passes and then the page is rendered. The requests are small.  And in fact, browsing directly to 9001/2/3 works perfectly. So I guess this is a one minute timeout of something.

For what I can see, it could be related to the 

 keepalive_timeout  65;

And in nginx error.log I see something like:

2013/11/25 17:38:18 [error] 22835#0: *73 upstream timed out (60: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request: "GET /dp HTTP/1.1", upstream: "fastcgi://127.0.0.1:9001", host: "localhost:33300"
2013/11/25 17:38:18 [info] 22835#0: *73 kevent() reported that client 127.0.0.1 closed keepalive connection

Any ideas what could be wrong?


Thanks!

--
Mariano
http://marianopeck.wordpress.com



--
Mariano
http://marianopeck.wordpress.com
_______________________________________________



--
Mariano
http://marianopeck.wordpress.com

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Reply | Threaded
Open this post in threaded view
|

Re: [Glass] Nginx , FastCGI and GLASS problem

Mariano Martinez Peck
ObjectLog, from yesterday:  FastCGI: topaz exit     Object: port: 9003 pid: 2743


And now, FastCGI of 9001 (gem 1)

Unreportable ERROR Encountered: 2013-12-04T07:22:54.77649903297424-08:00UserDefinedError: send(15,0x7f352f636400,49,0) failed with errno=107,ENOTCONN, Socket is not connected-----------

So I got this error in each of the gems....

Any idea? 



On Wed, Dec 4, 2013 at 9:56 AM, Mariano Martinez Peck <[hidden email]> wrote:



On Tue, Nov 26, 2013 at 3:22 AM, Johan Brichau <[hidden email]> wrote:
Mariano,

I would guess not all fastcgi gems are running correctly on all ports.
There is a default timeout of 60s in nginx before it will pass a fastcgi request to another port in the upstream configuration. 

The reason you see the delay with the post and not with the following get might be because nginx is doing a round-trip load balance over the fastcgi backends and one request goes to a working port but the next is not (or vice-versa).

You might want to experiment by limiting the nginx conf to a single fastcgi backend and/or change the default timeout and put some logging code in your app when the request gets to seaside. That would at least allow to find on what to focus.



Thanks Johan, that was indeed the problem. This is the second time that happened to me. If I restart everything, it will probably be "fixed". But I don't want to do that to really fix the problem. So 9001 is answering correct, yet, 9002 yields timeone and 9003 yields could not connect after 1 minute.... I tried by doing:


So...the thing is how to know what the hell is happening that some of my gems (or  FastCGI adaptors) go down for some reason.
I have checked all my gemstone logs. 2 things look suspicious. FastCGI_server-9003.log shows that I have a button that updates my app code in GemStone which is causing this:

a RepositoryViewLost occurred (notification 3031), When running outside
of a transaction the session failed to respond quickly enough to a
request from Stone to abort.  All object caches have been cleared.
nil

Then,there are some:  ----------- Commit failure - retrying LOG ENTRY: aSymbolDictionary-----------

Here is the pieces of logs I could rescue. Maybe someone could help me figure out what is happening!

Thanks in advance!!


seaside_2485pcmon.log

[12/04/13 02:17:21.210 EST]: Client died: Slot   12, PID    2743, LostOtFlags    0, Name FastCGI-11-DataCurator
[12/04/13 02:17:21.210 EST]: Starting crashed client recovery: Slot 12, PID 2743, Name FastCGI-11-DataCurator
    Cleaned up locked/pinned frame 550 for crashed process 2743
    Cleaned up locked/pinned frame 11545 for crashed process 2743
    Cleaned up locked/pinned frame 3929 for crashed process 2743
    Cleaned up locked/pinned frame 11407 for crashed process 2743
    Disposing free frame cache from slot 12:  4 of 4 frames recovered.
[12/04/13 02:17:23.451 EST]: Finished crashed client recovery: Slot 12, PID 2743, Name FastCGI-11-DataCurator


FastCGI_server-9001.log  (which is the only gem/adaptor that seems to be working)

paz 1> topaz 1> topaz 1> topaz 1> FastCGI Server started on port 9001
-----------  Unreportable ERROR Encountered: 2013-12-03T22:52:06.46091294288635-08:00UserDefinedError: send(16,0x7f352f6ebba8,7416,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2013-12-03T22:53:06.45396900177002-08:00UserDefinedError: send(17,0x7f352f786110,7416,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2013-12-03T23:05:07.57434701919556-08:00UserDefinedError: send(14,0x7f352f65e6c0,2673,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2013-12-03T23:05:31.43626189231873-08:00UserDefinedError: send(15,0x7f352f6bed60,2673,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2013-12-03T23:14:13.39595103263855-08:00UserDefinedError: send(16,0x7f352f71f7e0,2673,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2013-12-03T23:15:13.47269105911255-08:00UserDefinedError: send(17,0x7f352f77ff90,2673,0) failed with errno=107,ENOTCONN, Socket is not connected-----------


FastCGI_server-9002.log

failure
Read-Write Conflicts...
Write-Write Conflicts...
    383168257
Write-Dependency Conflicts...
Write-ReadLock Conflicts...
Write-WriteLock Conflicts...
Rc-Write-Write Conflicts...
Synchronized-Commit Conflicts...
----------- Commit failure - retrying LOG ENTRY: aSymbolDictionary-----------
failure
Read-Write Conflicts...
Write-Write Conflicts...
    383168257
Write-Dependency Conflicts...
Write-ReadLock Conflicts...
Write-WriteLock Conflicts...
Rc-Write-Write Conflicts...
Synchronized-Commit Conflicts...
----------- Commit failure - retrying LOG ENTRY: aSymbolDictionary-----------
-----------  Unreportable ERROR Encountered: 2013-12-04T04:36:49.04186797142029-08:00UserDefinedError: send(16,0x7f21f9462268,2673,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2013-12-04T04:36:49.0669538974762-08:00UserDefinedError: send(17,0x7f21f94ed6c8,2673,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2013-12-04T04:36:49.10030889511108-08:00UserDefinedError: send(18,0x7f21f9551ae8,2673,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2013-12-04T04:36:49.11388611793518-08:00UserDefinedError: send(14,0x7f21f95b2918,2673,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2013-12-04T04:36:49.12687110900879-08:00UserDefinedError: send(19,0x7f21f96184e8,2673,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2013-12-04T04:36:49.12758493423462-08:00UserDefinedError: Incorrect FCGI version. Expected: 1 Received: 71-----------
-----------  Unreportable ERROR Encountered: 2013-12-04T04:36:49.15798401832581-08:00UserDefinedError: send(15,0x7f21f968f7d8,2673,0) failed with errno=107,ENOTCONN, Socket is not connected-----------



FastCGI_server-9003.log


--transcript--'...finished 1.4-baseline'
failure
Read-Write Conflicts...
Write-Write Conflicts...
    288128769
    294245633
Write-Dependency Conflicts...
Write-ReadLock Conflicts...
Write-WriteLock Conflicts...
Rc-Write-Write Conflicts...
Synchronized-Commit Conflicts...
----------- Commit failure - retrying LOG ENTRY: aSymbolDictionary-----------
-----------------------------------------------------
GemStone: Error         Nonfatal
a RepositoryViewLost occurred (notification 3031), When running outside
of a transaction the session failed to respond quickly enough to a
request from Stone to abort.  All object caches have been cleared.
nil
Error Category: 231169 [GemStone] Number: 3031  Arg Count: 1 Context : 318063361 exception : 318063105
Arg 1: [20 sz:0 cls: 76289 UndefinedObject] nil
topaz > exec iferr 1 : where
==> 1 AbstractException >> _signalWith:             (envId 0) @6 line 25   [methId 4496129]
2 [] in  AbstractException >> _signalAsync      (envId 0) @2 line 19   [methId 4605185]
3 ExecBlock >> ensure:                          (envId 0) @2 line 12   [methId 3709185]
4 AbstractException >> _signalAsync             (envId 0) @6 line 21   [methId 4600321]
5 ProcessorScheduler >> _reapEvents:            (envId 0) @96 line 86   [methId 4810241]
6 ProcessorScheduler >> _findReadyProcess:      (envId 0) @2 line 8   [methId 4815105]
7 ProcessorScheduler >> _reschedule             (envId 0) @3 line 8   [methId 4805121]
8 GsProcess >> _wait                            (envId 0) @3 line 3   [methId 4486145]
9 Delay >> _wait:                               (envId 0) @26 line 26   [methId 13285377]
10 Delay >> wait                                 (envId 0) @3 line 5   [methId 13307905]
11 [] in  Executed Code                          (envId 0) @3 line 32   [methId 318074625]
12 GsProcess >> _start                           (envId 0) @7 line 16   [methId 4467969]
13 GsNMethod class >> _gsReturnToC               (envId 0) @1 line 1   [methId 4461825]
  [GsProcess 318063361]
topaz 1> topaz 1> [268 sz:0 cls: 68097 Boolean] true






 
Johan

On 26 Nov 2013, at 00:33, Mariano Martinez Peck <[hidden email]> wrote:

Also, when I see that 1-minute request in the browser development tools, it appears like 2ms receiving, 1 minute waiting...weird!


On Mon, Nov 25, 2013 at 8:26 PM, Mariano Martinez Peck <[hidden email]> wrote:
HI guys. This is the first time I am trying to use FastCGI. For some reason, i have a timeout with fastCGI.
I started the Gems either with:


WAGemStoneRunSeasideGems default
        name: 'FastCGI';
        adaptorClass: WAFastCGIAdaptor;
        ports: #(9001 9002 9003).
WAGemStoneRunSeasideGems restartGems.

(from GemTools) or from command line:

./startSeaside_FastCGI 9001

In either case, what happens is that I can browse my app http:localhost:9001/dp (and 9002 and 9003). But when I do a request to the server trough my FastCGI, it takes ONE MINUTE to load the page. I am using Nginx in the backend with this configuration:

    upstream seaside 
      {
        server localhost:9001;
        server localhost:9002;
        server localhost:9003;
      }
 
      server
      {
 
listen 33300;
server_name localhost; 
        root /var/www/glass/;


   access_log  /var/log/nginx/fastCGI.log;
   error_log  /var/log/nginx/error.log info;
 
        location /
        { 
            try_files $uri @seaside;
 #  error_page 403 404 = @seaside;
        }
     
        location @seaside
        {
          include fastcgi_params;
          fastcgi_pass seaside;
        }
      }


Using the webtools of the browser, I see that each time I go to a page, there is either a GET or a POST that takes exactly 1 minute. I mean...nothing happens, until one minute passes and then the page is rendered. The requests are small.  And in fact, browsing directly to 9001/2/3 works perfectly. So I guess this is a one minute timeout of something.

For what I can see, it could be related to the 

 keepalive_timeout  65;

And in nginx error.log I see something like:

2013/11/25 17:38:18 [error] 22835#0: *73 upstream timed out (60: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request: "GET /dp HTTP/1.1", upstream: "fastcgi://127.0.0.1:9001", host: "localhost:33300"
2013/11/25 17:38:18 [info] 22835#0: *73 kevent() reported that client 127.0.0.1 closed keepalive connection

Any ideas what could be wrong?


Thanks!

--
Mariano
http://marianopeck.wordpress.com



--
Mariano
http://marianopeck.wordpress.com
_______________________________________________



--
Mariano
http://marianopeck.wordpress.com



--
Mariano
http://marianopeck.wordpress.com

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Reply | Threaded
Open this post in threaded view
|

Re: [Glass] Nginx , FastCGI and GLASS problem

Paul DeBruicker
Sounds to me like you have an error in your Seaside app or your own code that kills your FastCGI gems.

In your Seaside app are you using the WAGemStoneProductionErrorHandler? If not, switch to it.  If so, are any errors getting put on the ObjectLog?



Do you have monit or daemontools monitoring your FastCGI gems to restart them automatically when they become unresponsive?




Mariano Martinez Peck wrote
ObjectLog, from yesterday:  FastCGI: topaz exit     Object: port: 9003 pid:
2743


And now, FastCGI of 9001 (gem 1)

Unreportable ERROR Encountered:
2013-12-04T07:22:54.77649903297424-08:00UserDefinedError:
send(15,0x7f352f636400,49,0) failed with errno=107,ENOTCONN, Socket is not
connected-----------

So I got this error in each of the gems....

Any idea?



On Wed, Dec 4, 2013 at 9:56 AM, Mariano Martinez Peck <[hidden email]
> wrote:

>
>
>
> On Tue, Nov 26, 2013 at 3:22 AM, Johan Brichau <[hidden email]> wrote:
>
>> Mariano,
>>
>> I would guess not all fastcgi gems are running correctly on all ports.
>> There is a default timeout of 60s in nginx before it will pass a fastcgi
>> request to another port in the upstream configuration.
>>
>> The reason you see the delay with the post and not with the following get
>> might be because nginx is doing a round-trip load balance over the fastcgi
>> backends and one request goes to a working port but the next is not (or
>> vice-versa).
>>
>> You might want to experiment by limiting the nginx conf to a single
>> fastcgi backend and/or change the default timeout and put some logging code
>> in your app when the request gets to seaside. That would at least allow to
>> find on what to focus.
>>
>>
>
> Thanks Johan, that was indeed the problem. This is the second time that
> happened to me. If I restart everything, it will probably be "fixed". But I
> don't want to do that to really fix the problem. So 9001 is answering
> correct, yet, 9002 yields timeone and 9003 yields could not connect after 1
> minute.... I tried by doing:
>
> curl -v http://localhost:9003/myApp
>
> So...the thing is how to know what the hell is happening that some of my
> gems (or  FastCGI adaptors) go down for some reason.
> I have checked all my gemstone logs. 2 things look suspicious.
> FastCGI_server-9003.log shows that I have a button that updates my app code
> in GemStone which is causing this:
>
> a RepositoryViewLost occurred (notification 3031), When running outside
> of a transaction the session failed to respond quickly enough to a
> request from Stone to abort.  All object caches have been cleared.
> nil
>
> Then,there are some:  ----------- Commit failure - retrying LOG ENTRY:
> aSymbolDictionary-----------
>
> Here is the pieces of logs I could rescue. Maybe someone could help me
> figure out what is happening!
>
> Thanks in advance!!
>
>
> seaside_2485pcmon.log
>
> [12/04/13 02:17:21.210 EST]: Client died: Slot   12, PID    2743,
> LostOtFlags    0, Name FastCGI-11-DataCurator
> [12/04/13 02:17:21.210 EST]: Starting crashed client recovery: Slot 12,
> PID 2743, Name FastCGI-11-DataCurator
>     Cleaned up locked/pinned frame 550 for crashed process 2743
>     Cleaned up locked/pinned frame 11545 for crashed process 2743
>     Cleaned up locked/pinned frame 3929 for crashed process 2743
>     Cleaned up locked/pinned frame 11407 for crashed process 2743
>     Disposing free frame cache from slot 12:  4 of 4 frames recovered.
> [12/04/13 02:17:23.451 EST]: Finished crashed client recovery: Slot 12,
> PID 2743, Name FastCGI-11-DataCurator
>
>
> FastCGI_server-9001.log  (which is the only gem/adaptor that seems to be
> working)
>
> paz 1> topaz 1> topaz 1> topaz 1> FastCGI Server started on port 9001
> -----------  Unreportable ERROR Encountered:
> 2013-12-03T22:52:06.46091294288635-08:00UserDefinedError:
> send(16,0x7f352f6ebba8,7416,0) failed with errno=107,ENOTCONN, Socket is
> not connected-----------
> -----------  Unreportable ERROR Encountered:
> 2013-12-03T22:53:06.45396900177002-08:00UserDefinedError:
> send(17,0x7f352f786110,7416,0) failed with errno=107,ENOTCONN, Socket is
> not connected-----------
> -----------  Unreportable ERROR Encountered:
> 2013-12-03T23:05:07.57434701919556-08:00UserDefinedError:
> send(14,0x7f352f65e6c0,2673,0) failed with errno=107,ENOTCONN, Socket is
> not connected-----------
> -----------  Unreportable ERROR Encountered:
> 2013-12-03T23:05:31.43626189231873-08:00UserDefinedError:
> send(15,0x7f352f6bed60,2673,0) failed with errno=107,ENOTCONN, Socket is
> not connected-----------
> -----------  Unreportable ERROR Encountered:
> 2013-12-03T23:14:13.39595103263855-08:00UserDefinedError:
> send(16,0x7f352f71f7e0,2673,0) failed with errno=107,ENOTCONN, Socket is
> not connected-----------
> -----------  Unreportable ERROR Encountered:
> 2013-12-03T23:15:13.47269105911255-08:00UserDefinedError:
> send(17,0x7f352f77ff90,2673,0) failed with errno=107,ENOTCONN, Socket is
> not connected-----------
>
>
> FastCGI_server-9002.log
>
> failure
> Read-Write Conflicts...
> Write-Write Conflicts...
>     383168257
> Write-Dependency Conflicts...
> Write-ReadLock Conflicts...
> Write-WriteLock Conflicts...
> Rc-Write-Write Conflicts...
> Synchronized-Commit Conflicts...
> ----------- Commit failure - retrying LOG ENTRY:
> aSymbolDictionary-----------
> failure
> Read-Write Conflicts...
> Write-Write Conflicts...
>     383168257
> Write-Dependency Conflicts...
> Write-ReadLock Conflicts...
> Write-WriteLock Conflicts...
> Rc-Write-Write Conflicts...
> Synchronized-Commit Conflicts...
> ----------- Commit failure - retrying LOG ENTRY:
> aSymbolDictionary-----------
> -----------  Unreportable ERROR Encountered:
> 2013-12-04T04:36:49.04186797142029-08:00UserDefinedError:
> send(16,0x7f21f9462268,2673,0) failed with errno=107,ENOTCONN, Socket is
> not connected-----------
> -----------  Unreportable ERROR Encountered:
> 2013-12-04T04:36:49.0669538974762-08:00UserDefinedError:
> send(17,0x7f21f94ed6c8,2673,0) failed with errno=107,ENOTCONN, Socket is
> not connected-----------
> -----------  Unreportable ERROR Encountered:
> 2013-12-04T04:36:49.10030889511108-08:00UserDefinedError:
> send(18,0x7f21f9551ae8,2673,0) failed with errno=107,ENOTCONN, Socket is
> not connected-----------
> -----------  Unreportable ERROR Encountered:
> 2013-12-04T04:36:49.11388611793518-08:00UserDefinedError:
> send(14,0x7f21f95b2918,2673,0) failed with errno=107,ENOTCONN, Socket is
> not connected-----------
> -----------  Unreportable ERROR Encountered:
> 2013-12-04T04:36:49.12687110900879-08:00UserDefinedError:
> send(19,0x7f21f96184e8,2673,0) failed with errno=107,ENOTCONN, Socket is
> not connected-----------
> -----------  Unreportable ERROR Encountered:
> 2013-12-04T04:36:49.12758493423462-08:00UserDefinedError: Incorrect FCGI
> version. Expected: 1 Received: 71-----------
> -----------  Unreportable ERROR Encountered:
> 2013-12-04T04:36:49.15798401832581-08:00UserDefinedError:
> send(15,0x7f21f968f7d8,2673,0) failed with errno=107,ENOTCONN, Socket is
> not connected-----------
>
>
>
> FastCGI_server-9003.log
>
>
> --transcript--'...finished 1.4-baseline'
> failure
> Read-Write Conflicts...
> Write-Write Conflicts...
>     288128769
>     294245633
> Write-Dependency Conflicts...
> Write-ReadLock Conflicts...
> Write-WriteLock Conflicts...
> Rc-Write-Write Conflicts...
> Synchronized-Commit Conflicts...
> ----------- Commit failure - retrying LOG ENTRY:
> aSymbolDictionary-----------
> -----------------------------------------------------
> GemStone: Error         Nonfatal
> a RepositoryViewLost occurred (notification 3031), When running outside
> of a transaction the session failed to respond quickly enough to a
> request from Stone to abort.  All object caches have been cleared.
> nil
> Error Category: 231169 [GemStone] Number: 3031  Arg Count: 1 Context :
> 318063361 exception : 318063105
> Arg 1: [20 sz:0 cls: 76289 UndefinedObject] nil
> topaz > exec iferr 1 : where
> ==> 1 AbstractException >> _signalWith:             (envId 0) @6 line 25
> [methId 4496129]
> 2 [] in  AbstractException >> _signalAsync      (envId 0) @2 line 19
> [methId 4605185]
> 3 ExecBlock >> ensure:                          (envId 0) @2 line 12
> [methId 3709185]
> 4 AbstractException >> _signalAsync             (envId 0) @6 line 21
> [methId 4600321]
> 5 ProcessorScheduler >> _reapEvents:            (envId 0) @96 line 86
> [methId 4810241]
> 6 ProcessorScheduler >> _findReadyProcess:      (envId 0) @2 line 8
> [methId 4815105]
> 7 ProcessorScheduler >> _reschedule             (envId 0) @3 line 8
> [methId 4805121]
> 8 GsProcess >> _wait                            (envId 0) @3 line 3
> [methId 4486145]
> 9 Delay >> _wait:                               (envId 0) @26 line 26
> [methId 13285377]
> 10 Delay >> wait                                 (envId 0) @3 line 5
> [methId 13307905]
> 11 [] in  Executed Code                          (envId 0) @3 line 32
> [methId 318074625]
> 12 GsProcess >> _start                           (envId 0) @7 line 16
> [methId 4467969]
> 13 GsNMethod class >> _gsReturnToC               (envId 0) @1 line 1
> [methId 4461825]
>   [GsProcess 318063361]
> topaz 1> topaz 1> [268 sz:0 cls: 68097 Boolean] true
>
>
>
>
>
>
>
>
>> Johan
>>
>> On 26 Nov 2013, at 00:33, Mariano Martinez Peck <[hidden email]>
>> wrote:
>>
>> Also, when I see that 1-minute request in the browser development tools,
>> it appears like 2ms receiving, 1 minute waiting...weird!
>>
>>
>> On Mon, Nov 25, 2013 at 8:26 PM, Mariano Martinez Peck <
>> [hidden email]> wrote:
>>
>>> HI guys. This is the first time I am trying to use FastCGI. For some
>>> reason, i have a timeout with fastCGI.
>>> I started the Gems either with:
>>>
>>>
>>> WAGemStoneRunSeasideGems default
>>>         name: 'FastCGI';
>>>         adaptorClass: WAFastCGIAdaptor;
>>>         ports: #(9001 9002 9003).
>>> WAGemStoneRunSeasideGems restartGems.
>>>
>>> (from GemTools) or from command line:
>>>
>>> ./startSeaside_FastCGI 9001
>>>
>>> In either case, what happens is that I can browse my app
>>> http:localhost:9001/dp (and 9002 and 9003). But when I do a request to the
>>> server trough my FastCGI, it takes ONE MINUTE to load the page. I am using
>>> Nginx in the backend with this configuration:
>>>
>>>     upstream seaside
>>>       {
>>>         server localhost:9001;
>>>         server localhost:9002;
>>>         server localhost:9003;
>>>       }
>>>
>>>       server
>>>       {
>>>
>>> listen 33300;
>>> server_name localhost;
>>>         root /var/www/glass/;
>>>
>>>
>>>     access_log  /var/log/nginx/fastCGI.log;
>>>     error_log  /var/log/nginx/error.log info;
>>>
>>>         location /
>>>         {
>>>             try_files $uri @seaside;
>>>   #  error_page 403 404 = @seaside;
>>>         }
>>>
>>>         location @seaside
>>>         {
>>>           include fastcgi_params;
>>>           fastcgi_pass seaside;
>>>         }
>>>       }
>>>
>>>
>>> Using the webtools of the browser, I see that each time I go to a page,
>>> there is either a GET or a POST that takes exactly 1 minute. I
>>> mean...nothing happens, until one minute passes and then the page is
>>> rendered. The requests are small.  And in fact, browsing directly to
>>> 9001/2/3 works perfectly. So I guess this is a one minute timeout of
>>> something.
>>>
>>> For what I can see, it could be related to the
>>>
>>>  keepalive_timeout  65;
>>>
>>> And in nginx error.log I see something like:
>>>
>>> 2013/11/25 17:38:18 [error] 22835#0: *73 upstream timed out (60:
>>> Operation timed out) while reading response header from upstream, client:
>>> 127.0.0.1, server: localhost, request: "GET /dp HTTP/1.1", upstream:
>>> "fastcgi://127.0.0.1:9001", host: "localhost:33300"
>>> 2013/11/25 17:38:18 [info] 22835#0: *73 kevent() reported that client
>>> 127.0.0.1 closed keepalive connection
>>>
>>> Any ideas what could be wrong?
>>>
>>>
>>> Thanks!
>>>
>>> --
>>> Mariano
>>> http://marianopeck.wordpress.com
>>>
>>
>>
>>
>> --
>> Mariano
>> http://marianopeck.wordpress.com
>>
>> _______________________________________________
>>
>> Glass mailing list
>> [hidden email]
>> http://lists.gemtalksystems.com/mailman/listinfo/glass
>>
>>
>
>
> --
> Mariano
> http://marianopeck.wordpress.com
>



--
Mariano
http://marianopeck.wordpress.com

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Reply | Threaded
Open this post in threaded view
|

Re: [Glass] Nginx , FastCGI and GLASS problem

Mariano Martinez Peck


On Wed, Dec 4, 2013 at 7:29 PM, Paul DeBruicker <[hidden email]> wrote:
Sounds to me like you have an error in your Seaside app or your own code that
kills your FastCGI gems.

Weird :(   The only problem I found strange was clicking in "update button" which took more than 30 seconds. See thread "[GS/SS Beta] What do these error messages mean?".
Does this sound like the problem?
 

In your Seaside app are you using the WAGemStoneProductionErrorHandler?

No, I am using WARemoteDebuggingWalkbackErrorHandler since I am still in development and I really need to be able to debug problems.
I can temporarily move to WAGemStoneProductionErrorHandler to see if this is the cause of the problem. 
 
If
not, switch to it.  If so, are any errors getting put on the ObjectLog?


I will check. 
 


Do you have monit or daemontools monitoring your FastCGI gems to restart
them automatically when they become unresponsive?


Not for FastCGI in particular, but I do have for nginx (monit):

$ cat /etc/monit.d/nginx
check process nginx with pidfile /var/run/nginx.pid
group nginx
start program = "/etc/init.d/nginx start"
stop program = "/etc/init.d/nginx stop"
if failed host 127.0.0.1 port 80 protocol http then restart
if 5 restarts within 5 cycles then timeout


 
Thanks Paul!!






Mariano Martinez Peck wrote
> ObjectLog, from yesterday:  FastCGI: topaz exit     Object: port: 9003
> pid:
> 2743
>
>
> And now, FastCGI of 9001 (gem 1)
>
> Unreportable ERROR Encountered:
> 2013-12-04T07:22:54.77649903297424-08:00UserDefinedError:
> send(15,0x7f352f636400,49,0) failed with errno=107,ENOTCONN, Socket is not
> connected-----------
>
> So I got this error in each of the gems....
>
> Any idea?
>
>
>
> On Wed, Dec 4, 2013 at 9:56 AM, Mariano Martinez Peck &lt;

> marianopeck@

> &gt; wrote:
>
>>
>>
>>
>> On Tue, Nov 26, 2013 at 3:22 AM, Johan Brichau &lt;

> johan@

> &gt; wrote:
>>
>>> Mariano,
>>>
>>> I would guess not all fastcgi gems are running correctly on all ports.
>>> There is a default timeout of 60s in nginx before it will pass a fastcgi
>>> request to another port in the upstream configuration.
>>>
>>> The reason you see the delay with the post and not with the following
>>> get
>>> might be because nginx is doing a round-trip load balance over the
>>> fastcgi
>>> backends and one request goes to a working port but the next is not (or
>>> vice-versa).
>>>
>>> You might want to experiment by limiting the nginx conf to a single
>>> fastcgi backend and/or change the default timeout and put some logging
>>> code
>>> in your app when the request gets to seaside. That would at least allow
>>> to
>>> find on what to focus.
>>>
>>>
>>
>> Thanks Johan, that was indeed the problem. This is the second time that
>> happened to me. If I restart everything, it will probably be "fixed". But
>> I
>> don't want to do that to really fix the problem. So 9001 is answering
>> correct, yet, 9002 yields timeone and 9003 yields could not connect after
>> 1
>> minute.... I tried by doing:
>>
>> curl -v http://localhost:9003/myApp
>>
>> So...the thing is how to know what the hell is happening that some of my
>> gems (or  FastCGI adaptors) go down for some reason.
>> I have checked all my gemstone logs. 2 things look suspicious.
>> FastCGI_server-9003.log shows that I have a button that updates my app
>> code
>> in GemStone which is causing this:
>>
>> a RepositoryViewLost occurred (notification 3031), When running outside
>> of a transaction the session failed to respond quickly enough to a
>> request from Stone to abort.  All object caches have been cleared.
>> nil
>>
>> Then,there are some:  ----------- Commit failure - retrying LOG ENTRY:
>> aSymbolDictionary-----------
>>
>> Here is the pieces of logs I could rescue. Maybe someone could help me
>> figure out what is happening!
>>
>> Thanks in advance!!
>>
>>
>> seaside_2485pcmon.log
>>
>> [12/04/13 02:17:21.210 EST]: Client died: Slot   12, PID    2743,
>> LostOtFlags    0, Name FastCGI-11-DataCurator
>> [12/04/13 02:17:21.210 EST]: Starting crashed client recovery: Slot 12,
>> PID 2743, Name FastCGI-11-DataCurator
>>     Cleaned up locked/pinned frame 550 for crashed process 2743
>>     Cleaned up locked/pinned frame 11545 for crashed process 2743
>>     Cleaned up locked/pinned frame 3929 for crashed process 2743
>>     Cleaned up locked/pinned frame 11407 for crashed process 2743
>>     Disposing free frame cache from slot 12:  4 of 4 frames recovered.
>> [12/04/13 02:17:23.451 EST]: Finished crashed client recovery: Slot 12,
>> PID 2743, Name FastCGI-11-DataCurator
>>
>>
>> FastCGI_server-9001.log  (which is the only gem/adaptor that seems to be
>> working)
>>
>> paz 1> topaz 1> topaz 1> topaz 1> FastCGI Server started on port 9001
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T22:52:06.46091294288635-08:00UserDefinedError:
>> send(16,0x7f352f6ebba8,7416,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T22:53:06.45396900177002-08:00UserDefinedError:
>> send(17,0x7f352f786110,7416,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T23:05:07.57434701919556-08:00UserDefinedError:
>> send(14,0x7f352f65e6c0,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T23:05:31.43626189231873-08:00UserDefinedError:
>> send(15,0x7f352f6bed60,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T23:14:13.39595103263855-08:00UserDefinedError:
>> send(16,0x7f352f71f7e0,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T23:15:13.47269105911255-08:00UserDefinedError:
>> send(17,0x7f352f77ff90,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>>
>>
>> FastCGI_server-9002.log
>>
>> failure
>> Read-Write Conflicts...
>> Write-Write Conflicts...
>>     383168257
>> Write-Dependency Conflicts...
>> Write-ReadLock Conflicts...
>> Write-WriteLock Conflicts...
>> Rc-Write-Write Conflicts...
>> Synchronized-Commit Conflicts...
>> ----------- Commit failure - retrying LOG ENTRY:
>> aSymbolDictionary-----------
>> failure
>> Read-Write Conflicts...
>> Write-Write Conflicts...
>>     383168257
>> Write-Dependency Conflicts...
>> Write-ReadLock Conflicts...
>> Write-WriteLock Conflicts...
>> Rc-Write-Write Conflicts...
>> Synchronized-Commit Conflicts...
>> ----------- Commit failure - retrying LOG ENTRY:
>> aSymbolDictionary-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.04186797142029-08:00UserDefinedError:
>> send(16,0x7f21f9462268,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.0669538974762-08:00UserDefinedError:
>> send(17,0x7f21f94ed6c8,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.10030889511108-08:00UserDefinedError:
>> send(18,0x7f21f9551ae8,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.11388611793518-08:00UserDefinedError:
>> send(14,0x7f21f95b2918,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.12687110900879-08:00UserDefinedError:
>> send(19,0x7f21f96184e8,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.12758493423462-08:00UserDefinedError: Incorrect FCGI
>> version. Expected: 1 Received: 71-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.15798401832581-08:00UserDefinedError:
>> send(15,0x7f21f968f7d8,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>>
>>
>>
>> FastCGI_server-9003.log
>>
>>
>> --transcript--'...finished 1.4-baseline'
>> failure
>> Read-Write Conflicts...
>> Write-Write Conflicts...
>>     288128769
>>     294245633
>> Write-Dependency Conflicts...
>> Write-ReadLock Conflicts...
>> Write-WriteLock Conflicts...
>> Rc-Write-Write Conflicts...
>> Synchronized-Commit Conflicts...
>> ----------- Commit failure - retrying LOG ENTRY:
>> aSymbolDictionary-----------
>> -----------------------------------------------------
>> GemStone: Error         Nonfatal
>> a RepositoryViewLost occurred (notification 3031), When running outside
>> of a transaction the session failed to respond quickly enough to a
>> request from Stone to abort.  All object caches have been cleared.
>> nil
>> Error Category: 231169 [GemStone] Number: 3031  Arg Count: 1 Context :
>> 318063361 exception : 318063105
>> Arg 1: [20 sz:0 cls: 76289 UndefinedObject] nil
>> topaz > exec iferr 1 : where
>> ==> 1 AbstractException >> _signalWith:             (envId 0) @6 line 25
>> [methId 4496129]
>> 2 [] in  AbstractException >> _signalAsync      (envId 0) @2 line 19
>> [methId 4605185]
>> 3 ExecBlock >> ensure:                          (envId 0) @2 line 12
>> [methId 3709185]
>> 4 AbstractException >> _signalAsync             (envId 0) @6 line 21
>> [methId 4600321]
>> 5 ProcessorScheduler >> _reapEvents:            (envId 0) @96 line 86
>> [methId 4810241]
>> 6 ProcessorScheduler >> _findReadyProcess:      (envId 0) @2 line 8
>> [methId 4815105]
>> 7 ProcessorScheduler >> _reschedule             (envId 0) @3 line 8
>> [methId 4805121]
>> 8 GsProcess >> _wait                            (envId 0) @3 line 3
>> [methId 4486145]
>> 9 Delay >> _wait:                               (envId 0) @26 line 26
>> [methId 13285377]
>> 10 Delay >> wait                                 (envId 0) @3 line 5
>> [methId 13307905]
>> 11 [] in  Executed Code                          (envId 0) @3 line 32
>> [methId 318074625]
>> 12 GsProcess >> _start                           (envId 0) @7 line 16
>> [methId 4467969]
>> 13 GsNMethod class >> _gsReturnToC               (envId 0) @1 line 1
>> [methId 4461825]
>>   [GsProcess 318063361]
>> topaz 1> topaz 1> [268 sz:0 cls: 68097 Boolean] true
>>
>>
>>
>>
>>
>>
>>
>>
>>> Johan
>>>
>>> On 26 Nov 2013, at 00:33, Mariano Martinez Peck &lt;

> marianopeck@

> &gt;
>>> wrote:
>>>
>>> Also, when I see that 1-minute request in the browser development tools,
>>> it appears like 2ms receiving, 1 minute waiting...weird!
>>>
>>>
>>> On Mon, Nov 25, 2013 at 8:26 PM, Mariano Martinez Peck <
>>>

> marianopeck@

>> wrote:
>>>
>>>> HI guys. This is the first time I am trying to use FastCGI. For some
>>>> reason, i have a timeout with fastCGI.
>>>> I started the Gems either with:
>>>>
>>>>
>>>> WAGemStoneRunSeasideGems default
>>>>         name: 'FastCGI';
>>>>         adaptorClass: WAFastCGIAdaptor;
>>>>         ports: #(9001 9002 9003).
>>>> WAGemStoneRunSeasideGems restartGems.
>>>>
>>>> (from GemTools) or from command line:
>>>>
>>>> ./startSeaside_FastCGI 9001
>>>>
>>>> In either case, what happens is that I can browse my app
>>>> http:localhost:9001/dp (and 9002 and 9003). But when I do a request to
>>>> the
>>>> server trough my FastCGI, it takes ONE MINUTE to load the page. I am
>>>> using
>>>> Nginx in the backend with this configuration:
>>>>
>>>>     upstream seaside
>>>>       {
>>>>         server localhost:9001;
>>>>         server localhost:9002;
>>>>         server localhost:9003;
>>>>       }
>>>>
>>>>       server
>>>>       {
>>>>
>>>> listen 33300;
>>>> server_name localhost;
>>>>         root /var/www/glass/;
>>>>
>>>>
>>>>     access_log  /var/log/nginx/fastCGI.log;
>>>>     error_log  /var/log/nginx/error.log info;
>>>>
>>>>         location /
>>>>         {
>>>>             try_files $uri @seaside;
>>>>   #  error_page 403 404 = @seaside;
>>>>         }
>>>>
>>>>         location @seaside
>>>>         {
>>>>           include fastcgi_params;
>>>>           fastcgi_pass seaside;
>>>>         }
>>>>       }
>>>>
>>>>
>>>> Using the webtools of the browser, I see that each time I go to a page,
>>>> there is either a GET or a POST that takes exactly 1 minute. I
>>>> mean...nothing happens, until one minute passes and then the page is
>>>> rendered. The requests are small.  And in fact, browsing directly to
>>>> 9001/2/3 works perfectly. So I guess this is a one minute timeout of
>>>> something.
>>>>
>>>> For what I can see, it could be related to the
>>>>
>>>>  keepalive_timeout  65;
>>>>
>>>> And in nginx error.log I see something like:
>>>>
>>>> 2013/11/25 17:38:18 [error] 22835#0: *73 upstream timed out (60:
>>>> Operation timed out) while reading response header from upstream,
>>>> client:
>>>> 127.0.0.1, server: localhost, request: "GET /dp HTTP/1.1", upstream:
>>>> "fastcgi://127.0.0.1:9001", host: "localhost:33300"
>>>> 2013/11/25 17:38:18 [info] 22835#0: *73 kevent() reported that client
>>>> 127.0.0.1 closed keepalive connection
>>>>
>>>> Any ideas what could be wrong?
>>>>
>>>>
>>>> Thanks!
>>>>
>>>> --
>>>> Mariano
>>>> http://marianopeck.wordpress.com
>>>>
>>>
>>>
>>>
>>> --
>>> Mariano
>>> http://marianopeck.wordpress.com
>>>
>>> _______________________________________________
>>>
>>> Glass mailing list
>>>

> Glass@.gemtalksystems
> _______________________________________________
> Glass mailing list

> Glass@.gemtalksystems

> http://lists.gemtalksystems.com/mailman/listinfo/glass





--
View this message in context: http://forum.world.st/Glass-Nginx-FastCGI-and-GLASS-problem-tp4725218p4727568.html
Sent from the GLASS mailing list archive at Nabble.com.
_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass



--
Mariano
http://marianopeck.wordpress.com

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Reply | Threaded
Open this post in threaded view
|

Re: [Glass] Nginx , FastCGI and GLASS problem

Mariano Martinez Peck
mmmm I could reproduce the problem even that long request....some problem as a few days back...my gems start to go down...just browsing a bit my app...
In fact...I have now particular button that saves an object and that "hungs" the gem....
Ohhh ah I have the same problem with Swazoo so I doesn't seem FastCGI related...
Weird that in my local gemstone I have no problem. 
So it really seems like something is happening in the remote gemstone that doesn't happen here. I will try to do a backup in remote one and restore here to see if I can reproduce it. If not, then there is something in the server installation. 

Thanks guys. I will continue digging and let you know.

Cheers,


On Wed, Dec 4, 2013 at 8:12 PM, Mariano Martinez Peck <[hidden email]> wrote:


On Wed, Dec 4, 2013 at 7:29 PM, Paul DeBruicker <[hidden email]> wrote:
Sounds to me like you have an error in your Seaside app or your own code that
kills your FastCGI gems.

Weird :(   The only problem I found strange was clicking in "update button" which took more than 30 seconds. See thread "[GS/SS Beta] What do these error messages mean?".
Does this sound like the problem?
 

In your Seaside app are you using the WAGemStoneProductionErrorHandler?

No, I am using WARemoteDebuggingWalkbackErrorHandler since I am still in development and I really need to be able to debug problems.
I can temporarily move to WAGemStoneProductionErrorHandler to see if this is the cause of the problem. 
 
If
not, switch to it.  If so, are any errors getting put on the ObjectLog?


I will check. 
 


Do you have monit or daemontools monitoring your FastCGI gems to restart
them automatically when they become unresponsive?


Not for FastCGI in particular, but I do have for nginx (monit):

$ cat /etc/monit.d/nginx
check process nginx with pidfile /var/run/nginx.pid
group nginx
start program = "/etc/init.d/nginx start"
stop program = "/etc/init.d/nginx stop"
if failed host 127.0.0.1 port 80 protocol http then restart
if 5 restarts within 5 cycles then timeout


 
Thanks Paul!!






Mariano Martinez Peck wrote
> ObjectLog, from yesterday:  FastCGI: topaz exit     Object: port: 9003
> pid:
> 2743
>
>
> And now, FastCGI of 9001 (gem 1)
>
> Unreportable ERROR Encountered:
> 2013-12-04T07:22:54.77649903297424-08:00UserDefinedError:
> send(15,0x7f352f636400,49,0) failed with errno=107,ENOTCONN, Socket is not
> connected-----------
>
> So I got this error in each of the gems....
>
> Any idea?
>
>
>
> On Wed, Dec 4, 2013 at 9:56 AM, Mariano Martinez Peck &lt;

> marianopeck@

> &gt; wrote:
>
>>
>>
>>
>> On Tue, Nov 26, 2013 at 3:22 AM, Johan Brichau &lt;

> johan@

> &gt; wrote:
>>
>>> Mariano,
>>>
>>> I would guess not all fastcgi gems are running correctly on all ports.
>>> There is a default timeout of 60s in nginx before it will pass a fastcgi
>>> request to another port in the upstream configuration.
>>>
>>> The reason you see the delay with the post and not with the following
>>> get
>>> might be because nginx is doing a round-trip load balance over the
>>> fastcgi
>>> backends and one request goes to a working port but the next is not (or
>>> vice-versa).
>>>
>>> You might want to experiment by limiting the nginx conf to a single
>>> fastcgi backend and/or change the default timeout and put some logging
>>> code
>>> in your app when the request gets to seaside. That would at least allow
>>> to
>>> find on what to focus.
>>>
>>>
>>
>> Thanks Johan, that was indeed the problem. This is the second time that
>> happened to me. If I restart everything, it will probably be "fixed". But
>> I
>> don't want to do that to really fix the problem. So 9001 is answering
>> correct, yet, 9002 yields timeone and 9003 yields could not connect after
>> 1
>> minute.... I tried by doing:
>>
>> curl -v http://localhost:9003/myApp
>>
>> So...the thing is how to know what the hell is happening that some of my
>> gems (or  FastCGI adaptors) go down for some reason.
>> I have checked all my gemstone logs. 2 things look suspicious.
>> FastCGI_server-9003.log shows that I have a button that updates my app
>> code
>> in GemStone which is causing this:
>>
>> a RepositoryViewLost occurred (notification 3031), When running outside
>> of a transaction the session failed to respond quickly enough to a
>> request from Stone to abort.  All object caches have been cleared.
>> nil
>>
>> Then,there are some:  ----------- Commit failure - retrying LOG ENTRY:
>> aSymbolDictionary-----------
>>
>> Here is the pieces of logs I could rescue. Maybe someone could help me
>> figure out what is happening!
>>
>> Thanks in advance!!
>>
>>
>> seaside_2485pcmon.log
>>
>> [12/04/13 02:17:21.210 EST]: Client died: Slot   12, PID    2743,
>> LostOtFlags    0, Name FastCGI-11-DataCurator
>> [12/04/13 02:17:21.210 EST]: Starting crashed client recovery: Slot 12,
>> PID 2743, Name FastCGI-11-DataCurator
>>     Cleaned up locked/pinned frame 550 for crashed process 2743
>>     Cleaned up locked/pinned frame 11545 for crashed process 2743
>>     Cleaned up locked/pinned frame 3929 for crashed process 2743
>>     Cleaned up locked/pinned frame 11407 for crashed process 2743
>>     Disposing free frame cache from slot 12:  4 of 4 frames recovered.
>> [12/04/13 02:17:23.451 EST]: Finished crashed client recovery: Slot 12,
>> PID 2743, Name FastCGI-11-DataCurator
>>
>>
>> FastCGI_server-9001.log  (which is the only gem/adaptor that seems to be
>> working)
>>
>> paz 1> topaz 1> topaz 1> topaz 1> FastCGI Server started on port 9001
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T22:52:06.46091294288635-08:00UserDefinedError:
>> send(16,0x7f352f6ebba8,7416,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T22:53:06.45396900177002-08:00UserDefinedError:
>> send(17,0x7f352f786110,7416,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T23:05:07.57434701919556-08:00UserDefinedError:
>> send(14,0x7f352f65e6c0,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T23:05:31.43626189231873-08:00UserDefinedError:
>> send(15,0x7f352f6bed60,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T23:14:13.39595103263855-08:00UserDefinedError:
>> send(16,0x7f352f71f7e0,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T23:15:13.47269105911255-08:00UserDefinedError:
>> send(17,0x7f352f77ff90,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>>
>>
>> FastCGI_server-9002.log
>>
>> failure
>> Read-Write Conflicts...
>> Write-Write Conflicts...
>>     383168257
>> Write-Dependency Conflicts...
>> Write-ReadLock Conflicts...
>> Write-WriteLock Conflicts...
>> Rc-Write-Write Conflicts...
>> Synchronized-Commit Conflicts...
>> ----------- Commit failure - retrying LOG ENTRY:
>> aSymbolDictionary-----------
>> failure
>> Read-Write Conflicts...
>> Write-Write Conflicts...
>>     383168257
>> Write-Dependency Conflicts...
>> Write-ReadLock Conflicts...
>> Write-WriteLock Conflicts...
>> Rc-Write-Write Conflicts...
>> Synchronized-Commit Conflicts...
>> ----------- Commit failure - retrying LOG ENTRY:
>> aSymbolDictionary-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.04186797142029-08:00UserDefinedError:
>> send(16,0x7f21f9462268,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.0669538974762-08:00UserDefinedError:
>> send(17,0x7f21f94ed6c8,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.10030889511108-08:00UserDefinedError:
>> send(18,0x7f21f9551ae8,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.11388611793518-08:00UserDefinedError:
>> send(14,0x7f21f95b2918,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.12687110900879-08:00UserDefinedError:
>> send(19,0x7f21f96184e8,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.12758493423462-08:00UserDefinedError: Incorrect FCGI
>> version. Expected: 1 Received: 71-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.15798401832581-08:00UserDefinedError:
>> send(15,0x7f21f968f7d8,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>>
>>
>>
>> FastCGI_server-9003.log
>>
>>
>> --transcript--'...finished 1.4-baseline'
>> failure
>> Read-Write Conflicts...
>> Write-Write Conflicts...
>>     288128769
>>     294245633
>> Write-Dependency Conflicts...
>> Write-ReadLock Conflicts...
>> Write-WriteLock Conflicts...
>> Rc-Write-Write Conflicts...
>> Synchronized-Commit Conflicts...
>> ----------- Commit failure - retrying LOG ENTRY:
>> aSymbolDictionary-----------
>> -----------------------------------------------------
>> GemStone: Error         Nonfatal
>> a RepositoryViewLost occurred (notification 3031), When running outside
>> of a transaction the session failed to respond quickly enough to a
>> request from Stone to abort.  All object caches have been cleared.
>> nil
>> Error Category: 231169 [GemStone] Number: 3031  Arg Count: 1 Context :
>> 318063361 exception : 318063105
>> Arg 1: [20 sz:0 cls: 76289 UndefinedObject] nil
>> topaz > exec iferr 1 : where
>> ==> 1 AbstractException >> _signalWith:             (envId 0) @6 line 25
>> [methId 4496129]
>> 2 [] in  AbstractException >> _signalAsync      (envId 0) @2 line 19
>> [methId 4605185]
>> 3 ExecBlock >> ensure:                          (envId 0) @2 line 12
>> [methId 3709185]
>> 4 AbstractException >> _signalAsync             (envId 0) @6 line 21
>> [methId 4600321]
>> 5 ProcessorScheduler >> _reapEvents:            (envId 0) @96 line 86
>> [methId 4810241]
>> 6 ProcessorScheduler >> _findReadyProcess:      (envId 0) @2 line 8
>> [methId 4815105]
>> 7 ProcessorScheduler >> _reschedule             (envId 0) @3 line 8
>> [methId 4805121]
>> 8 GsProcess >> _wait                            (envId 0) @3 line 3
>> [methId 4486145]
>> 9 Delay >> _wait:                               (envId 0) @26 line 26
>> [methId 13285377]
>> 10 Delay >> wait                                 (envId 0) @3 line 5
>> [methId 13307905]
>> 11 [] in  Executed Code                          (envId 0) @3 line 32
>> [methId 318074625]
>> 12 GsProcess >> _start                           (envId 0) @7 line 16
>> [methId 4467969]
>> 13 GsNMethod class >> _gsReturnToC               (envId 0) @1 line 1
>> [methId 4461825]
>>   [GsProcess 318063361]
>> topaz 1> topaz 1> [268 sz:0 cls: 68097 Boolean] true
>>
>>
>>
>>
>>
>>
>>
>>
>>> Johan
>>>
>>> On 26 Nov 2013, at 00:33, Mariano Martinez Peck &lt;

> marianopeck@

> &gt;
>>> wrote:
>>>
>>> Also, when I see that 1-minute request in the browser development tools,
>>> it appears like 2ms receiving, 1 minute waiting...weird!
>>>
>>>
>>> On Mon, Nov 25, 2013 at 8:26 PM, Mariano Martinez Peck <
>>>

> marianopeck@

>> wrote:
>>>
>>>> HI guys. This is the first time I am trying to use FastCGI. For some
>>>> reason, i have a timeout with fastCGI.
>>>> I started the Gems either with:
>>>>
>>>>
>>>> WAGemStoneRunSeasideGems default
>>>>         name: 'FastCGI';
>>>>         adaptorClass: WAFastCGIAdaptor;
>>>>         ports: #(9001 9002 9003).
>>>> WAGemStoneRunSeasideGems restartGems.
>>>>
>>>> (from GemTools) or from command line:
>>>>
>>>> ./startSeaside_FastCGI 9001
>>>>
>>>> In either case, what happens is that I can browse my app
>>>> http:localhost:9001/dp (and 9002 and 9003). But when I do a request to
>>>> the
>>>> server trough my FastCGI, it takes ONE MINUTE to load the page. I am
>>>> using
>>>> Nginx in the backend with this configuration:
>>>>
>>>>     upstream seaside
>>>>       {
>>>>         server localhost:9001;
>>>>         server localhost:9002;
>>>>         server localhost:9003;
>>>>       }
>>>>
>>>>       server
>>>>       {
>>>>
>>>> listen 33300;
>>>> server_name localhost;
>>>>         root /var/www/glass/;
>>>>
>>>>
>>>>     access_log  /var/log/nginx/fastCGI.log;
>>>>     error_log  /var/log/nginx/error.log info;
>>>>
>>>>         location /
>>>>         {
>>>>             try_files $uri @seaside;
>>>>   #  error_page 403 404 = @seaside;
>>>>         }
>>>>
>>>>         location @seaside
>>>>         {
>>>>           include fastcgi_params;
>>>>           fastcgi_pass seaside;
>>>>         }
>>>>       }
>>>>
>>>>
>>>> Using the webtools of the browser, I see that each time I go to a page,
>>>> there is either a GET or a POST that takes exactly 1 minute. I
>>>> mean...nothing happens, until one minute passes and then the page is
>>>> rendered. The requests are small.  And in fact, browsing directly to
>>>> 9001/2/3 works perfectly. So I guess this is a one minute timeout of
>>>> something.
>>>>
>>>> For what I can see, it could be related to the
>>>>
>>>>  keepalive_timeout  65;
>>>>
>>>> And in nginx error.log I see something like:
>>>>
>>>> 2013/11/25 17:38:18 [error] 22835#0: *73 upstream timed out (60:
>>>> Operation timed out) while reading response header from upstream,
>>>> client:
>>>> 127.0.0.1, server: localhost, request: "GET /dp HTTP/1.1", upstream:
>>>> "fastcgi://127.0.0.1:9001", host: "localhost:33300"
>>>> 2013/11/25 17:38:18 [info] 22835#0: *73 kevent() reported that client
>>>> 127.0.0.1 closed keepalive connection
>>>>
>>>> Any ideas what could be wrong?
>>>>
>>>>
>>>> Thanks!
>>>>
>>>> --
>>>> Mariano
>>>> http://marianopeck.wordpress.com
>>>>
>>>
>>>
>>>
>>> --
>>> Mariano
>>> http://marianopeck.wordpress.com
>>>
>>> _______________________________________________
>>>
>>> Glass mailing list
>>>

> Glass@.gemtalksystems
> _______________________________________________
> Glass mailing list

> Glass@.gemtalksystems

> http://lists.gemtalksystems.com/mailman/listinfo/glass





--
View this message in context: http://forum.world.st/Glass-Nginx-FastCGI-and-GLASS-problem-tp4725218p4727568.html
Sent from the GLASS mailing list archive at Nabble.com.
_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass



--
Mariano
http://marianopeck.wordpress.com



--
Mariano
http://marianopeck.wordpress.com

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Reply | Threaded
Open this post in threaded view
|

Re: [Glass] Nginx , FastCGI and GLASS problem

Mariano Martinez Peck
OK, I found the problem.....

For some reason, reading from /dev/random is very very slow in my centos server...the next lines takes forever there (but answered immediately in my local gemstone in OSX):


[

| stream |
stream := (FileStream oldFileNamed: '/dev/random').
stream binary.
(stream next: 20) asByteArray.
stream close.


] timeToRun



On Thu, Dec 5, 2013 at 12:33 AM, Mariano Martinez Peck <[hidden email]> wrote:
mmmm I could reproduce the problem even that long request....some problem as a few days back...my gems start to go down...just browsing a bit my app...
In fact...I have now particular button that saves an object and that "hungs" the gem....
Ohhh ah I have the same problem with Swazoo so I doesn't seem FastCGI related...
Weird that in my local gemstone I have no problem. 
So it really seems like something is happening in the remote gemstone that doesn't happen here. I will try to do a backup in remote one and restore here to see if I can reproduce it. If not, then there is something in the server installation. 

Thanks guys. I will continue digging and let you know.

Cheers,


On Wed, Dec 4, 2013 at 8:12 PM, Mariano Martinez Peck <[hidden email]> wrote:


On Wed, Dec 4, 2013 at 7:29 PM, Paul DeBruicker <[hidden email]> wrote:
Sounds to me like you have an error in your Seaside app or your own code that
kills your FastCGI gems.

Weird :(   The only problem I found strange was clicking in "update button" which took more than 30 seconds. See thread "[GS/SS Beta] What do these error messages mean?".
Does this sound like the problem?
 

In your Seaside app are you using the WAGemStoneProductionErrorHandler?

No, I am using WARemoteDebuggingWalkbackErrorHandler since I am still in development and I really need to be able to debug problems.
I can temporarily move to WAGemStoneProductionErrorHandler to see if this is the cause of the problem. 
 
If
not, switch to it.  If so, are any errors getting put on the ObjectLog?


I will check. 
 


Do you have monit or daemontools monitoring your FastCGI gems to restart
them automatically when they become unresponsive?


Not for FastCGI in particular, but I do have for nginx (monit):

$ cat /etc/monit.d/nginx
check process nginx with pidfile /var/run/nginx.pid
group nginx
start program = "/etc/init.d/nginx start"
stop program = "/etc/init.d/nginx stop"
if failed host 127.0.0.1 port 80 protocol http then restart
if 5 restarts within 5 cycles then timeout


 
Thanks Paul!!






Mariano Martinez Peck wrote
> ObjectLog, from yesterday:  FastCGI: topaz exit     Object: port: 9003
> pid:
> 2743
>
>
> And now, FastCGI of 9001 (gem 1)
>
> Unreportable ERROR Encountered:
> 2013-12-04T07:22:54.77649903297424-08:00UserDefinedError:
> send(15,0x7f352f636400,49,0) failed with errno=107,ENOTCONN, Socket is not
> connected-----------
>
> So I got this error in each of the gems....
>
> Any idea?
>
>
>
> On Wed, Dec 4, 2013 at 9:56 AM, Mariano Martinez Peck &lt;

> marianopeck@

> &gt; wrote:
>
>>
>>
>>
>> On Tue, Nov 26, 2013 at 3:22 AM, Johan Brichau &lt;

> johan@

> &gt; wrote:
>>
>>> Mariano,
>>>
>>> I would guess not all fastcgi gems are running correctly on all ports.
>>> There is a default timeout of 60s in nginx before it will pass a fastcgi
>>> request to another port in the upstream configuration.
>>>
>>> The reason you see the delay with the post and not with the following
>>> get
>>> might be because nginx is doing a round-trip load balance over the
>>> fastcgi
>>> backends and one request goes to a working port but the next is not (or
>>> vice-versa).
>>>
>>> You might want to experiment by limiting the nginx conf to a single
>>> fastcgi backend and/or change the default timeout and put some logging
>>> code
>>> in your app when the request gets to seaside. That would at least allow
>>> to
>>> find on what to focus.
>>>
>>>
>>
>> Thanks Johan, that was indeed the problem. This is the second time that
>> happened to me. If I restart everything, it will probably be "fixed". But
>> I
>> don't want to do that to really fix the problem. So 9001 is answering
>> correct, yet, 9002 yields timeone and 9003 yields could not connect after
>> 1
>> minute.... I tried by doing:
>>
>> curl -v http://localhost:9003/myApp
>>
>> So...the thing is how to know what the hell is happening that some of my
>> gems (or  FastCGI adaptors) go down for some reason.
>> I have checked all my gemstone logs. 2 things look suspicious.
>> FastCGI_server-9003.log shows that I have a button that updates my app
>> code
>> in GemStone which is causing this:
>>
>> a RepositoryViewLost occurred (notification 3031), When running outside
>> of a transaction the session failed to respond quickly enough to a
>> request from Stone to abort.  All object caches have been cleared.
>> nil
>>
>> Then,there are some:  ----------- Commit failure - retrying LOG ENTRY:
>> aSymbolDictionary-----------
>>
>> Here is the pieces of logs I could rescue. Maybe someone could help me
>> figure out what is happening!
>>
>> Thanks in advance!!
>>
>>
>> seaside_2485pcmon.log
>>
>> [12/04/13 02:17:21.210 EST]: Client died: Slot   12, PID    2743,
>> LostOtFlags    0, Name FastCGI-11-DataCurator
>> [12/04/13 02:17:21.210 EST]: Starting crashed client recovery: Slot 12,
>> PID 2743, Name FastCGI-11-DataCurator
>>     Cleaned up locked/pinned frame 550 for crashed process 2743
>>     Cleaned up locked/pinned frame 11545 for crashed process 2743
>>     Cleaned up locked/pinned frame 3929 for crashed process 2743
>>     Cleaned up locked/pinned frame 11407 for crashed process 2743
>>     Disposing free frame cache from slot 12:  4 of 4 frames recovered.
>> [12/04/13 02:17:23.451 EST]: Finished crashed client recovery: Slot 12,
>> PID 2743, Name FastCGI-11-DataCurator
>>
>>
>> FastCGI_server-9001.log  (which is the only gem/adaptor that seems to be
>> working)
>>
>> paz 1> topaz 1> topaz 1> topaz 1> FastCGI Server started on port 9001
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T22:52:06.46091294288635-08:00UserDefinedError:
>> send(16,0x7f352f6ebba8,7416,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T22:53:06.45396900177002-08:00UserDefinedError:
>> send(17,0x7f352f786110,7416,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T23:05:07.57434701919556-08:00UserDefinedError:
>> send(14,0x7f352f65e6c0,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T23:05:31.43626189231873-08:00UserDefinedError:
>> send(15,0x7f352f6bed60,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T23:14:13.39595103263855-08:00UserDefinedError:
>> send(16,0x7f352f71f7e0,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T23:15:13.47269105911255-08:00UserDefinedError:
>> send(17,0x7f352f77ff90,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>>
>>
>> FastCGI_server-9002.log
>>
>> failure
>> Read-Write Conflicts...
>> Write-Write Conflicts...
>>     383168257
>> Write-Dependency Conflicts...
>> Write-ReadLock Conflicts...
>> Write-WriteLock Conflicts...
>> Rc-Write-Write Conflicts...
>> Synchronized-Commit Conflicts...
>> ----------- Commit failure - retrying LOG ENTRY:
>> aSymbolDictionary-----------
>> failure
>> Read-Write Conflicts...
>> Write-Write Conflicts...
>>     383168257
>> Write-Dependency Conflicts...
>> Write-ReadLock Conflicts...
>> Write-WriteLock Conflicts...
>> Rc-Write-Write Conflicts...
>> Synchronized-Commit Conflicts...
>> ----------- Commit failure - retrying LOG ENTRY:
>> aSymbolDictionary-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.04186797142029-08:00UserDefinedError:
>> send(16,0x7f21f9462268,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.0669538974762-08:00UserDefinedError:
>> send(17,0x7f21f94ed6c8,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.10030889511108-08:00UserDefinedError:
>> send(18,0x7f21f9551ae8,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.11388611793518-08:00UserDefinedError:
>> send(14,0x7f21f95b2918,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.12687110900879-08:00UserDefinedError:
>> send(19,0x7f21f96184e8,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.12758493423462-08:00UserDefinedError: Incorrect FCGI
>> version. Expected: 1 Received: 71-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.15798401832581-08:00UserDefinedError:
>> send(15,0x7f21f968f7d8,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>>
>>
>>
>> FastCGI_server-9003.log
>>
>>
>> --transcript--'...finished 1.4-baseline'
>> failure
>> Read-Write Conflicts...
>> Write-Write Conflicts...
>>     288128769
>>     294245633
>> Write-Dependency Conflicts...
>> Write-ReadLock Conflicts...
>> Write-WriteLock Conflicts...
>> Rc-Write-Write Conflicts...
>> Synchronized-Commit Conflicts...
>> ----------- Commit failure - retrying LOG ENTRY:
>> aSymbolDictionary-----------
>> -----------------------------------------------------
>> GemStone: Error         Nonfatal
>> a RepositoryViewLost occurred (notification 3031), When running outside
>> of a transaction the session failed to respond quickly enough to a
>> request from Stone to abort.  All object caches have been cleared.
>> nil
>> Error Category: 231169 [GemStone] Number: 3031  Arg Count: 1 Context :
>> 318063361 exception : 318063105
>> Arg 1: [20 sz:0 cls: 76289 UndefinedObject] nil
>> topaz > exec iferr 1 : where
>> ==> 1 AbstractException >> _signalWith:             (envId 0) @6 line 25
>> [methId 4496129]
>> 2 [] in  AbstractException >> _signalAsync      (envId 0) @2 line 19
>> [methId 4605185]
>> 3 ExecBlock >> ensure:                          (envId 0) @2 line 12
>> [methId 3709185]
>> 4 AbstractException >> _signalAsync             (envId 0) @6 line 21
>> [methId 4600321]
>> 5 ProcessorScheduler >> _reapEvents:            (envId 0) @96 line 86
>> [methId 4810241]
>> 6 ProcessorScheduler >> _findReadyProcess:      (envId 0) @2 line 8
>> [methId 4815105]
>> 7 ProcessorScheduler >> _reschedule             (envId 0) @3 line 8
>> [methId 4805121]
>> 8 GsProcess >> _wait                            (envId 0) @3 line 3
>> [methId 4486145]
>> 9 Delay >> _wait:                               (envId 0) @26 line 26
>> [methId 13285377]
>> 10 Delay >> wait                                 (envId 0) @3 line 5
>> [methId 13307905]
>> 11 [] in  Executed Code                          (envId 0) @3 line 32
>> [methId 318074625]
>> 12 GsProcess >> _start                           (envId 0) @7 line 16
>> [methId 4467969]
>> 13 GsNMethod class >> _gsReturnToC               (envId 0) @1 line 1
>> [methId 4461825]
>>   [GsProcess 318063361]
>> topaz 1> topaz 1> [268 sz:0 cls: 68097 Boolean] true
>>
>>
>>
>>
>>
>>
>>
>>
>>> Johan
>>>
>>> On 26 Nov 2013, at 00:33, Mariano Martinez Peck &lt;

> marianopeck@

> &gt;
>>> wrote:
>>>
>>> Also, when I see that 1-minute request in the browser development tools,
>>> it appears like 2ms receiving, 1 minute waiting...weird!
>>>
>>>
>>> On Mon, Nov 25, 2013 at 8:26 PM, Mariano Martinez Peck <
>>>

> marianopeck@

>> wrote:
>>>
>>>> HI guys. This is the first time I am trying to use FastCGI. For some
>>>> reason, i have a timeout with fastCGI.
>>>> I started the Gems either with:
>>>>
>>>>
>>>> WAGemStoneRunSeasideGems default
>>>>         name: 'FastCGI';
>>>>         adaptorClass: WAFastCGIAdaptor;
>>>>         ports: #(9001 9002 9003).
>>>> WAGemStoneRunSeasideGems restartGems.
>>>>
>>>> (from GemTools) or from command line:
>>>>
>>>> ./startSeaside_FastCGI 9001
>>>>
>>>> In either case, what happens is that I can browse my app
>>>> http:localhost:9001/dp (and 9002 and 9003). But when I do a request to
>>>> the
>>>> server trough my FastCGI, it takes ONE MINUTE to load the page. I am
>>>> using
>>>> Nginx in the backend with this configuration:
>>>>
>>>>     upstream seaside
>>>>       {
>>>>         server localhost:9001;
>>>>         server localhost:9002;
>>>>         server localhost:9003;
>>>>       }
>>>>
>>>>       server
>>>>       {
>>>>
>>>> listen 33300;
>>>> server_name localhost;
>>>>         root /var/www/glass/;
>>>>
>>>>
>>>>     access_log  /var/log/nginx/fastCGI.log;
>>>>     error_log  /var/log/nginx/error.log info;
>>>>
>>>>         location /
>>>>         {
>>>>             try_files $uri @seaside;
>>>>   #  error_page 403 404 = @seaside;
>>>>         }
>>>>
>>>>         location @seaside
>>>>         {
>>>>           include fastcgi_params;
>>>>           fastcgi_pass seaside;
>>>>         }
>>>>       }
>>>>
>>>>
>>>> Using the webtools of the browser, I see that each time I go to a page,
>>>> there is either a GET or a POST that takes exactly 1 minute. I
>>>> mean...nothing happens, until one minute passes and then the page is
>>>> rendered. The requests are small.  And in fact, browsing directly to
>>>> 9001/2/3 works perfectly. So I guess this is a one minute timeout of
>>>> something.
>>>>
>>>> For what I can see, it could be related to the
>>>>
>>>>  keepalive_timeout  65;
>>>>
>>>> And in nginx error.log I see something like:
>>>>
>>>> 2013/11/25 17:38:18 [error] 22835#0: *73 upstream timed out (60:
>>>> Operation timed out) while reading response header from upstream,
>>>> client:
>>>> 127.0.0.1, server: localhost, request: "GET /dp HTTP/1.1", upstream:
>>>> "fastcgi://127.0.0.1:9001", host: "localhost:33300"
>>>> 2013/11/25 17:38:18 [info] 22835#0: *73 kevent() reported that client
>>>> 127.0.0.1 closed keepalive connection
>>>>
>>>> Any ideas what could be wrong?
>>>>
>>>>
>>>> Thanks!
>>>>
>>>> --
>>>> Mariano
>>>> http://marianopeck.wordpress.com
>>>>
>>>
>>>
>>>
>>> --
>>> Mariano
>>> http://marianopeck.wordpress.com
>>>
>>> _______________________________________________
>>>
>>> Glass mailing list
>>>

> Glass@.gemtalksystems
> _______________________________________________
> Glass mailing list

> Glass@.gemtalksystems

> http://lists.gemtalksystems.com/mailman/listinfo/glass





--
View this message in context: http://forum.world.st/Glass-Nginx-FastCGI-and-GLASS-problem-tp4725218p4727568.html
Sent from the GLASS mailing list archive at Nabble.com.
_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass



--
Mariano
http://marianopeck.wordpress.com



--
Mariano
http://marianopeck.wordpress.com



--
Mariano
http://marianopeck.wordpress.com

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Reply | Threaded
Open this post in threaded view
|

Re: [Glass] Nginx , FastCGI and GLASS problem

Mariano Martinez Peck


On Thu, Dec 5, 2013 at 1:13 AM, Mariano Martinez Peck <[hidden email]> wrote:
OK, I found the problem.....

For some reason, reading from /dev/random is very very slow in my centos server...the next lines takes forever there (but answered immediately in my local gemstone in OSX):


[

| stream |
stream := (FileStream oldFileNamed: '/dev/random').
stream binary.
(stream next: 20) asByteArray.
stream close.


] timeToRun



On Thu, Dec 5, 2013 at 12:33 AM, Mariano Martinez Peck <[hidden email]> wrote:
mmmm I could reproduce the problem even that long request....some problem as a few days back...my gems start to go down...just browsing a bit my app...
In fact...I have now particular button that saves an object and that "hungs" the gem....
Ohhh ah I have the same problem with Swazoo so I doesn't seem FastCGI related...
Weird that in my local gemstone I have no problem. 
So it really seems like something is happening in the remote gemstone that doesn't happen here. I will try to do a backup in remote one and restore here to see if I can reproduce it. If not, then there is something in the server installation. 

Thanks guys. I will continue digging and let you know.

Cheers,


On Wed, Dec 4, 2013 at 8:12 PM, Mariano Martinez Peck <[hidden email]> wrote:


On Wed, Dec 4, 2013 at 7:29 PM, Paul DeBruicker <[hidden email]> wrote:
Sounds to me like you have an error in your Seaside app or your own code that
kills your FastCGI gems.

Weird :(   The only problem I found strange was clicking in "update button" which took more than 30 seconds. See thread "[GS/SS Beta] What do these error messages mean?".
Does this sound like the problem?
 

In your Seaside app are you using the WAGemStoneProductionErrorHandler?

No, I am using WARemoteDebuggingWalkbackErrorHandler since I am still in development and I really need to be able to debug problems.
I can temporarily move to WAGemStoneProductionErrorHandler to see if this is the cause of the problem. 
 
If
not, switch to it.  If so, are any errors getting put on the ObjectLog?


I will check. 
 


Do you have monit or daemontools monitoring your FastCGI gems to restart
them automatically when they become unresponsive?


Not for FastCGI in particular, but I do have for nginx (monit):

$ cat /etc/monit.d/nginx
check process nginx with pidfile /var/run/nginx.pid
group nginx
start program = "/etc/init.d/nginx start"
stop program = "/etc/init.d/nginx stop"
if failed host 127.0.0.1 port 80 protocol http then restart
if 5 restarts within 5 cycles then timeout


 
Thanks Paul!!






Mariano Martinez Peck wrote
> ObjectLog, from yesterday:  FastCGI: topaz exit     Object: port: 9003
> pid:
> 2743
>
>
> And now, FastCGI of 9001 (gem 1)
>
> Unreportable ERROR Encountered:
> 2013-12-04T07:22:54.77649903297424-08:00UserDefinedError:
> send(15,0x7f352f636400,49,0) failed with errno=107,ENOTCONN, Socket is not
> connected-----------
>
> So I got this error in each of the gems....
>
> Any idea?
>
>
>
> On Wed, Dec 4, 2013 at 9:56 AM, Mariano Martinez Peck &lt;

> marianopeck@

> &gt; wrote:
>
>>
>>
>>
>> On Tue, Nov 26, 2013 at 3:22 AM, Johan Brichau &lt;

> johan@

> &gt; wrote:
>>
>>> Mariano,
>>>
>>> I would guess not all fastcgi gems are running correctly on all ports.
>>> There is a default timeout of 60s in nginx before it will pass a fastcgi
>>> request to another port in the upstream configuration.
>>>
>>> The reason you see the delay with the post and not with the following
>>> get
>>> might be because nginx is doing a round-trip load balance over the
>>> fastcgi
>>> backends and one request goes to a working port but the next is not (or
>>> vice-versa).
>>>
>>> You might want to experiment by limiting the nginx conf to a single
>>> fastcgi backend and/or change the default timeout and put some logging
>>> code
>>> in your app when the request gets to seaside. That would at least allow
>>> to
>>> find on what to focus.
>>>
>>>
>>
>> Thanks Johan, that was indeed the problem. This is the second time that
>> happened to me. If I restart everything, it will probably be "fixed". But
>> I
>> don't want to do that to really fix the problem. So 9001 is answering
>> correct, yet, 9002 yields timeone and 9003 yields could not connect after
>> 1
>> minute.... I tried by doing:
>>
>> curl -v http://localhost:9003/myApp
>>
>> So...the thing is how to know what the hell is happening that some of my
>> gems (or  FastCGI adaptors) go down for some reason.
>> I have checked all my gemstone logs. 2 things look suspicious.
>> FastCGI_server-9003.log shows that I have a button that updates my app
>> code
>> in GemStone which is causing this:
>>
>> a RepositoryViewLost occurred (notification 3031), When running outside
>> of a transaction the session failed to respond quickly enough to a
>> request from Stone to abort.  All object caches have been cleared.
>> nil
>>
>> Then,there are some:  ----------- Commit failure - retrying LOG ENTRY:
>> aSymbolDictionary-----------
>>
>> Here is the pieces of logs I could rescue. Maybe someone could help me
>> figure out what is happening!
>>
>> Thanks in advance!!
>>
>>
>> seaside_2485pcmon.log
>>
>> [12/04/13 02:17:21.210 EST]: Client died: Slot   12, PID    2743,
>> LostOtFlags    0, Name FastCGI-11-DataCurator
>> [12/04/13 02:17:21.210 EST]: Starting crashed client recovery: Slot 12,
>> PID 2743, Name FastCGI-11-DataCurator
>>     Cleaned up locked/pinned frame 550 for crashed process 2743
>>     Cleaned up locked/pinned frame 11545 for crashed process 2743
>>     Cleaned up locked/pinned frame 3929 for crashed process 2743
>>     Cleaned up locked/pinned frame 11407 for crashed process 2743
>>     Disposing free frame cache from slot 12:  4 of 4 frames recovered.
>> [12/04/13 02:17:23.451 EST]: Finished crashed client recovery: Slot 12,
>> PID 2743, Name FastCGI-11-DataCurator
>>
>>
>> FastCGI_server-9001.log  (which is the only gem/adaptor that seems to be
>> working)
>>
>> paz 1> topaz 1> topaz 1> topaz 1> FastCGI Server started on port 9001
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T22:52:06.46091294288635-08:00UserDefinedError:
>> send(16,0x7f352f6ebba8,7416,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T22:53:06.45396900177002-08:00UserDefinedError:
>> send(17,0x7f352f786110,7416,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T23:05:07.57434701919556-08:00UserDefinedError:
>> send(14,0x7f352f65e6c0,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T23:05:31.43626189231873-08:00UserDefinedError:
>> send(15,0x7f352f6bed60,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T23:14:13.39595103263855-08:00UserDefinedError:
>> send(16,0x7f352f71f7e0,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-03T23:15:13.47269105911255-08:00UserDefinedError:
>> send(17,0x7f352f77ff90,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>>
>>
>> FastCGI_server-9002.log
>>
>> failure
>> Read-Write Conflicts...
>> Write-Write Conflicts...
>>     383168257
>> Write-Dependency Conflicts...
>> Write-ReadLock Conflicts...
>> Write-WriteLock Conflicts...
>> Rc-Write-Write Conflicts...
>> Synchronized-Commit Conflicts...
>> ----------- Commit failure - retrying LOG ENTRY:
>> aSymbolDictionary-----------
>> failure
>> Read-Write Conflicts...
>> Write-Write Conflicts...
>>     383168257
>> Write-Dependency Conflicts...
>> Write-ReadLock Conflicts...
>> Write-WriteLock Conflicts...
>> Rc-Write-Write Conflicts...
>> Synchronized-Commit Conflicts...
>> ----------- Commit failure - retrying LOG ENTRY:
>> aSymbolDictionary-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.04186797142029-08:00UserDefinedError:
>> send(16,0x7f21f9462268,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.0669538974762-08:00UserDefinedError:
>> send(17,0x7f21f94ed6c8,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.10030889511108-08:00UserDefinedError:
>> send(18,0x7f21f9551ae8,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.11388611793518-08:00UserDefinedError:
>> send(14,0x7f21f95b2918,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.12687110900879-08:00UserDefinedError:
>> send(19,0x7f21f96184e8,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.12758493423462-08:00UserDefinedError: Incorrect FCGI
>> version. Expected: 1 Received: 71-----------
>> -----------  Unreportable ERROR Encountered:
>> 2013-12-04T04:36:49.15798401832581-08:00UserDefinedError:
>> send(15,0x7f21f968f7d8,2673,0) failed with errno=107,ENOTCONN, Socket is
>> not connected-----------
>>
>>
>>
>> FastCGI_server-9003.log
>>
>>
>> --transcript--'...finished 1.4-baseline'
>> failure
>> Read-Write Conflicts...
>> Write-Write Conflicts...
>>     288128769
>>     294245633
>> Write-Dependency Conflicts...
>> Write-ReadLock Conflicts...
>> Write-WriteLock Conflicts...
>> Rc-Write-Write Conflicts...
>> Synchronized-Commit Conflicts...
>> ----------- Commit failure - retrying LOG ENTRY:
>> aSymbolDictionary-----------
>> -----------------------------------------------------
>> GemStone: Error         Nonfatal
>> a RepositoryViewLost occurred (notification 3031), When running outside
>> of a transaction the session failed to respond quickly enough to a
>> request from Stone to abort.  All object caches have been cleared.
>> nil
>> Error Category: 231169 [GemStone] Number: 3031  Arg Count: 1 Context :
>> 318063361 exception : 318063105
>> Arg 1: [20 sz:0 cls: 76289 UndefinedObject] nil
>> topaz > exec iferr 1 : where
>> ==> 1 AbstractException >> _signalWith:             (envId 0) @6 line 25
>> [methId 4496129]
>> 2 [] in  AbstractException >> _signalAsync      (envId 0) @2 line 19
>> [methId 4605185]
>> 3 ExecBlock >> ensure:                          (envId 0) @2 line 12
>> [methId 3709185]
>> 4 AbstractException >> _signalAsync             (envId 0) @6 line 21
>> [methId 4600321]
>> 5 ProcessorScheduler >> _reapEvents:            (envId 0) @96 line 86
>> [methId 4810241]
>> 6 ProcessorScheduler >> _findReadyProcess:      (envId 0) @2 line 8
>> [methId 4815105]
>> 7 ProcessorScheduler >> _reschedule             (envId 0) @3 line 8
>> [methId 4805121]
>> 8 GsProcess >> _wait                            (envId 0) @3 line 3
>> [methId 4486145]
>> 9 Delay >> _wait:                               (envId 0) @26 line 26
>> [methId 13285377]
>> 10 Delay >> wait                                 (envId 0) @3 line 5
>> [methId 13307905]
>> 11 [] in  Executed Code                          (envId 0) @3 line 32
>> [methId 318074625]
>> 12 GsProcess >> _start                           (envId 0) @7 line 16
>> [methId 4467969]
>> 13 GsNMethod class >> _gsReturnToC               (envId 0) @1 line 1
>> [methId 4461825]
>>   [GsProcess 318063361]
>> topaz 1> topaz 1> [268 sz:0 cls: 68097 Boolean] true
>>
>>
>>
>>
>>
>>
>>
>>
>>> Johan
>>>
>>> On 26 Nov 2013, at 00:33, Mariano Martinez Peck &lt;

> marianopeck@

> &gt;
>>> wrote:
>>>
>>> Also, when I see that 1-minute request in the browser development tools,
>>> it appears like 2ms receiving, 1 minute waiting...weird!
>>>
>>>
>>> On Mon, Nov 25, 2013 at 8:26 PM, Mariano Martinez Peck <
>>>

> marianopeck@

>> wrote:
>>>
>>>> HI guys. This is the first time I am trying to use FastCGI. For some
>>>> reason, i have a timeout with fastCGI.
>>>> I started the Gems either with:
>>>>
>>>>
>>>> WAGemStoneRunSeasideGems default
>>>>         name: 'FastCGI';
>>>>         adaptorClass: WAFastCGIAdaptor;
>>>>         ports: #(9001 9002 9003).
>>>> WAGemStoneRunSeasideGems restartGems.
>>>>
>>>> (from GemTools) or from command line:
>>>>
>>>> ./startSeaside_FastCGI 9001
>>>>
>>>> In either case, what happens is that I can browse my app
>>>> http:localhost:9001/dp (and 9002 and 9003). But when I do a request to
>>>> the
>>>> server trough my FastCGI, it takes ONE MINUTE to load the page. I am
>>>> using
>>>> Nginx in the backend with this configuration:
>>>>
>>>>     upstream seaside
>>>>       {
>>>>         server localhost:9001;
>>>>         server localhost:9002;
>>>>         server localhost:9003;
>>>>       }
>>>>
>>>>       server
>>>>       {
>>>>
>>>> listen 33300;
>>>> server_name localhost;
>>>>         root /var/www/glass/;
>>>>
>>>>
>>>>     access_log  /var/log/nginx/fastCGI.log;
>>>>     error_log  /var/log/nginx/error.log info;
>>>>
>>>>         location /
>>>>         {
>>>>             try_files $uri @seaside;
>>>>   #  error_page 403 404 = @seaside;
>>>>         }
>>>>
>>>>         location @seaside
>>>>         {
>>>>           include fastcgi_params;
>>>>           fastcgi_pass seaside;
>>>>         }
>>>>       }
>>>>
>>>>
>>>> Using the webtools of the browser, I see that each time I go to a page,
>>>> there is either a GET or a POST that takes exactly 1 minute. I
>>>> mean...nothing happens, until one minute passes and then the page is
>>>> rendered. The requests are small.  And in fact, browsing directly to
>>>> 9001/2/3 works perfectly. So I guess this is a one minute timeout of
>>>> something.
>>>>
>>>> For what I can see, it could be related to the
>>>>
>>>>  keepalive_timeout  65;
>>>>
>>>> And in nginx error.log I see something like:
>>>>
>>>> 2013/11/25 17:38:18 [error] 22835#0: *73 upstream timed out (60:
>>>> Operation timed out) while reading response header from upstream,
>>>> client:
>>>> 127.0.0.1, server: localhost, request: "GET /dp HTTP/1.1", upstream:
>>>> "fastcgi://127.0.0.1:9001", host: "localhost:33300"
>>>> 2013/11/25 17:38:18 [info] 22835#0: *73 kevent() reported that client
>>>> 127.0.0.1 closed keepalive connection
>>>>
>>>> Any ideas what could be wrong?
>>>>
>>>>
>>>> Thanks!
>>>>
>>>> --
>>>> Mariano
>>>> http://marianopeck.wordpress.com
>>>>
>>>
>>>
>>>
>>> --
>>> Mariano
>>> http://marianopeck.wordpress.com
>>>
>>> _______________________________________________
>>>
>>> Glass mailing list
>>>

> Glass@.gemtalksystems
> _______________________________________________
> Glass mailing list

> Glass@.gemtalksystems

> http://lists.gemtalksystems.com/mailman/listinfo/glass





--
View this message in context: http://forum.world.st/Glass-Nginx-FastCGI-and-GLASS-problem-tp4725218p4727568.html
Sent from the GLASS mailing list archive at Nabble.com.
_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass



--
Mariano
http://marianopeck.wordpress.com



--
Mariano
http://marianopeck.wordpress.com



--
Mariano
http://marianopeck.wordpress.com



--
Mariano
http://marianopeck.wordpress.com

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Reply | Threaded
Open this post in threaded view
|

Re: [Glass] Nginx , FastCGI and GLASS problem

Johan Brichau-3
In reply to this post by Mariano Martinez Peck
Mariano,

The logs you show looks so similar to what I see in our gem logs when a gem stops responding...
When it occurs, can you look at the object with the mentioned oop in the write-write conflicts:

> Write-Write Conflicts...
>     383168257
> Write-Dependency Conflicts...

Inspect this:

        Object _objectForOop: 383168257

In my case this always opens on a dictionary with the #cacheTimeout property in it.
Is this also true in your case?

Johan
_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Reply | Threaded
Open this post in threaded view
|

Re: [Glass] Nginx , FastCGI and GLASS problem

Mariano Martinez Peck



On Thu, Dec 5, 2013 at 1:43 PM, Johan Brichau <[hidden email]> wrote:
Mariano,

The logs you show looks so similar to what I see in our gem logs when a gem stops responding...
When it occurs, can you look at the object with the mentioned oop in the write-write conflicts:

> Write-Write Conflicts...
>     383168257
> Write-Dependency Conflicts...

Inspect this:

        Object _objectForOop: 383168257

In my case this always opens on a dictionary with the #cacheTimeout property in it.
Is this also true in your case?


Thanks Johan for the advice. Unfortunately, I restarted everything did some changes etc so that OOP doesn't exist anymore :(

But I will keep it in case I need it again.

BTW, in my case I discovered the problem...it's that reading from /dev/random is blocking and when you run the OS in a virtual machine (like in my case I am using a VirtualBox vm) it is likely it will block for some time. There are lot of info about this in the internet. 
So at least that was my problem.

Thanks,

--
Mariano
http://marianopeck.wordpress.com

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Reply | Threaded
Open this post in threaded view
|

Re: [Glass] Nginx , FastCGI and GLASS problem

Johan Brichau-3
And were you being blocked outside of a transaction or not? Because that is what the error says. I am getting this from time to time and still looking for a reason. 


Johan (sent from my mobile)

On 05 Dec 2013, at 17:48, Mariano Martinez Peck <[hidden email]> wrote:




On Thu, Dec 5, 2013 at 1:43 PM, Johan Brichau <[hidden email]> wrote:
Mariano,

The logs you show looks so similar to what I see in our gem logs when a gem stops responding...
When it occurs, can you look at the object with the mentioned oop in the write-write conflicts:

> Write-Write Conflicts...
>     383168257
> Write-Dependency Conflicts...

Inspect this:

        Object _objectForOop: 383168257

In my case this always opens on a dictionary with the #cacheTimeout property in it.
Is this also true in your case?


Thanks Johan for the advice. Unfortunately, I restarted everything did some changes etc so that OOP doesn't exist anymore :(

But I will keep it in case I need it again.

BTW, in my case I discovered the problem...it's that reading from /dev/random is blocking and when you run the OS in a virtual machine (like in my case I am using a VirtualBox vm) it is likely it will block for some time. There are lot of info about this in the internet. 
So at least that was my problem.

Thanks,

--
Mariano
http://marianopeck.wordpress.com

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Reply | Threaded
Open this post in threaded view
|

Re: [Glass] Nginx , FastCGI and GLASS problem

Dale Henrichs-3




From: "Johan Brichau" <[hidden email]>
To: "Mariano Martinez Peck" <[hidden email]>
Cc: [hidden email]
Sent: Thursday, December 5, 2013 9:09:46 AM
Subject: Re: [Glass] Nginx , FastCGI and GLASS problem

And were you being blocked outside of a transaction or not? Because that is what the error says. I am getting this from time to time and still looking for a reason.
Mariano, I assume that you are running in a 3.1.x system?

Johan, are you seeing this in 2.4.x or 3.1.x?

I'm going to give you guys a revised start fastCGI script with a handler for the "lost ot" error so that we can get some better information about what's going on ...

Dale

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Reply | Threaded
Open this post in threaded view
|

Re: [Glass] Nginx , FastCGI and GLASS problem

Mariano Martinez Peck
In reply to this post by Johan Brichau-3



On Thu, Dec 5, 2013 at 2:09 PM, Johan Brichau <[hidden email]> wrote:
And were you being blocked outside of a transaction or not?

Sorry Johan, I didn't understand the question. 
But yes, I think I was being block outside the transaction. 
 
Because that is what the error says. I am getting this from time to time and still looking for a reason. 


Johan (sent from my mobile)

On 05 Dec 2013, at 17:48, Mariano Martinez Peck <[hidden email]> wrote:




On Thu, Dec 5, 2013 at 1:43 PM, Johan Brichau <[hidden email]> wrote:
Mariano,

The logs you show looks so similar to what I see in our gem logs when a gem stops responding...
When it occurs, can you look at the object with the mentioned oop in the write-write conflicts:

> Write-Write Conflicts...
>     383168257
> Write-Dependency Conflicts...

Inspect this:

        Object _objectForOop: 383168257

In my case this always opens on a dictionary with the #cacheTimeout property in it.
Is this also true in your case?


Thanks Johan for the advice. Unfortunately, I restarted everything did some changes etc so that OOP doesn't exist anymore :(

But I will keep it in case I need it again.

BTW, in my case I discovered the problem...it's that reading from /dev/random is blocking and when you run the OS in a virtual machine (like in my case I am using a VirtualBox vm) it is likely it will block for some time. There are lot of info about this in the internet. 
So at least that was my problem.

Thanks,

--
Mariano
http://marianopeck.wordpress.com



--
Mariano
http://marianopeck.wordpress.com

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Reply | Threaded
Open this post in threaded view
|

Re: [Glass] Nginx , FastCGI and GLASS problem

Dale Henrichs-3
In reply to this post by Johan Brichau-3
Johan and Mariano,

For 3.1, I think the following should work in the startSeaside30_Adaptor script. NOTE, I've used `true ifTrue: [] ifFalse:[]` to enclose the new-style static exception handler that in addition to handling (and logging) the fact that a SigAbort was handled installs a handler for the RepositoryViewLost notification that dumps a stack so we can get more info about what the gem is doing when the lost ot is issued:

true ifTrue: [.
Transcript cr; show: 'New style SigAbort hanlder'.
TransactionBacklog
  addDefaultHandler: [ :ex |.
    "Run the abort in a lowPriority process, since we must acquire the
     transactionMutex."
    Transcript cr; show: 'handled sigabort: ', DateAndTime now printString.
    [
      GRPlatform current transactionMutex
        critical: [ GRPlatform current doAbortTransaction ].
      TransactionBacklog enableSignalling ]
        forkAt: Processor lowestPriority.
      ex resume ].
 RepositoryViewLost
   addDefaultHandler: [ :ex |.
     GRPlatform current logError: ex description title: 'Lost OT' shouldCommit: false.
     ex pass ].
TransactionBacklog enableSignalling.
] ifFalse: [
Transcript cr; show: 'Old style SigAbort hanlder'.
Exception.
  installStaticException:.
    [:ex :cat :num :args |
      "Run the abort in a lowPriority process, since we must acquire the
       transactionMutex."
      Transcript cr; show: 'handled sigabort: ', DateAndTime now printString.
      [
        GRPlatform current transactionMutex.
          critical: [.
            GRPlatform current doAbortTransaction ].
        System enableSignaledAbortError.
      ] forkAt: Processor lowestPriority.
    ]
  category: GemStoneError
  number: 6009
  subtype: nil.
System enableSignaledAbortError.
].

If this is happening in 2.4 (Johan), I'll have to do a little more research to see if there is an exception equivalent to RepositoryViewLost signalled.

Dale

From: "Johan Brichau" <[hidden email]>
To: "Mariano Martinez Peck" <[hidden email]>
Cc: [hidden email]
Sent: Thursday, December 5, 2013 9:09:46 AM
Subject: Re: [Glass] Nginx , FastCGI and GLASS problem

And were you being blocked outside of a transaction or not? Because that is what the error says. I am getting this from time to time and still looking for a reason. 


Johan (sent from my mobile)

On 05 Dec 2013, at 17:48, Mariano Martinez Peck <[hidden email]> wrote:




On Thu, Dec 5, 2013 at 1:43 PM, Johan Brichau <[hidden email]> wrote:
Mariano,

The logs you show looks so similar to what I see in our gem logs when a gem stops responding...
When it occurs, can you look at the object with the mentioned oop in the write-write conflicts:

> Write-Write Conflicts...
>     383168257
> Write-Dependency Conflicts...

Inspect this:

        Object _objectForOop: 383168257

In my case this always opens on a dictionary with the #cacheTimeout property in it.
Is this also true in your case?


Thanks Johan for the advice. Unfortunately, I restarted everything did some changes etc so that OOP doesn't exist anymore :(

But I will keep it in case I need it again.

BTW, in my case I discovered the problem...it's that reading from /dev/random is blocking and when you run the OS in a virtual machine (like in my case I am using a VirtualBox vm) it is likely it will block for some time. There are lot of info about this in the internet. 
So at least that was my problem.

Thanks,

--
Mariano
http://marianopeck.wordpress.com

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass


_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
12