Messages getting mixed up

sjlongland commented 9 years ago

Hi,

Just been experimenting with QAMQP, so far it's been a very easy introduction to AMQP on C++. The project I'm using AMQP for is a crude SCADA system for energy management. So we've got energy meters being polled (Modbus or BACnet) with data being collected and reported via AMQP messaging.

For testing purposes, I've done a dummy driver. It uses the rand() function out of stdlib.h to generate dummy readings. Message content uses YAML format.

I have some existing code using Python (and the Pika library) to act as a client, and I'm implementing the server in C++ for speed. One thing I observe is that sometimes QAMQP seems to get messages mixed up, so one message's content gets appended to another unrelated message sent to the same queue. (In this case, both are for an energy meter named "B79_04_RT"; so sent to a fan-out exchange named "entity.rq.B79_04_RT".)

Example:

1427720769 DEBUG AMQPQueueHandler.amq.gen-b20F7zyH9m-osJS8uSLQuA : New message received.
1427720769 DEBUG MessageParser : Content-type is text/x-yaml; charset=utf-8
1427720769 DEBUG MessageParser : Message payload:
_debug_: {created: ! '2015-03-30 13:06:07.446333+00:00', sent: ! '2015-03-30 13:06:08.062488+00:00'}
attributes: {FREQ: ! '2015-03-30 14:06:07.439992+00:00', I_AVG_TOT: ! '2015-03-30
    14:06:07.445290+00:00', I_PH4: ! '2015-03-30 14:06:07.441783+00:00', I_PHA: &id001 ! '2015-03-30
    14:06:07.428174+00:00', I_PHB: ! '2015-03-30 14:06:07.429421+00:00', I_PHC: ! '2015-03-30
    14:06:07.428822+00:00', KVAH_EXP: ! '2015-03-30 14:06:07.434671+00:00', KVAH_IMP: ! '2015-03-30
    14:06:07.431752+00:00', KVARH_CAP_EXP: ! '2015-03-30 14:06:07.444093+00:00', KVARH_CAP_IMP: ! '2015-03-30
    14:06:07.441202+00:00', KVARH_IND_EXP: ! '2015-03-30 14:06:07.432938+00:00', KVARH_IND_IMP: ! '2015-03-30
    14:06:07.437034+00:00', KVAR_PHA: ! '2015-03-30 14:06:07.439386+00:00', KVAR_PHB: ! '2015-03-30
    14:06:07.438808+00:00', KVAR_PHC: ! '2015-03-30 14:06:07.438191+00:00', KVA_TOT: ! '2015-03-30
    14:06:07.442939+00:00', KWH_EXP: ! '2015-03-30 14:06:07.442358+00:00', KWH_IMP: ! '2015-03-30
    14:06:07.435252+00:00', KW_PHA: ! '2015-03-30 14:06:07.443510+00:00', KW_PHB: ! '2015-03-30
    14:06:07.444674+00:00', KW_PHC: ! '2015-03-30 14:06:07.431175+00:00', KW_TOT: ! '2015-03-30
    14:06:07.440578+00:00', MAX_DEMAND: ! '2015-03-30 14:06:07.430599+00:00', PF_PHA: ! '2015-03-30
    14:06:07.432328+00:00', PF_PHB: ! '2015-03-30 14:06:07.434090+00:00', PF_PHC: ! '2015-03-30
    14:06:07.433517+00:00', PF_TOT: ! '2015-03-30 14:06:07.430015+00:00', V_PHA: ! '2015-03-30
    14:06:07.437617+00:00', V_PHB: ! '2015-03-30 14:06:07.435830+00:00', V_PHC: ! '2015-03-30
    14:06:07.436406+00:00'}
deadline: *id001
entity: B79_04_RT
priority: 127
type: demand_add
_debug_: {created: ! '2015-03-30 13:06:09.075516+00:00', sent: ! '2015-03-30 13:06:09.493511+00:00'}
attributes: [FREQ, I_AVG_TOT, I_PH4, I_PHA, I_PHB, I_PHC, KVAH_EXP, KVAH_IMP, KVARH_CAP_EXP,
  KVARH_CAP_IMP, KVARH_IND_EXP, KVARH_IND_IMP, KVAR_PHA, KVAR_PHB, KVAR_PHC, KVA_TOT,
  KWH_EXP, KWH_IMP, KW_PHA, KW_PHB, KW_PHC, KW_TOT, MAX_DEMAND, PF_PHA, PF_PHB, PF_PHC,
  PF_TOT, V_PHA, V_PHB, V_PHC]
deadline: 2015-03-30 13:07:06.700407+00:00
entity: B79_04_RT
priority: 127
type: rt_read

1427720769 DEBUG MessageParser RtReadRequest: Bad incoming message: yaml-cpp: error at line 0, column 0: bad conversion
1427720769 DEBUG MessageParser : Message at 0x8e1d730 has type UNDEFINED???
1427720769 DEBUG AMQPQueueHandler.amq.gen-b20F7zyH9m-osJS8uSLQuA : Bad message received.  Dropped.

The code I'm using looks like this:

void AMQPQueueHandler::messageReceived()
{
    QAmqpMessage raw_msg(this->queue->dequeue());
    log4cpp::Category& log(this->getLog());
    log.debugStream()
        << "New message received.";
    try {
        BaseMessage* msg = BaseMessage::fromMessage(raw_msg);
        if (msg != NULL) {
            emit messageReceived(
                    this->ref(),
                    MessageRef(msg));
        } else {
            log.debugStream()
                << "Bad message received.  Dropped.";
        }
    } catch (std::exception& ex) {
        log.errorStream()
                << "Bad message received: "
                << ex.what();
    }
}

/* ... */

/* 
 * Note, the charset is given here as normally the default is ISO8859-1
 * for text/... types.  We use x-yaml because at time of writing YAML was
 * not an official MIME type.
 */
static const QString CONTENT_TYPE("text/x-yaml; charset=utf-8");
static const QString ALT_CONTENT_TYPE("application/x-yaml");

BaseMessage* BaseMessage::fromMessage(const QAmqpMessage& amqp_msg)
{
    log4cpp::Category& log = log4cpp::Category::getInstance(
            "MessageParser");
    try {
        /* Verify all the required fields are present. */
        if (!amqp_msg.hasProperty(QAmqpMessage::CorrelationId)) {
            log.debugStream()
                << "No correlation ID";
            return NULL;
        }
        if (!amqp_msg.hasProperty(QAmqpMessage::MessageId)) {
            log.debugStream()
                << "No message ID";
            return NULL;
        }
        if (!amqp_msg.hasProperty(QAmqpMessage::ContentType)) {
            log.debugStream()
                << "No content-type";
            return NULL;
        }

        /* Verify that the content type is correct */
        QString content_type(amqp_msg.property(
                    QAmqpMessage::ContentType).toString());
        log.debugStream() << "Content-type is " << content_type;
        if ((content_type != CONTENT_TYPE) &&
                (content_type != ALT_CONTENT_TYPE))
            return NULL;

        /* Decode the message body */
        log.debugStream() << "Message payload:\n---\n"
                << amqp_msg.payload().constData()
                << "\n---";
        YAML::Node body = YAML::Load(amqp_msg.payload().constData());
        if (!body.IsMap())
            return NULL;

        /* What message type do we have? */
        MessageType type = body["type"].as<MessageType>();
        BaseMessage* msg = NULL;
        switch(type) {
            /* Diagnostics */
            case MSG_TYPE_PING:
                msg = new PingRequest(amqp_msg, body);
                break;
            case MSG_TYPE_PING_RES:
                msg = new PingResponse(amqp_msg, body);
                break;
            /* Namespace queries */
            case MSG_TYPE_NS_SEARCH:
                msg = new NamespaceSearchRequest(amqp_msg, body);
                break;
            case MSG_TYPE_NS_SEARCH_RES:
                msg = new NamespaceSearchResponse(amqp_msg, body);
                break;
            /* Configuration */
            case MSG_TYPE_CFG_INFO:
                msg = new CfgInfoRequest(amqp_msg, body);
                break;
            case MSG_TYPE_CFG_COC:
                msg = new CfgChangeOfConfigMessage(amqp_msg, body);
                break;
            case MSG_TYPE_CFG_INFO_RES:
                msg = new CfgInfoResponse(amqp_msg, body);
                break;
            /* Demand management */
            case MSG_TYPE_DEMAND_ADD:
                msg = new DemandAddRequest(amqp_msg, body);
                break;
            case MSG_TYPE_DEMAND_RM:
                msg = new DemandRmRequest(amqp_msg, body);
                break;
            case MSG_TYPE_DEMAND_RES:
                msg = new DemandResponse(amqp_msg, body);
                break;
            /* Real-time */
            case MSG_TYPE_RT_READ:
                msg = new RtReadRequest(amqp_msg, body);
                break;
            case MSG_TYPE_RT_READ_RES:
                msg = new RtReadResponse(amqp_msg, body);
                break;
            case MSG_TYPE_RT_COS:
                msg = new RtChangeOfStateMessage(amqp_msg, body);
                break;
            case MSG_TYPE_RT_WRITE:
                msg = new RtWriteRequest(amqp_msg, body);
                break;
            case MSG_TYPE_RT_WRITE_RES:
                msg = new RtWriteResponse(amqp_msg, body);
                break;
            /* Historical: TODO */
            /* Events: TODO */
            default:
                log.debugStream()
                    << "Unhandled message type: "
                    << body["type"].as<QString>();
                return NULL;
        }
        log.debugStream()
            << "Message at "
            << (void*)msg
            << " has type "
            << msg->type;
        if (msg->type == MSG_TYPE_INVALID) {
            delete(msg);
            msg = NULL;
        }
        return msg;
    } catch (YAML::Exception& ex) {
        /* Conversion fails */
        log.debugStream()
            << "YAML error: "
            << ex.what();
        return NULL;
    }
}

Somehow, a real-time read request got mixed up with a demand-add request. It could be a timing issue, my application is single-threaded however RabbitMQ is running on a dual-core industrial computer. The Python code inter-operates with other Python scripts without issues, so far this problem has been unique to QAMQP.

I'll see if I can trace what's going on a little more closely

mbroadst commented 9 years ago

@sjlongland its entirely possible that this is happening, from my travels through implementations in a few other languages (I've now implemented this in 3 :smile:), I've seen other multiplex incoming messages. On the other hand the spec indicates that incoming frames should be sequential so the way we currently handle incoming bodies should just work (though it seems this is not the case).

The best course of action would be if you could submit a test case appended to the autotests showing this failure. I test against RabbitMQ explicitly, so you shouldn't find too much of a problem there (in fact, if you have RabbitMQ running locally without modification, you can run make check from the command line and easily run the tests yourself. I'm definitely motivated to fix the problem, but as ever am incredibly pressed for time!

Thanks for the report, hope we can get this cleared up

mbroadst commented 9 years ago

@sjlongland in your studies you'll probably want to focus on: https://github.com/mbroadst/qamqp/blob/master/src/qamqpqueue.cpp#L115. This basically assumes that there is one message being processed at a time (perhaps a wildly inappropriate assumption!). It's worked for me thus far in production, but maybe we haven't experienced the load/size of messages you are working with.

sjlongland commented 9 years ago

On 31/03/15 07:14, Matt Broadstone wrote:

@sjlongland https://github.com/sjlongland in your studies you'll probably want to focus on: https://github.com/mbroadst/qamqp/blob/master/src/qamqpqueue.cpp#L115. This basically assumes that there is one message being processed at a time (perhaps a wildly inappropriate assumption!). It's worked for me thus far in production, but maybe we haven't experienced the load/size of messages you are working with.

Indeed, it's not all the time, just intermittently, so I'm not sure what's going on. I can accept a lack of time to deal with this, know that feeling well. :-) (Lately I've had a mountain of work that'd give a Sherpa a nose bleed.)

I'm using RabbitMQ 3.5.0 (from their repository, not Debian's) here on Debian Wheezy i386, so similar platform to what QAMQP appears to be developed on.

The problem is rare it seems, so it looks as if the assumption isn't too far off the mark, just some edge case causes the mix-up. I've added some more logging statements in to the C++ program so I can hopefully match the messages up to the Python-generated logs and see what went awry.

The good news is QAMQP is fairly compact, so there isn't big globs of code to sift through to find the problem. :-)

Regards,

Stuart Longland (aka Redhatter, VK4MSL)

I haven't lost my mind... ...it's backed up on a tape somewhere.

sjlongland commented 9 years ago

Okay, a bit more information on the bug. It seems as if a buffer isn't cleared when the message is delivered, so old message data is left in the buffer when the next message comes along.

1427764939 DEBUG AMQPQueueHandler.amq.gen-O7z1CbHMR4JuouWzqwi_cQ : New message received.
1427764939 DEBUG MessageParser : Correlation ID is 5fde0c54-d744-11e4-b295-74fe48053a4b
1427764939 DEBUG MessageParser : Message ID is 5fde0c54-d744-11e4-b295-74fe48053a4b
1427764939 DEBUG MessageParser : Content-type is text/x-yaml; charset=utf-8
1427764939 DEBUG MessageParser : Message payload:
---
_debug_: {created: ! '2015-03-31 01:22:15.411380+00:00', sent: ! '2015-03-31 01:22:15.435809+00:00'}
deadline: 2015-03-31 01:22:25.387391+00:00
entity: B79_02_RT
priority: 127
type: cfg_info
_debug_: {created: ! '2015-03-31 01:22:19.410175+00:00', sent: ! '2015-03-31 01:22:19.423359+00:00'}
attributes: {FREQ: ! '2015-03-31 02:22:19.403593+00:00', I_AVG_TOT: ! '2015-03-31
    02:22:19.409137+00:00', I_PH4: ! '2015-03-31 02:22:19.405422+00:00', I_PHA: &id001 ! '2015-03-31
    02:22:19.391164+00:00', I_PHB: ! '2015-03-31 02:22:19.392376+00:00', I_PHC: ! '2015-03-31
    02:22:19.391783+00:00', KVAH_EXP: ! '2015-03-31 02:22:19.398004+00:00', KVAH_IMP: ! '2015-03-31
    02:22:19.395060+00:00', KVARH_CAP_EXP: ! '2015-03-31 02:22:19.407920+00:00', KVARH_CAP_IMP: ! '2015-03-31
    02:22:19.404806+00:00', KVARH_IND_EXP: ! '2015-03-31 02:22:19.396229+00:00', KVARH_IND_IMP: ! '2015-03-31
    02:22:19.400388+00:00', KVAR_PHA: ! '2015-03-31 02:22:19.402961+00:00', KVAR_PHB: ! '2015-03-31
    02:22:19.402374+00:00', KVAR_PHC: ! '2015-03-31 02:22:19.401795+00:00', KVA_TOT: ! '2015-03-31
    02:22:19.406656+00:00', KWH_EXP: ! '2015-03-31 02:22:19.406006+00:00', KWH_IMP: ! '2015-03-31
    02:22:19.398640+00:00', KW_PHA: ! '2015-03-31 02:22:19.407291+00:00', KW_PHB: ! '2015-03-31
    02:22:19.408525+00:00', KW_PHC: ! '2015-03-31 02:22:19.394405+00:00', KW_TOT: ! '2015-03-31
    02:22:19.404188+00:00', MAX_DEMAND: ! '2015-03-31 02:22:19.393722+00:00', PF_PHA: ! '2015-03-31
    02:22:19.395647+00:00', PF_PHB: ! '2015-03-31 02:22:19.397428+00:00', PF_PHC: ! '2015-03-31
    02:22:19.396838+00:00', PF_TOT: ! '2015-03-31 02:22:19.393035+00:00', V_PHA: ! '2015-03-31
    02:22:19.401089+00:00', V_PHB: ! '2015-03-31 02:22:19.399221+00:00', V_PHC: ! '2015-03-31
    02:22:19.399796+00:00'}
deadline: *id001
entity: B79_02_RT
priority: 127
type: demand_add
_debug_: {created: ! '2015-03-31 01:22:19.753403+00:00', sent: ! '2015-03-31 01:22:19.914092+00:00'}
attributes: [FREQ, I_AVG_TOT, I_PH4, I_PHA, I_PHB, I_PHC, KVAH_EXP, KVAH_IMP, KVARH_CAP_EXP,
  KVARH_CAP_IMP, KVARH_IND_EXP, KVARH_IND_IMP, KVAR_PHA, KVAR_PHB, KVAR_PHC, KVA_TOT,
  KWH_EXP, KWH_IMP, KW_PHA, KW_PHB, KW_PHC, KW_TOT, MAX_DEMAND, PF_PHA, PF_PHB, PF_PHC,
  PF_TOT, V_PHA, V_PHB, V_PHC]
deadline: 2015-03-31 01:23:19.147827+00:00
entity: B79_02_RT
priority: 127
type: rt_read

---
1427764939 DEBUG MessageParser DemandAddRequest: Bad incoming message: yaml-cpp: error at line 0, column 0: bad conversion
1427764939 DEBUG MessageParser : Message at 0xa9a2dd0 has type UNDEFINED???
1427764939 DEBUG AMQPQueueHandler.amq.gen-O7z1CbHMR4JuouWzqwi_cQ : Bad message received.  Dropped.
1427764939 DEBUG AMQPQueueHandler.amq.gen-O7z1CbHMR4JuouWzqwi_cQ : Queue is now empty.

There, three of them got mixed up. When I look for that UUID in my Python-based client, I see this:

2015-03-31 11:22:19,913 vrt.da.entity.B79_02_RT.TransmitQueue[txqueue.py:  95] DEBUG Transmitting message B79_02_RT.rt_read.5fde0c54-d744-11e4-b295-74fe48053a4b (delay 0:00:00.159819)
2015-03-31 11:22:19,918 vrt.da.message.B79_02_RT.rt_read.5fde0c54-d744-11e4-b295-74fe48053a4b[message.py: 473] DEBUG Outgoing message
        properties=<BasicProperties(['content_type=text/x-yaml; charset=utf-8', 'correlation_id=5fde0c54-d744-11e4-b295-74fe48053a4b', 'expiration=65535', 'message_id=5fde0c54-d744-11e4-b295-74fe48053a4b', 'priority=4', 'reply_to=amq.gen-OmOOCfSjgGnb3uapuTPfxg', 'timestamp=1427764939'])>
_debug_: {created: ! '2015-03-31 01:22:19.753403+00:00', sent: ! '2015-03-31 01:22:19.914092+00:00'}
attributes: [FREQ, I_AVG_TOT, I_PH4, I_PHA, I_PHB, I_PHC, KVAH_EXP, KVAH_IMP, KVARH_CAP_EXP,
  KVARH_CAP_IMP, KVARH_IND_EXP, KVARH_IND_IMP, KVAR_PHA, KVAR_PHB, KVAR_PHC, KVA_TOT,
  KWH_EXP, KWH_IMP, KW_PHA, KW_PHB, KW_PHC, KW_TOT, MAX_DEMAND, PF_PHA, PF_PHB, PF_PHC,
  PF_TOT, V_PHA, V_PHB, V_PHC]
deadline: 2015-03-31 01:23:19.147827+00:00
entity: B79_02_RT
priority: 127
type: rt_read

So it was supposed to be an rt_read message (reading attribute values). So I look back through the log to find the other messages. The demand_add message was the one before:

2015-03-31 11:22:19,434 vrt.da.message.B79_02_RT.demand_add.5fb61d98-d744-11e4-b295-74fe48053a4b[message.py: 473] DEBUG Outgoing message
        properties=<BasicProperties(['content_type=text/x-yaml; charset=utf-8', 'correlation_id=5fb61d98-d744-11e4-b295-74fe48053a4b', 'expiration=3599980', 'message_id=5fb61d98-d744-11e4-b295-74fe48053a4b', 'priority=4', 'reply_to=am
q.gen-OmOOCfSjgGnb3uapuTPfxg', 'timestamp=1427764939'])>
_debug_: {created: ! '2015-03-31 01:22:19.410175+00:00', sent: ! '2015-03-31 01:22:19.423359+00:00'}
attributes: {FREQ: ! '2015-03-31 02:22:19.403593+00:00', I_AVG_TOT: ! '2015-03-31
    02:22:19.409137+00:00', I_PH4: ! '2015-03-31 02:22:19.405422+00:00', I_PHA: &id001 ! '2015-03-31
    02:22:19.391164+00:00', I_PHB: ! '2015-03-31 02:22:19.392376+00:00', I_PHC: ! '2015-03-31
    02:22:19.391783+00:00', KVAH_EXP: ! '2015-03-31 02:22:19.398004+00:00', KVAH_IMP: ! '2015-03-31
    02:22:19.395060+00:00', KVARH_CAP_EXP: ! '2015-03-31 02:22:19.407920+00:00', KVARH_CAP_IMP: ! '2015-03-31
    02:22:19.404806+00:00', KVARH_IND_EXP: ! '2015-03-31 02:22:19.396229+00:00', KVARH_IND_IMP: ! '2015-03-31
    02:22:19.400388+00:00', KVAR_PHA: ! '2015-03-31 02:22:19.402961+00:00', KVAR_PHB: ! '2015-03-31
    02:22:19.402374+00:00', KVAR_PHC: ! '2015-03-31 02:22:19.401795+00:00', KVA_TOT: ! '2015-03-31
    02:22:19.406656+00:00', KWH_EXP: ! '2015-03-31 02:22:19.406006+00:00', KWH_IMP: ! '2015-03-31
    02:22:19.398640+00:00', KW_PHA: ! '2015-03-31 02:22:19.407291+00:00', KW_PHB: ! '2015-03-31
    02:22:19.408525+00:00', KW_PHC: ! '2015-03-31 02:22:19.394405+00:00', KW_TOT: ! '2015-03-31
    02:22:19.404188+00:00', MAX_DEMAND: ! '2015-03-31 02:22:19.393722+00:00', PF_PHA: ! '2015-03-31
    02:22:19.395647+00:00', PF_PHB: ! '2015-03-31 02:22:19.397428+00:00', PF_PHC: ! '2015-03-31
    02:22:19.396838+00:00', PF_TOT: ! '2015-03-31 02:22:19.393035+00:00', V_PHA: ! '2015-03-31
    02:22:19.401089+00:00', V_PHB: ! '2015-03-31 02:22:19.399221+00:00', V_PHC: ! '2015-03-31
    02:22:19.399796+00:00'}
deadline: *id001
entity: B79_02_RT
priority: 127
type: demand_add

So if I now look at the C++ program log for that message, I get this:

1427764939 DEBUG AMQPQueueHandler.amq.gen-O7z1CbHMR4JuouWzqwi_cQ : New message received.
1427764939 DEBUG MessageParser : Correlation ID is 5fb61d98-d744-11e4-b295-74fe48053a4b
1427764939 DEBUG MessageParser : Message ID is 5fb61d98-d744-11e4-b295-74fe48053a4b
1427764939 DEBUG MessageParser : Content-type is text/x-yaml; charset=utf-8
1427764939 DEBUG MessageParser : Message payload:
---
_debug_: {created: ! '2015-03-31 01:22:15.411380+00:00', sent: ! '2015-03-31 01:22:15.435809+00:00'}
deadline: 2015-03-31 01:22:25.387391+00:00
entity: B79_02_RT
priority: 127
type: cfg_info
_debug_: {created: ! '2015-03-31 01:22:19.410175+00:00', sent: ! '2015-03-31 01:22:19.423359+00:00'}
attributes: {FREQ: ! '2015-03-31 02:22:19.403593+00:00', I_AVG_TOT: ! '2015-03-31
    02:22:19.409137+00:00', I_PH4: ! '2015-03-31 02:22:19.405422+00:00', I_PHA: &id001 ! '2015-03-31
    02:22:19.391164+00:00', I_PHB: ! '2015-03-31 02:22:19.392376+00:00', I_PHC: ! '2015-03-31
    02:22:19.391783+00:00', KVAH_EXP: ! '2015-03-31 02:22:19.398004+00:00', KVAH_IMP: ! '2015-03-31
    02:22:19.395060+00:00', KVARH_CAP_EXP: ! '2015-03-31 02:22:19.407920+00:00', KVARH_CAP_IMP: ! '2015-03-31
    02:22:19.404806+00:00', KVARH_IND_EXP: ! '2015-03-31 02:22:19.396229+00:00', KVARH_IND_IMP: ! '2015-03-31
    02:22:19.400388+00:00', KVAR_PHA: ! '2015-03-31 02:22:19.402961+00:00', KVAR_PHB: ! '2015-03-31
    02:22:19.402374+00:00', KVAR_PHC: ! '2015-03-31 02:22:19.401795+00:00', KVA_TOT: ! '2015-03-31
    02:22:19.406656+00:00', KWH_EXP: ! '2015-03-31 02:22:19.406006+00:00', KWH_IMP: ! '2015-03-31
    02:22:19.398640+00:00', KW_PHA: ! '2015-03-31 02:22:19.407291+00:00', KW_PHB: ! '2015-03-31
    02:22:19.408525+00:00', KW_PHC: ! '2015-03-31 02:22:19.394405+00:00', KW_TOT: ! '2015-03-31
    02:22:19.404188+00:00', MAX_DEMAND: ! '2015-03-31 02:22:19.393722+00:00', PF_PHA: ! '2015-03-31
    02:22:19.395647+00:00', PF_PHB: ! '2015-03-31 02:22:19.397428+00:00', PF_PHC: ! '2015-03-31
    02:22:19.396838+00:00', PF_TOT: ! '2015-03-31 02:22:19.393035+00:00', V_PHA: ! '2015-03-31
    02:22:19.401089+00:00', V_PHB: ! '2015-03-31 02:22:19.399221+00:00', V_PHC: ! '2015-03-31
    02:22:19.399796+00:00'}
deadline: *id001
entity: B79_02_RT
priority: 127
type: demand_add

---
1427764939 DEBUG MessageParser : Message at 0xa8ff5a8 has type demand_add
1427764939 DEBUG B79_02_RT.AMQP messageReceived demand_add {5fb61d98-d744-11e4-b295-74fe48053a4b}: Received message ID {5fb61d98-d744-11e4-b295-74fe48053a4b}
1427764939 DEBUG AMQPExchangeHandler.(default) messageReceived demand_add {5fb61d98-d744-11e4-b295-74fe48053a4b} sendMessage {5fb61d98-d744-11e4-b295-74fe48053a4b}: Attempting delivery.
1427764939 DEBUG AMQPExchangeHandler.(default) messageReceived demand_add {5fb61d98-d744-11e4-b295-74fe48053a4b} sendMessage {5fb61d98-d744-11e4-b295-74fe48053a4b}: To Exchange:  routing key: amq.gen-OmOOCfSjgGnb3uapuTPfxg correlation ID: {5fb61d98-d744-11e4-b295-74fe48053a4b} message ID: {f771cb7b-9466-4aa6-95c7-766d9b078d0f} body:

By a shear fluke, the YAML parser ignored the bits of the cfg_info message that was there from before. So the bug is not so much in the accumulation of the message, but in the clearing out of the old message data when the message is delivered.

I wonder if the if (currentMessage.d->leftSize == 0) condition block isn't being triggered (maybe an off-by-one error somewhere?) and thus it is "missing" seeing that the message has been received?

fuCtor commented 9 years ago

As example you can try make tcpdump by Wireshark for this case. Compare received packet with processed by QAMQP, and log leftSize for current message.

sjlongland commented 9 years ago

Okay, for whatever reason a "basic.deliver" got missed. Or at least from my tinkering it appears that way.

I've made some changes to the library so that I can trace what's going on. These are in a separate branch:

https://github.com/mbroadst/qamqp/compare/master...sjlongland:investigate-issue-23

I've also added a shim layer that exposes QDebug messages to log4cpp in my code base, so that QAMQP's debug statements appear along side my own log messages with the prefix QDebug.

1427775632 DEBUG QDebug : New message object.  Payload:  "" 
1427775632 DEBUG QDebug : currentMessage.d->leftSize:  191 
1427775632 DEBUG QDebug : currentMessage.d->leftSize:  191 ; frame.body().size()  191 ; frame body:  "_debug_: {created: ! '2015-03-31 04:20:32.894041+00:00', sent: ! '2015-03-31 04:20:32.923262+00:00'}
deadline: 2015-03-31 04:20:42.870653+00:00
entity: B79_01_RT
priority: 127
type: cfg_info
" 
1427775632 DEBUG QDebug : Emitting message, payload: "_debug_: {created: ! '2015-03-31 04:20:32.894041+00:00', sent: ! '2015-03-31 04:20:32.923262+00:00'}
deadline: 2015-03-31 04:20:42.870653+00:00
entity: B79_01_RT
priority: 127
type: cfg_info
" 
1427775632 DEBUG AMQPQueueHandler.amq.gen-fZY7X31Y9_DlGcBJe4rpEA : New message received.
1427775632 DEBUG MessageParser : Correlation ID is 45acae4e-d75d-11e4-a3be-74fe48053a4b
1427775632 DEBUG MessageParser : Message ID is 45acae4e-d75d-11e4-a3be-74fe48053a4b
1427775632 DEBUG MessageParser : Content-type is text/x-yaml; charset=utf-8
1427775632 DEBUG MessageParser : Message payload:
---
_debug_: {created: ! '2015-03-31 04:20:32.894041+00:00', sent: ! '2015-03-31 04:20:32.923262+00:00'}
deadline: 2015-03-31 04:20:42.870653+00:00
entity: B79_01_RT
priority: 127
type: cfg_info

---
1427775632 DEBUG MessageParser : Message at 0xa14d4d8 has type cfg_info
1427775632 DEBUG B79_01_RT.AMQP messageReceived cfg_info {45acae4e-d75d-11e4-a3be-74fe48053a4b}: Received message ID {45acae4e-d75d-11e4-a3be-74fe48053a4b}
[…]
1427775633 DEBUG AMQPQueueHandler.amq.gen-fZY7X31Y9_DlGcBJe4rpEA : Queue is now empty.

Note that at this point, QAMQP has dispatched the message, and my code has dealt with it, sent its reply. Another message comes in from the same queue. Note this time, we don't get the "New message object" message seen earlier.

1427775636 DEBUG QDebug : currentMessage.d->leftSize:  1666 
1427775636 DEBUG QDebug : currentMessage.d->leftSize:  1666 ; frame.body().size()  1666 ; frame body:  "_debug_: {created: ! '2015-03-31 04:20:36.843263+00:00', sent: ! '2015-03-31 04:20:36.865248+00:00'}
attributes: {FREQ: ! '2015-03-31 05:20:36.835484+00:00', I_AVG_TOT: ! '2015-03-31
    05:20:36.842103+00:00', I_PH4: ! '2015-03-31 05:20:36.837318+00:00', I_PHA: &id001 ! '2015-03-31
    05:20:36.818882+00:00', I_PHB: ! '2015-03-31 05:20:36.820125+00:00', I_PHC: ! '2015-03-31
    05:20:36.819510+00:00', KVAH_EXP: ! '2015-03-31 05:20:36.828457+00:00', KVAH_IMP: ! '2015-03-31
    05:20:36.825393+00:00', KVARH_CAP_EXP: ! '2015-03-31 05:20:36.839695+00:00', KVARH_CAP_IMP: ! '2015-03-31
    05:20:36.836655+00:00', KVARH_IND_EXP: ! '2015-03-31 05:20:36.826692+00:00', KVARH_IND_IMP: ! '2015-03-31
    05:20:36.832171+00:00', KVAR_PHA: ! '2015-03-31 05:20:36.834907+00:00', KVAR_PHB: ! '2015-03-31
    05:20:36.834315+00:00', KVAR_PHC: ! '2015-03-31 05:20:36.833451+00:00', KVA_TOT: ! '2015-03-31
    05:20:36.838484+00:00', KWH_EXP: ! '2015-03-31 05:20:36.837906+00:00', KWH_IMP: ! '2015-03-31
    05:20:36.829072+00:00', KW_PHA: ! '2015-03-31 05:20:36.839077+00:00', KW_PHB: ! '2015-03-31
    05:20:36.840285+00:00', KW_PHC: ! '2015-03-31 05:20:36.823667+00:00', KW_TOT: ! '2015-03-31
    05:20:36.836063+00:00', MAX_DEMAND: ! '2015-03-31 05:20:36.821414+00:00', PF_PHA: ! '2015-03-31
    05:20:36.826069+00:00', PF_PHB: ! '2015-03-31 05:20:36.827872+00:00', PF_PHC: ! '2015-03-31
    05:20:36.827287+00:00', PF_TOT: ! '2015-03-31 05:20:36.820721+00:00', V_PHA: ! '2015-03-31
    05:20:36.832849+00:00', V_PHB: ! '2015-03-31 05:20:36.830897+00:00', V_PHC: ! '2015-03-31
    05:20:36.831569+00:00'}
deadline: *id001
entity: B79_01_RT
priority: 127
type: demand_add
" 
1427775636 DEBUG QDebug : Emitting message, payload: "_debug_: {created: ! '2015-03-31 04:20:32.894041+00:00', sent: ! '2015-03-31 04:20:32.923262+00:00'}
deadline: 2015-03-31 04:20:42.870653+00:00
entity: B79_01_RT
priority: 127
type: cfg_info
_debug_: {created: ! '2015-03-31 04:20:36.843263+00:00', sent: ! '2015-03-31 04:20:36.865248+00:00'}
attributes: {FREQ: ! '2015-03-31 05:20:36.835484+00:00', I_AVG_TOT: ! '2015-03-31
    05:20:36.842103+00:00', I_PH4: ! '2015-03-31 05:20:36.837318+00:00', I_PHA: &id001 ! '2015-03-31
    05:20:36.818882+00:00', I_PHB: ! '2015-03-31 05:20:36.820125+00:00', I_PHC: ! '2015-03-31
    05:20:36.819510+00:00', KVAH_EXP: ! '2015-03-31 05:20:36.828457+00:00', KVAH_IMP: ! '2015-03-31
    05:20:36.825393+00:00', KVARH_CAP_EXP: ! '2015-03-31 05:20:36.839695+00:00', KVARH_CAP_IMP: ! '2015-03-31
    05:20:36.836655+00:00', KVARH_IND_EXP: ! '2015-03-31 05:20:36.826692+00:00', KVARH_IND_IMP: ! '2015-03-31
    05:20:36.832171+00:00', KVAR_PHA: ! '2015-03-31 05:20:36.834907+00:00', KVAR_PHB: ! '2015-03-31
    05:20:36.834315+00:00', KVAR_PHC: ! '2015-03-31 05:20:36.833451+00:00', KVA_TOT: ! '2015-03-31
    05:20:36.838484+00:00', KWH_EXP: ! '2015-03-31 05:20:36.837906+00:00', KWH_IMP: ! '2015-03-31
    05:20:36.829072+00:00', KW_PHA: ! '2015-03-31 05:20:36.839077+00:00', KW_PHB: ! '2015-03-31
    05:20:36.840285+00:00', KW_PHC: ! '2015-03-31 05:20:36.823667+00:00', KW_TOT: ! '2015-03-31
    05:20:36.836063+00:00', MAX_DEMAND: ! '2015-03-31 05:20:36.821414+00:00', PF_PHA: ! '2015-03-31
    05:20:36.826069+00:00', PF_PHB: ! '2015-03-31 05:20:36.827872+00:00', PF_PHC: ! '2015-03-31
    05:20:36.827287+00:00', PF_TOT: ! '2015-03-31 05:20:36.820721+00:00', V_PHA: ! '2015-03-31
    05:20:36.832849+00:00', V_PHB: ! '2015-03-31 05:20:36.830897+00:00', V_PHC: ! '2015-03-31
    05:20:36.831569+00:00'}
deadline: *id001
entity: B79_01_RT
priority: 127
type: demand_add
" 
1427775636 DEBUG AMQPQueueHandler.amq.gen-fZY7X31Y9_DlGcBJe4rpEA : New message received.
1427775636 DEBUG MessageParser : Correlation ID is 47e43f42-d75d-11e4-a3be-74fe48053a4b
1427775636 DEBUG MessageParser : Message ID is 47e43f42-d75d-11e4-a3be-74fe48053a4b
1427775636 DEBUG MessageParser : Content-type is text/x-yaml; charset=utf-8
1427775636 DEBUG MessageParser : Message payload:
---
_debug_: {created: ! '2015-03-31 04:20:32.894041+00:00', sent: ! '2015-03-31 04:20:32.923262+00:00'}
deadline: 2015-03-31 04:20:42.870653+00:00
entity: B79_01_RT
priority: 127
type: cfg_info
_debug_: {created: ! '2015-03-31 04:20:36.843263+00:00', sent: ! '2015-03-31 04:20:36.865248+00:00'}
attributes: {FREQ: ! '2015-03-31 05:20:36.835484+00:00', I_AVG_TOT: ! '2015-03-31
    05:20:36.842103+00:00', I_PH4: ! '2015-03-31 05:20:36.837318+00:00', I_PHA: &id001 ! '2015-03-31
    05:20:36.818882+00:00', I_PHB: ! '2015-03-31 05:20:36.820125+00:00', I_PHC: ! '2015-03-31
    05:20:36.819510+00:00', KVAH_EXP: ! '2015-03-31 05:20:36.828457+00:00', KVAH_IMP: ! '2015-03-31
    05:20:36.825393+00:00', KVARH_CAP_EXP: ! '2015-03-31 05:20:36.839695+00:00', KVARH_CAP_IMP: ! '2015-03-31
    05:20:36.836655+00:00', KVARH_IND_EXP: ! '2015-03-31 05:20:36.826692+00:00', KVARH_IND_IMP: ! '2015-03-31
    05:20:36.832171+00:00', KVAR_PHA: ! '2015-03-31 05:20:36.834907+00:00', KVAR_PHB: ! '2015-03-31
    05:20:36.834315+00:00', KVAR_PHC: ! '2015-03-31 05:20:36.833451+00:00', KVA_TOT: ! '2015-03-31
    05:20:36.838484+00:00', KWH_EXP: ! '2015-03-31 05:20:36.837906+00:00', KWH_IMP: ! '2015-03-31
    05:20:36.829072+00:00', KW_PHA: ! '2015-03-31 05:20:36.839077+00:00', KW_PHB: ! '2015-03-31
    05:20:36.840285+00:00', KW_PHC: ! '2015-03-31 05:20:36.823667+00:00', KW_TOT: ! '2015-03-31
    05:20:36.836063+00:00', MAX_DEMAND: ! '2015-03-31 05:20:36.821414+00:00', PF_PHA: ! '2015-03-31
    05:20:36.826069+00:00', PF_PHB: ! '2015-03-31 05:20:36.827872+00:00', PF_PHC: ! '2015-03-31
    05:20:36.827287+00:00', PF_TOT: ! '2015-03-31 05:20:36.820721+00:00', V_PHA: ! '2015-03-31
    05:20:36.832849+00:00', V_PHB: ! '2015-03-31 05:20:36.830897+00:00', V_PHC: ! '2015-03-31
    05:20:36.831569+00:00'}
deadline: *id001
entity: B79_01_RT
priority: 127
type: demand_add

---
1427775636 DEBUG MessageParser : Message at 0xa152628 has type demand_add
1427775636 DEBUG B79_01_RT.AMQP messageReceived demand_add {47e43f42-d75d-11e4-a3be-74fe48053a4b}: Received message ID {47e43f42-d75d-11e4-a3be-74fe48053a4b}
1427775636 DEBUG AMQPExchangeHandler.(default) messageReceived demand_add {47e43f42-d75d-11e4-a3be-74fe48053a4b} sendMessage {47e43f42-d75d-11e4-a3be-74fe48053a4b}: Attempting delivery.

Now there are two places in QAmqpQueue where a message is replaced like that:

You'll notice I've added logging statements around there.

I managed to get a trace out of tcpdump:

No.     Time        Source                Destination           Protocol Length Info
   3352 444.779022  ::1                   ::1                   AMQP     2015   Basic.DeliverContent-Header Content-Body 

Frame 3352: 2015 bytes on wire (16120 bits), 2015 bytes captured (16120 bits)
    Encapsulation type: Ethernet (1)
    Arrival Time: Mar 31, 2015 14:20:36.888387000 EST
    [Time shift for this packet: 0.000000000 seconds]
    Epoch Time: 1427775636.888387000 seconds
    [Time delta from previous captured frame: 0.001230000 seconds]
    [Time delta from previous displayed frame: 0.000000000 seconds]
    [Time since reference or first frame: 444.779022000 seconds]
    Frame Number: 3352
    Frame Length: 2015 bytes (16120 bits)
    Capture Length: 2015 bytes (16120 bits)
    [Frame is marked: True]
    [Frame is ignored: False]
    [Protocols in frame: eth:ethertype:ipv6:ipv6.nxt:tcp:amqp]
    [Coloring Rule Name: TCP]
    [Coloring Rule String: tcp]
Ethernet II, Src: 00:00:00_00:00:00 (00:00:00:00:00:00), Dst: 00:00:00_00:00:00 (00:00:00:00:00:00)
    Destination: 00:00:00_00:00:00 (00:00:00:00:00:00)
        Address: 00:00:00_00:00:00 (00:00:00:00:00:00)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Source: 00:00:00_00:00:00 (00:00:00:00:00:00)
        Address: 00:00:00_00:00:00 (00:00:00:00:00:00)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Type: IPv6 (0x86dd)
Internet Protocol Version 6, Src: ::1 (::1), Dst: ::1 (::1)
    0110 .... = Version: 6
        [0110 .... = This field makes the filter "ip.version == 6" possible: 6]
    .... 0000 0000 .... .... .... .... .... = Traffic class: 0x00000000
        .... 0000 00.. .... .... .... .... .... = Differentiated Services Field: Default (0x00000000)
        .... .... ..0. .... .... .... .... .... = ECN-Capable Transport (ECT): Not set
        .... .... ...0 .... .... .... .... .... = ECN-CE: Not set
    .... .... .... 0000 0000 0000 0000 0000 = Flowlabel: 0x00000000
    Payload length: 1961
    Next header: TCP (6)
    Hop limit: 64
    Source: ::1 (::1)
    Destination: ::1 (::1)
Transmission Control Protocol, Src Port: 5672 (5672), Dst Port: 37030 (37030), Seq: 43445, Ack: 65468, Len: 1929
    Source Port: 5672 (5672)
    Destination Port: 37030 (37030)
    [Stream index: 3]
    [TCP Segment Len: 1929]
    Sequence number: 43445    (relative sequence number)
    [Next sequence number: 45374    (relative sequence number)]
    Acknowledgment number: 65468    (relative ack number)
    Header Length: 32 bytes
    .... 0000 0001 1000 = Flags: 0x018 (PSH, ACK)
        000. .... .... = Reserved: Not set
        ...0 .... .... = Nonce: Not set
        .... 0... .... = Congestion Window Reduced (CWR): Not set
        .... .0.. .... = ECN-Echo: Not set
        .... ..0. .... = Urgent: Not set
        .... ...1 .... = Acknowledgment: Set
        .... .... 1... = Push: Set
        .... .... .0.. = Reset: Not set
        .... .... ..0. = Syn: Not set
        .... .... ...0 = Fin: Not set
    Window size value: 2046
    [Calculated window size: 32736]
    [Window size scaling factor: 16]
    Checksum: 0x07b1 [validation disabled]
        [Good Checksum: False]
        [Bad Checksum: False]
    Urgent pointer: 0
    Options: (12 bytes), No-Operation (NOP), No-Operation (NOP), Timestamps
        No-Operation (NOP)
            Type: 1
                0... .... = Copy on fragmentation: No
                .00. .... = Class: Control (0)
                ...0 0001 = Number: No-Operation (NOP) (1)
        No-Operation (NOP)
            Type: 1
                0... .... = Copy on fragmentation: No
                .00. .... = Class: Control (0)
                ...0 0001 = Number: No-Operation (NOP) (1)
        Timestamps: TSval 92539083, TSecr 92538144
            Kind: Time Stamp Option (8)
            Length: 10
            Timestamp value: 92539083
            Timestamp echo reply: 92538144
    [SEQ/ACK analysis]
        [iRTT: 0.000077000 seconds]
        [Bytes in flight: 1929]
Advanced Message Queueing Protocol
    Type: Method (1)
    Channel: 306
    Length: 76
    Class: Basic (60)
    Method: Deliver (60)
    Arguments
        Consumer-Tag: amq.ctag-G9wPPU5roWl4oSbDbeUqyg
        Delivery-Tag: 3
        .... ...0 = Redelivered: False
        Exchange: entity.rq.B79_01_RT
        Routing-Key: demand_add
Advanced Message Queueing Protocol
    Type: Content header (2)
    Channel: 306
    Length: 163
    Class ID: Basic (60)
    Weight: 0
    Body size: 1666
    Property flags: 0x8fc0
    Properties
        Content-Type: text/x-yaml; charset=utf-8
        Priority: 4
        Correlation-Id: 47e43f42-d75d-11e4-a3be-74fe48053a4b
        Reply-To: amq.gen-N-wLi2XfTKANdxLh1MIIfA
        Expiration: 3599975
        Message-Id: 47e43f42-d75d-11e4-a3be-74fe48053a4b
        Timestamp: 1427775636
Advanced Message Queueing Protocol
    Type: Content body (3)
    Channel: 306
    Length: 1666
    Payload: 5f64656275675f3a207b637265617465643a202120273230...

0000  00 00 00 00 00 00 00 00 00 00 00 00 86 dd 60 00   ..............`.
0010  00 00 07 a9 06 40 00 00 00 00 00 00 00 00 00 00   .....@..........
0020  00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00   ................
0030  00 00 00 00 00 01 16 28 90 a6 6c 85 9a 61 69 f6   .......(..l..ai.
0040  b2 e0 80 18 07 fe 07 b1 00 00 01 01 08 0a 05 84   ................
0050  08 cb 05 84 05 20 01 01 32 00 00 00 4c 00 3c 00   ..... ..2...L.<.
0060  3c 1f 61 6d 71 2e 63 74 61 67 2d 47 39 77 50 50   <.amq.ctag-G9wPP
0070  55 35 72 6f 57 6c 34 6f 53 62 44 62 65 55 71 79   U5roWl4oSbDbeUqy
0080  67 00 00 00 00 00 00 00 03 00 13 65 6e 74 69 74   g..........entit
0090  79 2e 72 71 2e 42 37 39 5f 30 31 5f 52 54 0a 64   y.rq.B79_01_RT.d
00a0  65 6d 61 6e 64 5f 61 64 64 ce 02 01 32 00 00 00   emand_add...2...
00b0  a3 00 3c 00 00 00 00 00 00 00 00 06 82 8f c0 1a   ..<.............
00c0  74 65 78 74 2f 78 2d 79 61 6d 6c 3b 20 63 68 61   text/x-yaml; cha
00d0  72 73 65 74 3d 75 74 66 2d 38 04 24 34 37 65 34   rset=utf-8.$47e4
00e0  33 66 34 32 2d 64 37 35 64 2d 31 31 65 34 2d 61   3f42-d75d-11e4-a
00f0  33 62 65 2d 37 34 66 65 34 38 30 35 33 61 34 62   3be-74fe48053a4b
0100  1e 61 6d 71 2e 67 65 6e 2d 4e 2d 77 4c 69 32 58   .amq.gen-N-wLi2X
0110  66 54 4b 41 4e 64 78 4c 68 31 4d 49 49 66 41 07   fTKANdxLh1MIIfA.
0120  33 35 39 39 39 37 35 24 34 37 65 34 33 66 34 32   3599975$47e43f42
0130  2d 64 37 35 64 2d 31 31 65 34 2d 61 33 62 65 2d   -d75d-11e4-a3be-
0140  37 34 66 65 34 38 30 35 33 61 34 62 00 00 00 00   74fe48053a4b....
0150  55 1a 20 94 ce 03 01 32 00 00 06 82 5f 64 65 62   U. ....2...._deb
0160  75 67 5f 3a 20 7b 63 72 65 61 74 65 64 3a 20 21   ug_: {created: !
0170  20 27 32 30 31 35 2d 30 33 2d 33 31 20 30 34 3a    '2015-03-31 04:
0180  32 30 3a 33 36 2e 38 34 33 32 36 33 2b 30 30 3a   20:36.843263+00:
0190  30 30 27 2c 20 73 65 6e 74 3a 20 21 20 27 32 30   00', sent: ! '20
01a0  31 35 2d 30 33 2d 33 31 20 30 34 3a 32 30 3a 33   15-03-31 04:20:3
01b0  36 2e 38 36 35 32 34 38 2b 30 30 3a 30 30 27 7d   6.865248+00:00'}
01c0  0a 61 74 74 72 69 62 75 74 65 73 3a 20 7b 46 52   .attributes: {FR
01d0  45 51 3a 20 21 20 27 32 30 31 35 2d 30 33 2d 33   EQ: ! '2015-03-3
01e0  31 20 30 35 3a 32 30 3a 33 36 2e 38 33 35 34 38   1 05:20:36.83548
01f0  34 2b 30 30 3a 30 30 27 2c 20 49 5f 41 56 47 5f   4+00:00', I_AVG_
0200  54 4f 54 3a 20 21 20 27 32 30 31 35 2d 30 33 2d   TOT: ! '2015-03-
0210  33 31 0a 20 20 20 20 30 35 3a 32 30 3a 33 36 2e   31.    05:20:36.
0220  38 34 32 31 30 33 2b 30 30 3a 30 30 27 2c 20 49   842103+00:00', I
0230  5f 50 48 34 3a 20 21 20 27 32 30 31 35 2d 30 33   _PH4: ! '2015-03
0240  2d 33 31 20 30 35 3a 32 30 3a 33 36 2e 38 33 37   -31 05:20:36.837
0250  33 31 38 2b 30 30 3a 30 30 27 2c 20 49 5f 50 48   318+00:00', I_PH
0260  41 3a 20 26 69 64 30 30 31 20 21 20 27 32 30 31   A: &id001 ! '201
0270  35 2d 30 33 2d 33 31 0a 20 20 20 20 30 35 3a 32   5-03-31.    05:2
0280  30 3a 33 36 2e 38 31 38 38 38 32 2b 30 30 3a 30   0:36.818882+00:0
0290  30 27 2c 20 49 5f 50 48 42 3a 20 21 20 27 32 30   0', I_PHB: ! '20
02a0  31 35 2d 30 33 2d 33 31 20 30 35 3a 32 30 3a 33   15-03-31 05:20:3
02b0  36 2e 38 32 30 31 32 35 2b 30 30 3a 30 30 27 2c   6.820125+00:00',
02c0  20 49 5f 50 48 43 3a 20 21 20 27 32 30 31 35 2d    I_PHC: ! '2015-
02d0  30 33 2d 33 31 0a 20 20 20 20 30 35 3a 32 30 3a   03-31.    05:20:
02e0  33 36 2e 38 31 39 35 31 30 2b 30 30 3a 30 30 27   36.819510+00:00'
02f0  2c 20 4b 56 41 48 5f 45 58 50 3a 20 21 20 27 32   , KVAH_EXP: ! '2
0300  30 31 35 2d 30 33 2d 33 31 20 30 35 3a 32 30 3a   015-03-31 05:20:
0310  33 36 2e 38 32 38 34 35 37 2b 30 30 3a 30 30 27   36.828457+00:00'
0320  2c 20 4b 56 41 48 5f 49 4d 50 3a 20 21 20 27 32   , KVAH_IMP: ! '2
0330  30 31 35 2d 30 33 2d 33 31 0a 20 20 20 20 30 35   015-03-31.    05
0340  3a 32 30 3a 33 36 2e 38 32 35 33 39 33 2b 30 30   :20:36.825393+00
0350  3a 30 30 27 2c 20 4b 56 41 52 48 5f 43 41 50 5f   :00', KVARH_CAP_
0360  45 58 50 3a 20 21 20 27 32 30 31 35 2d 30 33 2d   EXP: ! '2015-03-
0370  33 31 20 30 35 3a 32 30 3a 33 36 2e 38 33 39 36   31 05:20:36.8396
0380  39 35 2b 30 30 3a 30 30 27 2c 20 4b 56 41 52 48   95+00:00', KVARH
0390  5f 43 41 50 5f 49 4d 50 3a 20 21 20 27 32 30 31   _CAP_IMP: ! '201
03a0  35 2d 30 33 2d 33 31 0a 20 20 20 20 30 35 3a 32   5-03-31.    05:2
03b0  30 3a 33 36 2e 38 33 36 36 35 35 2b 30 30 3a 30   0:36.836655+00:0
03c0  30 27 2c 20 4b 56 41 52 48 5f 49 4e 44 5f 45 58   0', KVARH_IND_EX
03d0  50 3a 20 21 20 27 32 30 31 35 2d 30 33 2d 33 31   P: ! '2015-03-31
03e0  20 30 35 3a 32 30 3a 33 36 2e 38 32 36 36 39 32    05:20:36.826692
03f0  2b 30 30 3a 30 30 27 2c 20 4b 56 41 52 48 5f 49   +00:00', KVARH_I
0400  4e 44 5f 49 4d 50 3a 20 21 20 27 32 30 31 35 2d   ND_IMP: ! '2015-
0410  30 33 2d 33 31 0a 20 20 20 20 30 35 3a 32 30 3a   03-31.    05:20:
0420  33 36 2e 38 33 32 31 37 31 2b 30 30 3a 30 30 27   36.832171+00:00'
0430  2c 20 4b 56 41 52 5f 50 48 41 3a 20 21 20 27 32   , KVAR_PHA: ! '2
0440  30 31 35 2d 30 33 2d 33 31 20 30 35 3a 32 30 3a   015-03-31 05:20:
0450  33 36 2e 38 33 34 39 30 37 2b 30 30 3a 30 30 27   36.834907+00:00'
0460  2c 20 4b 56 41 52 5f 50 48 42 3a 20 21 20 27 32   , KVAR_PHB: ! '2
0470  30 31 35 2d 30 33 2d 33 31 0a 20 20 20 20 30 35   015-03-31.    05
0480  3a 32 30 3a 33 36 2e 38 33 34 33 31 35 2b 30 30   :20:36.834315+00
0490  3a 30 30 27 2c 20 4b 56 41 52 5f 50 48 43 3a 20   :00', KVAR_PHC: 
04a0  21 20 27 32 30 31 35 2d 30 33 2d 33 31 20 30 35   ! '2015-03-31 05
04b0  3a 32 30 3a 33 36 2e 38 33 33 34 35 31 2b 30 30   :20:36.833451+00
04c0  3a 30 30 27 2c 20 4b 56 41 5f 54 4f 54 3a 20 21   :00', KVA_TOT: !
04d0  20 27 32 30 31 35 2d 30 33 2d 33 31 0a 20 20 20    '2015-03-31.   
04e0  20 30 35 3a 32 30 3a 33 36 2e 38 33 38 34 38 34    05:20:36.838484
04f0  2b 30 30 3a 30 30 27 2c 20 4b 57 48 5f 45 58 50   +00:00', KWH_EXP
0500  3a 20 21 20 27 32 30 31 35 2d 30 33 2d 33 31 20   : ! '2015-03-31 
0510  30 35 3a 32 30 3a 33 36 2e 38 33 37 39 30 36 2b   05:20:36.837906+
0520  30 30 3a 30 30 27 2c 20 4b 57 48 5f 49 4d 50 3a   00:00', KWH_IMP:
0530  20 21 20 27 32 30 31 35 2d 30 33 2d 33 31 0a 20    ! '2015-03-31. 
0540  20 20 20 30 35 3a 32 30 3a 33 36 2e 38 32 39 30      05:20:36.8290
0550  37 32 2b 30 30 3a 30 30 27 2c 20 4b 57 5f 50 48   72+00:00', KW_PH
0560  41 3a 20 21 20 27 32 30 31 35 2d 30 33 2d 33 31   A: ! '2015-03-31
0570  20 30 35 3a 32 30 3a 33 36 2e 38 33 39 30 37 37    05:20:36.839077
0580  2b 30 30 3a 30 30 27 2c 20 4b 57 5f 50 48 42 3a   +00:00', KW_PHB:
0590  20 21 20 27 32 30 31 35 2d 30 33 2d 33 31 0a 20    ! '2015-03-31. 
05a0  20 20 20 30 35 3a 32 30 3a 33 36 2e 38 34 30 32      05:20:36.8402
05b0  38 35 2b 30 30 3a 30 30 27 2c 20 4b 57 5f 50 48   85+00:00', KW_PH
05c0  43 3a 20 21 20 27 32 30 31 35 2d 30 33 2d 33 31   C: ! '2015-03-31
05d0  20 30 35 3a 32 30 3a 33 36 2e 38 32 33 36 36 37    05:20:36.823667
05e0  2b 30 30 3a 30 30 27 2c 20 4b 57 5f 54 4f 54 3a   +00:00', KW_TOT:
05f0  20 21 20 27 32 30 31 35 2d 30 33 2d 33 31 0a 20    ! '2015-03-31. 
0600  20 20 20 30 35 3a 32 30 3a 33 36 2e 38 33 36 30      05:20:36.8360
0610  36 33 2b 30 30 3a 30 30 27 2c 20 4d 41 58 5f 44   63+00:00', MAX_D
0620  45 4d 41 4e 44 3a 20 21 20 27 32 30 31 35 2d 30   EMAND: ! '2015-0
0630  33 2d 33 31 20 30 35 3a 32 30 3a 33 36 2e 38 32   3-31 05:20:36.82
0640  31 34 31 34 2b 30 30 3a 30 30 27 2c 20 50 46 5f   1414+00:00', PF_
0650  50 48 41 3a 20 21 20 27 32 30 31 35 2d 30 33 2d   PHA: ! '2015-03-
0660  33 31 0a 20 20 20 20 30 35 3a 32 30 3a 33 36 2e   31.    05:20:36.
0670  38 32 36 30 36 39 2b 30 30 3a 30 30 27 2c 20 50   826069+00:00', P
0680  46 5f 50 48 42 3a 20 21 20 27 32 30 31 35 2d 30   F_PHB: ! '2015-0
0690  33 2d 33 31 20 30 35 3a 32 30 3a 33 36 2e 38 32   3-31 05:20:36.82
06a0  37 38 37 32 2b 30 30 3a 30 30 27 2c 20 50 46 5f   7872+00:00', PF_
06b0  50 48 43 3a 20 21 20 27 32 30 31 35 2d 30 33 2d   PHC: ! '2015-03-
06c0  33 31 0a 20 20 20 20 30 35 3a 32 30 3a 33 36 2e   31.    05:20:36.
06d0  38 32 37 32 38 37 2b 30 30 3a 30 30 27 2c 20 50   827287+00:00', P
06e0  46 5f 54 4f 54 3a 20 21 20 27 32 30 31 35 2d 30   F_TOT: ! '2015-0
06f0  33 2d 33 31 20 30 35 3a 32 30 3a 33 36 2e 38 32   3-31 05:20:36.82
0700  30 37 32 31 2b 30 30 3a 30 30 27 2c 20 56 5f 50   0721+00:00', V_P
0710  48 41 3a 20 21 20 27 32 30 31 35 2d 30 33 2d 33   HA: ! '2015-03-3
0720  31 0a 20 20 20 20 30 35 3a 32 30 3a 33 36 2e 38   1.    05:20:36.8
0730  33 32 38 34 39 2b 30 30 3a 30 30 27 2c 20 56 5f   32849+00:00', V_
0740  50 48 42 3a 20 21 20 27 32 30 31 35 2d 30 33 2d   PHB: ! '2015-03-
0750  33 31 20 30 35 3a 32 30 3a 33 36 2e 38 33 30 38   31 05:20:36.8308
0760  39 37 2b 30 30 3a 30 30 27 2c 20 56 5f 50 48 43   97+00:00', V_PHC
0770  3a 20 21 20 27 32 30 31 35 2d 30 33 2d 33 31 0a   : ! '2015-03-31.
0780  20 20 20 20 30 35 3a 32 30 3a 33 36 2e 38 33 31       05:20:36.831
0790  35 36 39 2b 30 30 3a 30 30 27 7d 0a 64 65 61 64   569+00:00'}.dead
07a0  6c 69 6e 65 3a 20 2a 69 64 30 30 31 0a 65 6e 74   line: *id001.ent
07b0  69 74 79 3a 20 42 37 39 5f 30 31 5f 52 54 0a 70   ity: B79_01_RT.p
07c0  72 69 6f 72 69 74 79 3a 20 31 32 37 0a 74 79 70   riority: 127.typ
07d0  65 3a 20 64 65 6d 61 6e 64 5f 61 64 64 0a ce      e: demand_add..

No.     Time        Source                Destination           Protocol Length Info
   3353 444.779121  ::1                   ::1                   TCP      86     37030→5672 [ACK] Seq=65468 Ack=45374 Win=64288 Len=0 TSval=92539083 TSecr=92539083

Frame 3353: 86 bytes on wire (688 bits), 86 bytes captured (688 bits)
    Encapsulation type: Ethernet (1)
    Arrival Time: Mar 31, 2015 14:20:36.888486000 EST
    [Time shift for this packet: 0.000000000 seconds]
    Epoch Time: 1427775636.888486000 seconds
    [Time delta from previous captured frame: 0.000099000 seconds]
    [Time delta from previous displayed frame: 0.000099000 seconds]
    [Time since reference or first frame: 444.779121000 seconds]
    Frame Number: 3353
    Frame Length: 86 bytes (688 bits)
    Capture Length: 86 bytes (688 bits)
    [Frame is marked: False]
    [Frame is ignored: False]
    [Protocols in frame: eth:ethertype:ipv6:ipv6.nxt:tcp]
    [Coloring Rule Name: TCP]
    [Coloring Rule String: tcp]
Ethernet II, Src: 00:00:00_00:00:00 (00:00:00:00:00:00), Dst: 00:00:00_00:00:00 (00:00:00:00:00:00)
    Destination: 00:00:00_00:00:00 (00:00:00:00:00:00)
        Address: 00:00:00_00:00:00 (00:00:00:00:00:00)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Source: 00:00:00_00:00:00 (00:00:00:00:00:00)
        Address: 00:00:00_00:00:00 (00:00:00:00:00:00)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Type: IPv6 (0x86dd)
Internet Protocol Version 6, Src: ::1 (::1), Dst: ::1 (::1)
    0110 .... = Version: 6
        [0110 .... = This field makes the filter "ip.version == 6" possible: 6]
    .... 0000 0000 .... .... .... .... .... = Traffic class: 0x00000000
        .... 0000 00.. .... .... .... .... .... = Differentiated Services Field: Default (0x00000000)
        .... .... ..0. .... .... .... .... .... = ECN-Capable Transport (ECT): Not set
        .... .... ...0 .... .... .... .... .... = ECN-CE: Not set
    .... .... .... 0000 0000 0000 0000 0000 = Flowlabel: 0x00000000
    Payload length: 32
    Next header: TCP (6)
    Hop limit: 64
    Source: ::1 (::1)
    Destination: ::1 (::1)
Transmission Control Protocol, Src Port: 37030 (37030), Dst Port: 5672 (5672), Seq: 65468, Ack: 45374, Len: 0
    Source Port: 37030 (37030)
    Destination Port: 5672 (5672)
    [Stream index: 3]
    [TCP Segment Len: 0]
    Sequence number: 65468    (relative sequence number)
    Acknowledgment number: 45374    (relative ack number)
    Header Length: 32 bytes
    .... 0000 0001 0000 = Flags: 0x010 (ACK)
        000. .... .... = Reserved: Not set
        ...0 .... .... = Nonce: Not set
        .... 0... .... = Congestion Window Reduced (CWR): Not set
        .... .0.. .... = ECN-Echo: Not set
        .... ..0. .... = Urgent: Not set
        .... ...1 .... = Acknowledgment: Set
        .... .... 0... = Push: Not set
        .... .... .0.. = Reset: Not set
        .... .... ..0. = Syn: Not set
        .... .... ...0 = Fin: Not set
    Window size value: 4018
    [Calculated window size: 64288]
    [Window size scaling factor: 16]
    Checksum: 0x0028 [validation disabled]
        [Good Checksum: False]
        [Bad Checksum: False]
    Urgent pointer: 0
    Options: (12 bytes), No-Operation (NOP), No-Operation (NOP), Timestamps
        No-Operation (NOP)
            Type: 1
                0... .... = Copy on fragmentation: No
                .00. .... = Class: Control (0)
                ...0 0001 = Number: No-Operation (NOP) (1)
        No-Operation (NOP)
            Type: 1
                0... .... = Copy on fragmentation: No
                .00. .... = Class: Control (0)
                ...0 0001 = Number: No-Operation (NOP) (1)
        Timestamps: TSval 92539083, TSecr 92539083
            Kind: Time Stamp Option (8)
            Length: 10
            Timestamp value: 92539083
            Timestamp echo reply: 92539083
    [SEQ/ACK analysis]
        [This is an ACK to the segment in frame: 3352]
        [The RTT to ACK the segment was: 0.000099000 seconds]
        [iRTT: 0.000077000 seconds]

0000  00 00 00 00 00 00 00 00 00 00 00 00 86 dd 60 00   ..............`.
0010  00 00 00 20 06 40 00 00 00 00 00 00 00 00 00 00   ... .@..........
0020  00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00   ................
0030  00 00 00 00 00 01 90 a6 16 28 69 f6 b2 e0 6c 85   .........(i...l.
0040  a1 ea 80 10 0f b2 00 28 00 00 01 01 08 0a 05 84   .......(........
0050  08 cb 05 84 08 cb                                 ......

No.     Time        Source                Destination           Protocol Length Info
   3354 444.818053  ::1                   ::1                   AMQP     133    Basic.Publish

Frame 3354: 133 bytes on wire (1064 bits), 133 bytes captured (1064 bits)
    Encapsulation type: Ethernet (1)
    Arrival Time: Mar 31, 2015 14:20:36.927418000 EST
    [Time shift for this packet: 0.000000000 seconds]
    Epoch Time: 1427775636.927418000 seconds
    [Time delta from previous captured frame: 0.038932000 seconds]
    [Time delta from previous displayed frame: 0.038932000 seconds]
    [Time since reference or first frame: 444.818053000 seconds]
    Frame Number: 3354
    Frame Length: 133 bytes (1064 bits)
    Capture Length: 133 bytes (1064 bits)
    [Frame is marked: False]
    [Frame is ignored: False]
    [Protocols in frame: eth:ethertype:ipv6:ipv6.nxt:tcp:amqp]
    [Coloring Rule Name: TCP]
    [Coloring Rule String: tcp]
Ethernet II, Src: 00:00:00_00:00:00 (00:00:00:00:00:00), Dst: 00:00:00_00:00:00 (00:00:00:00:00:00)
    Destination: 00:00:00_00:00:00 (00:00:00:00:00:00)
        Address: 00:00:00_00:00:00 (00:00:00:00:00:00)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Source: 00:00:00_00:00:00 (00:00:00:00:00:00)
        Address: 00:00:00_00:00:00 (00:00:00:00:00:00)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Type: IPv6 (0x86dd)
Internet Protocol Version 6, Src: ::1 (::1), Dst: ::1 (::1)
    0110 .... = Version: 6
        [0110 .... = This field makes the filter "ip.version == 6" possible: 6]
    .... 0000 0000 .... .... .... .... .... = Traffic class: 0x00000000
        .... 0000 00.. .... .... .... .... .... = Differentiated Services Field: Default (0x00000000)
        .... .... ..0. .... .... .... .... .... = ECN-Capable Transport (ECT): Not set
        .... .... ...0 .... .... .... .... .... = ECN-CE: Not set
    .... .... .... 0000 0000 0000 0000 0000 = Flowlabel: 0x00000000
    Payload length: 79
    Next header: TCP (6)
    Hop limit: 64
    Source: ::1 (::1)
    Destination: ::1 (::1)
Transmission Control Protocol, Src Port: 37030 (37030), Dst Port: 5672 (5672), Seq: 65468, Ack: 45374, Len: 47
    Source Port: 37030 (37030)
    Destination Port: 5672 (5672)
    [Stream index: 3]
    [TCP Segment Len: 47]
    Sequence number: 65468    (relative sequence number)
    [Next sequence number: 65515    (relative sequence number)]
    Acknowledgment number: 45374    (relative ack number)
    Header Length: 32 bytes
    .... 0000 0001 1000 = Flags: 0x018 (PSH, ACK)
        000. .... .... = Reserved: Not set
        ...0 .... .... = Nonce: Not set
        .... 0... .... = Congestion Window Reduced (CWR): Not set
        .... .0.. .... = ECN-Echo: Not set
        .... ..0. .... = Urgent: Not set
        .... ...1 .... = Acknowledgment: Set
        .... .... 1... = Push: Set
        .... .... .0.. = Reset: Not set
        .... .... ..0. = Syn: Not set
        .... .... ...0 = Fin: Not set
    Window size value: 4098
    [Calculated window size: 65568]
    [Window size scaling factor: 16]
    Checksum: 0x0057 [validation disabled]
        [Good Checksum: False]
        [Bad Checksum: False]
    Urgent pointer: 0
    Options: (12 bytes), No-Operation (NOP), No-Operation (NOP), Timestamps
        No-Operation (NOP)
            Type: 1
                0... .... = Copy on fragmentation: No
                .00. .... = Class: Control (0)
                ...0 0001 = Number: No-Operation (NOP) (1)
        No-Operation (NOP)
            Type: 1
                0... .... = Copy on fragmentation: No
                .00. .... = Class: Control (0)
                ...0 0001 = Number: No-Operation (NOP) (1)
        Timestamps: TSval 92539093, TSecr 92539083
            Kind: Time Stamp Option (8)
            Length: 10
            Timestamp value: 92539093
            Timestamp echo reply: 92539083
    [SEQ/ACK analysis]
        [iRTT: 0.000077000 seconds]
        [Bytes in flight: 47]
Advanced Message Queueing Protocol
    Type: Method (1)
    Channel: 118
    Length: 39
    Class: Basic (60)
    Method: Publish (40)
    Arguments
        Ticket: 0
        Exchange: 
        Routing-Key: amq.gen-N-wLi2XfTKANdxLh1MIIfA
        .... ...0 = Mandatory: False
        .... ..0. = Immediate: False

0000  00 00 00 00 00 00 00 00 00 00 00 00 86 dd 60 00   ..............`.
0010  00 00 00 4f 06 40 00 00 00 00 00 00 00 00 00 00   ...O.@..........
0020  00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00   ................
0030  00 00 00 00 00 01 90 a6 16 28 69 f6 b2 e0 6c 85   .........(i...l.
0040  a1 ea 80 18 10 02 00 57 00 00 01 01 08 0a 05 84   .......W........
0050  08 d5 05 84 08 cb 01 00 76 00 00 00 27 00 3c 00   ........v...'.<.
0060  28 00 00 00 1e 61 6d 71 2e 67 65 6e 2d 4e 2d 77   (....amq.gen-N-w
0070  4c 69 32 58 66 54 4b 41 4e 64 78 4c 68 31 4d 49   Li2XfTKANdxLh1MI
0080  49 66 41 00 ce                                    IfA..

No.     Time        Source                Destination           Protocol Length Info
   3355 444.818130  ::1                   ::1                   TCP      86     5672→37030 [ACK] Seq=45374 Ack=65515 Win=32736 Len=0 TSval=92539093 TSecr=92539093

Frame 3355: 86 bytes on wire (688 bits), 86 bytes captured (688 bits)
    Encapsulation type: Ethernet (1)
    Arrival Time: Mar 31, 2015 14:20:36.927495000 EST
    [Time shift for this packet: 0.000000000 seconds]
    Epoch Time: 1427775636.927495000 seconds
    [Time delta from previous captured frame: 0.000077000 seconds]
    [Time delta from previous displayed frame: 0.000077000 seconds]
    [Time since reference or first frame: 444.818130000 seconds]
    Frame Number: 3355
    Frame Length: 86 bytes (688 bits)
    Capture Length: 86 bytes (688 bits)
    [Frame is marked: False]
    [Frame is ignored: False]
    [Protocols in frame: eth:ethertype:ipv6:ipv6.nxt:tcp]
    [Coloring Rule Name: TCP]
    [Coloring Rule String: tcp]
Ethernet II, Src: 00:00:00_00:00:00 (00:00:00:00:00:00), Dst: 00:00:00_00:00:00 (00:00:00:00:00:00)
    Destination: 00:00:00_00:00:00 (00:00:00:00:00:00)
        Address: 00:00:00_00:00:00 (00:00:00:00:00:00)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Source: 00:00:00_00:00:00 (00:00:00:00:00:00)
        Address: 00:00:00_00:00:00 (00:00:00:00:00:00)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Type: IPv6 (0x86dd)
Internet Protocol Version 6, Src: ::1 (::1), Dst: ::1 (::1)
    0110 .... = Version: 6
        [0110 .... = This field makes the filter "ip.version == 6" possible: 6]
    .... 0000 0000 .... .... .... .... .... = Traffic class: 0x00000000
        .... 0000 00.. .... .... .... .... .... = Differentiated Services Field: Default (0x00000000)
        .... .... ..0. .... .... .... .... .... = ECN-Capable Transport (ECT): Not set
        .... .... ...0 .... .... .... .... .... = ECN-CE: Not set
    .... .... .... 0000 0000 0000 0000 0000 = Flowlabel: 0x00000000
    Payload length: 32
    Next header: TCP (6)
    Hop limit: 64
    Source: ::1 (::1)
    Destination: ::1 (::1)
Transmission Control Protocol, Src Port: 5672 (5672), Dst Port: 37030 (37030), Seq: 45374, Ack: 65515, Len: 0
    Source Port: 5672 (5672)
    Destination Port: 37030 (37030)
    [Stream index: 3]
    [TCP Segment Len: 0]
    Sequence number: 45374    (relative sequence number)
    Acknowledgment number: 65515    (relative ack number)
    Header Length: 32 bytes
    .... 0000 0001 0000 = Flags: 0x010 (ACK)
        000. .... .... = Reserved: Not set
        ...0 .... .... = Nonce: Not set
        .... 0... .... = Congestion Window Reduced (CWR): Not set
        .... .0.. .... = ECN-Echo: Not set
        .... ..0. .... = Urgent: Not set
        .... ...1 .... = Acknowledgment: Set
        .... .... 0... = Push: Not set
        .... .... .0.. = Reset: Not set
        .... .... ..0. = Syn: Not set
        .... .... ...0 = Fin: Not set
    Window size value: 2046
    [Calculated window size: 32736]
    [Window size scaling factor: 16]
    Checksum: 0x0028 [validation disabled]
        [Good Checksum: False]
        [Bad Checksum: False]
    Urgent pointer: 0
    Options: (12 bytes), No-Operation (NOP), No-Operation (NOP), Timestamps
        No-Operation (NOP)
            Type: 1
                0... .... = Copy on fragmentation: No
                .00. .... = Class: Control (0)
                ...0 0001 = Number: No-Operation (NOP) (1)
        No-Operation (NOP)
            Type: 1
                0... .... = Copy on fragmentation: No
                .00. .... = Class: Control (0)
                ...0 0001 = Number: No-Operation (NOP) (1)
        Timestamps: TSval 92539093, TSecr 92539093
            Kind: Time Stamp Option (8)
            Length: 10
            Timestamp value: 92539093
            Timestamp echo reply: 92539093
    [SEQ/ACK analysis]
        [This is an ACK to the segment in frame: 3354]
        [The RTT to ACK the segment was: 0.000077000 seconds]
        [iRTT: 0.000077000 seconds]

0000  00 00 00 00 00 00 00 00 00 00 00 00 86 dd 60 00   ..............`.
0010  00 00 00 20 06 40 00 00 00 00 00 00 00 00 00 00   ... .@..........
0020  00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00   ................
0030  00 00 00 00 00 01 16 28 90 a6 6c 85 a1 ea 69 f6   .......(..l...i.
0040  b3 0f 80 10 07 fe 00 28 00 00 01 01 08 0a 05 84   .......(........
0050  08 d5 05 84 08 d5                                 ......

No.     Time        Source                Destination           Protocol Length Info
   3356 444.818426  ::1                   ::1                   AMQP     229    Content-Header 

Frame 3356: 229 bytes on wire (1832 bits), 229 bytes captured (1832 bits)
    Encapsulation type: Ethernet (1)
    Arrival Time: Mar 31, 2015 14:20:36.927791000 EST
    [Time shift for this packet: 0.000000000 seconds]
    Epoch Time: 1427775636.927791000 seconds
    [Time delta from previous captured frame: 0.000296000 seconds]
    [Time delta from previous displayed frame: 0.000296000 seconds]
    [Time since reference or first frame: 444.818426000 seconds]
    Frame Number: 3356
    Frame Length: 229 bytes (1832 bits)
    Capture Length: 229 bytes (1832 bits)
    [Frame is marked: False]
    [Frame is ignored: False]
    [Protocols in frame: eth:ethertype:ipv6:ipv6.nxt:tcp:amqp]
    [Coloring Rule Name: TCP]
    [Coloring Rule String: tcp]
Ethernet II, Src: 00:00:00_00:00:00 (00:00:00:00:00:00), Dst: 00:00:00_00:00:00 (00:00:00:00:00:00)
    Destination: 00:00:00_00:00:00 (00:00:00:00:00:00)
        Address: 00:00:00_00:00:00 (00:00:00:00:00:00)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Source: 00:00:00_00:00:00 (00:00:00:00:00:00)
        Address: 00:00:00_00:00:00 (00:00:00:00:00:00)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Type: IPv6 (0x86dd)
Internet Protocol Version 6, Src: ::1 (::1), Dst: ::1 (::1)
    0110 .... = Version: 6
        [0110 .... = This field makes the filter "ip.version == 6" possible: 6]
    .... 0000 0000 .... .... .... .... .... = Traffic class: 0x00000000
        .... 0000 00.. .... .... .... .... .... = Differentiated Services Field: Default (0x00000000)
        .... .... ..0. .... .... .... .... .... = ECN-Capable Transport (ECT): Not set
        .... .... ...0 .... .... .... .... .... = ECN-CE: Not set
    .... .... .... 0000 0000 0000 0000 0000 = Flowlabel: 0x00000000
    Payload length: 175
    Next header: TCP (6)
    Hop limit: 64
    Source: ::1 (::1)
    Destination: ::1 (::1)
Transmission Control Protocol, Src Port: 37030 (37030), Dst Port: 5672 (5672), Seq: 65515, Ack: 45374, Len: 143
    Source Port: 37030 (37030)
    Destination Port: 5672 (5672)
    [Stream index: 3]
    [TCP Segment Len: 143]
    Sequence number: 65515    (relative sequence number)
    [Next sequence number: 65658    (relative sequence number)]
    Acknowledgment number: 45374    (relative ack number)
    Header Length: 32 bytes
    .... 0000 0001 1000 = Flags: 0x018 (PSH, ACK)
        000. .... .... = Reserved: Not set
        ...0 .... .... = Nonce: Not set
        .... 0... .... = Congestion Window Reduced (CWR): Not set
        .... .0.. .... = ECN-Echo: Not set
        .... ..0. .... = Urgent: Not set
        .... ...1 .... = Acknowledgment: Set
        .... .... 1... = Push: Set
        .... .... .0.. = Reset: Not set
        .... .... ..0. = Syn: Not set
        .... .... ...0 = Fin: Not set
    Window size value: 4098
    [Calculated window size: 65568]
    [Window size scaling factor: 16]
    Checksum: 0x00b7 [validation disabled]
        [Good Checksum: False]
        [Bad Checksum: False]
    Urgent pointer: 0
    Options: (12 bytes), No-Operation (NOP), No-Operation (NOP), Timestamps
        No-Operation (NOP)
            Type: 1
                0... .... = Copy on fragmentation: No
                .00. .... = Class: Control (0)
                ...0 0001 = Number: No-Operation (NOP) (1)
        No-Operation (NOP)
            Type: 1
                0... .... = Copy on fragmentation: No
                .00. .... = Class: Control (0)
                ...0 0001 = Number: No-Operation (NOP) (1)
        Timestamps: TSval 92539093, TSecr 92539093
            Kind: Time Stamp Option (8)
            Length: 10
            Timestamp value: 92539093
            Timestamp echo reply: 92539093
    [SEQ/ACK analysis]
        [iRTT: 0.000077000 seconds]
        [Bytes in flight: 143]
Advanced Message Queueing Protocol
    Type: Content header (2)
    Channel: 118
    Length: 135
    Class ID: Basic (60)
    Weight: 0
    Body size: 2179
    Property flags: 0xed80
    Properties
        Content-Type: text/x-yaml; charset=utf-8
        Content-Encoding: utf-8
        Headers
        Priority: 4
        Correlation-Id: {47e43f42-d75d-11e4-a3be-74fe48053a4b}
        Expiration: 5970
        Message-Id: {5063945f-7be8-485d-ab22-f15c4becd001}

0000  00 00 00 00 00 00 00 00 00 00 00 00 86 dd 60 00   ..............`.
0010  00 00 00 af 06 40 00 00 00 00 00 00 00 00 00 00   .....@..........
0020  00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00   ................
0030  00 00 00 00 00 01 90 a6 16 28 69 f6 b3 0f 6c 85   .........(i...l.
0040  a1 ea 80 18 10 02 00 b7 00 00 01 01 08 0a 05 84   ................
0050  08 d5 05 84 08 d5 02 00 76 00 00 00 87 00 3c 00   ........v.....<.
0060  00 00 00 00 00 00 00 08 83 ed 80 1a 74 65 78 74   ............text
0070  2f 78 2d 79 61 6d 6c 3b 20 63 68 61 72 73 65 74   /x-yaml; charset
0080  3d 75 74 66 2d 38 05 75 74 66 2d 38 00 00 00 00   =utf-8.utf-8....
0090  04 26 7b 34 37 65 34 33 66 34 32 2d 64 37 35 64   .&{47e43f42-d75d
00a0  2d 31 31 65 34 2d 61 33 62 65 2d 37 34 66 65 34   -11e4-a3be-74fe4
00b0  38 30 35 33 61 34 62 7d 04 35 39 37 30 26 7b 35   8053a4b}.5970&{5
00c0  30 36 33 39 34 35 66 2d 37 62 65 38 2d 34 38 35   063945f-7be8-485
00d0  64 2d 61 62 32 32 2d 66 31 35 63 34 62 65 63 64   d-ab22-f15c4becd
00e0  30 30 31 7d ce                                    001}.

No.     Time        Source                Destination           Protocol Length Info
   3357 444.818454  ::1                   ::1                   TCP      86     5672→37030 [ACK] Seq=45374 Ack=65658 Win=32736 Len=0 TSval=92539093 TSecr=92539093

Frame 3357: 86 bytes on wire (688 bits), 86 bytes captured (688 bits)
    Encapsulation type: Ethernet (1)
    Arrival Time: Mar 31, 2015 14:20:36.927819000 EST
    [Time shift for this packet: 0.000000000 seconds]
    Epoch Time: 1427775636.927819000 seconds
    [Time delta from previous captured frame: 0.000028000 seconds]
    [Time delta from previous displayed frame: 0.000028000 seconds]
    [Time since reference or first frame: 444.818454000 seconds]
    Frame Number: 3357
    Frame Length: 86 bytes (688 bits)
    Capture Length: 86 bytes (688 bits)
    [Frame is marked: False]
    [Frame is ignored: False]
    [Protocols in frame: eth:ethertype:ipv6:ipv6.nxt:tcp]
    [Coloring Rule Name: TCP]
    [Coloring Rule String: tcp]
Ethernet II, Src: 00:00:00_00:00:00 (00:00:00:00:00:00), Dst: 00:00:00_00:00:00 (00:00:00:00:00:00)
    Destination: 00:00:00_00:00:00 (00:00:00:00:00:00)
        Address: 00:00:00_00:00:00 (00:00:00:00:00:00)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Source: 00:00:00_00:00:00 (00:00:00:00:00:00)
        Address: 00:00:00_00:00:00 (00:00:00:00:00:00)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Type: IPv6 (0x86dd)
Internet Protocol Version 6, Src: ::1 (::1), Dst: ::1 (::1)
    0110 .... = Version: 6
        [0110 .... = This field makes the filter "ip.version == 6" possible: 6]
    .... 0000 0000 .... .... .... .... .... = Traffic class: 0x00000000
        .... 0000 00.. .... .... .... .... .... = Differentiated Services Field: Default (0x00000000)
        .... .... ..0. .... .... .... .... .... = ECN-Capable Transport (ECT): Not set
        .... .... ...0 .... .... .... .... .... = ECN-CE: Not set
    .... .... .... 0000 0000 0000 0000 0000 = Flowlabel: 0x00000000
    Payload length: 32
    Next header: TCP (6)
    Hop limit: 64
    Source: ::1 (::1)
    Destination: ::1 (::1)
Transmission Control Protocol, Src Port: 5672 (5672), Dst Port: 37030 (37030), Seq: 45374, Ack: 65658, Len: 0
    Source Port: 5672 (5672)
    Destination Port: 37030 (37030)
    [Stream index: 3]
    [TCP Segment Len: 0]
    Sequence number: 45374    (relative sequence number)
    Acknowledgment number: 65658    (relative ack number)
    Header Length: 32 bytes
    .... 0000 0001 0000 = Flags: 0x010 (ACK)
        000. .... .... = Reserved: Not set
        ...0 .... .... = Nonce: Not set
        .... 0... .... = Congestion Window Reduced (CWR): Not set
        .... .0.. .... = ECN-Echo: Not set
        .... ..0. .... = Urgent: Not set
        .... ...1 .... = Acknowledgment: Set
        .... .... 0... = Push: Not set
        .... .... .0.. = Reset: Not set
        .... .... ..0. = Syn: Not set
        .... .... ...0 = Fin: Not set
    Window size value: 2046
    [Calculated window size: 32736]
    [Window size scaling factor: 16]
    Checksum: 0x0028 [validation disabled]
        [Good Checksum: False]
        [Bad Checksum: False]
    Urgent pointer: 0
    Options: (12 bytes), No-Operation (NOP), No-Operation (NOP), Timestamps
        No-Operation (NOP)
            Type: 1
                0... .... = Copy on fragmentation: No
                .00. .... = Class: Control (0)
                ...0 0001 = Number: No-Operation (NOP) (1)
        No-Operation (NOP)
            Type: 1
                0... .... = Copy on fragmentation: No
                .00. .... = Class: Control (0)
                ...0 0001 = Number: No-Operation (NOP) (1)
        Timestamps: TSval 92539093, TSecr 92539093
            Kind: Time Stamp Option (8)
            Length: 10
            Timestamp value: 92539093
            Timestamp echo reply: 92539093
    [SEQ/ACK analysis]
        [This is an ACK to the segment in frame: 3356]
        [The RTT to ACK the segment was: 0.000028000 seconds]
        [iRTT: 0.000077000 seconds]

0000  00 00 00 00 00 00 00 00 00 00 00 00 86 dd 60 00   ..............`.
0010  00 00 00 20 06 40 00 00 00 00 00 00 00 00 00 00   ... .@..........
0020  00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00   ................
0030  00 00 00 00 00 01 16 28 90 a6 6c 85 a1 ea 69 f6   .......(..l...i.
0040  b3 9e 80 10 07 fe 00 28 00 00 01 01 08 0a 05 84   .......(........
0050  08 d5 05 84 08 d5                                 ......

No.     Time        Source                Destination           Protocol Length Info
   3358 444.818553  ::1                   ::1                   AMQP     2273   Content-Body 

Frame 3358: 2273 bytes on wire (18184 bits), 2273 bytes captured (18184 bits)
    Encapsulation type: Ethernet (1)
    Arrival Time: Mar 31, 2015 14:20:36.927918000 EST
    [Time shift for this packet: 0.000000000 seconds]
    Epoch Time: 1427775636.927918000 seconds
    [Time delta from previous captured frame: 0.000099000 seconds]
    [Time delta from previous displayed frame: 0.000099000 seconds]
    [Time since reference or first frame: 444.818553000 seconds]
    Frame Number: 3358
    Frame Length: 2273 bytes (18184 bits)
    Capture Length: 2273 bytes (18184 bits)
    [Frame is marked: False]
    [Frame is ignored: False]
    [Protocols in frame: eth:ethertype:ipv6:ipv6.nxt:tcp:amqp]
    [Coloring Rule Name: TCP]
    [Coloring Rule String: tcp]
Ethernet II, Src: 00:00:00_00:00:00 (00:00:00:00:00:00), Dst: 00:00:00_00:00:00 (00:00:00:00:00:00)
    Destination: 00:00:00_00:00:00 (00:00:00:00:00:00)
        Address: 00:00:00_00:00:00 (00:00:00:00:00:00)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Source: 00:00:00_00:00:00 (00:00:00:00:00:00)
        Address: 00:00:00_00:00:00 (00:00:00:00:00:00)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Type: IPv6 (0x86dd)
Internet Protocol Version 6, Src: ::1 (::1), Dst: ::1 (::1)
    0110 .... = Version: 6
        [0110 .... = This field makes the filter "ip.version == 6" possible: 6]
    .... 0000 0000 .... .... .... .... .... = Traffic class: 0x00000000
        .... 0000 00.. .... .... .... .... .... = Differentiated Services Field: Default (0x00000000)
        .... .... ..0. .... .... .... .... .... = ECN-Capable Transport (ECT): Not set
        .... .... ...0 .... .... .... .... .... = ECN-CE: Not set
    .... .... .... 0000 0000 0000 0000 0000 = Flowlabel: 0x00000000
    Payload length: 2219
    Next header: TCP (6)
    Hop limit: 64
    Source: ::1 (::1)
    Destination: ::1 (::1)
Transmission Control Protocol, Src Port: 37030 (37030), Dst Port: 5672 (5672), Seq: 65658, Ack: 45374, Len: 2187
    Source Port: 37030 (37030)
    Destination Port: 5672 (5672)
    [Stream index: 3]
    [TCP Segment Len: 2187]
    Sequence number: 65658    (relative sequence number)
    [Next sequence number: 67845    (relative sequence number)]
    Acknowledgment number: 45374    (relative ack number)
    Header Length: 32 bytes
    .... 0000 0001 1000 = Flags: 0x018 (PSH, ACK)
        000. .... .... = Reserved: Not set
        ...0 .... .... = Nonce: Not set
        .... 0... .... = Congestion Window Reduced (CWR): Not set
        .... .0.. .... = ECN-Echo: Not set
        .... ..0. .... = Urgent: Not set
        .... ...1 .... = Acknowledgment: Set
        .... .... 1... = Push: Set
        .... .... .0.. = Reset: Not set
        .... .... ..0. = Syn: Not set
        .... .... ...0 = Fin: Not set
    Window size value: 4098
    [Calculated window size: 65568]
    [Window size scaling factor: 16]
    Checksum: 0x08b3 [validation disabled]
        [Good Checksum: False]
        [Bad Checksum: False]
    Urgent pointer: 0
    Options: (12 bytes), No-Operation (NOP), No-Operation (NOP), Timestamps
        No-Operation (NOP)
            Type: 1
                0... .... = Copy on fragmentation: No
                .00. .... = Class: Control (0)
                ...0 0001 = Number: No-Operation (NOP) (1)
        No-Operation (NOP)
            Type: 1
                0... .... = Copy on fragmentation: No
                .00. .... = Class: Control (0)
                ...0 0001 = Number: No-Operation (NOP) (1)
        Timestamps: TSval 92539093, TSecr 92539093
            Kind: Time Stamp Option (8)
            Length: 10
            Timestamp value: 92539093
            Timestamp echo reply: 92539093
    [SEQ/ACK analysis]
        [iRTT: 0.000077000 seconds]
        [Bytes in flight: 2187]
Advanced Message Queueing Protocol
    Type: Content body (3)
    Channel: 118
    Length: 2179
    Payload: 7072696f726974793a203132370a747970653a2064656d61...

0000  00 00 00 00 00 00 00 00 00 00 00 00 86 dd 60 00   ..............`.
0010  00 00 08 ab 06 40 00 00 00 00 00 00 00 00 00 00   .....@..........
0020  00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00   ................
0030  00 00 00 00 00 01 90 a6 16 28 69 f6 b3 9e 6c 85   .........(i...l.
0040  a1 ea 80 18 10 02 08 b3 00 00 01 01 08 0a 05 84   ................
0050  08 d5 05 84 08 d5 03 00 76 00 00 08 83 70 72 69   ........v....pri
0060  6f 72 69 74 79 3a 20 31 32 37 0a 74 79 70 65 3a   ority: 127.type:
0070  20 64 65 6d 61 6e 64 5f 72 65 73 0a 65 6e 74 69    demand_res.enti
0080  74 79 3a 20 42 37 39 5f 30 31 5f 52 54 0a 61 74   ty: B79_01_RT.at
0090  74 72 69 62 75 74 65 73 3a 0a 20 20 56 5f 50 48   tributes:.  V_PH
00a0  41 3a 0a 20 20 20 20 73 74 61 74 65 3a 20 4f 4b   A:.    state: OK
00b0  0a 20 20 20 20 65 78 70 69 72 79 3a 20 32 30 31   .    expiry: 201
00c0  35 2d 30 33 2d 33 31 54 30 35 3a 32 30 3a 33 36   5-03-31T05:20:36
00d0  2e 38 33 32 30 30 30 2b 30 30 3a 30 30 0a 20 20   .832000+00:00.  
00e0  56 5f 50 48 43 3a 0a 20 20 20 20 73 74 61 74 65   V_PHC:.    state
00f0  3a 20 4f 4b 0a 20 20 20 20 65 78 70 69 72 79 3a   : OK.    expiry:
0100  20 32 30 31 35 2d 30 33 2d 33 31 54 30 35 3a 32    2015-03-31T05:2
0110  30 3a 33 36 2e 38 33 31 30 30 30 2b 30 30 3a 30   0:36.831000+00:0
0120  30 0a 20 20 4b 57 5f 50 48 41 3a 0a 20 20 20 20   0.  KW_PHA:.    
0130  73 74 61 74 65 3a 20 4f 4b 0a 20 20 20 20 65 78   state: OK.    ex
0140  70 69 72 79 3a 20 32 30 31 35 2d 30 33 2d 33 31   piry: 2015-03-31
0150  54 30 35 3a 32 30 3a 33 36 2e 38 33 39 30 30 30   T05:20:36.839000
0160  2b 30 30 3a 30 30 0a 20 20 56 5f 50 48 42 3a 0a   +00:00.  V_PHB:.
0170  20 20 20 20 73 74 61 74 65 3a 20 4f 4b 0a 20 20       state: OK.  
0180  20 20 65 78 70 69 72 79 3a 20 32 30 31 35 2d 30     expiry: 2015-0
0190  33 2d 33 31 54 30 35 3a 32 30 3a 33 36 2e 38 33   3-31T05:20:36.83
01a0  30 30 30 30 2b 30 30 3a 30 30 0a 20 20 4b 56 41   0000+00:00.  KVA
01b0  52 48 5f 49 4e 44 5f 49 4d 50 3a 0a 20 20 20 20   RH_IND_IMP:.    
01c0  73 74 61 74 65 3a 20 4f 4b 0a 20 20 20 20 65 78   state: OK.    ex
01d0  70 69 72 79 3a 20 32 30 31 35 2d 30 33 2d 33 31   piry: 2015-03-31
01e0  54 30 35 3a 32 30 3a 33 36 2e 38 33 32 30 30 30   T05:20:36.832000
01f0  2b 30 30 3a 30 30 0a 20 20 50 46 5f 50 48 41 3a   +00:00.  PF_PHA:
0200  0a 20 20 20 20 73 74 61 74 65 3a 20 4f 4b 0a 20   .    state: OK. 
0210  20 20 20 65 78 70 69 72 79 3a 20 32 30 31 35 2d      expiry: 2015-
0220  30 33 2d 33 31 54 30 35 3a 32 30 3a 33 36 2e 38   03-31T05:20:36.8
0230  32 36 30 30 30 2b 30 30 3a 30 30 0a 20 20 4b 57   26000+00:00.  KW
0240  48 5f 45 58 50 3a 0a 20 20 20 20 73 74 61 74 65   H_EXP:.    state
0250  3a 20 4f 4b 0a 20 20 20 20 65 78 70 69 72 79 3a   : OK.    expiry:
0260  20 32 30 31 35 2d 30 33 2d 33 31 54 30 35 3a 32    2015-03-31T05:2
0270  30 3a 33 36 2e 38 33 37 30 30 30 2b 30 30 3a 30   0:36.837000+00:0
0280  30 0a 20 20 50 46 5f 50 48 42 3a 0a 20 20 20 20   0.  PF_PHB:.    
0290  73 74 61 74 65 3a 20 4f 4b 0a 20 20 20 20 65 78   state: OK.    ex
02a0  70 69 72 79 3a 20 32 30 31 35 2d 30 33 2d 33 31   piry: 2015-03-31
02b0  54 30 35 3a 32 30 3a 33 36 2e 38 32 37 30 30 30   T05:20:36.827000
02c0  2b 30 30 3a 30 30 0a 20 20 49 5f 50 48 34 3a 0a   +00:00.  I_PH4:.
02d0  20 20 20 20 73 74 61 74 65 3a 20 4f 4b 0a 20 20       state: OK.  
02e0  20 20 65 78 70 69 72 79 3a 20 32 30 31 35 2d 30     expiry: 2015-0
02f0  33 2d 33 31 54 30 35 3a 32 30 3a 33 36 2e 38 33   3-31T05:20:36.83
0300  37 30 30 30 2b 30 30 3a 30 30 0a 20 20 46 52 45   7000+00:00.  FRE
0310  51 3a 0a 20 20 20 20 73 74 61 74 65 3a 20 4f 4b   Q:.    state: OK
0320  0a 20 20 20 20 65 78 70 69 72 79 3a 20 32 30 31   .    expiry: 201
0330  35 2d 30 33 2d 33 31 54 30 35 3a 32 30 3a 33 36   5-03-31T05:20:36
0340  2e 38 33 35 30 30 30 2b 30 30 3a 30 30 0a 20 20   .835000+00:00.  
0350  4b 56 41 52 48 5f 43 41 50 5f 45 58 50 3a 0a 20   KVARH_CAP_EXP:. 
0360  20 20 20 73 74 61 74 65 3a 20 4f 4b 0a 20 20 20      state: OK.   
0370  20 65 78 70 69 72 79 3a 20 32 30 31 35 2d 30 33    expiry: 2015-03
0380  2d 33 31 54 30 35 3a 32 30 3a 33 36 2e 38 33 39   -31T05:20:36.839
0390  30 30 30 2b 30 30 3a 30 30 0a 20 20 50 46 5f 50   000+00:00.  PF_P
03a0  48 43 3a 0a 20 20 20 20 73 74 61 74 65 3a 20 4f   HC:.    state: O
03b0  4b 0a 20 20 20 20 65 78 70 69 72 79 3a 20 32 30   K.    expiry: 20
03c0  31 35 2d 30 33 2d 33 31 54 30 35 3a 32 30 3a 33   15-03-31T05:20:3
03d0  36 2e 38 32 37 30 30 30 2b 30 30 3a 30 30 0a 20   6.827000+00:00. 
03e0  20 4b 56 41 52 48 5f 49 4e 44 5f 45 58 50 3a 0a    KVARH_IND_EXP:.
03f0  20 20 20 20 73 74 61 74 65 3a 20 4f 4b 0a 20 20       state: OK.  
0400  20 20 65 78 70 69 72 79 3a 20 32 30 31 35 2d 30     expiry: 2015-0
0410  33 2d 33 31 54 30 35 3a 32 30 3a 33 36 2e 38 32   3-31T05:20:36.82
0420  36 30 30 30 2b 30 30 3a 30 30 0a 20 20 4b 57 48   6000+00:00.  KWH
0430  5f 49 4d 50 3a 0a 20 20 20 20 73 74 61 74 65 3a   _IMP:.    state:
0440  20 4f 4b 0a 20 20 20 20 65 78 70 69 72 79 3a 20    OK.    expiry: 
0450  32 30 31 35 2d 30 33 2d 33 31 54 30 35 3a 32 30   2015-03-31T05:20
0460  3a 33 36 2e 38 32 39 30 30 30 2b 30 30 3a 30 30   :36.829000+00:00
0470  0a 20 20 50 46 5f 54 4f 54 3a 0a 20 20 20 20 73   .  PF_TOT:.    s
0480  74 61 74 65 3a 20 4f 4b 0a 20 20 20 20 65 78 70   tate: OK.    exp
0490  69 72 79 3a 20 32 30 31 35 2d 30 33 2d 33 31 54   iry: 2015-03-31T
04a0  30 35 3a 32 30 3a 33 36 2e 38 32 30 30 30 30 2b   05:20:36.820000+
04b0  30 30 3a 30 30 0a 20 20 4b 56 41 5f 54 4f 54 3a   00:00.  KVA_TOT:
04c0  0a 20 20 20 20 73 74 61 74 65 3a 20 4f 4b 0a 20   .    state: OK. 
04d0  20 20 20 65 78 70 69 72 79 3a 20 32 30 31 35 2d      expiry: 2015-
04e0  30 33 2d 33 31 54 30 35 3a 32 30 3a 33 36 2e 38   03-31T05:20:36.8
04f0  33 38 30 30 30 2b 30 30 3a 30 30 0a 20 20 4b 56   38000+00:00.  KV
0500  41 48 5f 49 4d 50 3a 0a 20 20 20 20 73 74 61 74   AH_IMP:.    stat
0510  65 3a 20 4f 4b 0a 20 20 20 20 65 78 70 69 72 79   e: OK.    expiry
0520  3a 20 32 30 31 35 2d 30 33 2d 33 31 54 30 35 3a   : 2015-03-31T05:
0530  32 30 3a 33 36 2e 38 32 35 30 30 30 2b 30 30 3a   20:36.825000+00:
0540  30 30 0a 20 20 4b 56 41 52 5f 50 48 41 3a 0a 20   00.  KVAR_PHA:. 
0550  20 20 20 73 74 61 74 65 3a 20 4f 4b 0a 20 20 20      state: OK.   
0560  20 65 78 70 69 72 79 3a 20 32 30 31 35 2d 30 33    expiry: 2015-03
0570  2d 33 31 54 30 35 3a 32 30 3a 33 36 2e 38 33 34   -31T05:20:36.834
0580  30 30 30 2b 30 30 3a 30 30 0a 20 20 49 5f 50 48   000+00:00.  I_PH
0590  41 3a 0a 20 20 20 20 73 74 61 74 65 3a 20 4f 4b   A:.    state: OK
05a0  0a 20 20 20 20 65 78 70 69 72 79 3a 20 32 30 31   .    expiry: 201
05b0  35 2d 30 33 2d 33 31 54 30 35 3a 32 30 3a 33 36   5-03-31T05:20:36
05c0  2e 38 31 38 30 30 30 2b 30 30 3a 30 30 0a 20 20   .818000+00:00.  
05d0  4b 56 41 52 5f 50 48 42 3a 0a 20 20 20 20 73 74   KVAR_PHB:.    st
05e0  61 74 65 3a 20 4f 4b 0a 20 20 20 20 65 78 70 69   ate: OK.    expi
05f0  72 79 3a 20 32 30 31 35 2d 30 33 2d 33 31 54 30   ry: 2015-03-31T0
0600  35 3a 32 30 3a 33 36 2e 38 33 34 30 30 30 2b 30   5:20:36.834000+0
0610  30 3a 30 30 0a 20 20 49 5f 50 48 42 3a 0a 20 20   0:00.  I_PHB:.  
0620  20 20 73 74 61 74 65 3a 20 4f 4b 0a 20 20 20 20     state: OK.    
0630  65 78 70 69 72 79 3a 20 32 30 31 35 2d 30 33 2d   expiry: 2015-03-
0640  33 31 54 30 35 3a 32 30 3a 33 36 2e 38 32 30 30   31T05:20:36.8200
0650  30 30 2b 30 30 3a 30 30 0a 20 20 4b 56 41 52 5f   00+00:00.  KVAR_
0660  50 48 43 3a 0a 20 20 20 20 73 74 61 74 65 3a 20   PHC:.    state: 
0670  4f 4b 0a 20 20 20 20 65 78 70 69 72 79 3a 20 32   OK.    expiry: 2
0680  30 31 35 2d 30 33 2d 33 31 54 30 35 3a 32 30 3a   015-03-31T05:20:
0690  33 36 2e 38 33 33 30 30 30 2b 30 30 3a 30 30 0a   36.833000+00:00.
06a0  20 20 49 5f 50 48 43 3a 0a 20 20 20 20 73 74 61     I_PHC:.    sta
06b0  74 65 3a 20 4f 4b 0a 20 20 20 20 65 78 70 69 72   te: OK.    expir
06c0  79 3a 20 32 30 31 35 2d 30 33 2d 33 31 54 30 35   y: 2015-03-31T05
06d0  3a 32 30 3a 33 36 2e 38 31 39 30 30 30 2b 30 30   :20:36.819000+00
06e0  3a 30 30 0a 20 20 49 5f 41 56 47 5f 54 4f 54 3a   :00.  I_AVG_TOT:
06f0  0a 20 20 20 20 73 74 61 74 65 3a 20 4f 4b 0a 20   .    state: OK. 
0700  20 20 20 65 78 70 69 72 79 3a 20 32 30 31 35 2d      expiry: 2015-
0710  30 33 2d 33 31 54 30 35 3a 32 30 3a 33 36 2e 38   03-31T05:20:36.8
0720  34 32 30 30 30 2b 30 30 3a 30 30 0a 20 20 4b 57   42000+00:00.  KW
0730  5f 50 48 42 3a 0a 20 20 20 20 73 74 61 74 65 3a   _PHB:.    state:
0740  20 4f 4b 0a 20 20 20 20 65 78 70 69 72 79 3a 20    OK.    expiry: 
0750  32 30 31 35 2d 30 33 2d 33 31 54 30 35 3a 32 30   2015-03-31T05:20
0760  3a 33 36 2e 38 34 30 30 30 30 2b 30 30 3a 30 30   :36.840000+00:00
0770  0a 20 20 4d 41 58 5f 44 45 4d 41 4e 44 3a 0a 20   .  MAX_DEMAND:. 
0780  20 20 20 73 74 61 74 65 3a 20 4f 4b 0a 20 20 20      state: OK.   
0790  20 65 78 70 69 72 79 3a 20 32 30 31 35 2d 30 33    expiry: 2015-03
07a0  2d 33 31 54 30 35 3a 32 30 3a 33 36 2e 38 32 31   -31T05:20:36.821
07b0  30 30 30 2b 30 30 3a 30 30 0a 20 20 4b 56 41 52   000+00:00.  KVAR
07c0  48 5f 43 41 50 5f 49 4d 50 3a 0a 20 20 20 20 73   H_CAP_IMP:.    s
07d0  74 61 74 65 3a 20 4f 4b 0a 20 20 20 20 65 78 70   tate: OK.    exp
07e0  69 72 79 3a 20 32 30 31 35 2d 30 33 2d 33 31 54   iry: 2015-03-31T
07f0  30 35 3a 32 30 3a 33 36 2e 38 33 36 30 30 30 2b   05:20:36.836000+
0800  30 30 3a 30 30 0a 20 20 4b 57 5f 54 4f 54 3a 0a   00:00.  KW_TOT:.
0810  20 20 20 20 65 78 70 69 72 79 3a 20 32 30 31 35       expiry: 2015
0820  2d 30 33 2d 33 31 54 30 35 3a 32 30 3a 33 36 2e   -03-31T05:20:36.
0830  38 33 36 30 30 30 2b 30 30 3a 30 30 0a 20 20 20   836000+00:00.   
0840  20 73 74 61 74 65 3a 20 4f 4b 0a 20 20 4b 57 5f    state: OK.  KW_
0850  50 48 43 3a 0a 20 20 20 20 73 74 61 74 65 3a 20   PHC:.    state: 
0860  4f 4b 0a 20 20 20 20 65 78 70 69 72 79 3a 20 32   OK.    expiry: 2
0870  30 31 35 2d 30 33 2d 33 31 54 30 35 3a 32 30 3a   015-03-31T05:20:
0880  33 36 2e 38 32 33 30 30 30 2b 30 30 3a 30 30 0a   36.823000+00:00.
0890  20 20 4b 56 41 48 5f 45 58 50 3a 0a 20 20 20 20     KVAH_EXP:.    
08a0  65 78 70 69 72 79 3a 20 32 30 31 35 2d 30 33 2d   expiry: 2015-03-
08b0  33 31 54 30 35 3a 32 30 3a 33 36 2e 38 32 38 30   31T05:20:36.8280
08c0  30 30 2b 30 30 3a 30 30 0a 20 20 20 20 73 74 61   00+00:00.    sta
08d0  74 65 3a 20 4f 4b 0a 73 74 61 74 65 3a 20 4f 4b   te: OK.state: OK
08e0  ce                                                .

No.     Time        Source                Destination           Protocol Length Info
   3359 444.818586  ::1                   ::1                   TCP      86     5672→37030 [ACK] Seq=45374 Ack=67845 Win=32736 Len=0 TSval=92539093 TSecr=92539093

Frame 3359: 86 bytes on wire (688 bits), 86 bytes captured (688 bits)
    Encapsulation type: Ethernet (1)
    Arrival Time: Mar 31, 2015 14:20:36.927951000 EST
    [Time shift for this packet: 0.000000000 seconds]
    Epoch Time: 1427775636.927951000 seconds
    [Time delta from previous captured frame: 0.000033000 seconds]
    [Time delta from previous displayed frame: 0.000033000 seconds]
    [Time since reference or first frame: 444.818586000 seconds]
    Frame Number: 3359
    Frame Length: 86 bytes (688 bits)
    Capture Length: 86 bytes (688 bits)
    [Frame is marked: False]
    [Frame is ignored: False]
    [Protocols in frame: eth:ethertype:ipv6:ipv6.nxt:tcp]
    [Coloring Rule Name: TCP]
    [Coloring Rule String: tcp]
Ethernet II, Src: 00:00:00_00:00:00 (00:00:00:00:00:00), Dst: 00:00:00_00:00:00 (00:00:00:00:00:00)
    Destination: 00:00:00_00:00:00 (00:00:00:00:00:00)
        Address: 00:00:00_00:00:00 (00:00:00:00:00:00)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Source: 00:00:00_00:00:00 (00:00:00:00:00:00)
        Address: 00:00:00_00:00:00 (00:00:00:00:00:00)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Type: IPv6 (0x86dd)
Internet Protocol Version 6, Src: ::1 (::1), Dst: ::1 (::1)
    0110 .... = Version: 6
        [0110 .... = This field makes the filter "ip.version == 6" possible: 6]
    .... 0000 0000 .... .... .... .... .... = Traffic class: 0x00000000
        .... 0000 00.. .... .... .... .... .... = Differentiated Services Field: Default (0x00000000)
        .... .... ..0. .... .... .... .... .... = ECN-Capable Transport (ECT): Not set
        .... .... ...0 .... .... .... .... .... = ECN-CE: Not set
    .... .... .... 0000 0000 0000 0000 0000 = Flowlabel: 0x00000000
    Payload length: 32
    Next header: TCP (6)
    Hop limit: 64
    Source: ::1 (::1)
    Destination: ::1 (::1)
Transmission Control Protocol, Src Port: 5672 (5672), Dst Port: 37030 (37030), Seq: 45374, Ack: 67845, Len: 0
    Source Port: 5672 (5672)
    Destination Port: 37030 (37030)
    [Stream index: 3]
    [TCP Segment Len: 0]
    Sequence number: 45374    (relative sequence number)
    Acknowledgment number: 67845    (relative ack number)
    Header Length: 32 bytes
    .... 0000 0001 0000 = Flags: 0x010 (ACK)
        000. .... .... = Reserved: Not set
        ...0 .... .... = Nonce: Not set
        .... 0... .... = Congestion Window Reduced (CWR): Not set
        .... .0.. .... = ECN-Echo: Not set
        .... ..0. .... = Urgent: Not set
        .... ...1 .... = Acknowledgment: Set
        .... .... 0... = Push: Not set
        .... .... .0.. = Reset: Not set
        .... .... ..0. = Syn: Not set
        .... .... ...0 = Fin: Not set
    Window size value: 2046
    [Calculated window size: 32736]
    [Window size scaling factor: 16]
    Checksum: 0x0028 [validation disabled]
        [Good Checksum: False]
        [Bad Checksum: False]
    Urgent pointer: 0
    Options: (12 bytes), No-Operation (NOP), No-Operation (NOP), Timestamps
        No-Operation (NOP)
            Type: 1
                0... .... = Copy on fragmentation: No
                .00. .... = Class: Control (0)
                ...0 0001 = Number: No-Operation (NOP) (1)
        No-Operation (NOP)
            Type: 1
                0... .... = Copy on fragmentation: No
                .00. .... = Class: Control (0)
                ...0 0001 = Number: No-Operation (NOP) (1)
        Timestamps: TSval 92539093, TSecr 92539093
            Kind: Time Stamp Option (8)
            Length: 10
            Timestamp value: 92539093
            Timestamp echo reply: 92539093
    [SEQ/ACK analysis]
        [This is an ACK to the segment in frame: 3358]
        [The RTT to ACK the segment was: 0.000033000 seconds]
        [iRTT: 0.000077000 seconds]

0000  00 00 00 00 00 00 00 00 00 00 00 00 86 dd 60 00   ..............`.
0010  00 00 00 20 06 40 00 00 00 00 00 00 00 00 00 00   ... .@..........
0020  00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00   ................
0030  00 00 00 00 00 01 16 28 90 a6 6c 85 a1 ea 69 f6   .......(..l...i.
0040  bc 29 80 10 07 fe 00 28 00 00 01 01 08 0a 05 84   .).....(........
0050  08 d5 05 84 08 d5                                 ......

Looking at the above, it seems QAmqpQueuePrivate::deliver should get called, but for whatever reason, doesn't. I'm not sure where the headers are being picked up from. Is there some other method that plucks out header details and inserts them into the waiting message?

mbroadst commented 9 years ago

@sjlongland it would be useful to throw in the output of enabling QAMQP debugging (QAMQP_DEBUG=1 ./test/auto/sometest) as well

sjlongland commented 9 years ago

On 31/03/15 22:30, Matt Broadstone wrote:

@sjlongland https://github.com/sjlongland it would be useful to throw in the output of enabling QAMQP debugging (QAMQP_DEBUG=1 ./test/auto/sometest) as well

Ahh, so THAT's what QAmqpDebug does. Okay, I've added that to my environment and I'm doing a test now.

Regards,

Stuart Longland (aka Redhatter, VK4MSL)

I haven't lost my mind... ...it's backed up on a tape somewhere.

mbroadst commented 9 years ago

@sjlongland it's not exactly the best, but it's more data :smile:

sjlongland commented 9 years ago

Indeed, and I think I see a problem:

1427829972 DEBUG QDebug : void QAmqpQueuePrivate::deliver(const QAmqpMethodFrame&) 
1427829972 DEBUG QDebug : void QAmqpQueuePrivate::deliver(const QAmqpMethodFrame&) invalid consumer tag:  "amq.ctag-Lxayf60oSe_N9r2dwXZrdQ" 
1427829972 DEBUG QDebug : received content-header without delivered message 
1427829972 DEBUG QDebug : received content-body without delivered message 
1427829975 DEBUG QDebug : void QAmqpQueuePrivate::deliver(const QAmqpMethodFrame&) 
1427829975 DEBUG QDebug : void QAmqpQueuePrivate::deliver(const QAmqpMethodFrame&) invalid consumer tag:  "amq.ctag-OBXV9bYBBHbGn1tylMsOqQ" 
1427829975 DEBUG QDebug : currentMessage.d->leftSize:  1666 
1427829975 DEBUG QDebug : currentMessage.d->leftSize:  1666 ; frame.body().size()  1666 ; frame body:  "_debug_: {created: ! '2015-03-31 19:26:15.760065+00:00', sent: ! '2015-03-31 19:26:15.780293+00:00'}
attributes: {FREQ: ! '2015-03-31 20:26:15.749075+00:00', I_AVG_TOT: ! '2015-03-31
    20:26:15.758797+00:00', I_PH4: ! '2015-03-31 20:26:15.751397+00:00', I_PHA: &id001 ! '2015-03-31
    20:26:15.719745+00:00', I_PHB: ! '2015-03-31 20:26:15.725703+00:00', I_PHC: ! '2015-03-31
    20:26:15.722833+00:00', KVAH_EXP: ! '2015-03-31 20:26:15.739239+00:00', KVAH_IMP: ! '2015-03-31
    20:26:15.735045+00:00', KVARH_CAP_EXP: ! '2015-03-31 20:26:15.755873+00:00', KVARH_CAP_IMP: ! '2015-03-31
    20:26:15.750634+00:00', KVARH_IND_EXP: ! '2015-03-31 20:26:15.736603+00:00', KVARH_IND_IMP: ! '2015-03-31
    20:26:15.743515+00:00', KVAR_PHA: ! '2015-03-31 20:26:15.748266+00:00', KVAR_PHB: ! '2015-03-31
    20:26:15.747497+00:00', KVAR_PHC: ! '2015-03-31 20:26:15.746708+00:00', KVA_TOT: ! '2015-03-31
    20:26:15.754149+00:00', KWH_EXP: ! '2015-03-31 20:26:15.752166+00:00', KWH_IMP: ! '2015-03-31
    20:26:15.740009+00:00', KW_PHA: ! '2015-03-31 20:26:15.755040+00:00', KW_PHB: ! '2015-03-31
    20:26:15.757893+00:00', KW_PHC: ! '2015-03-31 20:26:15.734215+00:00', KW_TOT: ! '2015-03-31
    20:26:15.749847+00:00', MAX_DEMAND: ! '2015-03-31 20:26:15.732098+00:00', PF_PHA: ! '2015-03-31
    20:26:15.735824+00:00', PF_PHB: ! '2015-03-31 20:26:15.738433+00:00', PF_PHC: ! '2015-03-31
    20:26:15.737429+00:00', PF_TOT: ! '2015-03-31 20:26:15.729047+00:00', V_PHA: ! '2015-03-31
    20:26:15.745797+00:00', V_PHB: ! '2015-03-31 20:26:15.740837+00:00', V_PHC: ! '2015-03-31
    20:26:15.741620+00:00'}
deadline: *id001
entity: B79_01_RT
priority: 127
type: demand_add
" 
1427829975 DEBUG QDebug : Emitting message, payload: "_debug_: {created: ! '2015-03-31 19:26:12.041736+00:00', sent: ! '2015-03-31 19:26:12.095316+00:00'}
deadline: 2015-03-31 19:26:22.018312+00:00
entity: B79_01_RT
priority: 127
type: cfg_info
_debug_: {created: ! '2015-03-31 19:26:15.760065+00:00', sent: ! '2015-03-31 19:26:15.780293+00:00'}
attributes: {FREQ: ! '2015-03-31 20:26:15.749075+00:00', I_AVG_TOT: ! '2015-03-31
    20:26:15.758797+00:00', I_PH4: ! '2015-03-31 20:26:15.751397+00:00', I_PHA: &id001 ! '2015-03-31
    20:26:15.719745+00:00', I_PHB: ! '2015-03-31 20:26:15.725703+00:00', I_PHC: ! '2015-03-31
    20:26:15.722833+00:00', KVAH_EXP: ! '2015-03-31 20:26:15.739239+00:00', KVAH_IMP: ! '2015-03-31
    20:26:15.735045+00:00', KVARH_CAP_EXP: ! '2015-03-31 20:26:15.755873+00:00', KVARH_CAP_IMP: ! '2015-03-31
    20:26:15.750634+00:00', KVARH_IND_EXP: ! '2015-03-31 20:26:15.736603+00:00', KVARH_IND_IMP: ! '2015-03-31
    20:26:15.743515+00:00', KVAR_PHA: ! '2015-03-31 20:26:15.748266+00:00', KVAR_PHB: ! '2015-03-31
    20:26:15.747497+00:00', KVAR_PHC: ! '2015-03-31 20:26:15.746708+00:00', KVA_TOT: ! '2015-03-31
    20:26:15.754149+00:00', KWH_EXP: ! '2015-03-31 20:26:15.752166+00:00', KWH_IMP: ! '2015-03-31
    20:26:15.740009+00:00', KW_PHA: ! '2015-03-31 20:26:15.755040+00:00', KW_PHB: ! '2015-03-31
    20:26:15.757893+00:00', KW_PHC: ! '2015-03-31 20:26:15.734215+00:00', KW_TOT: ! '2015-03-31
    20:26:15.749847+00:00', MAX_DEMAND: ! '2015-03-31 20:26:15.732098+00:00', PF_PHA: ! '2015-03-31
    20:26:15.735824+00:00', PF_PHB: ! '2015-03-31 20:26:15.738433+00:00', PF_PHC: ! '2015-03-31
    20:26:15.737429+00:00', PF_TOT: ! '2015-03-31 20:26:15.729047+00:00', V_PHA: ! '2015-03-31
    20:26:15.745797+00:00', V_PHB: ! '2015-03-31 20:26:15.740837+00:00', V_PHC: ! '2015-03-31
    20:26:15.741620+00:00'}
deadline: *id001
entity: B79_01_RT
priority: 127
type: demand_add
" 
1427829975 DEBUG AMQPQueueHandler.amq.gen-qhfdczcsHSd8-yksIQkGzg : New message received.
1427829975 DEBUG MessageParser : Correlation ID is cc56852c-d7db-11e4-aa19-74fe48053a4b
1427829975 DEBUG MessageParser : Message ID is cc56852c-d7db-11e4-aa19-74fe48053a4b
1427829975 DEBUG MessageParser : Content-type is text/x-yaml; charset=utf-8
1427829975 DEBUG MessageParser : Message payload:
---
_debug_: {created: ! '2015-03-31 19:26:12.041736+00:00', sent: ! '2015-03-31 19:26:12.095316+00:00'}
deadline: 2015-03-31 19:26:22.018312+00:00
entity: B79_01_RT
priority: 127
type: cfg_info
_debug_: {created: ! '2015-03-31 19:26:15.760065+00:00', sent: ! '2015-03-31 19:26:15.780293+00:00'}
attributes: {FREQ: ! '2015-03-31 20:26:15.749075+00:00', I_AVG_TOT: ! '2015-03-31
    20:26:15.758797+00:00', I_PH4: ! '2015-03-31 20:26:15.751397+00:00', I_PHA: &id001 ! '2015-03-31
    20:26:15.719745+00:00', I_PHB: ! '2015-03-31 20:26:15.725703+00:00', I_PHC: ! '2015-03-31
    20:26:15.722833+00:00', KVAH_EXP: ! '2015-03-31 20:26:15.739239+00:00', KVAH_IMP: ! '2015-03-31
    20:26:15.735045+00:00', KVARH_CAP_EXP: ! '2015-03-31 20:26:15.755873+00:00', KVARH_CAP_IMP: ! '2015-03-31
    20:26:15.750634+00:00', KVARH_IND_EXP: ! '2015-03-31 20:26:15.736603+00:00', KVARH_IND_IMP: ! '2015-03-31
    20:26:15.743515+00:00', KVAR_PHA: ! '2015-03-31 20:26:15.748266+00:00', KVAR_PHB: ! '2015-03-31
    20:26:15.747497+00:00', KVAR_PHC: ! '2015-03-31 20:26:15.746708+00:00', KVA_TOT: ! '2015-03-31
    20:26:15.754149+00:00', KWH_EXP: ! '2015-03-31 20:26:15.752166+00:00', KWH_IMP: ! '2015-03-31
    20:26:15.740009+00:00', KW_PHA: ! '2015-03-31 20:26:15.755040+00:00', KW_PHB: ! '2015-03-31
    20:26:15.757893+00:00', KW_PHC: ! '2015-03-31 20:26:15.734215+00:00', KW_TOT: ! '2015-03-31
    20:26:15.749847+00:00', MAX_DEMAND: ! '2015-03-31 20:26:15.732098+00:00', PF_PHA: ! '2015-03-31
    20:26:15.735824+00:00', PF_PHB: ! '2015-03-31 20:26:15.738433+00:00', PF_PHC: ! '2015-03-31
    20:26:15.737429+00:00', PF_TOT: ! '2015-03-31 20:26:15.729047+00:00', V_PHA: ! '2015-03-31
    20:26:15.745797+00:00', V_PHB: ! '2015-03-31 20:26:15.740837+00:00', V_PHC: ! '2015-03-31
    20:26:15.741620+00:00'}
deadline: *id001
entity: B79_01_RT
priority: 127
type: demand_add

---
1427829975 DEBUG MessageParser : Message at 0x92523e0 has type demand_add

So somewhere it is getting the consumer tags muddled. If I look back in the log, this was what was captured when the program started declaring that particular queue.

1427829935 DEBUG AMQPQueueHandler : Entering state Q_DECLARED (old state Q_DECLARING)
1427829935 DEBUG AMQPQueueHandler : Queue declared, officially known as amq.gen-qhfdczcsHSd8-yksIQkGzg
1427829935 DEBUG AMQPQueueHandler.amq.gen-qhfdczcsHSd8-yksIQkGzg : Re-binding all subscriptions.
1427829935 DEBUG AMQPQueueHandler.amq.gen-qhfdczcsHSd8-yksIQkGzg : Checking exists entity.rq.B79_01_RT
1427829935 DEBUG AMQPQueueHandler.amq.gen-qhfdczcsHSd8-yksIQkGzg : Checking entity.rq.B79_01_RT is declared (EXC_DECLARED)
1427829935 DEBUG AMQPQueueHandler.amq.gen-qhfdczcsHSd8-yksIQkGzg : Checking entity.rq.B79_01_RT is declared
1427829935 DEBUG AMQPQueueHandler.amq.gen-qhfdczcsHSd8-yksIQkGzg : Checking 'to subscribe' list. (1 actions)
1427829935 DEBUG AMQPQueueHandler.amq.gen-qhfdczcsHSd8-yksIQkGzg : Entering state Q_BINDING (old state Q_DECLARED)
1427829935 DEBUG AMQPQueueHandler.amq.gen-qhfdczcsHSd8-yksIQkGzg : Binding entity.rq.B79_01_RT key #
1427829935 DEBUG AMQPQueueHandler.amq.gen-qhfdczcsHSd8-yksIQkGzg processState: Setting QOS parameters: Count=1, Size=0
1427829935 DEBUG AMQPQueueHandler.amq.gen-qhfdczcsHSd8-yksIQkGzg processState: Entering state Q_QOS (old state Q_BINDING)
[…]
1427829937 DEBUG AMQPQueueHandler.amq.gen-qhfdczcsHSd8-yksIQkGzg : QOS settings defined.
1427829937 DEBUG AMQPQueueHandler.amq.gen-qhfdczcsHSd8-yksIQkGzg processState: Intended state:Q_CONSUMING
1427829937 DEBUG AMQPQueueHandler.amq.gen-qhfdczcsHSd8-yksIQkGzg : QOS settings defined.
1427829937 DEBUG AMQPQueueHandler.amq.gen-qhfdczcsHSd8-yksIQkGzg processState: Intended state:Q_CONSUMING
1427829937 DEBUG QDebug : consume ok:  "amq.gen--T_99XcfQ26nk5HfF1A5_g" 
1427829937 DEBUG QDebug : consumer tag = amq.ctag-KmepNdh504ggYYLqq4Ws4w
1427829937 DEBUG QDebug : consume ok:  "amq.gen-pGkOfUg3mRzHrTtWkUsliQ" 
1427829937 DEBUG QDebug : consumer tag = amq.ctag-GcP-lshxRsYHZCySv_eKOQ
1427829937 DEBUG AMQPQueueHandler.amq.gen-pGkOfUg3mRzHrTtWkUsliQ processState: Intended state:Q_CONSUMING
1427829937 DEBUG AMQPQueueHandler.amq.gen-pGkOfUg3mRzHrTtWkUsliQ processState: Entering state Q_CONSUMING (old state Q_QOS)
1427829937 DEBUG QDebug : consume ok:  "amq.gen-qhfdczcsHSd8-yksIQkGzg" 
1427829937 DEBUG QDebug : consumer tag = amq.ctag-OBXV9bYBBHbGn1tylMsOqQ
1427829937 DEBUG AMQPQueueHandler.amq.gen-qhfdczcsHSd8-yksIQkGzg processState: Intended state:Q_CONSUMING
1427829937 DEBUG AMQPQueueHandler.amq.gen-qhfdczcsHSd8-yksIQkGzg processState: Entering state Q_CONSUMING (old state Q_QOS)

I'll double check that consume() isn't being called by mistake twice. Ideally this shouldn't be happening but if it is, that might be the culprit.

mbroadst commented 9 years ago

@sjlongland ah that would be a bug indeed :smile:

sjlongland commented 9 years ago

I think there's my problem. So a state machine bug in my code, triggering a bug in QAMQP.

rabbitmq

There are a couple of ways we can prevent this from accidentally occurring. One would be to put a boolean flag that gets set when consume() is called, (and re-set when the consumer is cancelled), another would be to store the consumer tags in a QStringList so it handles the other consumers.

A third would be to make a note of the last consumer tag, and ignore all message bodies not belonging to that consumer tag.

mbroadst commented 9 years ago

@sjlongland Ah great sleuthing! Yes there should be a 1-1 guarantee between a queue and a consumer tag. Can we start with a test case expressing the problem? I'm not sure I understand quite how you're trigging the error as we already have a check to prevent multiple consumption on a given QAmqpQueue: https://github.com/mbroadst/qamqp/blob/master/src/qamqpqueue.cpp#L448.

sjlongland commented 9 years ago

Okay, what I think is happening… in my code I've got a state machine that wraps the queue, basically so my objects just hold a reference (thank-you QSharedPointer) to my state machine object.

The Queue state machine (AMQPQueueHandler) begins in the DISCONNECTED state, when it receives the connected signal from the connection (AMQPConnectionHandler; which wraps QAmqpClient), it creates a queue object then calls declare() on it. In the meantime, my code has signalled its intent for a consumer to be started on that queue and to bind it to a few exchanges. The state machine doesn't act on these yet.

When binding to an exchange, it listens for the declared event from the exchange object (also a state machine; AMQPExchangeHandler). The exchange would have also called its declare() when it received the connected signal.

So there's a race between the queue and the exchange. Not a problem yet.

AMQPQueueHandler receives declared from the QAmqpQueue, sees that it's supposed to be in the CONSUMING state, sees that it doesn't yet have a consumer tag, calls consume(). (Doesn't change state.)

AMQPQueueHandler then receives a declared from AMQPExchangeHandler. It checks, sees that it hasn't yet got a consumer tag but should be in the CONSUMING state, calls consume() on QAmqpQueue again.

So I think the problem is me accidentally calling consume() between a previous call to consume() and receiving either an error signal or the consuming signal.

Something like the following might reproduce the bug:

QAmqpClient c(…);
QAmqpQueue* q;

/* … later after receiving connect() from c */
q = c.queue(…);
q.declare(…);

/* … later after receiving declared from q */
q.consume(…);
q.consume(…);

Since we don't wait for the consumed signal, that should trigger two consumers on the same channel.

I'll have a look at some point and see if that reproduces the issue.

On this, it would appear that should a buggy AMQP broker send messages with the wrong consumer tag, that will trigger the same bug. It'd be worth having a flag in QAmqpQueue that ignores message body frames when the last-seen consumer tag doesn't match the one for that queue. In fact, I'd go so far as to trigger an abort at that point (or at least complain very loudly).

mbroadst commented 9 years ago

to me it seems more likely that you are calling declare multiple times here, there is no corresponding guard in the declare() method. Try adding a line there to bail if (d->consuming) and see if it fixes your problem

sjlongland commented 9 years ago

Okay, I spent the last day re-working my code to ensure correct state when setting up objects, only to hit a separate issue with socket operation timeouts. So I've branched that code off and backtracked to where I was yesterday morning.

It appears there is some logic there in QAMQP to do an automatic re-connect, and it appears that queues then get re-declared on reconnect. Not sure if it re-binds and re-starts consumers though, and that's something I was trying to achieve. The fact that re-connecting doesn't appear to invalidate queue/exchange pointers is a good thing.

So in looking at this I'm looking at QAmqpQueue::consume, which has been the bane of my troubles lately to see what locking prevention is in place.

https://github.com/mbroadst/qamqp/blob/master/src/qamqpqueue.cpp#L440

So that immediately triggers a frame to be written to the channel, if and only if the queue hasn't already been placed in the "consuming" state. Sounds sane, now what constitutes "consuming"? It's a boolean flag, the same one returned by the QAmqpQueue::isConsuming method. It appears this flag gets set on receipt of a consumeOk message from the broker:

https://github.com/mbroadst/qamqp/blob/master/src/qamqpqueue.cpp#L212

It appears that if code calls consume multiple times in quick succession on the same queue, it is possible for this race condition to take place. Thus we wind up with multiple consumers on a queue.

sjlongland commented 9 years ago

And it looks like I've nailed it. The fixes will need some cleaning up but this is probably closer to the target than what we had before.

https://github.com/mbroadst/qamqp/compare/master...sjlongland:investigate-issue-23

There are a couple of problems that are superimposed on top of each-other. Firstly, is the lack of checking to see if some operations (notably declare and consume) are already in progress. Easy enough to fix, set a boolean flag when consume is first called, clear it when the consumeOk message comes in (or if we re-open the channel).

Attempting to fix this I ran into a separate issue, that is it's real easy to piss off the AMQP server if you're not careful to wait until one synchronous operation completes before starting the next. A number of operations require that you wait for the reply before sending the next message, or at least that's my reading of the spec.

An approach I've seen used in Pika is to queue the tasks and execute them later. So taking on a similar approach, we can stash the frame to be sent in a buffer, then when the previous operations are clear, we can recall the frame and push it down the pipe.

For this purpose, I've hijacked the QAmqpFrame base class creating QAmqpPendingFrame which basically is a clone of a frame to be sent. sendFrame now takes a boolean flag that indicates if the frame is for a synchronous operation. When a synchronous operation is in progress, calls to sendFrame cause those frames to be stashed as QAmqpPendingFrame instances for later delivery.

When the reply is received, clearPending is called, and that triggers whatever is in the queue to be delivered to the socket. If one of those is also a synchronous frame, it blocks the remainder of the queue and causes new frames to be queued until the pending flag is cleared later.

So far, having done both these things, I'm finding that subscription is a little more reliable and I'm not getting double-ups on consumers.

mbroadst commented 9 years ago

@sjlongland cool, I'm glad you found a solution here. I'm still concerned that without a test case showing the behavior, we will not be able to fully verify that the issue(s) you are facing are completely solved. There's proof enough of this being the case by simply observing your initial bug blossom into at least one other one. Can you provide a PR that shows your initial bug within the context of one of the auto tests?

sjlongland commented 9 years ago

On 02/04/15 23:34, Matt Broadstone wrote:

@sjlongland https://github.com/sjlongland cool, I'm glad you found a solution here. I'm still concerned that without a test case showing the behavior, we will not be able to fully verify that the issue(s) you are facing are completely solved. There's proof enough of this being the case by simply observing your initial bug blossom into at least one other one. Can you provide a PR that shows your initial bug within the context of one of the auto tests?

I'll see what I can do. Should be possible by creating a queue,

double-consuming it then sending a message to it.

Stuart Longland (aka Redhatter, VK4MSL)

I haven't lost my mind... ...it's backed up on a tape somewhere.

sjlongland commented 9 years ago

Okay, see https://github.com/mbroadst/qamqp/pull/24

sjlongland commented 9 years ago

Well, I did some further exploration to see what minimal fixes would nail this issue, and the result of that is in https://github.com/mbroadst/qamqp/pull/25.

I note that Travis-CI reports a successful fix.

mbroadst / qamqp