Karel Gardas wrote:
Hello,
On Thu, 17 Aug 2006, Arne Pajunen wrote:
Hello,
Attached is a patch of a fix I made to an issue we encountered with
the handling of the reader TLS (Thread Local Storage) keys in GIOPConn.
The issue was such that we had a call being made to a server, which
returned a reference to a generic resource. When the client receives
this, Mico does a _is_a query to verify it in the thread where the
reply was received. In our case this _is_a query went to another
process with a different connection which was just started by the server.
The problem was that the newly started connection created it's reader
threads, but then the query in the old connections reader thread calls
ORB:wait() to wait for the reply, and it determined that this is a
reader thread so it should directly call the dispatcher to wait for
the reply. Unfortunately, in this scenario it was the wrong reader
thread, and the new connections reader thread was also happily
reading. This ended up with a race in do_read(), where two threads
would enter with the do_read simultaneously causing a unpredictable
condition.
Unfortunately I'm unable to produce a reasonable test case for it as
this occurred in a complex system, and was kind of rare and timing
keen (sometimes had to run the program in while loops until it occurred).
The exact issue is that the static
MICO::GIOPConn::is_this_reader_thread() method verifies whether
current thread is a reader, but doesn't care for which connection. I
fixed this by making it use the pointer to the GIOPConn instance as
the thread local keys value, so it can verify that it's a reader for
the current connection.
I'm not sure if this patch is perfectly correct (or more like I'm not
sure I fixed the right problem.) and whether it has any side effects.
I would be interested in comments and feedback on this patch.
your information are very interesting. Could you also be so kind and
tell us what concurrency model do you use on client side? I would also
be interested to know more details about how is it possible you call
_is_a operation from reader thread directly. IMHO this shouldn't happen
at all...
Hi,
The thread concurrency model is thread pool, we use the following
initialization flags on the client side.
corba_args[0] = "InterfaceServer";
corba_args[1] = "-ORBThreadPool";
corba_args[2] = "-ORBRequestLimit";
corba_args[3] = "25";
corba_args[4] = "-ORBNoResolve";
It is interesting to know that the call isn't most likely supposed to
happen from a reader thread. This makes a lot more sense now.
I have attached a backtrace I copy&pasted during one debugging session.
There you can see how the reply handler that received the response to a
previous resource->allocate() call (from our idl-stubs) and during the
processing attempts to narrow it causing an _is_a query to be invoked,
which goes through another connection.
Unfortunately I haven't written down exactly how this thread ends up in
ORB::wait() in the old reader thread.
I believe the reason it ends up handling the invoke in a reader thread
is because its directed to another connection instead of the connection
from where the Resource was received.
second attachment, micolog.txt, contains a -ORBDebug All snippet from
the failing part. It has lots of additional debug prints added by me to
clarify the issue.
You can see it calls our stub allocate on the old connection, the
receives the response, after which it starts a _is_a over a new
connection. When you look near the end where it handles the reply for
the _is_a, you see this:
MICO::GIOPConn::do_read t:\mico-2.3.12\ot.win32\orb\iop.cc:2561 [3852]
preparing to read: conn:00FAC5D8 inbuf.len 0 inlen 12
MICO::GIOPConn::do_read t:\mico-2.3.12\ot.win32\orb\iop.cc:2561 [3364]
preparing to read: conn:00FAC5D8 inbuf.len 0 inlen 12
.. ie. two separate threads, 3364 and 3852 reading the same connection
concurrently. Those are win32 thread ids. Thread 3852 is the new
connection's reader thread, over which the _is_a went, and thread 3364
is the reader thread of the old connection over which the allocate was
invoked.
at the end you can see the end result:
entering handler, _inlen = 0, r = 12, inbuf.len = 24
After which the do_read mechanism is totally messed because it skips
over a portion of the message.
Hope this clarifies the issue at least somewhat. I would be very
interested in anything you find out. If you have further questions I
will try to answer them.
--
Arne Pajunen
Software Engineer
OpenTTCN Oy, Test and Test Control Components for Test System Vendors
Web: http://www.openttcn.com
invoke call stack for an _is_a request originating from a idl-compiled stub
call:
> adapter.exe!MICO::IIOPProxy::invoke(CORBA::ORBInvokeRec *
> id=0x010a0218, CORBA::Object * obj=0x0109f5d0, CORBA::ORBRequest *
> req=0x0109fea0, CORBA::Principal * pr=0x00000000, unsigned char
> response_exp='') Line 3945 C++
adapter.exe!CORBA::ORB::invoke_async(CORBA::Object * obj=0x0109f5d0,
CORBA::ORBRequest * req=0x0109fea0, CORBA::Principal * pr=0x00000000, unsigned
char response_exp='', CORBA::ORBCallback * cb=0x010a0338, CORBA::ORBInvokeRec
* id=0x010a0218) Line 2508 + 0x23 bytes C++
adapter.exe!CORBA::Request::send_deferred(CORBA::RequestCallback *
cb=0x00000000) Line 878 C++
adapter.exe!CORBA::Request::invoke() Line 786 C++
adapter.exe!CORBA::ORB::is_a(CORBA::Object * obj=0x0109f5d0, const char
* repo_id=0x00f68330) Line 3003 + 0x1d bytes C++
adapter.exe!CORBA::Object::_is_a_remote(const char * repoid=0x00f68330)
Line 396 C++
adapter.exe!otResourcePool::Resource::_narrow(CORBA::Object *
_obj=0x0109f5d0) Line 41 + 0x27 bytes C++
adapter.exe!_Marshaller_otResourcePool_Resource::demarshal(CORBA::DataDecoder &
dc={...}, void * v=0x0012f0c8) Line 99 + 0x9 bytes C++
adapter.exe!CORBA::StaticAny::demarshal(CORBA::DataDecoder & dc={...})
Line 145 + 0x20 bytes C++
adapter.exe!CORBA::StaticRequest::set_out_args(CORBA::DataDecoder *
dc=0x0109e3d8, unsigned char is_ex=0) Line 2014 + 0xf bytes C++
adapter.exe!MICO::GIOPCodec::get_invoke_reply2(MICO::GIOPInContext &
in={...}, unsigned long req_id=18, GIOP::ReplyStatusType_1_2 stat=NO_EXCEPTION,
CORBA::Object * & obj=0x00000000, CORBA::ORBRequest * req=0x0012f054, short &
ad=0, SequenceTmpl<IOP::ServiceContext,0> & ctx={...}) Line 1393 + 0x15 bytes
C++
adapter.exe!MICO::IIOPProxy::handle_invoke_reply(MICO::GIOPConn *
conn=0x0109b270, MICO::GIOPInContext & in={...}) Line 4261 + 0x33 bytes
C++
adapter.exe!MICO::IIOPProxy::handle_input(MICO::GIOPConn *
conn=0x0109b270, CORBA::Buffer * inp=0x0109e930) Line 4407 + 0x10 bytes C++
adapter.exe!MICO::IIOPProxy::input_callback(MICO::GIOPConn *
conn=0x0109b270, CORBA::Buffer * inp=0x0109e930) Line 4484 C++
adapter.exe!MICO::GIOPConn::input_ready_callback(CORBA::Buffer *
b=0x0109e930) Line 528 + 0x1d bytes C++
adapter.exe!MICO::GIOPConn::input_ready() Line 2509 + 0x11 bytes
C++
adapter.exe!MICO::GIOPConn::do_read(const unsigned char
break_after_read=0) Line 2853 + 0x8 bytes C++
adapter.exe!MICO::GIOPConn::callback(CORBA::Transport *
__formal=0x0109ae48, CORBA::TransportCallback::Event ev=Read) Line 2910
C++
adapter.exe!MICO::SocketTransport::callback(CORBA::Dispatcher *
disp=0x0109af18, CORBA::Dispatcher::Event ev=Read) Line 209 + 0x1d bytes
C++
adapter.exe!MICO::SelectDispatcher::handle_fevents(fd_set & rset={...},
fd_set & wset={...}, fd_set & xset={...}) Line 267 + 0x2b bytes C++
adapter.exe!MICO::SelectDispatcher::run(unsigned char infinite=0) Line
458 C++
adapter.exe!MICO::GIOPConnReader::_run(void * arg=0x0109ba08) Line
2157 + 0x28 bytes C++
adapter.exe!MICOMT::Thread::_thr_startup(void * arg=0x0109ba08) Line
145 + 0x13 bytes C++
adapter.exe!MICOMT::Thread::ThreadWrapper(void * arg=0x0109ba08) Line
134 C++
[EMAIL PROTECTED]() + 0x61 bytes C
adapter.exe!_callthreadstartex() Line 348 + 0x6 bytes C
adapter.exe!_threadstartex(void * ptd=0x0109bb48) Line 326 + 0x5 bytes
C
kernel32.dll!7c80b683()
[Frames below may be incorrect and/or missing, no symbols loaded for
kernel32.dll]
-ORBDebug All for a run
-snip-
ORB::add_invoke (MsgId=18)
MICO::IIOPProxy::invoke t:\mico-2.3.12\ot.win32\orb\iop.cc:3869 [2304]
activeref
MICO::GIOPConn::active_ref t:\mico-2.3.12\ot.win32\orb\iop.cc:2337 [2304]
00FA6ED0: _activerefs++=2 -> 3 ret:succeeded
GIOP: sending Request to inet:192.168.11.11:5500 msgid is 18
MICO::GIOPConn::ref t:\mico-2.3.12\ot.win32\orb\iop.cc:2990 [2304]
00FA6ED0: _refcnt++=1 -> 2
IIOPProxy::add_invoke: rec=00FAAD40, id=00FAA130, msgid=18)
MICO::GIOPConn::output (CORBA::Buffer *b)
b: 00FAACF0
Out Data 47 49 4f 50 01 00 01 00 4c 00 00 00 00 00 00 00 GIOP....L.......
12 00 00 00 01 00 00 00 25 00 00 00 ab ac ab 31 ........%...«¬«1
31 31 35 35 36 34 32 35 31 37 00 5f 52 6f 6f 74 1155642517._Root
50 4f 41 00 00 ca fe ba be 44 e1 b4 95 00 00 00 POA..Êþº¾Dá´...
f2 00 00 00 09 00 00 00 61 6c 6c 6f 63 61 74 65 ò.......allocate
00 00 00 00 00 00 00 00 ........
MICO::GIOPConn::active_deref t:\mico-2.3.12\ot.win32\orb\iop.cc:2345 [2304]
00FA6ED0: _activerefs--=2 -> 1
ORB::wait for 00FAA130
MICO::GIOPConn::do_read t:\mico-2.3.12\ot.win32\orb\iop.cc:2561 [3364]
preparing to read: conn:00FA6ED0 inbuf.len 0 inlen 12
MICO::GIOPConn::do_read t:\mico-2.3.12\ot.win32\orb\iop.cc:2563 [3364]
READ complete: r = 12 conn:00FA6ED0
READ data: 47 49 4f 50 01 00 01 01 d0 00 00 00 GIOP....Ð...
MICO::GIOPConn::do_read t:\mico-2.3.12\ot.win32\orb\iop.cc:2587 [3364]
entering handler, _inlen = 0, r = 12, inbuf.len = 12
MICO::GIOPConn::do_read t:\mico-2.3.12\ot.win32\orb\iop.cc:2590 [3364]
Header completely received.
HEADER data: 47 49 4f 50 01 00 01 01 d0 00 00 00 GIOP....Ð...
MICO::GIOPConn::do_read t:\mico-2.3.12\ot.win32\orb\iop.cc:2607 [3364]
Header parsed, mt=1, inlen=208, inflags=1
MICO::GIOPConn::do_read t:\mico-2.3.12\ot.win32\orb\iop.cc:2561 [3364]
preparing to read: conn:00FA6ED0 inbuf.len 12 inlen 208
MICO::GIOPConn::do_read t:\mico-2.3.12\ot.win32\orb\iop.cc:2563 [3364]
READ complete: r = 208 conn:00FA6ED0
READ data: 47 49 4f 50 01 00 01 01 d0 00 00 00 00 00 00 00 GIOP....Ð.......
12 00 00 00 00 00 00 00 35 00 00 00 49 44 4c 3a ........5...IDL:
69 64 6c 2e 6f 74 2e 74 33 2e 63 6f 6d 2f 6f 74 idl.ot.t3.com/ot
54 65 73 74 43 6f 6d 70 6f 6e 65 6e 74 2f 49 6d TestComponent/Im
70 6c 65 6d 65 6e 74 61 74 69 6f 6e 3a 31 2e 30 plementation:1.0
00 6e 65 6e 01 00 00 00 00 00 00 00 7c 00 00 00 .nen........|...
01 01 02 00 0e 00 00 00 31 39 32 2e 31 36 38 2e ........192.168.
31 31 2e 31 31 00 6c 06 25 00 00 00 ab ac ab 31 11.11.l.%...«¬«1
31 31 35 35 36 35 33 36 38 33 00 5f 52 6f 6f 74 1155653683._Root
50 4f 41 00 00 ca fe ba be 44 e1 e0 33 00 00 00 POA..Êþº¾Dáà3...
00 00 00 00 01 00 00 00 01 00 00 00 2c 00 00 00 ............,...
01 00 00 00 01 00 01 00 02 00 00 00 01 00 01 05 ................
20 00 01 00 09 01 01 00 04 00 00 00 00 01 01 00 ...............
01 00 01 00 01 00 01 05 20 00 01 00 ........ ...
MICO::GIOPConn::do_read t:\mico-2.3.12\ot.win32\orb\iop.cc:2587 [3364]
entering handler, _inlen = 0, r = 208, inbuf.len = 220
MICO::GIOPConn::do_read t:\mico-2.3.12\ot.win32\orb\iop.cc:2677 [3364]
Message completely received.
MSG data: 47 49 4f 50 01 00 01 01 d0 00 00 00 00 00 00 00 GIOP....Ð.......
12 00 00 00 00 00 00 00 35 00 00 00 49 44 4c 3a ........5...IDL:
69 64 6c 2e 6f 74 2e 74 33 2e 63 6f 6d 2f 6f 74 idl.ot.t3.com/ot
54 65 73 74 43 6f 6d 70 6f 6e 65 6e 74 2f 49 6d TestComponent/Im
70 6c 65 6d 65 6e 74 61 74 69 6f 6e 3a 31 2e 30 plementation:1.0
00 6e 65 6e 01 00 00 00 00 00 00 00 7c 00 00 00 .nen........|...
01 01 02 00 0e 00 00 00 31 39 32 2e 31 36 38 2e ........192.168.
31 31 2e 31 31 00 6c 06 25 00 00 00 ab ac ab 31 11.11.l.%...«¬«1
31 31 35 35 36 35 33 36 38 33 00 5f 52 6f 6f 74 1155653683._Root
50 4f 41 00 00 ca fe ba be 44 e1 e0 33 00 00 00 POA..Êþº¾Dáà3...
00 00 00 00 01 00 00 00 01 00 00 00 2c 00 00 00 ............,...
01 00 00 00 01 00 01 00 02 00 00 00 01 00 01 05 ................
20 00 01 00 09 01 01 00 04 00 00 00 00 01 01 00 ...............
01 00 01 00 01 00 01 05 20 00 01 00 ........ ...
MICO::GIOPConn::active_ref t:\mico-2.3.12\ot.win32\orb\iop.cc:2337 [3364]
00FA6ED0: _activerefs++=2 -> 3 ret:succeeded
MICO::GIOPConn::input_ready ()
conn: 00FA6ED0
ev: GIOPConnCallback::InputReady
t_mod: 0
pool:
conn:
req:
_activerefs: 2
In Data 47 49 4f 50 01 00 01 01 d0 00 00 00 00 00 00 00 GIOP....Ð.......
12 00 00 00 00 00 00 00 35 00 00 00 49 44 4c 3a ........5...IDL:
69 64 6c 2e 6f 74 2e 74 33 2e 63 6f 6d 2f 6f 74 idl.ot.t3.com/ot
54 65 73 74 43 6f 6d 70 6f 6e 65 6e 74 2f 49 6d TestComponent/Im
70 6c 65 6d 65 6e 74 61 74 69 6f 6e 3a 31 2e 30 plementation:1.0
00 6e 65 6e 01 00 00 00 00 00 00 00 7c 00 00 00 .nen........|...
01 01 02 00 0e 00 00 00 31 39 32 2e 31 36 38 2e ........192.168.
31 31 2e 31 31 00 6c 06 25 00 00 00 ab ac ab 31 11.11.l.%...«¬«1
31 31 35 35 36 35 33 36 38 33 00 5f 52 6f 6f 74 1155653683._Root
50 4f 41 00 00 ca fe ba be 44 e1 e0 33 00 00 00 POA..Êþº¾Dáà3...
00 00 00 00 01 00 00 00 01 00 00 00 2c 00 00 00 ............,...
01 00 00 00 01 00 01 00 02 00 00 00 01 00 01 05 ................
20 00 01 00 09 01 01 00 04 00 00 00 00 01 01 00 ...............
01 00 01 00 01 00 01 05 20 00 01 00 ........ ...
IIOP: incoming data from inet:192.168.11.11:5500
GIOP: incoming Reply from inet:192.168.11.11:5500 for msgid 18 status is 0
ORB::get_invoke (MsgId=18)
IIOPProxy::pull_invoke: id=00FAA130, rec = 00FAAD40
IIOPProxy::handle_invoke_reply: rec=00FAAD40)
ORB::add_invoke (MsgId=19)
IIOP: making new GIOP 1.0 connection to inet:192.168.11.11:1644
GIOPCodec::GIOPCodec(): 00FAB658
MICO::GIOPConnReader::GIOPConnReader(00FAC5D8)
MICO::GIOPConn::ref t:\mico-2.3.12\ot.win32\orb\iop.cc:2990 [3364]
00FAC5D8: _refcnt++=0 -> 1
MICO::GIOPConn::active_ref t:\mico-2.3.12\ot.win32\orb\iop.cc:2337 [3364]
00FAC5D8: _activerefs++=1 -> 2 ret:succeeded
MICO::IIOPProxy::make_conn t:\mico-2.3.12\ot.win32\orb\iop.cc:3536 [3364]
created connection, active_ref incremented
MICO::GIOPConnReader::_run()
MICO::GIOPConnReader::_run t:\mico-2.3.12\ot.win32\orb\iop.cc:2148 [3852]
running.
MICO::GIOPConnReader::_run t:\mico-2.3.12\ot.win32\orb\iop.cc:2150 [3852]
set as reader thread.
MICO::GIOPConnReader::_run t:\mico-2.3.12\ot.win32\orb\iop.cc:2153 [3852]
threaded client, CLIENT_SIDE, entering dispatch loop
MICO::IIOPProxy::invoke t:\mico-2.3.12\ot.win32\orb\iop.cc:3869 [3364]
activeref
MICO::GIOPConn::active_ref t:\mico-2.3.12\ot.win32\orb\iop.cc:2337 [3364]
00FAC5D8: _activerefs++=2 -> 3 ret:succeeded
GIOP: Codeset negotiation with inet:192.168.11.11:1644 using GIOP version 1.0
GIOP: sending Request to inet:192.168.11.11:1644 msgid is 19
MICO::GIOPConn::ref t:\mico-2.3.12\ot.win32\orb\iop.cc:2990 [3364]
00FAC5D8: _refcnt++=1 -> 2
IIOPProxy::add_invoke: rec=00FACFB0, id=00FABF28, msgid=19)
MICO::GIOPConn::output (CORBA::Buffer *b)
b: 00FACFE0
Out Data 47 49 4f 50 01 00 01 00 7a 00 00 00 00 00 00 00 GIOP....z.......
13 00 00 00 01 00 00 00 25 00 00 00 ab ac ab 31 ........%...«¬«1
31 31 35 35 36 35 33 36 38 33 00 5f 52 6f 6f 74 1155653683._Root
50 4f 41 00 00 ca fe ba be 44 e1 e0 33 00 00 00 POA..Êþº¾Dáà3...
00 00 00 00 06 00 00 00 5f 69 73 5f 61 00 00 00 ........_is_a...
00 00 00 00 2e 00 00 00 49 44 4c 3a 69 64 6c 2e ........IDL:idl.
6f 74 2e 74 33 2e 63 6f 6d 2f 6f 74 52 65 73 6f ot.t3.com/otReso
75 72 63 65 50 6f 6f 6c 2f 52 65 73 6f 75 72 63 urcePool/Resourc
65 3a 31 2e 30 00 e:1.0.
MICO::GIOPConn::active_deref t:\mico-2.3.12\ot.win32\orb\iop.cc:2345 [3364]
00FAC5D8: _activerefs--=2 -> 1
ORB::wait for 00FABF28
MICO::GIOPConn::do_read t:\mico-2.3.12\ot.win32\orb\iop.cc:2561 [3852]
preparing to read: conn:00FAC5D8 inbuf.len 0 inlen 12
MICO::GIOPConn::do_read t:\mico-2.3.12\ot.win32\orb\iop.cc:2561 [3364]
preparing to read: conn:00FAC5D8 inbuf.len 0 inlen 12
MICO::GIOPConn::do_read t:\mico-2.3.12\ot.win32\orb\iop.cc:2563 [3852]
READ complete: r = 12 conn:00FAC5D8
READ data: 47 49 4f 50 01 00 01 01 0d 00 00 00 00 00 00 00 GIOP............
13 00 00 00 00 00 00 00 ........
MICO::GIOPConn::do_read t:\mico-2.3.12\ot.win32\orb\iop.cc:2587 [3852]
entering handler, _inlen = 0, r = 12, inbuf.len = 24
MICO::GIOPConn::do_read t:\mico-2.3.12\ot.win32\orb\iop.cc:2677 [3852]
Message completely received.
MSG data: 47 49 4f 50 01 00 01 01 0d 00 00 00 00 00 00 00 GIOP............
13 00 00 00 00 00 00 00 ........
MICO::GIOPConn::active_ref t:\mico-2.3.12\ot.win32\orb\iop.cc:2337 [3852]
00FAC5D8: _activerefs++=2 -> 3 ret:succeeded
-snip-
_______________________________________________
Mico-devel mailing list
[email protected]
http://www.mico.org/mailman/listinfo/mico-devel
