[Ace-users] Notification Service Issue: Marshalling exception for nested struct in 5.5.10, but not for 5.5.9

Rob Ratcliff rrr6399 at futuretek.com
Fri Aug 10 10:29:31 CDT 2007 

    ACE VERSION: 5.5.10

    HOST MACHINE and OPERATING SYSTEM:

    Windows XP

    TARGET MACHINE and OPERATING SYSTEM, if different from HOST:
    COMPILER NAME AND VERSION (AND PATCHLEVEL):

    Windows XP, MS Visual C++ 8 (no service pack applied)

    THE $ACE_ROOT/ace/config.h FILE [if you use a link to a platform-
    specific file, simply state which one]:

    config-win32.h

    THE $ACE_ROOT/include/makeinclude/platform_macros.GNU FILE [if you
    use a link to a platform-specific file, simply state which one
    (unless this isn't used in this case, e.g., with Microsoft Visual
    C++)]:

    AREA/CLASS/EXAMPLE AFFECTED:

    Notification Service

    DOES THE PROBLEM AFFECT: EXECUTION

    SYNOPSIS:
      Marshaling exception in TAO 5.5.10 for a sequence of complex nested
      structs sent from the latest version of JacORB.
      TAO 5.5.9 transfers it without the exception.

    DESCRIPTION:
      When I send a sequence of nested structs from JacORB to the 5.5.10
Notification service, I get the
      marshalling exception in the attached log. It is possible that I
have a bug in creating the Notification message
      that was triggered the error in 5.5.10 and not 5.5.9, but I
haven't found it yet.

Here is the debug log of the case with 5.5.10 and 5.5.9:


JacORB stack trace:
org.omg.CosNotification.StructuredEvent at 1ab8f3f
loading class = class org.omg.CORBA.MARSHAL
constructor = public
org.omg.CORBA.MARSHAL(java.lang.String,int,org.omg.CORBA.CompletionStatus)
org.omg.CORBA.MARSHAL: Server-side Exception: null  vmcid: 0x0  minor
code: 0  completed: No
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native
Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown
Source)
        at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
        at java.lang.reflect.Constructor.newInstance(Unknown Source)
        at
org.jacorb.orb.SystemExceptionHelper.read(SystemExceptionHelper.java:225)
        at org.jacorb.orb.ReplyReceiver.getReply(ReplyReceiver.java:321)
        at org.jacorb.orb.Delegate.invoke_internal(Delegate.java:1074)
        at org.jacorb.orb.Delegate.invoke(Delegate.java:939)
        at org.omg.CORBA.portable.ObjectImpl._invoke(Unknown Source)
        at
org.omg.CosNotifyChannelAdmin._StructuredProxyPushConsumerStub.push_structured_event(_StructuredProxyPushConsumerStub.jav
a:230)
        at
com.notification.EventPublisher.sendEvent(EventPublisher.java:188)
        at java.lang.Thread.run(Unknown Source)


TAO 5.5.10 Offending part of dump:

