Description of problem: The broker trace logs lack almost any wire-level information when AMQP 1.0 protocol version is used. That makes some of the trace logs useless and prevents any in-depth investigation of AMQP 1.0 traffic. Altogether with missing dissector for AMQP 1.0 in Wireshark, it is impossible to debug issues like "session failed to re-attach" or "connection tunables ignored" or even "message consumed twice" (as first "consumer" was a browser, in fact - cant see it from traces/tcpdump). Leaving broker logs in their current shape would fully prevent debugging some customer problems. As C++ client _provides_ similar protocol-specific information, I would suppose this can be relatively easily added to the broker as well. Version-Release number of selected component (if applicable): 0.22-26 How reproducible: 100% Steps to Reproduce: 1. 2. Generate any traffic (like send 1 message and receive it) using AMQP 1.0 protocol 3. Try to decode from traces what the clients did Actual results: useless logs like below are printed out: 2013-11-22 12:44:19 [Broker] trace qpid.127.0.0.1:5672-127.0.0.1:58187 process() 2013-11-22 12:44:19 [Network] trace qpid.127.0.0.1:5672-127.0.0.1:58187 canEncode(): 0 2013-11-22 12:44:19 [Broker] trace qpid.127.0.0.1:5672-127.0.0.1:58187 decode(30) 2013-11-22 12:44:19 [Network] debug qpid.127.0.0.1:5672-127.0.0.1:58187 decoded 30 bytes from 30 2013-11-22 12:44:19 [Broker] trace qpid.127.0.0.1:5672-127.0.0.1:58187 process() 2013-11-22 12:44:19 [Model] debug qpid.127.0.0.1:5672-127.0.0.1:58187 session begun 2013-11-22 12:44:19 [Model] trace Mgmt create session. id:0x7f5c480182a0 Expected results: something similar to AMQP 0-10 traces, or at least what C++ client logs, i.e. something like: [0x23ab500:0] -> @attach [name="myQueue2_bef24369-e2cf-4e22-a4b6-48201568666b", handle=0, role=true, snd-settle-mode=2, rcv-settle-mode=0, source=@source [address="myQueue2", durable=0, timeout=0, dynamic=false, capabilities=:"create-on-demand"], target=@target [address="myQueue2", durable=0, timeout=0, dynamic=false], initial-delivery-count=0] [0x23ab500:0] <- @attach [name="myQueue2_bef24369-e2cf-4e22-a4b6-48201568666b", handle=0, role=false, snd-settle-mode=2, rcv-settle-mode=0, source=@source [address="myQueue2", durable=0, timeout=0, dynamic=false, capabilities=:"create-on-demand"], target=@target [durable=0, timeout=0, dynamic=false], initial-delivery-count=0] [0x23ab500:0] -> @flow [next-incoming-id=0, incoming-window=2147483647, next-outgoing-id=0, outgoing-window=0, handle=0, delivery-count=0, link-credit=1000, drain=false] .. Additional info: (*) This is a BIG regression from AMQP 0-10, where I can see logs like: 2013-11-22 12:25:51 [Protocol] trace RECV [qpid.127.0.0.1:5672-127.0.0.1:57185]: Frame[BEbe; channel=0; {ConnectionStartOkBody: client-properties={qpid.client_pid:F4:int32(3641),qpid.client_ppid:F4:int32(3436),qpid.client_process:V2:12:str16(qpid-receive),qpid.session_flow:F4:int32(1)}; mechanism=ANONYMOUS; response=xxxxxx; locale=en_US; }] or: 2013-11-22 12:25:51 [Protocol] trace SENT [qpid.127.0.0.1:5672-127.0.0.1:57185]: Frame[BEbe; channel=0; {ConnectionTuneBody: channel-max=32767; max-frame-size=65535; heartbeat-min=0; heartbeat-max=120; }] How can I get that info when using AMQP 1.0? (*) gsim stated proton can log required traces to console, but that is not compatible with --log-to-file option. Hence that is just very limited workaround (btw will proton be in MRG 3.0 by default?).
Both broker and client rely on the proton engines logging here. The same mechanism is used in both. The trace pasted above for 1.0 on the client is available on the broker as well. However in both cases the trace is sent only to console and can't be controlled through --log-to-file or similar. Further, the brokerside engine trace is often hard to read as concurrent prints get merged. To fix this either the protocol engine needs to offer better facilities for logging or qpid-cpp would need to decode incoming and outgoing IO streams in order to do its own logging. If this approach was adopted I would recommend abandoning the engine altogether.
A wireshark dissector for 1.0 would in my view be the best tool overall.
A sort of workaround: let proton to log to stdout redirected to logfile: qpidd --log-to-file=/tmp/qpidd.log --log-to-stdout=yes --trace >> /tmp/qpidd.log 2>&1 Anyway it is quite impractical for standard cases when qpidd runs as a service managed by init script, and the workaround requires broker restart.
The required proton changes are http://svn.apache.org/r1547827, http://svn.apache.org/r1548123 and will be part of 0.6. The change for qpidc is http://svn.apache.org/r1548177. This will only improve things if built against latest proton code. However it will work as before against proton 0.5 so this change doesn't force 0.6 (though getting the issue solved would require 0.6).
Tested on the latest available packages on RHEL6 (both i386 and x86_64). Broker's logs contain the AMQP1.0 frames description at 'trace' level now of the form: [Protocol] trace [qpid.127.0.0.1:5672-127.0.0.1:53097]: 0 -> @open(16) [container-id="ce2d93f6-4421-463b-99d9-eecd613be117"] [Protocol] trace [qpid.127.0.0.1:5672-127.0.0.1:53097]: 0 <- @begin(17) [next-outgoing-id=0, incoming-window=2147483647, outgoing-window=0] [Protocol] trace [qpid.127.0.0.1:5672-127.0.0.1:53097]: 0 -> @attach(18) [name="test_a2e31edb-426d-46f6-ae23-11ae5fd2129f", 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="test", durable=0, timeout=0, dynamic=false], initial-delivery-count=0] Packages used for testing: qpid-cpp-0.22-47 qpid-proton-c-0.7-3 -> VERIFIED