[Glass] Nginx , FastCGI and GLASS problem
Mariano Martinez Peck
marianopeck at gmail.com
Wed Dec 4 20:18:50 PST 2013
http://stackoverflow.com/questions/4819359/dev-random-extremely-slow
that makes it!
On Thu, Dec 5, 2013 at 1:13 AM, Mariano Martinez Peck <marianopeck at gmail.com
> 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 <
> marianopeck at gmail.com> 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 <
>> marianopeck at gmail.com> wrote:
>>
>>>
>>>
>>> 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
>>>
>>
>>
>>
>> --
>> Mariano
>> http://marianopeck.wordpress.com
>>
>
>
>
> --
> Mariano
> http://marianopeck.wordpress.com
>
--
Mariano
http://marianopeck.wordpress.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.gemtalksystems.com/mailman/private/glass/attachments/20131205/c3dfbb84/attachment-0001.html>
More information about the Glass
mailing list