00 00 00 00 00 00 00 00  00                        .........      
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5528) - Connection_Handler[1528]::handle_input, handle = 1528/1528
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5528) - Transport[1528]::handle_input
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5528) - Transport[1528]::process_queue_head, 0 enqueued
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5528) - Transport[1528]::handle_input_parse_data, enter
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5528) - Transport[1528]::handle_input_parse_data, read 1032 bytes
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5528) - GIOP_Message_State::parse_message_header_i
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5528) - GIOP_Message_State::get_version_info
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5528) - GIOP_Message_State::get_byte_order_info
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5528) - Connection_Handler[1528]::handle_input, handle =
1528/1528, retval = 0
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5528) - ORB_Core::run, handle_events() returns 1
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5528) - ORB_Core::run, calling handle_events()
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5264) - ORB_Core::run, handle_events() returns 0
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5264) - ORB_Core::run, calling handle_events()
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|4564) - Connection_Handler[1528]::handle_input, handle = 1528/1528
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|4564) - Transport[1528]::handle_input
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|4564) - Transport[1528]::process_queue_head, 0 enqueued
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|4564) - Transport[1528]::handle_input_missing_data_message, enter
(missing data == 22672)
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|4564) - Transport[1528]::handle_input_missing_data_message, read
bytes 22672
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|4564) - Transport[1528]::process_parsed_messages, entering
(missing data == 0)
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5264) - ORB_Core::run, handle_events() returns 0
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5264) - ORB_Core::run, calling handle_events()
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|4564) - GIOP_Message_Base::dump_msg, recv GIOP v1.2 msg, 23692
data bytes, other endian, Type Request[20]
...
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|4564) - GIOP_Message_Base::dump_msg, send GIOP v1.2 msg, 56 data
bytes, my endian, Type Reply[20]
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|GIOP
message - HEXDUMP 68 bytes
47 49 4f 50 01 02 01 01  38 00 00 00 14 00 00 00   GIOP....8.......
02 00 00 00 00 00 00 00  1e 00 00 00 49 44 4c 3a   ............IDL:
6f 6d 67 2e 6f 72 67 2f  43 4f 52 42 41 2f 4d 41   omg.org/CORBA/MA
52 53 48 41 4c 3a 31 2e  30 00 8b 01 00 00 00 00   RSHAL:1.0.......
01 00 00 00                                        ....           
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|4640) - Transport[1528]::cleanup_queue, byte_count = 25
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|4640) - Transport[1528]::cleanup_queue, after transfer, bc = 0,
all_sent = 1, ml = 0
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|4640) - Transport[1528]::drain_queue_helper, byte_count = 25,
head_is_empty = 1
Aug 09 22:19:47.843
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|4640) - Transport[1528]::drain_queue_i, helper retval = 1
Aug 09 22:19:47.859
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5264) - Connection_Handler[1528]::handle_input, handle = 1528/1528
Aug 09 22:19:47.859
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5264) - Transport[1528]::handle_input
Aug 09 22:19:47.859
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5264) - Transport[1528]::process_queue_head, 0 enqueued
Aug 09 22:19:47.859
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5264) - Transport[1528]::handle_input_parse_data, enter
Aug 09 22:19:47.859
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5264) - Transport[1528]::handle_input_parse_data, read 88 bytes
Aug 09 22:19:47.859
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5264) - GIOP_Message_State::parse_message_header_i
Aug 09 22:19:47.859
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5264) - GIOP_Message_State::get_version_info
Aug 09 22:19:47.859
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5264) - GIOP_Message_State::get_byte_order_info
Aug 09 22:19:47.859
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5264) - Transport[1528]::process_parsed_messages, entering
(missing data == 0)
Aug 09 22:19:47.859
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5528) - ORB_Core::run, handle_events() returns 0
Aug 09 22:19:47.859
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5528) - ORB_Core::run, calling handle_events()
Aug 09 22:19:47.859
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5264) - GIOP_Message_Base::dump_msg, recv GIOP v1.2 msg, 76 data
bytes, other endian, Type Request[22]
Aug 09 22:19:47.859
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|GIOP
message - HEXDUMP 88 bytes
47 49 4f 50 01 02 00 00  00 00 00 4c 00 00 00 16   GIOP.......L....
03 00 00 00 00 00 00 00  00 00 00 23 14 01 0f 00   ...........#....
4e 55 54 8e d8 bb 46 24  f4 00 00 01 00 00 00 01   NUT...F$........
00 00 00 04 00 00 00 01  00 00 00 05 00 00 00 00   ................
00 00 00 0e 5f 6e 6f 6e  5f 65 78 69 73 74 65 6e   ...._non_existen
74 00 00 00 00 00 00 00                            t.......       
Aug 09 22:19:47.859
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|TAO
(1124|5264) - GIOP_Message_Base::dump_msg, send GIOP v1.2 msg, 13 data
bytes, my endian, Type Reply[22]
Aug 09 22:19:47.859
2007@<local_host>@1124 at LM_DEBUG@C:\corba\tao-5.5.10\bin\Notify_Service.exe|GIOP
message - HEXDUMP 25 bytes
47 49 4f 50 01 02 01 01  0d 00 00 00 16 00 00 00   GIOP............
00 00 00 00 00 00 00 00  00                        .........      

TAO 5.5.9 dump showing successful completion:

Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - Transport[1588]::cleanup_queue, byte_count = 25
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - Transport[1588]::cleanup_queue, after transfer, bc = 0,
all_sent = 1, ml = 0
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - Transport[1588]::drain_queue_helper, byte_count = 25,
head_is_empty = 1
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - Transport[1588]::drain_queue_i, helper retval = 1
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - Connection_Handler[1588]::handle_input, handle = 1588/1588,
retval = 0
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - ORB_Core::run, handle_events() returns 1
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - ORB_Core::run, calling handle_events()
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - Connection_Handler[1588]::handle_input, handle = 1588/1588
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - Transport[1588]::handle_input
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - Transport[1588]::process_queue_head, 0 enqueued
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - Transport[1588]::handle_input_parse_data, enter
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - Transport[1588]::handle_input_parse_data, read 1032 bytes
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - GIOP_Message_State::parse_message_header_i
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - GIOP_Message_State::get_version_info
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - GIOP_Message_State::get_byte_order_info
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - Connection_Handler[1588]::handle_input, handle = 1588/1588,
retval = 0
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - ORB_Core::run, handle_events() returns 1
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - ORB_Core::run, calling handle_events()
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - Connection_Handler[1588]::handle_input, handle = 1588/1588
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - Transport[1588]::handle_input
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - Transport[1588]::process_queue_head, 0 enqueued
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - Transport[1588]::handle_input_missing_data_message, enter
(missing data == 22208)
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - Transport[1588]::handle_input_missing_data_message, read
bytes 22208
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - Transport[1588]::process_parsed_messages, entering (missing
data == 0)
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - GIOP_Message_Base::dump_msg, recv GIOP v1.2 msg, 23228 data
bytes, other endian, Type Request[20]
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|GIOP
message - HEXDUMP 23240 bytes (showing first 912 bytes)
...
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|object:fbd0c0
incr refcount = 4
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|Proxyconsumer
11bf120 filter eval result = 1Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|object:fbd0c0
decr refcount = 3
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - GIOP_Message_Base::dump_msg, send GIOP v1.2 msg, 12 data
bytes, my endian, Type Reply[20]
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|GIOP
message - HEXDUMP 24 bytes
47 49 4f 50 01 02 01 01  0c 00 00 00 14 00 00 00   GIOP............
00 00 00 00 00 00 00 00                            ........       
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - Transport[1588]::cleanup_queue, byte_count = 24
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - Transport[1588]::cleanup_queue, after transfer, bc = 0,
all_sent = 1, ml = 0
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - Transport[1588]::drain_queue_helper, byte_count = 24,
head_is_empty = 1
Aug 10 09:53:59.328
2007@<local_host>@380 at LM_DEBUG@C:\corba\tao-5.5.9\bin\Notify_Service.exe|TAO
(380|332) - Transport[1588]::drain_queue_i, helper retval = 1

More information about the Ace-users mailing list