What do these error messages mean?

Hi everyone,
Hi Dale ;-)

I'm seeing these kinds of error messages in my logs. When this happens, the system also seems to hog down.
Any ideas of what I should be looking at to find the origin of these errors?

I found this thread: http://forum.world.st/Issue-282-in-glassdb-Swazoo-server-crashing-with-aGsSocket-that-has-some-associated-session-state-har-td3705456.html   But I'm using Fastcgi.


-----------  Unreportable ERROR Encountered: 2011-09-20T11:28:42.02116894721985+02:00send(8,0x8f7ee90,65535,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2011-09-20T11:28:42.19034600257874+02:00InterpreterError 2364: The object <aGsSocket> that has some associated session state has lost that transient state. Examples of classes that use session state are GsSocket and GsFile.-----------
-----------  Unreportable ERROR Encountered: 2011-09-20T11:28:42.3823390007019+02:00InterpreterError 2364: The object <aGsSocket> that has some associated session state has lost that transient state. Examples of classes that use session state are GsSocket and GsFile.-----------
-----------  Unreportable ERROR Encountered: 2011-09-20T11:28:42.53602409362793+02:00InterpreterError 2364: The object <aGsSocket> that has some associated session state has lost that transient state. Examples of classes that use session state are GsSocket and GsFile.-----------
-----------  Unreportable ERROR Encountered: 2011-09-20T11:28:42.69039011001587+02:00send(12,0x8fae060,14214,0) failed with errno=107,ENOTCONN,
Socket is not connected-----------


and somewhere else:


-----------  Unreportable ERROR Encountered: 2011-09-20T10:36:41.4460608959198+02:00send(8,0x5a2fd70,65535,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2011-09-20T10:36:41.51716709136963+02:00send(8,0x7fff7df65d30,134,0) failed with errno=107,ENOTCONN, Socket is not connected-----------
-----------  Unreportable ERROR Encountered: 2011-09-20T10:37:22.28720808029175+02:00send(8,0x5abf4b0,26618,0) failed with errno=107,ENOTCONN, Socket is not connected-----------


Johan

Johan,

>From one of our engineers:

> InterpreterError 2364: The
> | object<aGsSocket>  that has some associated session state has lost
> | that transient state. Examples of classes that use session state are
> | GsSocket and GsFile.
> and

A GsSocket got committed, dropped out of memory and then faulted
back in, thereby loosing any connection state for the GsSocket.
>
> 2011-09-20T10:36:41.4460608959198+02:00send(8,0x5a2fd70,65535,0)
> | failed with errno=107,ENOTCONN, Socket is not connected-

The TCP connection associated with a GsSocket disconnected

==============

For error 2364, it means that someone has referenced the socket again to either read/write or close it ... Perhaps you can dump the stack. Calling the following at the point where you log the 2364 error would make sure the stack is dumped in the log:

  GRPlatform current logError: 'xxx' title: 'xxx'.

The second error (ENOTCONN) sounds like a variant of the first, only that the socket wasn't flushed/faulted ... stack would help here too...

Dale

----- Original Message -----
| From: "Johan Brichau" <[hidden email]>
| To: "GemStone Seaside beta discussion" <[hidden email]>
| Sent: Wednesday, September 21, 2011 3:43:51 PM
| Subject: [GS/SS Beta] What do these error messages mean?
|
| Hi everyone,
| Hi Dale ;-)
|
| I'm seeing these kinds of error messages in my logs. When this
| happens, the system also seems to hog down.
| Any ideas of what I should be looking at to find the origin of these
| errors?
|
| I found this thread:
| http://forum.world.st/Issue-282-in-glassdb-Swazoo-server-crashing-with-aGsSocket-that-has-some-associated-session-state-har-td3705456.html
|   But I'm using Fastcgi.
|
|
| -----------  Unreportable ERROR Encountered:
| 2011-09-20T11:28:42.02116894721985+02:00send(8,0x8f7ee90,65535,0)
| failed with errno=107,ENOTCONN, Socket is not connected-----------
| -----------  Unreportable ERROR Encountered:
| 2011-09-20T11:28:42.19034600257874+02:00InterpreterError 2364: The
| object <aGsSocket> that has some associated session state has lost
| that transient state. Examples of classes that use session state are
| GsSocket and GsFile.-----------
| -----------  Unreportable ERROR Encountered:
| 2011-09-20T11:28:42.3823390007019+02:00InterpreterError 2364: The
| object <aGsSocket> that has some associated session state has lost
| that transient state. Examples of classes that use session state are
| GsSocket and GsFile.-----------
| -----------  Unreportable ERROR Encountered:
| 2011-09-20T11:28:42.53602409362793+02:00InterpreterError 2364: The
| object <aGsSocket> that has some associated session state has lost
| that transient state. Examples of classes that use session state are
| GsSocket and GsFile.-----------
| -----------  Unreportable ERROR Encountered:
| 2011-09-20T11:28:42.69039011001587+02:00send(12,0x8fae060,14214,0)
| failed with errno=107,ENOTCONN,
| Socket is not connected-----------
|
|
| and somewhere else:
|
|
| -----------  Unreportable ERROR Encountered:
| 2011-09-20T10:36:41.4460608959198+02:00send(8,0x5a2fd70,65535,0)
| failed with errno=107,ENOTCONN, Socket is not connected-----------
| -----------  Unreportable ERROR Encountered:
| 2011-09-20T10:36:41.51716709136963+02:00send(8,0x7fff7df65d30,134,0)
| failed with errno=107,ENOTCONN, Socket is not connected-----------
| -----------  Unreportable ERROR Encountered:
| 2011-09-20T10:37:22.28720808029175+02:00send(8,0x5abf4b0,26618,0)
| failed with errno=107,ENOTCONN, Socket is not connected-----------
|
|
| Johan

Hi Dale,

Thanks for that information. I will try to catch some stack dumps.

I have another one that I am seeing occasionally since we fixed the transactionMutex.
I think I know what it means, but I don't understand how it can happen in a seaside gem.


GemStone: Error         Nonfatal
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.  ---
Error Category: 231169 [GemStone] Number: 3031 Arg Count: 0 Context : 1362441473

Now executing the following command saved from "iferr 1":
   where
==> 1 ProcessorScheduler >> _reapEvents: @63 line 65   [GsMethod 10209537]
2 ProcessorScheduler >> _findReadyProcess @2 line 7   [GsMethod 10204417]
3 ProcessorScheduler >> _reschedule @2 line 8   [GsMethod 10207489]
4 GsProcess >> _wait @2 line 3   [GsMethod 4503553]
5 Delay >> wait @23 line 23   [GsMethod 11755009]
6 SimpleBlock in Executed Code @18 line 23   [GsMethod 5704714241]
7 GsProcess >> _startPart2 @15 line 17   [GsMethod 4501249]
8 GsProcess >> _start @1 line 9   [GsMethod 4501761]
  [GsProcess 1362441473]
topaz 1> [268 sz:0 cls: 68097 Boolean] true
topaz 1>
[Info]: Logging out at 09/22/11 18:43:29 CEST

On 22 Sep 2011, at 18:15, Dale Henrichs wrote:

Johan,

There should be some code in the topaz script for the seaside server that looks like the following:

System transactionMode: #manualBegin.

Exception
  installStaticException:
    [:ex :cat :num :args |
      "Run the abort in a lowPriority process, since we must acquire the
       transactionMutex."
      [
        SeasidePlatformSupport transactionMutex
          critical: [
            SeasidePlatformSupport doAbortTransaction ].
        System enableSignaledAbortError.
      ] forkAt: Processor lowestPriority.
    ]
  category: GemStoneError
  number: 6009
  subtype: nil.
System enableSignaledAbortError.
"This thread is needed to handle the SigAbort exception, when the primary
 thread is blocked on an accept. Assuming default 60 second
 STN_GEM_ABORT_TIMEOUT, wake up at 30 second intervals."
[
  [ true ] whileTrue: [ (Delay forSeconds: 30) wait ].
] forkAt: Processor lowestPriority.

The code puts the system into manual transaction mode and installs a SigAbort handler. The forked process makes sure that the sigabort handler can run when the main thread is blocked on a socket accept ...

If your script has that code and your system is heavily loaded it is possible that forked thread doesn't get a chance to run before the stone decides the gem isn't going to respond ...

Dale  

----- Original Message -----
| From: "Johan Brichau" <[hidden email]>
| To: "GemStone Seaside beta discussion" <[hidden email]>
| Sent: Thursday, September 22, 2011 10:15:10 AM
| Subject: Re: [GS/SS Beta] What do these error messages mean?
|
| Hi Dale,
|
| Thanks for that information. I will try to catch some stack dumps.
|
| I have another one that I am seeing occasionally since we fixed the
| transactionMutex.
| I think I know what it means, but I don't understand how it can
| happen in a seaside gem.
|
|
| GemStone: Error         Nonfatal
| 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.  ---
| Error Category: 231169 [GemStone] Number: 3031 Arg Count: 0 Context :
| 1362441473
|
| Now executing the following command saved from "iferr 1":
|    where
| ==> 1 ProcessorScheduler >> _reapEvents: @63 line 65   [GsMethod
| 10209537]
| 2 ProcessorScheduler >> _findReadyProcess @2 line 7   [GsMethod
| 10204417]
| 3 ProcessorScheduler >> _reschedule @2 line 8   [GsMethod 10207489]
| 4 GsProcess >> _wait @2 line 3   [GsMethod 4503553]
| 5 Delay >> wait @23 line 23   [GsMethod 11755009]
| 6 SimpleBlock in Executed Code @18 line 23   [GsMethod 5704714241]
| 7 GsProcess >> _startPart2 @15 line 17   [GsMethod 4501249]
| 8 GsProcess >> _start @1 line 9   [GsMethod 4501761]
|   [GsProcess 1362441473]
| topaz 1> [268 sz:0 cls: 68097 Boolean] true
| topaz 1>
| [Info]: Logging out at 09/22/11 18:43:29 CEST
|
| On 22 Sep 2011, at 18:15, Dale Henrichs wrote:
|
| > Johan,
| >
| >> From one of our engineers:
| >
| >> InterpreterError 2364: The
| >> | object<aGsSocket>  that has some associated session state has
| >> | lost
| >> | that transient state. Examples of classes that use session state
| >> | are
| >> | GsSocket and GsFile.
| >> and
| >
| > A GsSocket got committed, dropped out of memory and then faulted
| > back in, thereby loosing any connection state for the GsSocket.
| >>
| >> 2011-09-20T10:36:41.4460608959198+02:00send(8,0x5a2fd70,65535,0)
| >> | failed with errno=107,ENOTCONN, Socket is not connected-
| >
| > The TCP connection associated with a GsSocket disconnected
| >
| > ==============
| >
| > For error 2364, it means that someone has referenced the socket
| > again to either read/write or close it ... Perhaps you can dump
| > the stack. Calling the following at the point where you log the
| > 2364 error would make sure the stack is dumped in the log:
| >
| >  GRPlatform current logError: 'xxx' title: 'xxx'.
| >
| > The second error (ENOTCONN) sounds like a variant of the first,
| > only that the socket wasn't flushed/faulted ... stack would help
| > here too...
| >
| > Dale
| >
| > ----- Original Message -----
| > | From: "Johan Brichau" <[hidden email]>
| > | To: "GemStone Seaside beta discussion"
| > | <[hidden email]>
| > | Sent: Wednesday, September 21, 2011 3:43:51 PM
| > | Subject: [GS/SS Beta] What do these error messages mean?
| > |
| > | Hi everyone,
| > | Hi Dale ;-)
| > |
| > | I'm seeing these kinds of error messages in my logs. When this
| > | happens, the system also seems to hog down.
| > | Any ideas of what I should be looking at to find the origin of
| > | these
| > | errors?
| > |
| > | I found this thread:
| > | http://forum.world.st/Issue-282-in-glassdb-Swazoo-server-crashing-with-aGsSocket-that-has-some-associated-session-state-har-td3705456.html
| > |   But I'm using Fastcgi.
| > |
| > |
| > | -----------  Unreportable ERROR Encountered:
| > | 2011-09-20T11:28:42.02116894721985+02:00send(8,0x8f7ee90,65535,0)
| > | failed with errno=107,ENOTCONN, Socket is not
| > | connected-----------
| > | -----------  Unreportable ERROR Encountered:
| > | 2011-09-20T11:28:42.19034600257874+02:00InterpreterError 2364:
| > | The
| > | object <aGsSocket> that has some associated session state has
| > | lost
| > | that transient state. Examples of classes that use session state
| > | are
| > | GsSocket and GsFile.-----------
| > | -----------  Unreportable ERROR Encountered:
| > | 2011-09-20T11:28:42.3823390007019+02:00InterpreterError 2364: The
| > | object <aGsSocket> that has some associated session state has
| > | lost
| > | that transient state. Examples of classes that use session state
| > | are
| > | GsSocket and GsFile.-----------
| > | -----------  Unreportable ERROR Encountered:
| > | 2011-09-20T11:28:42.53602409362793+02:00InterpreterError 2364:
| > | The
| > | object <aGsSocket> that has some associated session state has
| > | lost
| > | that transient state. Examples of classes that use session state
| > | are
| > | GsSocket and GsFile.-----------
| > | -----------  Unreportable ERROR Encountered:
| > | 2011-09-20T11:28:42.69039011001587+02:00send(12,0x8fae060,14214,0)
| > | failed with errno=107,ENOTCONN,
| > | Socket is not connected-----------
| > |
| > |
| > | and somewhere else:
| > |
| > |
| > | -----------  Unreportable ERROR Encountered:
| > | 2011-09-20T10:36:41.4460608959198+02:00send(8,0x5a2fd70,65535,0)
| > | failed with errno=107,ENOTCONN, Socket is not
| > | connected-----------
| > | -----------  Unreportable ERROR Encountered:
| > | 2011-09-20T10:36:41.51716709136963+02:00send(8,0x7fff7df65d30,134,0)
| > | failed with errno=107,ENOTCONN, Socket is not
| > | connected-----------
| > | -----------  Unreportable ERROR Encountered:
| > | 2011-09-20T10:37:22.28720808029175+02:00send(8,0x5abf4b0,26618,0)
| > | failed with errno=107,ENOTCONN, Socket is not
| > | connected-----------
| > |
| > |
| > | Johan
|
|