[omniORB] Clarification needed

Tue Apr 27 21:37:16 BST 2004

Hello!
In the begining of the function giopStrand::acquireServer(giopWorker* w) 
there is some description of the thread/strand model called "Theory of 
operation". It states (citing):
   // One or more threads may serve the same strand. However, only
   // one thread works on the same GIOP_S instance. This invariant
   // is enforced by this function.
However in processing of CancelRequest message the instance of GIOP_S is 
being worken on by two threads simultaneously. In attachment is a 
extensive log with thread ids appended to each line and small file with 
thread-instance relation. In this log this misbehaviour is plainly seen.

It seems to me that misbehaviour is closely related to bugs seen by me 
and my coworker. Namely in my case (message 
omniorb-list/2004-April/025334.html) when it constructs and then destroy 
  GIOP_S_Holder that it shouldn't. And in case of my coworker (message 
omniorb-list/2003-December/024654.html) when it loops infinitely.

I wrote servant that does following when activated:
1. sleeps for 20 seconds
2. returns some data

Please, tell me if my investigations are heading right direction.
Thanks in advance.

-- 
Regards,
Andrei Zaparii
-------------- next part --------------
Reading config from /home/zappa/work/maps/src/guts/servant.cfg
in CORBA::ORB_init Pure debug version used
omniORB: (0) Distribution date: Thu Apr  8 11:06:08 BST 2004 dgrisby
omniORB: (0) Information: the omniDynamic library is not linked.
omniORB: (0) Invoke '_is_a' on remote: key<NameService>
enter giopStream::inputMessage got to line 785 (tid: 0)
in giopStream::inputMessage got to line 790 (tid: 0)
in giopStream::inputMessage got to line 833 (tid: 0)
in giopStream::inputMessage got to line 840 (tid: 0)
in giopStream::inputMessage got to line 856 (tid: 0)
in giopStream::inputMessage got to line 868 (tid: 0)
in giopStream::inputMessage got to line 872 (tid: 0)
in giopStream::inputMessage got to line 980 (tid: 0)
omniORB: (0) Invoke 'resolve' on remote: key<NameService>
enter giopStream::inputMessage got to line 785 (tid: 0)
in giopStream::inputMessage got to line 790 (tid: 0)
in giopStream::inputMessage got to line 825 (tid: 0)
in giopStream::inputMessage got to line 840 (tid: 0)
in giopStream::inputMessage got to line 856 (tid: 0)
in giopStream::inputMessage got to line 868 (tid: 0)
in giopStream::inputMessage got to line 872 (tid: 0)
in giopStream::inputMessage got to line 980 (tid: 0)
enter giopImpl12::inputMessageBegin for giopStream 0x807a3f4 (tid: 0)
in giopImpl12::inputMessageBegin got to line 713 (tid: 0)
enter giopImpl12::inputReplyBegin for giopStream 0x807a3f4 (tid: 0)
enter giopStream::inputMessage got to line 785 (tid: 0)
in giopStream::inputMessage got to line 790 (tid: 0)
in giopStream::inputMessage got to line 833 (tid: 0)
in giopStream::inputMessage got to line 840 (tid: 0)
in giopStream::inputMessage got to line 856 (tid: 0)
in giopStream::inputMessage got to line 868 (tid: 0)
in giopStream::inputMessage got to line 872 (tid: 0)
in giopStream::inputMessage got to line 980 (tid: 0)
enter giopImpl12::inputQueueMessage for giopStream 0x807a3f4 (tid: 0)
in giopImpl12::inputQueueMessage got to line 227 (tid: 0)
in giopImpl12::inputQueueMessage got to line 267 (tid: 0)
in giopImpl12::inputQueueMessage got to line 274 (tid: 0)
omniORB: (0) Invoke 'bind' on remote: root/<3af044400100021a/286>
enter giopImpl12::inputMessageBegin for giopStream 0x807a3f4 (tid: 0)
in giopImpl12::inputMessageBegin got to line 713 (tid: 0)
enter giopImpl12::inputReplyBegin for giopStream 0x807a3f4 (tid: 0)
enter giopStream::inputMessage got to line 785 (tid: 0)
in giopStream::inputMessage got to line 790 (tid: 0)
in giopStream::inputMessage got to line 825 (tid: 0)
in giopStream::inputMessage got to line 840 (tid: 0)
in giopStream::inputMessage got to line 856 (tid: 0)
in giopStream::inputMessage got to line 868 (tid: 0)
in giopStream::inputMessage got to line 872 (tid: 0)
in giopStream::inputMessage got to line 980 (tid: 0)
enter giopImpl12::inputQueueMessage for giopStream 0x807a3f4 (tid: 0)
in giopImpl12::inputQueueMessage got to line 227 (tid: 0)
in giopImpl12::inputQueueMessage got to line 267 (tid: 0)
in giopImpl12::inputQueueMessage got to line 274 (tid: 0)
omniORB: (0) Invoke 'rebind' on remote: root/<3af044400100021a/286>
enter giopImpl12::inputMessageBegin for giopStream 0x807a3f4 (tid: 0)
in giopImpl12::inputMessageBegin got to line 713 (tid: 0)
enter giopImpl12::inputReplyBegin for giopStream 0x807a3f4 (tid: 0)
enter giopStream::inputMessage got to line 785 (tid: 0)
in giopStream::inputMessage got to line 790 (tid: 0)
in giopStream::inputMessage got to line 825 (tid: 0)
in giopStream::inputMessage got to line 840 (tid: 0)
in giopStream::inputMessage got to line 856 (tid: 0)
in giopStream::inputMessage got to line 868 (tid: 0)
in giopStream::inputMessage got to line 872 (tid: 0)
in giopStream::inputMessage got to line 980 (tid: 0)
enter giopImpl12::inputQueueMessage for giopStream 0x807a3f4 (tid: 0)
in giopImpl12::inputQueueMessage got to line 227 (tid: 0)
in giopImpl12::inputQueueMessage got to line 267 (tid: 0)
in giopImpl12::inputQueueMessage got to line 274 (tid: 0)
IDL object Yandex::Maps::MapGuts IOR = 'IOR:010000001c00000049444c3a59616e6465782f4d6170732f4d6170477574733a312e300001000000000000006800000001010200100000003231332e3138302e3139332e31303400ad71000010000000ff6d617067757473006d6170677574730200000000000000080000000100000000545441010000001c00000001000000010001050100000001000105090101000100000009010100'
enter giopServer::notifyRzReadable called for 0x8079fd8 (tid: 2)
in giopServer::notifyRzReadable line 843 (tid: 2)
in giopServer::notifyRzReadable line 856 (tid: 2)
ctor giopWorker 0x8079f18 with strand 0x807e558, server 0x8078bf0 and singleshot=1 (tid: 2)
in giopServer::notifyRzReadable line 864 (tid: 2)
entering giopWorker::execute (tid: 3)
ctor giopWorkerInfo for 0x8079f18 (tid: 3)
entering giopWorker::real_execute (tid: 3)
omniORB: (3) Accepted connection from giop:tcp:213.180.193.104:56293 because of this rule: "* unix,ssl,tcp"
Init ctor GIOP_S instance 0x807e720 for operation  (tid: 3)
Init ctor GIOP_S_Holder instance 0xbf3ff934 for IOP_S 0x807e720 (tid: 3)
in giopWorker::real_execute iop_s is 0x807e720 iteration 1 (tid: 3)
in GIOP_S::dispatcher 0x807e720 state is 1 (tid: 3)
in GIOP_S::dispatcher 0x807e720 got to line 241 (tid: 3)
enter giopImpl12::inputMessageBegin for giopStream 0x807e724 (tid: 3)
in giopImpl12::inputMessageBegin got to line 718 (tid: 3)
in giopImpl12::inputMessageBegin got to line 728 (tid: 3)
in giopImpl12::inputMessageBegin got to line 741 (tid: 3)
enter giopImpl12::inputNewServerMessage for 0x807e724 (tid: 3)
in giopImpl12::inputNewServerMessage got to line 510 (tid: 3)
enter giopStream::inputMessage got to line 785 (tid: 3)
in giopStream::inputMessage got to line 790 (tid: 3)
in giopStream::inputMessage got to line 833 (tid: 3)
in giopStream::inputMessage got to line 840 (tid: 3)
in giopStream::inputMessage got to line 856 (tid: 3)
in giopStream::inputMessage got to line 868 (tid: 3)
in giopStream::inputMessage got to line 872 (tid: 3)
in giopStream::inputMessage got to line 980 (tid: 3)
in giopImpl12::inputNewServerMessage got to line 513 (tid: 3)
in giopImpl12::inputNewServerMessage got to line 523 (tid: 3)
in giopImpl12::inputMessageBegin got to line 747 (tid: 3)
in giopImpl12::inputMessageBegin got to line 764 (tid: 3)
enter giopImpl12::unmarshalWildCardRequestHeader got to line 989 (tid: 3)
in giopImpl12::unmarshalWildCardRequestHeader got to line 996 (tid: 3)
in giopImpl12::unmarshalWildCardRequestHeader got to line 999 (tid: 3)
in giopImpl12::unmarshalWildCardRequestHeader Recieved CancelRequest to 680 (tid: 3)
in giopImpl12::inputMessageBegin got to line 782 (tid: 3)
in giopImpl12::inputMessageBegin got to line 791 (tid: 3)
in GIOP_S::dispatcher 0x807e720 request type is 0 (tid: 3)
in GIOP_S::dispatcher got to line 266 (tid: 3)
in GIOP_S::dispatcher calling to handleRequest (tid: 3)
omniORB: (3) Dispatching remote call 'MyMethod' to: root/guts<guts> (active)
in omniCallHandle::upcall desc.pd_op = MyMethod
in omniCallHandle::upcall pointer 0x807e720 check
in omniCallHandle::upcall operation: MyMethod
DEBUG [2004-04-27 15:57:27 +0000] 2250 guts_i.cpp(201): In start of implementation
enter giopServer::notifyRzReadable called for 0x8079fd8 (tid: 2)
in giopServer::notifyRzReadable line 843 (tid: 2)
in giopServer::notifyRzReadable line 856 (tid: 2)
ctor giopWorker 0x807a1b8 with strand 0x807e558, server 0x8078bf0 and singleshot=1 (tid: 2)
in giopServer::notifyRzReadable line 864 (tid: 2)
entering giopWorker::execute (tid: 4)
ctor giopWorkerInfo for 0x807a1b8 (tid: 4)
entering giopWorker::real_execute (tid: 4)
Init ctor GIOP_S instance 0x8081b78 for operation  (tid: 4)
Init ctor GIOP_S_Holder instance 0xbf1ff934 for IOP_S 0x8081b78 (tid: 4)
in giopWorker::real_execute iop_s is 0x8081b78 iteration 1 (tid: 4)
in GIOP_S::dispatcher 0x8081b78 state is 1 (tid: 4)
in GIOP_S::dispatcher 0x8081b78 got to line 241 (tid: 4)
enter giopImpl12::inputMessageBegin for giopStream 0x8081b7c (tid: 4)
in giopImpl12::inputMessageBegin got to line 718 (tid: 4)
in giopImpl12::inputMessageBegin got to line 728 (tid: 4)
in giopImpl12::inputMessageBegin got to line 741 (tid: 4)
enter giopImpl12::inputNewServerMessage for 0x8081b7c (tid: 4)
in giopImpl12::inputNewServerMessage got to line 510 (tid: 4)
enter giopStream::inputMessage got to line 785 (tid: 4)
in giopStream::inputMessage got to line 790 (tid: 4)
in giopStream::inputMessage got to line 825 (tid: 4)
in giopStream::inputMessage got to line 840 (tid: 4)
in giopStream::inputMessage got to line 856 (tid: 4)
in giopStream::inputMessage got to line 868 (tid: 4)
in giopStream::inputMessage got to line 872 (tid: 4)
in giopStream::inputMessage got to line 980 (tid: 4)
in giopImpl12::inputNewServerMessage got to line 513 (tid: 4)
in giopImpl12::inputNewServerMessage got to line 523 (tid: 4)
in giopImpl12::inputNewServerMessage got to line 545 (tid: 4)
in giopImpl12::inputNewServerMessage got to line 551 (tid: 4)
enter giopImpl12::inputQueueMessage for giopStream 0x8081b7c (tid: 4)
in giopImpl12::inputQueueMessage got to line 227 (tid: 4)
in giopImpl12::inputQueueMessage got to line 267 (tid: 4)
in giopImpl12::inputQueueMessage got to line 274 (tid: 4)
in giopImpl12::inputQueueMessage got to line 372 (tid: 4)
in giopImpl12::inputQueueMessage got to line 444 (tid: 4)
in giopImpl12::inputQueueMessage got to line 448, mtype is 2 (tid: 4)
in giopImpl12::inputQueueMessage got to line 452 (tid: 4)
in giopImpl12::inputQueueMessage got to line 455 (tid: 4)
in giopImpl12::inputQueueMessage got to line 459 (tid: 4)
in giopImpl12::inputQueueMessage got to line 468 (tid: 4)
enter giopServer::notifyCallFullyBuffered called for 0x8079fd8 (tid: 4)
enter giopServer::notifyRzReadable called for 0x8079fd8 (tid: 4)
in giopServer::notifyRzReadable line 843 (tid: 4)
in giopServer::notifyRzReadable line 856 (tid: 4)
ctor giopWorker 0x8079ef0 with strand 0x807e558, server 0x8078bf0 and singleshot=1 (tid: 4)
in giopServer::notifyRzReadable line 864 (tid: 4)
entering giopWorker::execute (tid: 5)
ctor giopWorkerInfo for 0x8079ef0 (tid: 5)
entering giopWorker::real_execute (tid: 5)
in giopImpl12::inputQueueMessage got to line 473 (tid: 4)
in giopImpl12::inputQueueMessage got to line 476 (tid: 4)
in giopImpl12::inputQueueMessage got to line 479 (tid: 4)
in giopImpl12::inputMessageBegin got to line 741 (tid: 4)
enter giopImpl12::inputNewServerMessage for 0x8081b7c (tid: 4)
in giopImpl12::inputNewServerMessage got to line 510 (tid: 4)
enter giopStream::inputMessage got to line 785 (tid: 4)
in giopStream::inputMessage got to line 790 (tid: 4)
in giopStream::inputMessage got to line 833 (tid: 4)
Init ctor GIOP_S_Holder instance 0xbefff934 for IOP_S 0x807e720 (tid: 5)
in giopWorker::real_execute iop_s is 0x807e720 iteration 1 (tid: 5)
in GIOP_S::dispatcher 0x807e720 state is 1 (tid: 5)
in GIOP_S::dispatcher 0x807e720 got to line 241 (tid: 5)
enter giopImpl12::inputMessageBegin for giopStream 0x807e724 (tid: 5)
in giopImpl12::inputMessageBegin got to line 718 (tid: 5)
in giopImpl12::inputMessageBegin got to line 728 (tid: 5)
in giopImpl12::inputMessageBegin got to line 734 (tid: 5)
in giopImpl12::inputMessageBegin got to line 747 (tid: 5)
in giopImpl12::inputMessageBegin got to line 764 (tid: 5)
enter giopImpl12::unmarshalWildCardRequestHeader got to line 989 (tid: 5)
in giopImpl12::unmarshalWildCardRequestHeader got to line 996 (tid: 5)
in giopImpl12::unmarshalWildCardRequestHeader got to line 999 (tid: 5)
in giopImpl12::unmarshalWildCardRequestHeader Recieved CancelRequest to 680 (tid: 5)
in giopImpl12::inputMessageBegin got to line 782 (tid: 5)
in giopImpl12::inputMessageBegin got to line 791 (tid: 5)
in GIOP_S::dispatcher 0x807e720 request type is 2 (tid: 5)
in GIOP_S::dispatcher got to line 266 (tid: 5)
in GIOP_S::dispatcher calling to handleCancelRequest (tid: 5)
in giopStream::inputMessage got to line 840 (tid: 4)
omniORB: (5) Received and ignored a CancelRequest message. My version
in giopWorker::real_execute exit_on_error is 0 (tid: 5)
Destroying GIOP_S_Holder instance 0xbefff934 releasing iop_s 0x807e720 (tid: 5)
Destroying GIOP_S instance 0x807e720 for operation MyMethod (tid: 5)
enter giopServer::notifyWkDone called for 0x8079ef0/0
DEBUG [2004-04-27 15:57:27 +0000] 2250 guts_i.cpp(269): Exiting from implementation
in omniCallHandle::upcall pointer 0x807e720 check
-------------- next part --------------
       giopWorker  giopStrand  giopStream  giopServer   GIOP_S     Holder  
my     0x8079f18   0x807e558   0x807e724   0x8078bf0    0x807e720  0xbf3ff944
cri    0x807a1b8   0x807e558   0x8081b7c   0x8078bf0    0x8081b78  0xbf1ff934
cro    0x8079ef0   0x807e558   0x8081b7c   0x8078bf0    0x807e720  0xbefff934

Legend:
my - is a thread (tid: 3) in which initial request is being processed.
cri - initial thread (tid: 4) in which CancelRequest was stared to be processed
cro - other thread (tid: 5) in which CancelRequest is handled and GIOP_S instance from thread 3 is being manipulated (namely destroied)