[Glass] Nginx , FastCGI and GLASS problem
Mariano Martinez Peck
marianopeck at gmail.com
Wed Dec 4 15:12:44 PST 2013
On Wed, Dec 4, 2013 at 7:29 PM, Paul DeBruicker <pdebruic at gmail.com> 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 <
>
> > marianopeck@
>
> > > wrote:
> >
> >>
> >>
> >>
> >> On Tue, Nov 26, 2013 at 3:22 AM, Johan Brichau <
>
> > johan@
>
> > > 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@
>
> > >
> >>> 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 at .gemtalksystems
>
> >>> http://lists.gemtalksystems.com/mailman/listinfo/glass
> >>>
> >>>
> >>
> >>
> >> --
> >> Mariano
> >> http://marianopeck.wordpress.com
> >>
> >
> >
> >
> > --
> > Mariano
> > http://marianopeck.wordpress.com
> >
> > _______________________________________________
> > Glass mailing list
>
> > Glass at .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
> 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/3d15e637/attachment-0001.html>
More information about the Glass
mailing list