Hi Michael, Sorry for misleading you. I think the way qpidd integrates proton must override the PN_TRACE_FRM configuration. I believe you should be able to get the protocol trace from the broker by using the -t option, e.g. "qpidd -t". I'll take a look at the logs you posted, however I suspect the most useful one will be the broker trace, so I would appreciate any effort you can make to obtain it.
Thanks, --Rafael On Fri, Oct 24, 2014 at 3:40 PM, Michael Ivanov <iv...@logit-ag.de> wrote: > Ok I have some results. Now the core is not dumped but I have unusual > delays > during application startup. I have started qpidd up with PN_TRACE_FRM set, > but do not see any trace output. Only thing I have are the following > entries > from syslog: > > Oct 24 21:17:24 ccsfat qpidd[28477]: 2014-10-24 21:17:24 [Broker] notice > Broker 28477 initializing > Oct 24 21:17:24 ccsfat qpidd[28477]: 2014-10-24 21:17:24 [Security] notice > SSL plugin not enabled, you must set --ssl-cert-db to > enable it. > Oct 24 21:17:24 ccsfat qpidd[28477]: 2014-10-24 21:17:24 [Store] notice > Journal "TplStore": Created > Oct 24 21:17:24 ccsfat qpidd[28477]: 2014-10-24 21:17:24 [Store] notice > Store module initialized; store-dir=/var/spool/qpid > Oct 24 21:17:24 ccsfat qpidd[28477]: 2014-10-24 21:17:24 [Store] warning > Message store plugin: No storage providers available. > Oct 24 21:17:24 ccsfat qpidd[28477]: 2014-10-24 21:17:24 [Network] notice > Listening on TCP/TCP6 port 5672 > Oct 24 21:17:24 ccsfat qpidd[28477]: 2014-10-24 21:17:24 [Broker] notice > Broker 28477 initialized > Oct 24 21:17:24 ccsfat qpidd[28477]: 2014-10-24 21:17:24 [Broker] notice > Broker 28477 running > Oct 24 21:21:04 ccsfat qpidd[28477]: 2014-10-24 21:21:04 [System] error > Connection qpid.127.0.0.1:5672-127.0.0.1:39178 No > protocol received closing > Oct 24 21:21:04 ccsfat qpidd[28477]: 2014-10-24 21:21:04 [System] error > Connection qpid.127.0.0.1:5672-127.0.0.1:39180 No > protocol received closing > Oct 24 21:21:04 ccsfat qpidd[28477]: 2014-10-24 21:21:04 [Management] > error Detected two management objects with the same > identifier: > 0-5-1--174(org.apache.qpid.broker:incoming:aa8fef78-607a-4913-a9ba-f10972657cd7,sender-xxx) > Oct 24 21:21:05 ccsfat qpidd[28477]: 2014-10-24 21:21:05 [System] error > Connection qpid.127.0.0.1:5672-127.0.0.1:39182 No > protocol received closing > Oct 24 21:21:05 ccsfat qpidd[28477]: 2014-10-24 21:21:05 [System] error > Connection qpid.127.0.0.1:5672-127.0.0.1:39184 No > protocol received closing > Oct 24 21:21:05 ccsfat qpidd[28477]: 2014-10-24 21:21:05 [System] error > Connection qpid.127.0.0.1:5672-127.0.0.1:39186 No > protocol received closing > Oct 24 21:21:05 ccsfat qpidd[28477]: 2014-10-24 21:21:05 [System] error > Connection qpid.127.0.0.1:5672-127.0.0.1:39188 No > protocol received closing > Oct 24 21:21:06 ccsfat qpidd[28477]: 2014-10-24 21:21:06 [System] error > Connection qpid.127.0.0.1:5672-127.0.0.1:39195 No > protocol received closing > > With client processes it's a little better. Here's the output from one of > the > processes: > > [0x82dd50]: -> SASL > [0x82dd50]:0 -> @sasl-init(65) [mechanism=:ANONYMOUS, initial-response=b""] > [0x82dd50]: <- SASL > [0x82dd50]:0 <- @sasl-mechanisms(64) > [sasl-server-mechanisms=@PN_SYMBOL[:ANONYMOUS, :LOGIN, :PLAIN, :GSSAPI]] > [0x82dd50]:0 <- @sasl-outcome(68) [code=0] > [0x82dd50]: -> AMQP > [0x82dd50]:0 -> @open(16) > [container-id="f58f77fd-6473-4cd9-8a55-7a4d1ed083b2", hostname="127.0.0.1"] > [0x82dd50]:0 -> @begin(17) [next-outgoing-id=0, > incoming-window=2147483647, outgoing-window=0] > [0x82dd50]:0 -> @attach(18) [name="TPRBOX", handle=0, role=true, > snd-settle-mode=2, rcv-settle-mode=0, source=@source(40) > [address="TPRBOX", durable=0, timeout=0, dynamic=false], > target=@target(41) [address="TPRBOX", durable=0, timeout=0, > dynamic=false], initial-delivery-count=0] > [0x82dd50]:0 -> @flow(19) [incoming-window=2147483647, next-outgoing-id=0, > outgoing-window=0, handle=0, delivery-count=0, > link-credit=1, drain=false] > [0x82dd50]: <- AMQP > [0x82dd50]:0 <- @open(16) > [container-id="e5584c39-5ae9-4fad-ba53-2528475d71ba"] > [0x82dd50]:0 <- @begin(17) [remote-channel=0, next-outgoing-id=0, > incoming-window=2147483647, outgoing-window=1] > [0x82dd50]:0 <- @attach(18) [name="TPRBOX", handle=0, role=false, > snd-settle-mode=2, rcv-settle-mode=0, source=@source(40) > [address="TPRBOX", durable=0, timeout=0, dynamic=false], > target=@target(41) [durable=0, timeout=0, dynamic=false], > initial-delivery-count=0] > [0x82dd50]:0 <- @transfer(20) [handle=0, delivery-id=0, > delivery-tag=b"\x00\x00\x00\x00", message-format=0, settled=false, > more=false] (255) > "\x00Sp\xc0\x06\x04BP\x04@A\x00Ss\xd0\x00\x00\x008\x00\x00\x00\x0d@ > @\xa1\x15amqp:// > 0.0.0.0/TPRBOX@@@@@\x83\x00\x00\x00\x00\x00\x00\x00\x00\x83\x00\x00\x00\x00\x00\x00\x00\x00@R\x00@\x00Sw\xa0\xaf\x08\x00\x00\x00\x00\x00\x00\x00\x8c#\x00\x00\x00\x00\x00\x00 > !\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00apol\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00!\x00\x00\x00apol\x00\x00\x00\x005 > AP\x00\x00\x00\x00\x00\x00\x00\x003\x00\x00\x0024.10.14 21:21:35 APOL > _RECEIVE: Timer1 timed out.\x0a\x00%G\x01\x999\x00\x00" > > [0x82dd50]:0 -> @flow(19) [next-incoming-id=1, incoming-window=2147483647, > next-outgoing-id=0, outgoing-window=0, handle=0, > delivery-count=1, link-credit=1, drain=false] > [0x82dd50]:0 -> @disposition(21) [role=true, first=0, last=0, settled=true] > [0x82dd50]:0 <- @transfer(20) [handle=0, delivery-id=1, > delivery-tag=b"\x00\x00\x00\x01", message-format=0, settled=false, > more=false] (282) > "\x00Sp\xc0\x06\x04BP\x04@A\x00Ss\xd0\x00\x00\x008\x00\x00\x00\x0d@ > @\xa1\x15amqp:// > 0.0.0.0/TPRBOX@@@@@\x83\x00\x00\x00\x00\x00\x00\x00\x00\x83\x00\x00\x00\x00\x00\x00\x00\x00@R\x00@\x00Sw\xa0\xca\x08\x00\x00\x00\x00\x00\x00\x00\x8c#\x00\x00\x00\x00\x00\x00 > !\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00apol\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00!\x00\x00\x00apol\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00N\x00\x00\x0024.10.14 > 21:21:35 APOL > ++++++++++++++++++++++++++++++++++++++++++++++++++++++\x0a\x00\x0024.10." > [0x82dd50]:0 -> @flow(19) [next-incoming-id=2, incoming-window=2147483647, > next-outgoing-id=0, outgoing-window=0, handle=0, > delivery-count=2, link-credit=1, drain=false] > [0x82dd50]:0 -> @disposition(21) [role=true, first=1, last=1, settled=true] > [0x82dd50]:0 <- @transfer(20) [handle=0, delivery-id=2, > delivery-tag=b"\x00\x00\x00\x02", message-format=0, settled=false, > more=false] (252) > "\x00Sp\xc0\x06\x04BP\x04@A\x00Ss\xd0\x00\x00\x008\x00\x00\x00\x0d@ > @\xa1\x15amqp:// > 0.0.0.0/TPRBOX@@@@@\x83\x00\x00\x00\x00\x00\x00\x00\x00\x83\x00\x00\x00\x00\x00\x00\x00\x00@R\x00@\x00Sw\xa0\xac\x08\x00\x00\x00\x00\x00\x00\x00\x8c#\x00\x00\x00\x00\x00\x00 > !\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00apol\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00!\x00\x00\x00apol\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x000\x00\x00\x0024.10.14 > 21:21:35 APOL _POLL: Function started.\x0a\x00+++++++" > [0x82dd50]:0 -> @flow(19) [next-incoming-id=3, incoming-window=2147483647, > next-outgoing-id=0, outgoing-window=0, handle=0, > delivery-count=3, link-credit=1, drain=false] > [0x82dd50]:0 -> @disposition(21) [role=true, first=2, last=2, settled=true] > [0x82dd50]:0 <- @transfer(20) [handle=0, delivery-id=3, > delivery-tag=b"\x00\x00\x00\x03", message-format=0, settled=false, > more=false] (282) > "\x00Sp\xc0\x06\x04BP\x04@A\x00Ss\xd0\x00\x00\x008\x00\x00\x00\x0d@ > @\xa1\x15amqp:// > 0.0.0.0/TPRBOX@@@@@\x83\x00\x00\x00\x00\x00\x00\x00\x00\x83\x00\x00\x00\x00\x00\x00\x00\x00@R\x00@\x00Sw\xa0\xca\x08\x00\x00\x00\x00\x00\x00\x00\x8c#\x00\x00\x00\x00\x00\x00 > !\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00apol\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00!\x00\x00\x00apol\x008c#\x00\x00\x00N\x00\x00\x0024.10.14 > 21:21:35 APOL > ++++++++++++++++++++++++++++++++++++++++++++++++++++++\x0a\x0000\x00\" > [0x82dd50]:0 -> @flow(19) [next-incoming-id=4, incoming-window=2147483647, > next-outgoing-id=0, outgoing-window=0, handle=0, > delivery-count=4, link-credit=1, drain=false] > [0x82dd50]:0 -> @disposition(21) [role=true, first=3, last=3, settled=true] > [0x82dd50]:0 <- @transfer(20) [handle=0, delivery-id=4, > delivery-tag=b"\x00\x00\x00\x04", message-format=0, settled=false, > more=false] (262) > "\x00Sp\xc0\x06\x04BP\x04@A\x00Ss\xd0\x00\x00\x008\x00\x00\x00\x0d@ > @\xa1\x15amqp:// > 0.0.0.0/TPRBOX@@@@@\x83\x00\x00\x00\x00\x00\x00\x00\x00\x83\x00\x00\x00\x00\x00\x00\x00\x00@R\x00@\x00Sw\xa0\xb6\x08\x00\x00\x00\x00\x00\x00\x00\x8c#\x00\x00\x00\x00\x00\x00 > !\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00apol\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00!\x00\x00\x00apol\x008c#\x00\x00\x00:\x00\x00\x0024.10.14 > 21:21:35 APOL _CCS_TC_TIMEOUT: Function started.\x0a\x00+++++++" > [0x82dd50]:0 -> @flow(19) [next-incoming-id=5, incoming-window=2147483647, > next-outgoing-id=0, outgoing-window=0, handle=0, > delivery-count=5, link-credit=1, drain=false] > [0x82dd50]:0 -> @disposition(21) [role=true, first=4, last=4, settled=true] > [0x82dd50]:0 <- @transfer(20) [handle=0, delivery-id=5, > delivery-tag=b"\x00\x00\x00\x05", message-format=0, settled=false, > more=false] (330) > "\x00Sp\xc0\x06\x04BP\x04@A\x00Ss\xd0\x00\x00\x008\x00\x00\x00\x0d@ > @\xa1\x15amqp:// > 0.0.0.0/TPRBOX@@@@@\x83\x00\x00\x00\x00\x00\x00\x00\x00\x83\x00\x00\x00\x00\x00\x00\x00\x00@R\x00@\x00Sw\xa0\xfa\x08\x00\x00\x00\x00\x00\x00\x00\x8c#\x00\x00\x00\x00\x00\x00 > !\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00apol\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00!\x00\x00\x00apol\x008c#\x00\x00\x00~\x00\x00\x0024.10.14 > 21:21:35 APOL _CCS_TC_TIMEOUT: Fetching next record failed.\x0a > ORA-ERR: ORA-01403: no data > found\x0a\x0000\x00\" > [0x82dd50]:0 -> @flow(19) [next-incoming-id=6, incoming-window=2147483647, > next-outgoing-id=0, outgoing-window=0, handle=0, > delivery-count=6, link-credit=1, drain=false] > [0x82dd50]:0 -> @disposition(21) [role=true, first=5, last=5, settled=true] > [0x82dd50]:0 <- @transfer(20) [handle=0, delivery-id=6, > delivery-tag=b"\x00\x00\x00\x06", message-format=0, settled=false, > more=false] (282) > "\x00Sp\xc0\x06\x04BP\x04@A\x00Ss\xd0\x00\x00\x008\x00\x00\x00\x0d@ > @\xa1\x15amqp:// > 0.0.0.0/TPRBOX@@@@@\x83\x00\x00\x00\x00\x00\x00\x00\x00\x83\x00\x00\x00\x00\x00\x00\x00\x00@R\x00@\x00Sw\xa0\xca\x08\x00\x00\x00\x00\x00\x00\x00\x8c#\x00\x00\x00\x00\x00\x00 > !\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00apol\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00!\x00\x00\x00apol\x008c#\x00\x00\x00N\x00\x00\x0024.10.14 > 21:21:35 APOL > ++++++++++++++++++++++++++++++++++++++++++++++++++++++\x0a\x00 " > [0x82dd50]:0 -> @flow(19) [next-incoming-id=7, incoming-window=2147483647, > next-outgoing-id=0, outgoing-window=0, handle=0, > delivery-count=7, link-credit=1, drain=false] > [0x82dd50]:0 -> @disposition(21) [role=true, first=6, last=6, settled=true] > [0x82dd50]:0 <- @transfer(20) [handle=0, delivery-id=7, > delivery-tag=b"\x00\x00\x00\x07", message-format=0, settled=false, > more=false] (282) > "\x00Sp\xc0\x06\x04BP\x04@A\x00Ss\xd0\x00\x00\x008\x00\x00\x00\x0d@ > @\xa1\x15amqp:// > 0.0.0.0/TPRBOX@@@@@\x83\x00\x00\x00\x00\x00\x00\x00\x00\x83\x00\x00\x00\x00\x00\x00\x00\x00@R\x00@\x00Sw\xa0\xca\x08\x00\x00\x00\x00\x00\x00\x00\x8c#\x00\x00\x00\x00\x00\x00 > !\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00apol\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00!\x00\x00\x00apol\x00+++++++++++++++N\x00\x00\x0024.10.14 > 21:21:35 APOL > ++++++++++++++++++++++++++++++++++++++++++++++++++++++\x0a\x0000\x00\" > [0x82dd50]:0 -> @flow(19) [next-incoming-id=8, incoming-window=2147483647, > next-outgoing-id=0, outgoing-window=0, handle=0, > delivery-count=8, link-credit=1, drain=false] > [0x82dd50]:0 -> @disposition(21) [role=true, first=7, last=7, settled=true] > [0x82dd50]:0 <- @transfer(20) [handle=0, delivery-id=8, > delivery-tag=b"\x00\x00\x00\x08", message-format=0, settled=false, > more=false] (260) > "\x00Sp\xc0\x06\x04BP\x04@A\x00Ss\xd0\x00\x00\x008\x00\x00\x00\x0d@ > @\xa1\x15amqp:// > 0.0.0.0/TPRBOX@@@@@\x83\x00\x00\x00\x00\x00\x00\x00\x00\x83\x00\x00\x00\x00\x00\x00\x00\x00@R\x00@\x00Sw\xa0\xb4\x08\x00\x00\x00\x00\x00\x00\x00\x8c#\x00\x00\x00\x00\x00\x00 > !\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00apol\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00!\x00\x00\x00apol\x00+++++++++++++++8\x00\x00\x0024.10.14 > 21:21:35 APOL _CCS_TC_RESET: Function started.\x0a\x00+++++++" > [0x82dd50]:0 -> @flow(19) [next-incoming-id=9, incoming-window=2147483647, > next-outgoing-id=0, outgoing-window=0, handle=0, > delivery-count=9, link-credit=1, drain=false] > [0x82dd50]:0 -> @disposition(21) [role=true, first=8, last=8, settled=true] > [0x82dd50]:0 <- @transfer(20) [handle=0, delivery-id=9, > delivery-tag=b"\x00\x00\x00\x09", message-format=0, settled=false, > more=false] (328) > "\x00Sp\xc0\x06\x04BP\x04@A\x00Ss\xd0\x00\x00\x008\x00\x00\x00\x0d@ > @\xa1\x15amqp:// > 0.0.0.0/TPRBOX@@@@@\x83\x00\x00\x00\x00\x00\x00\x00\x00\x83\x00\x00\x00\x00\x00\x00\x00\x00@R\x00@\x00Sw\xa0\xf8\x08\x00\x00\x00\x00\x00\x00\x00\x8c#\x00\x00\x00\x00\x00\x00 > !\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00apol\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00!\x00\x00\x00apol\x00+++++++++++++++|\x00\x00\x0024.10.14 > 21:21:35 APOL _CCS_TC_RESET: Fetching next record failed.\x0a > ORA-ERR: ORA-01403: no data > found\x0a\x00\x00\x0" > [0x82dd50]:0 -> @flow(19) [next-incoming-id=10, > incoming-window=2147483647, next-outgoing-id=0, outgoing-window=0, handle=0, > delivery-count=10, link-credit=1, drain=false] > [0x82dd50]:0 -> @disposition(21) [role=true, first=9, last=9, settled=true] > > etc. This process is supposed to receive messages on TPRBOX queue. > > The following process is sending the data to TPRBOX: > > [0x12862d0]: -> SASL > [0x12862d0]:0 -> @sasl-init(65) [mechanism=:ANONYMOUS, > initial-response=b""] > [0x129d770]: -> SASL > [0x129d770]:0 -> @sasl-init(65) [mechanism=:ANONYMOUS, > initial-response=b""] > [0x12862d0]: <- SASL > [0x12862d0]:0 <- @sasl-mechanisms(64) > [sasl-server-mechanisms=@PN_SYMBOL[:ANONYMOUS, :LOGIN, :PLAIN, :GSSAPI]] > [0x12862d0]:0 <- @sasl-outcome(68) [code=0] > [0x12862d0]: -> AMQP > [0x12862d0]:0 -> @open(16) > [container-id="271772a8-3e5e-496e-8ad3-bd39815dbafb", hostname="127.0.0.1"] > [0x12862d0]:0 -> @begin(17) [next-outgoing-id=0, > incoming-window=2147483647, outgoing-window=0] > [0x12862d0]:0 -> @attach(18) [name="TPRBOX", handle=0, role=true, > snd-settle-mode=2, rcv-settle-mode=0, source=@source(40) > [address="TPRBOX", durable=0, timeout=0, dynamic=false], > target=@target(41) [address="TPRBOX", durable=0, timeout=0, > dynamic=false], initial-delivery-count=0] > [0x129d770]: <- SASL > [0x129d770]:0 <- @sasl-mechanisms(64) > [sasl-server-mechanisms=@PN_SYMBOL[:ANONYMOUS, :LOGIN, :PLAIN, :GSSAPI]] > [0x129d770]:0 <- @sasl-outcome(68) [code=0] > [0x129d770]: <- AMQP > [0x12862d0]: <- AMQP > [0x129d770]: -> AMQP > [0x129d770]:0 -> @open(16) > [container-id="271772a8-3e5e-496e-8ad3-bd39815dbafb", hostname="0.0.0.0"] > [0x129d770]:0 -> @begin(17) [next-outgoing-id=0, > incoming-window=2147483647, outgoing-window=1] > [0x129d770]:0 -> @attach(18) [name="sender-xxx", handle=0, role=false, > snd-settle-mode=2, rcv-settle-mode=0, source=@source(40) > [address="TPRBOX", durable=0, timeout=0, dynamic=false], > target=@target(41) [address="TPRBOX", durable=0, timeout=0, > dynamic=false], initial-delivery-count=0] > [0x129d770]:0 <- @open(16) > [container-id="e5584c39-5ae9-4fad-ba53-2528475d71ba"] > [0x129d770]:0 <- @begin(17) [remote-channel=0, next-outgoing-id=0, > incoming-window=2147483647, outgoing-window=0] > [0x129d770]:0 <- @attach(18) [name="sender-xxx", handle=0, role=true, > snd-settle-mode=2, rcv-settle-mode=0, source=@source(40) > [durable=0, timeout=0, dynamic=false], target=@target(41) > [address="TPRBOX", durable=0, timeout=0, dynamic=false], > initial-delivery-count=0] > [0x129d770]:0 <- @flow(19) [next-incoming-id=0, > incoming-window=2147483647, next-outgoing-id=0, outgoing-window=0, handle=0, > delivery-count=0, link-credit=100, drain=false] > [0x129d770]:0 -> @transfer(20) [handle=0, delivery-id=0, > delivery-tag=b"\x00\x00\x00\x00\x00\x00\x00\x00", message-format=0, > settled=true, more=false] (275) > "\x00Sp\xd0\x00\x00\x00\x0b\x00\x00\x00\x05BP\x04@BR > \x00\x00Ss\xd0\x00\x00\x008\x00\x00\x00\x0d@@\xa1\x15amqp:// > 0.0.0.0/TPRBOX@@@@@\x83\x00\x00\x00\x00\x00\x00\x00\x00\x83\x00\x00\x00\x00\x00\x00\x00\x00@R\x00@\x00Sw\xa0\xbb\x08\x00\x00\x00\x00\x00\x00\x00\x8c#\x00\x00\x00\x00\x00\x00 > !\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00alma\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00 > \x00\x00\x00alma\x00\x00\x00\x00\x00\x00\x00\x00\x00\x1aR\xfc\xff\x7f\x00\x00?\x00\x00\x0024.10.14 > 21:21:04 ALMA ** Process > alma[28883] is getting up...\x0a\x00\xff\x7f\x00\x00\x8dE@" > [0x129d770]:0 -> @transfer(20) [handle=0, delivery-id=1, > delivery-tag=b"\x01\x00\x00\x00\x00\x00\x00\x00", message-format=0, > settled=true, more=false] (249) > "\x00Sp\xd0\x00\x00\x00\x0b\x00\x00\x00\x05BP\x04@BR > \x00\x00Ss\xd0\x00\x00\x008\x00\x00\x00\x0d@@\xa1\x15amqp:// > 0.0.0.0/TPRBOX@@@@@\x83\x00\x00\x00\x00\x00\x00\x00\x00\x83\x00\x00\x00\x00\x00\x00\x00\x00@R\x00@\x00Sw\xa0\xa1\x08\x00\x00\x00\x00\x00\x00\x00\x8c#\x00\x00\x00\x00\x00\x00 > !\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00alma\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00 > \x00\x00\x00alma\x00\x00\x00\x00\x00\x00\x00\x00\x00\x1aR\xfc\xff\x7f\x00\x00%\x00\x00\x0024.10.14 > 21:21:04 ALMA apl_start: > OK\x0a\x00[28883]" > [0x129d770]:0 <- @flow(19) [next-incoming-id=1, > incoming-window=2147483647, next-outgoing-id=0, outgoing-window=0, handle=0, > delivery-count=1, link-credit=100, drain=false] > [0x129d770]:0 -> @transfer(20) [handle=0, delivery-id=2, > delivery-tag=b"\x02\x00\x00\x00\x00\x00\x00\x00", message-format=0, > settled=true, more=false] (281) > "\x00Sp\xd0\x00\x00\x00\x0b\x00\x00\x00\x05BP\x04@BR > \x00\x00Ss\xd0\x00\x00\x008\x00\x00\x00\x0d@@\xa1\x15amqp:// > 0.0.0.0/TPRBOX@@@@@\x83\x00\x00\x00\x00\x00\x00\x00\x00\x83\x00\x00\x00\x00\x00\x00\x00\x00@R\x00@\x00Sw\xa0\xc1\x08\x00\x00\x00\x00\x00\x00\x00\x8c#\x00\x00\x00\x00\x00\x00 > !\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00alma\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00 > \x00\x00\x00alma\x00\x07\x0a\x00\x18\x00\x15\x00\x15\x00\x04\x00L\x00\x00\x00E\x00\x00\x0024.10.14 > 21:21:04 ALMA Connecting to > oracle database as omgr@CCS_APP\x0a\x00R\xfc\xff\x7f\x00\x00P" > [0x129d770]:0 -> @transfer(20) [handle=0, delivery-id=3, > delivery-tag=b"\x03\x00\x00\x00\x00\x00\x00\x00", message-format=0, > settled=true, more=false] (284) > "\x00Sp\xd0\x00\x00\x00\x0b\x00\x00\x00\x05BP\x04@BR > \x00\x00Ss\xd0\x00\x00\x008\x00\x00\x00\x0d@@\xa1\x15amqp:// > 0.0.0.0/TPRBOX@@@@@\x83\x00\x00\x00\x00\x00\x00\x00\x00\x83\x00\x00\x00\x00\x00\x00\x00\x00@R\x00@\x00Sw\xa0\xc4\x08\x00\x00\x00\x00\x00\x00\x00\x8c#\x00\x00\x00\x00\x00\x00 > !\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00alma\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00 > \x00\x00\x00alma\x00\x13R\xfc\xff\x7f\x00\x00b\xf7F\x999\x00\x00\x00H\x00\x00\x0024.10.14 > 21:21:04 ALMA Oracle database > connected as user "omgr@CCS_APP"\x0a\x00\x00\x00\x00gT\xfc\x18" > [0x129d770]:0 <- @flow(19) [next-incoming-id=2, > incoming-window=2147483647, next-outgoing-id=0, outgoing-window=0, handle=0, > delivery-count=2, link-credit=100, drain=false] > [0x129d770]:0 <- @flow(19) [next-incoming-id=3, > incoming-window=2147483647, next-outgoing-id=0, outgoing-window=0, handle=0, > delivery-count=3, link-credit=100, drain=false] > [0x12862d0]:0 <- @open(16) > [container-id="e5584c39-5ae9-4fad-ba53-2528475d71ba"] > [0x12862d0]:0 <- @begin(17) [remote-channel=0, next-outgoing-id=0, > incoming-window=2147483647, outgoing-window=0] > [0x12862d0]:0 <- @attach(18) [name="TPRBOX", handle=0, role=false, > snd-settle-mode=2, rcv-settle-mode=0, source=@source(40) > [address="TPRBOX", durable=0, timeout=0, dynamic=false], > target=@target(41) [durable=0, timeout=0, dynamic=false], > initial-delivery-count=0] > [0x129d770]:0 -> @transfer(20) [handle=0, delivery-id=4, > delivery-tag=b"\x04\x00\x00\x00\x00\x00\x00\x00", message-format=0, > settled=true, more=false] (253) > "\x00Sp\xd0\x00\x00\x00\x0b\x00\x00\x00\x05BP\x04@BR > \x00\x00Ss\xd0\x00\x00\x008\x00\x00\x00\x0d@@\xa1\x15amqp:// > 0.0.0.0/TPRBOX@@@@@\x83\x00\x00\x00\x00\x00\x00\x00\x00\x83\x00\x00\x00\x00\x00\x00\x00\x00@R\x00@\x00Sw\xa0\xa5\x08\x00\x00\x00\x00\x00\x00\x00\x8c#\x00\x00\x00\x00\x00\x00 > !\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00alma\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00 > \x00\x00\x00alma\x00\x13R\xfc\xff\x7f\x00\x00b\xf7F\x999\x00\x00\x00)\x00\x00\x0024.10.14 > 21:21:04 ALMA apl_start_ora: > OK\x0a\x00nected " > [0x129d770]:0 <- @flow(19) [next-incoming-id=4, > incoming-window=2147483647, next-outgoing-id=0, outgoing-window=0, handle=0, > delivery-count=4, link-credit=100, drain=false] > > Best regards, > > 24.10.2014 22:36, Rafael Schloming пишет: > > You can check out the trunk source code from here: > > > > http://svn.apache.org/repos/asf/qpid/proton/trunk/ > > > > You should be able to turn on the protocol trace by setting the > > PN_TRACE_FRM environment variable to 1, e.g.: > > > > export PN_TRACE_FRM=1 > > run-client-program > > > > You will need to do this on the server side as well in order to get the > > server's version of the protocol trace. > > > > --Rafael > > > > > > On Fri, Oct 24, 2014 at 2:31 PM, Michael Ivanov <iv...@logit-ag.de> > wrote: > > > >> Sorry, should I check out the trunk from the repository or can I > download > >> the new sources tar archive from somewhere? The last version I used I > have > >> downloaded from > >> http://people.apache.org/~rhs/qpid-proton-0.8rc4/qpid-proton-0.8.tar.gz > >> If the sources are to be checked out which url should I use? > >> > >> And pls can you explain me how to turn the proitocol trace on? Or > should I > >> just tcpdump during exchange? > >> > >> Best regards, > >> > >> 24.10.2014 22:24, Rafael Schloming пишет: > >>> Hi Michael, > >>> > >>> I just committed the change Ken suggested to at least fix the abort. Is > >>> there any way you could retest with trunk? > >>> > >>> If the problem still occurs (I expect it will, just not quite so > fatally) > >>> it would be good to get the protocol trace for both the client and the > >>> server and see if that will shed some light on what is going on. > >>> > >>> --Rafael > >>> > >>> > >>> On Fri, Oct 24, 2014 at 2:00 PM, Michael Ivanov <iv...@logit-ag.de> > >> wrote: > >>> > >>>> I just rebuilt all client processes to use proton 0.8 (it was still > 0.7 > >>>> before) > >>>> Error is still the same. > >>>> > >>>> Best regards, > >>>> > >>>> 24.10.2014 18:16, Ken Giusti пишет: > >>>>> >From the trace, it seems like the broker is receiving a transfer > whose > >>>> delivery id is out of order. > >>>>> > >>>>> This shouldn't cause an abort - likely the result is an untested > >> failure > >>>> path, in transport.c:781: > >>>>> > >>>>> if (id_present && id != state->id) { > >>>>> int err = pn_do_error(transport, "amqp:session:invalid-field", > >>>>> "sequencing error, expected delivery-id > %u, > >>>> got %u", > >>>>> state->id, id); > >>>>> ====> // XXX: this will probably leave delivery buffer state messed > up > >>>>> pn_full_settle(incoming, delivery); > >>>>> return err; > >>>>> } > >>>>> > >>>>> It doesn't explain why a transfer is sent out of order by the client, > >>>> but at least we probably should remove the attempt to > pn_full_settle(), > >> and > >>>> just return the error to fail the connection (assumed - totally > >> untested). > >>>>> > >>>>> -K > >>>>> > >>>>> ----- Original Message ----- > >>>>>> From: "Michael Ivanov" <iv...@logit-ag.de> > >>>>>> To: proton@qpid.apache.org > >>>>>> Sent: Friday, October 24, 2014 9:38:54 AM > >>>>>> Subject: Re: VOTE: Release Proton 0.8 RC4 as 0.8 final > >>>>>> > >>>>>> Hallo, > >>>>>> > >>>>>> I used proton 0.7 and later when I had an error, proton 0.8 RC4 to > >> build > >>>>>> qpid-cpp-0.30. In both cases at some time qpidd aborts in proton > >> library > >>>>>> in the following location: > >>>>>> > >>>>>> > >>>>>> #0 0x0000003999432635 in raise () from /lib64/libc.so.6 > >>>>>> #1 0x0000003999433e15 in abort () from /lib64/libc.so.6 > >>>>>> #2 0x000000399942b75e in __assert_fail_base () from > /lib64/libc.so.6 > >>>>>> #3 0x000000399942b820 in __assert_fail () from /lib64/libc.so.6 > >>>>>> #4 0x00007f130a5af37d in pn_full_settle (db=<value optimized out>, > >>>>>> delivery=0x7f13001545f0) > >>>>>> at > >>>> /home/ksmgr/mq/qpid-proton-0.8/proton-c/src/transport/transport.c:742 > >>>>>> #5 0x00007f130a5b0cbe in pn_do_transfer (disp=0x1b6dcf0) at > >>>>>> > /home/ksmgr/mq/qpid-proton-0.8/proton-c/src/transport/transport.c:786 > >>>>>> #6 0x00007f130a5a94d5 in pni_dispatch_action (disp=0x1b6dcf0, > >>>> frame=...) > >>>>>> at > >>>> /home/ksmgr/mq/qpid-proton-0.8/proton-c/src/dispatcher/dispatcher.c:65 > >>>>>> #7 pn_dispatch_frame (disp=0x1b6dcf0, frame=...) at > >>>>>> > >> /home/ksmgr/mq/qpid-proton-0.8/proton-c/src/dispatcher/dispatcher.c:172 > >>>>>> #8 0x00007f130a5a9718 in pn_dispatcher_input (disp=0x1b6dcf0, > >>>>>> bytes=0x1b75e10 "", available=0) > >>>>>> at > >>>>>> > >>>> > /home/ksmgr/mq/qpid-proton-0.8/proton-c/src/dispatcher/dispatcher.c:194 > >>>>>> #9 0x00007f130a5b2606 in pn_input_read_amqp (io_layer=<value > >> optimized > >>>> out>, > >>>>>> bytes=<value optimized out>, available=<value > >>>>>> optimized out>) > >>>>>> at > >>>> /home/ksmgr/mq/qpid-proton-0.8/proton-c/src/transport/transport.c:1145 > >>>>>> #10 0x00007f130a5ae029 in transport_consume (transport=0x1b6dab0) at > >>>>>> > /home/ksmgr/mq/qpid-proton-0.8/proton-c/src/transport/transport.c:1064 > >>>>>> #11 0x00007f130a5ae198 in pn_transport_process (transport=0x1b6dab0, > >>>>>> size=<value optimized out>) > >>>>>> at > >>>> /home/ksmgr/mq/qpid-proton-0.8/proton-c/src/transport/transport.c:2120 > >>>>>> #12 0x00007f130a5ae8e0 in pn_transport_input (transport=0x1b6dab0, > >>>>>> bytes=0x1b2a9b6 "eeded\n", available=0) > >>>>>> at > >>>> /home/ksmgr/mq/qpid-proton-0.8/proton-c/src/transport/transport.c:1039 > >>>>>> #13 0x00007f130a81c192 in qpid::broker::amqp::Connection::decode > >>>>>> (this=0x1b6c4c8, buffer=0x1b2a880 "", size=310) > >>>>>> at > >>>> /home/ksmgr/mq/qpid-cpp-0.30/src/qpid/broker/amqp/Connection.cpp:119 > >>>>>> #14 0x00007f130a858c99 in qpid::broker::amqp::Sasl::decode > >>>> (this=0x1b6c470, > >>>>>> buffer=<value optimized out>, size=310) > >>>>>> at /home/ksmgr/mq/qpid-cpp-0.30/src/qpid/broker/amqp/Sasl.cpp:49 > >>>>>> #15 0x00007f130b0e9100 in qpid::sys::AsynchIOHandler::readbuff > >>>>>> (this=0x1b29a90, buff=0x1b6a890) > >>>>>> at > >> /home/ksmgr/mq/qpid-cpp-0.30/src/qpid/sys/AsynchIOHandler.cpp:135 > >>>>>> #16 0x00007f130b0689e7 in operator() (this=0x1b29ad0, h=...) at > >>>>>> /usr/include/boost/function/function_template.hpp:1013 > >>>>>> #17 qpid::sys::posix::AsynchIO::readable (this=0x1b29ad0, h=...) at > >>>>>> /home/ksmgr/mq/qpid-cpp-0.30/src/qpid/sys/posix/AsynchIO.cpp:452 > >>>>>> #18 0x00007f130b0ed853 in boost::function1<void, > >>>>>> qpid::sys::DispatchHandle&>::operator() (this=<value optimized out>, > >>>>>> a0=<value optimized out>) at > >>>>>> /usr/include/boost/function/function_template.hpp:1013 > >>>>>> #19 0x00007f130b0ec991 in qpid::sys::DispatchHandle::processEvent > >>>>>> (this=0x1b29ad8, type=qpid::sys::Poller::READABLE) > >>>>>> at > >> /home/ksmgr/mq/qpid-cpp-0.30/src/qpid/sys/DispatchHandle.cpp:280 > >>>>>> #20 0x00007f130b08d4f2 in process (this=0x176cc90) at > >>>>>> /home/ksmgr/mq/qpid-cpp-0.30/src/qpid/sys/Poller.h:131 > >>>>>> #21 qpid::sys::Poller::run (this=0x176cc90) at > >>>>>> /home/ksmgr/mq/qpid-cpp-0.30/src/qpid/sys/epoll/EpollPoller.cpp:522 > >>>>>> #22 0x00007f130b08240a in qpid::sys::(anonymous > >> namespace)::runRunnable > >>>>>> (p=<value optimized out>) > >>>>>> at /home/ksmgr/mq/qpid-cpp-0.30/src/qpid/sys/posix/Thread.cpp:35 > >>>>>> #23 0x0000003999c079d1 in start_thread () from > /lib64/libpthread.so.0 > >>>>>> #24 0x00000039994e886d in clone () from /lib64/libc.so.6 > >>>>>> > >>>>>> I have core file and probably I can try to recreate the situation. > >>>>>> > >>>>>> Best regards, > >>>>>> > >>>>>> 24.10.2014 17:05, Timothy Bish пишет: > >>>>>>> [ X ] Yes, release Proton 0.8 RC4 as 0.8 final. > >>>>>>> > >>>>>>> Tested Proton-J with ActiveMQ and the new JMS client and found no > >>>> issues, > >>>>>>> > >>>>>>> On 10/23/2014 12:21 PM, Rafael Schloming wrote: > >>>>>>>> Hi Everyone, > >>>>>>>> > >>>>>>>> I've put together RC4. This is pretty much the same as RC3 with a > >>>> number > >>>>>>>> of > >>>>>>>> fixes to disable those SSL versions that are vulnerable to attack. > >>>>>>>> > >>>>>>>> The sources are available here: > >>>>>>>> > >>>>>>>> - http://people.apache.org/~rhs/qpid-proton-0.8rc4/ > >>>>>>>> > >>>>>>>> Java binaries are here: > >>>>>>>> > >>>>>>>> - > >>>>>>>> > >>>> > https://repository.apache.org/content/repositories/orgapacheqpid-1020/ > >>>>>>>> > >>>>>>>> Changes since RC3: > >>>>>>>> > >>>>>>>> - PROTON-724: make sure to pop any pending output in > >>>>>>>> pn_transport_close_head() > >>>>>>>> - PROTON-720: [Windows IO] fix format specifier to print string > >>>>>>>> - added dispatch utility > >>>>>>>> - fixed error message > >>>>>>>> - fixed Collector.put > >>>>>>>> - PROTON-719 : prevent ssl3 connections in Windows with > schannel > >>>>>>>> - PROTON-717: disable SSLv3 > >>>>>>>> - PROTON-717: mitigate the CRIME SSL vulnerability > >>>>>>>> - PROTON-716: reject connections using SSLv3 - it is insecure > >>>>>>>> > >>>>>>>> Please check the sources out and register your vote: > >>>>>>>> > >>>>>>>> [ ] Yes, release Proton 0.8 RC4 as 0.8 final. > >>>>>>>> [ ] No, because... > >>>>>>>> > >>>>>>>> --Rafael > >>>>>>>> > >>>>>>> > >>>>>>> > >>>>>> > >>>>>> > >>>>>> -- > >>>>>> \ / | | > >>>>>> (OvO) | Mikhail Iwanow | > >>>>>> (^^^) | Voice: +7 (911) 223-1300 | > >>>>>> \^/ | E-mail: iv...@logit-ag.de | > >>>>>> ^ ^ | | > >>>>>> > >>>>> > >>>> > >>>> > >>>> -- > >>>> \ / | | > >>>> (OvO) | Mikhail Iwanow | > >>>> (^^^) | Voice: +7 (911) 223-1300 | > >>>> \^/ | E-mail: iv...@logit-ag.de | > >>>> ^ ^ | | > >>>> > >>> > >> > >> > >> -- > >> \ / | | > >> (OvO) | Mikhail Iwanow | > >> (^^^) | Voice: +7 (911) 223-1300 | > >> \^/ | E-mail: iv...@logit-ag.de | > >> ^ ^ | | > >> > > > > > -- > \ / | | > (OvO) | Mikhail Iwanow | > (^^^) | Voice: +7 (911) 223-1300 | > \^/ | E-mail: iv...@logit-ag.de | > ^ ^ | | >
