On Wed, Jun 24, 2015 at 12:23 PM, Matt Broadstone <[email protected]> wrote:
> On Wed, Jun 24, 2015 at 11:54 AM, Gordon Sim <[email protected]> wrote: > >> On 06/24/2015 04:15 PM, Matt Broadstone wrote: >> >>> Hey, >>> I'm implementing message disposition in node-amqp10 presently, and just >>> ran >>> into a crash taking down qpidd. I imagine it's a bounds issue related to >>> the first and last values for the disposition frame, in my particular >>> case >>> I've only sent two messages and I'm sending dispositions for each >>> individualls with first/last pairs: (0, 0), (1, 1). >>> >> >> Can you turn on logging with --log-enable notice+ --log-enable >> trace+:Protocol and attach the output along with this stacktrace to a new >> JIRA? >> >> It looks like it is some missing checking or similar within proton. >> Hopefully we can get that fixed for the next release. >> >> >> This might be a little more useful. I was using some qmf2 stuff in the other test to do some broker introspection for an integratin test. The following log removes all of that, and simply creates the sender/receiver links and tries to send two messages, dequeue both of them and send accepted dispositions for them: Starting program: /usr/sbin/qpidd --config /etc/qpid/qpidd.conf --log-enable notice+ --log-enable trace+:Protocol [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1". 2015-06-24 12:38:50 [Broker] notice Broker (pid=3900) start-up [New Thread 0x7ffff3223700 (LWP 3901)] 2015-06-24 12:38:50 [Security] notice SSL plugin not enabled, you must set --ssl-cert-db to enable it. 2015-06-24 12:38:50 [Store] notice Linear Store: Store module initialized; store-dir=/var/lib/qpidd 2015-06-24 12:38:50 [Broker] notice SASL disabled: No Authentication Performed 2015-06-24 12:38:50 [Network] notice Listening on TCP/TCP6 port 5672 [New Thread 0x7ffff2920700 (LWP 3902)] [New Thread 0x7ffff211f700 (LWP 3903)] 2015-06-24 12:39:01 [Protocol] trace [qpid.192.168.1.106:5672-192.168.1.9:60042]: <- AMQP 2015-06-24 12:39:01 [Protocol] trace [qpid.192.168.1.106:5672-192.168.1.9:60042]: -> AMQP 2015-06-24 12:39:01 [Protocol] trace [qpid.192.168.1.106:5672-192.168.1.9:60042]: 0 <- @open(16) [container-id="conn1435163942131", hostname="192.168.1.106", max-frame-size=4294967295, channel-max=65535, idle-time-out=120000, outgoing-locales=:"en-US", incoming-locales=:"en-US", properties={}] 2015-06-24 12:39:01 [Protocol] trace [qpid.192.168.1.106:5672-192.168.1.9:60042]: 0 -> @open(16) [container-id="18583796-c48c-4767-90a2-07d17a651e50", idle-time-out=120000] 2015-06-24 12:39:01 [Protocol] trace [qpid.192.168.1.106:5672-192.168.1.9:60042]: 1 <- @begin(17) [next-outgoing-id=1, incoming-window=100, outgoing-window=100, handle-max=4294967295, properties={}] 2015-06-24 12:39:01 [Protocol] trace [qpid.192.168.1.106:5672-192.168.1.9:60042]: 0 -> @begin(17) [remote-channel=1, next-outgoing-id=0, incoming-window=2147483647, outgoing-window=0] 2015-06-24 12:39:01 [Protocol] trace [qpid.192.168.1.106:5672-192.168.1.9:60042]: 1 <- @attach(18) [name="test.queue_RX", handle=0, role=true, snd-settle-mode=2, rcv-settle-mode=0, source=@source(40) [address="test.queue", durable=0, expiry-policy=:"session-end", timeout=0, dynamic=false, dynamic-node-properties={}], target=@target(41) [address="localhost", durable=0, expiry-policy=:"session-end", timeout=0, dynamic=false, dynamic-node-properties={}], unsettled={}, incomplete-unsettled=false, max-message-size=10000, properties={}] 2015-06-24 12:39:01 [Protocol] debug qpid.192.168.1.106:5672-192.168.1.9:60042 link 0x7fffe4003ad0 attached on 0x7fffe400fb30 2015-06-24 12:39:01 [Protocol] trace [qpid.192.168.1.106:5672-192.168.1.9:60042]: 0 -> @attach(18) [name="test.queue_RX", handle=0, role=false, snd-settle-mode=2, rcv-settle-mode=0, source=@source(40) [address="test.queue", durable=0, timeout=0, dynamic=false, distribution-mode=:move], target=@target(41) [durable=0, timeout=0, dynamic=false], initial-delivery-count=0] 2015-06-24 12:39:01 [Protocol] trace [qpid.192.168.1.106:5672-192.168.1.9:60042]: 1 <- @flow(19) [next-incoming-id=0, incoming-window=200, next-outgoing-id=1, outgoing-window=100, handle=0, link-credit=100, available=0, drain=false, echo=false, properties={}] 2015-06-24 12:39:01 [Protocol] trace [qpid.192.168.1.106:5672-192.168.1.9:60042]: 1 <- @attach(18) [name="test.queue_TX", handle=1, role=false, snd-settle-mode=2, rcv-settle-mode=0, source=@source(40) [address="localhost", durable=0, expiry-policy=:"session-end", timeout=0, dynamic=false, dynamic-node-properties={}, filter={}], target=@target(41) [address="test.queue", durable=0, expiry-policy=:"session-end", timeout=0, dynamic=false, dynamic-node-properties={}], unsettled={}, incomplete-unsettled=false, initial-delivery-count=1, max-message-size=0, properties={}] 2015-06-24 12:39:01 [Protocol] debug qpid.192.168.1.106:5672-192.168.1.9:60042 link 0x7fffe4015b30 attached on 0x7fffe400fb30 2015-06-24 12:39:01 [Protocol] trace [qpid.192.168.1.106:5672-192.168.1.9:60042]: 0 -> @attach(18) [name="test.queue_TX", handle=1, role=true, snd-settle-mode=2, rcv-settle-mode=0, source=@source(40) [durable=0, timeout=0, dynamic=false], target=@target(41) [address="test.queue", durable=0, timeout=0, dynamic=false], initial-delivery-count=0] 2015-06-24 12:39:01 [Protocol] trace [qpid.192.168.1.106:5672-192.168.1.9:60042]: 0 -> @flow(19) [next-incoming-id=1, incoming-window=2147483647, next-outgoing-id=0, outgoing-window=0, handle=1, delivery-count=1, link-credit=500, drain=false] 2015-06-24 12:39:01 [Protocol] trace [qpid.192.168.1.106:5672-192.168.1.9:60042]: 1 <- @transfer(20) [handle=1, delivery-id=1, delivery-tag=b"1", settled=false, more=false, resume=false, aborted=false, batchable=false] (18) "\x00Sw\xa1\x0dfirst message" 2015-06-24 12:39:01 [Protocol] trace [qpid.192.168.1.106:5672-192.168.1.9:60042]: 0 -> @flow(19) [next-incoming-id=2, incoming-window=2147483647, next-outgoing-id=0, outgoing-window=1, handle=1, delivery-count=2, link-credit=500, drain=false] 2015-06-24 12:39:01 [Protocol] trace [qpid.192.168.1.106:5672-192.168.1.9:60042]: 0 -> @transfer(20) [handle=0, delivery-id=0, delivery-tag=b"\x00\x00\x00\x00", message-format=0, settled=false, more=false] (29) "\x00Sp\xc0\x06\x04BP\x04@A\x00Sw\xa1\x0dfirst message" 2015-06-24 12:39:01 [Protocol] trace [qpid.192.168.1.106:5672-192.168.1.9:60042]: 0 -> @disposition(21) [role=true, first=1, last=1, settled=true, state=@accepted(36) []] 2015-06-24 12:39:01 [Protocol] trace [qpid.192.168.1.106:5672-192.168.1.9:60042]: 1 <- @transfer(20) [handle=1, delivery-id=2, delivery-tag=b"2", settled=false, more=false, resume=false, aborted=false, batchable=false] (19) "\x00Sw\xa1\x0esecond message" 2015-06-24 12:39:01 [Protocol] trace [qpid.192.168.1.106:5672-192.168.1.9:60042]: 0 -> @flow(19) [next-incoming-id=3, incoming-window=2147483647, next-outgoing-id=1, outgoing-window=1, handle=1, delivery-count=3, link-credit=500, drain=false] 2015-06-24 12:39:01 [Protocol] trace [qpid.192.168.1.106:5672-192.168.1.9:60042]: 0 -> @transfer(20) [handle=0, delivery-id=1, delivery-tag=b"\x00\x00\x00\x01", message-format=0, settled=false, more=false] (30) "\x00Sp\xc0\x06\x04BP\x04@A\x00Sw\xa1\x0esecond message" 2015-06-24 12:39:01 [Protocol] trace [qpid.192.168.1.106:5672-192.168.1.9:60042]: 0 -> @disposition(21) [role=true, first=2, last=2, settled=true, state=@accepted(36) []] 2015-06-24 12:39:01 [Protocol] trace [qpid.192.168.1.106:5672-192.168.1.9:60042]: 0 <- @disposition(21) [role=true, first=0, last=0, settled=true, state=@accepted(36) [], batchable=false] Program received signal SIGSEGV, Segmentation fault. [Switching to Thread 0x7ffff211f700 (LWP 3903)] pn_do_disposition (transport=0x7fffe4003670, frame_type=<optimized out>, channel=<optimized out>, args=<optimized out>, payload=<optimized out>) at /home/mbroadst/Development/qpid-proton/proton-c/src/transport/transport.c:1487 1487 pn_delivery_t *delivery = pni_delivery_map_get(deliveries, id); (gdb) Cheers, Matt > > See below for the output: > [New Thread 0x7ffff3223700 (LWP 3864)] > 2015-06-24 12:21:16 [Security] notice SSL plugin not enabled, you must set > --ssl-cert-db to enable it. > 2015-06-24 12:21:16 [Store] notice Linear Store: Store module initialized; > store-dir=/var/lib/qpidd > 2015-06-24 12:21:16 [Broker] notice SASL disabled: No Authentication > Performed > 2015-06-24 12:21:16 [Network] notice Listening on TCP/TCP6 port 5672 > [New Thread 0x7ffff2920700 (LWP 3865)] > [New Thread 0x7ffff211f700 (LWP 3866)] > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: <- AMQP > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: -> AMQP > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 0 <- @open(16) > [container-id="conn1435162883471", hostname="192.168.1.106", > max-frame-size=4294967295, channel-max=65535, idle-time-out=120000, > outgoing-locales=:"en-US", incoming-locales=:"en-US", properties={}] > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 0 -> @open(16) > [container-id="18583796-c48c-4767-90a2-07d17a651e50", idle-time-out=120000] > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 1 <- @begin(17) > [next-outgoing-id=1, incoming-window=100, outgoing-window=100, > handle-max=4294967295, properties={}] > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 0 -> @begin(17) > [remote-channel=1, next-outgoing-id=0, incoming-window=2147483647, > outgoing-window=0] > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 1 <- @attach(18) > [name="qmf.default.topic_RX", handle=0, role=true, snd-settle-mode=2, > rcv-settle-mode=0, source=@source(40) [address="qmf.default.topic", > durable=0, expiry-policy=:"session-end", timeout=0, dynamic=false, > dynamic-node-properties={}, filter={}], target=@target(41) > [address="localhost", durable=0, expiry-policy=:"session-end", timeout=0, > dynamic=false, dynamic-node-properties={}], unsettled={}, > incomplete-unsettled=false, max-message-size=10000, properties={}] > 2015-06-24 12:21:23 [Protocol] debug > qpid.192.168.1.106:5672-192.168.1.9:59946 link 0x7fffe4002370 attached on > 0x7fffe400e5f0 > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 0 -> @attach(18) > [name="qmf.default.topic_RX", handle=0, role=false, snd-settle-mode=2, > rcv-settle-mode=0, source=@source(40) [address="qmf.default.topic", > durable=0, timeout=0, dynamic=false], target=@target(41) [durable=0, > timeout=0, dynamic=false], initial-delivery-count=0] > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 1 <- @attach(18) > [name="test.queue_RX", handle=1, role=true, snd-settle-mode=2, > rcv-settle-mode=0, source=@source(40) [address="test.queue", durable=0, > expiry-policy=:"session-end", timeout=0, dynamic=false, > dynamic-node-properties={}], target=@target(41) [address="localhost", > durable=0, expiry-policy=:"session-end", timeout=0, dynamic=false, > dynamic-node-properties={}], unsettled={}, incomplete-unsettled=false, > max-message-size=10000, properties={}] > 2015-06-24 12:21:23 [Protocol] debug > qpid.192.168.1.106:5672-192.168.1.9:59946 link 0x7fffe4014090 attached on > 0x7fffe400e5f0 > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 0 -> @attach(18) > [name="test.queue_RX", handle=1, role=false, snd-settle-mode=2, > rcv-settle-mode=0, source=@source(40) [address="test.queue", durable=0, > timeout=0, dynamic=false, distribution-mode=:move], target=@target(41) > [durable=0, timeout=0, dynamic=false], initial-delivery-count=0] > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 1 <- @flow(19) > [next-incoming-id=0, incoming-window=200, next-outgoing-id=1, > outgoing-window=100, handle=0, link-credit=100, available=0, drain=false, > echo=false, properties={}] > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 1 <- @flow(19) > [next-incoming-id=0, incoming-window=300, next-outgoing-id=1, > outgoing-window=100, handle=1, link-credit=100, available=0, drain=false, > echo=false, properties={}] > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 1 <- @attach(18) > [name="test.queue_TX", handle=2, role=false, snd-settle-mode=2, > rcv-settle-mode=0, source=@source(40) [address="localhost", durable=0, > expiry-policy=:"session-end", timeout=0, dynamic=false, > dynamic-node-properties={}, filter={}], target=@target(41) > [address="test.queue", durable=0, expiry-policy=:"session-end", timeout=0, > dynamic=false, dynamic-node-properties={}], unsettled={}, > incomplete-unsettled=false, initial-delivery-count=1, max-message-size=0, > properties={}] > 2015-06-24 12:21:23 [Protocol] debug > qpid.192.168.1.106:5672-192.168.1.9:59946 link 0x7fffe401b750 attached on > 0x7fffe400e5f0 > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 0 -> @attach(18) > [name="test.queue_TX", handle=2, role=true, snd-settle-mode=2, > rcv-settle-mode=0, source=@source(40) [durable=0, timeout=0, > dynamic=false], target=@target(41) [address="test.queue", durable=0, > timeout=0, dynamic=false], initial-delivery-count=0] > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 0 -> @flow(19) > [next-incoming-id=1, incoming-window=2147483647, next-outgoing-id=0, > outgoing-window=0, handle=2, delivery-count=1, link-credit=500, drain=false] > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 1 <- @transfer(20) [handle=2, > delivery-id=1, delivery-tag=b"1", settled=false, more=false, resume=false, > aborted=false, batchable=false] (18) "\x00Sw\xa1\x0dfirst message" > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 0 -> @flow(19) > [next-incoming-id=2, incoming-window=2147483647, next-outgoing-id=0, > outgoing-window=1, handle=2, delivery-count=2, link-credit=500, drain=false] > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 0 -> @transfer(20) [handle=1, > delivery-id=0, delivery-tag=b"\x00\x00\x00\x00", message-format=0, > settled=false, more=false] (29) "\x00Sp\xc0\x06\x04BP\x04@A\x00Sw\xa1\x0dfirst > message" > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 0 -> @disposition(21) > [role=true, first=1, last=1, settled=true, state=@accepted(36) []] > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 1 <- @transfer(20) [handle=2, > delivery-id=2, delivery-tag=b"2", settled=false, more=false, resume=false, > aborted=false, batchable=false] (19) "\x00Sw\xa1\x0esecond message" > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 0 -> @flow(19) > [next-incoming-id=3, incoming-window=2147483647, next-outgoing-id=1, > outgoing-window=1, handle=2, delivery-count=3, link-credit=500, drain=false] > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 0 -> @transfer(20) [handle=1, > delivery-id=1, delivery-tag=b"\x00\x00\x00\x01", message-format=0, > settled=false, more=false] (30) > "\x00Sp\xc0\x06\x04BP\x04@A\x00Sw\xa1\x0esecond > message" > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 0 -> @disposition(21) > [role=true, first=2, last=2, settled=true, state=@accepted(36) []] > 2015-06-24 12:21:23 [Protocol] trace > [qpid.192.168.1.106:5672-192.168.1.9:59946]: 0 <- @disposition(21) > [role=true, first=0, last=0, settled=true, state=@accepted(36) [], > batchable=false] > > > Matt > > > >> >> Here's the backtrace: >>> >>> Program received signal SIGSEGV, Segmentation fault. >>> pn_do_disposition (transport=0x7fffe4002fa0, frame_type=<optimized out>, >>> channel=<optimized out>, >>> args=<optimized out>, payload=<optimized out>) >>> at >>> >>> /home/mbroadst/Development/qpid-proton/proton-c/src/transport/transport.c:1487 >>> 1487 pn_delivery_t *delivery = pni_delivery_map_get(deliveries, id); >>> (gdb) bt >>> #0 pn_do_disposition (transport=0x7fffe4002fa0, frame_type=<optimized >>> out>, channel=<optimized out>, >>> args=<optimized out>, payload=<optimized out>) >>> at >>> >>> /home/mbroadst/Development/qpid-proton/proton-c/src/transport/transport.c:1487 >>> #1 0x00007ffff430ea53 in pni_dispatch_action (payload=0x7fffffffd150, >>> args=0x7fffe4003190, >>> channel=<optimized out>, frame_type=0 '\000', lcode=<optimized out>, >>> transport=0x7fffe4002fa0) >>> at >>> >>> /home/mbroadst/Development/qpid-proton/proton-c/src/dispatcher/dispatcher.c:74 >>> #2 pni_dispatch_frame (args=0x7fffe4003190, transport=0x7fffe4002fa0, >>> frame=...) >>> at >>> >>> /home/mbroadst/Development/qpid-proton/proton-c/src/dispatcher/dispatcher.c:116 >>> #3 pn_dispatcher_input (transport=transport@entry=0x7fffe4002fa0, >>> bytes=0x7fffe4009400 "", available=0, >>> batch=batch@entry=true, halt=halt@entry=0x7fffe4003122) >>> at >>> >>> /home/mbroadst/Development/qpid-proton/proton-c/src/dispatcher/dispatcher.c:135 >>> #4 0x00007ffff4314fbc in pn_input_read_amqp (transport=0x7fffe4002fa0, >>> layer=<optimized out>, >>> bytes=<optimized out>, available=<optimized out>) >>> at >>> >>> /home/mbroadst/Development/qpid-proton/proton-c/src/transport/transport.c:1705 >>> #5 0x00007ffff431507a in transport_consume (transport=transport@entry >>> =0x7fffe4002fa0) >>> at >>> >>> /home/mbroadst/Development/qpid-proton/proton-c/src/transport/transport.c:1637 >>> #6 0x00007ffff4317ed2 in pn_transport_process >>> (transport=transport@entry=0x7fffe4002fa0, >>> >>> size=<optimized out>, size@entry=23) >>> at >>> >>> /home/mbroadst/Development/qpid-proton/proton-c/src/transport/transport.c:2701 >>> #7 0x00007ffff4317feb in pn_transport_input (transport=0x7fffe4002fa0, >>> bytes=0x7ffff7e1f027 "\177\377\377\377R", available=0) >>> at >>> >>> /home/mbroadst/Development/qpid-proton/proton-c/src/transport/transport.c:1609 >>> #8 0x00007ffff458b273 in qpid::broker::amqp::Connection::decode(char >>> const*, unsigned long) () >>> from /usr/lib/x86_64-linux-gnu/qpid/daemon/amqp.so >>> #9 0x00007ffff74a5938 in >>> qpid::sys::AsynchIOHandler::readbuff(qpid::sys::AsynchIO&, >>> qpid::sys::AsynchIOBufferBase*) () from >>> /usr/lib/x86_64-linux-gnu/libqpidcommon.so.2 >>> #10 0x00007ffff7425def in >>> qpid::sys::posix::AsynchIO::readable(qpid::sys::DispatchHandle&) () >>> from /usr/lib/x86_64-linux-gnu/libqpidcommon.so.2 >>> #11 0x00007ffff74a94b3 in >>> qpid::sys::DispatchHandle::processEvent(qpid::sys::Poller::EventType) () >>> from /usr/lib/x86_64-linux-gnu/libqpidcommon.so.2 >>> #12 0x00007ffff7449c7a in qpid::sys::Poller::run() () from >>> /usr/lib/x86_64-linux-gnu/libqpidcommon.so.2 >>> #13 0x00007ffff79cc600 in qpid::broker::Broker::run() () from >>> /usr/lib/x86_64-linux-gnu/libqpidbroker.so.2 >>> #14 0x00000000004054dc in >>> qpid::broker::QpiddBroker::execute(qpid::broker::QpiddOptions*) () >>> #15 0x0000000000408d34 in qpid::broker::run_broker(int, char**, bool) () >>> #16 0x00007ffff6812ec5 in __libc_start_main (main=0x404790 <main>, >>> argc=3, >>> argv=0x7fffffffe658, >>> init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized >>> out>, >>> stack_end=0x7fffffffe648) >>> #17 0x00000000004049ac in _start () >>> >>> Cheers, >>> Matt >>> >>> >> >> --------------------------------------------------------------------- >> To unsubscribe, e-mail: [email protected] >> For additional commands, e-mail: [email protected] >> >> >
