[Glass] Nginx , FastCGI and GLASS problem
Mariano Martinez Peck
marianopeck at gmail.com
Wed Dec 4 04:56:12 PST 2013
On Tue, Nov 26, 2013 at 3:22 AM, Johan Brichau <johan at yesplan.be> 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 <marianopeck at gmail.com>
> 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 at gmail.com> 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 at lists.gemtalksystems.com
> http://lists.gemtalksystems.com/mailman/listinfo/glass
>
>
--
Mariano
http://marianopeck.wordpress.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.gemtalksystems.com/mailman/private/glass/attachments/20131204/105b66cd/attachment-0001.html>
More information about the Glass
mailing list