Qpid
  1. Qpid
  2. QPID-4079

C++ Broker needs log messages to track object life cycles for auditing

    Details

    • Type: Improvement Improvement
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 0.16
    • Fix Version/s: 0.19
    • Component/s: C++ Broker
    • Labels:
      None

      Description

      The C++ broker logs are unfriendly and incomplete for customers who are hoping to audit system usage. Missing are log artifacts to expose which user created, used, or destroyed which resource.

      The proposed improvement adds INFO level log statements for the creation, destruction, and major state changes to connection, session, and subscription objects, and to exchange, queue, and binding objects.

      From this set of log messages a user could determine what user from what client system address created a connection, what sessions were created on that connection, and what subscriptions were created on those sessions. Similarly the exchange-binding-queue objects would have enough in their log messages to correlate the interactions between them.

      The log message for the destruction of an object would contain a record of all the management statistics kept for that object. Then, working through the log records a customer could attribute broker usage back to specific users.

      This class of log message has been requested by customers using Security Information and Event Management (SIEM) systems to scrape information from broker event logs.

        Activity

        Hide
        Chuck Rolke added a comment -

        Here's some progress on this issue. I added a new log category "Configuration" in which to place all of 'wiring life cycle auditing' messages. The log messages are issued in the constructors and destructors (mostly) of the objects in question and are not part of the management object life cycles. However the log messages in the destructors pull the management statistics just before going out of scope.

        This log is feature-complete for objects connection, session, subscription, and broker. Still to come are queue, exchange, and binding.

        > ./qpidd --auth no --no-data-dir --log-enable notice+ --log-enable info+:Configuration

        2012-06-22 11:34:39 [Broker] notice SASL disabled: No Authentication Performed
        2012-06-22 11:34:39 [Network] notice Listening on TCP/TCP6 port 5672
        2012-06-22 11:34:39 [Broker] notice Broker running
        2012-06-22 11:34:44 [Configuration] info Connection created. connectionId:[::1]:5672-[::1]:37726
        2012-06-22 11:34:44 [Configuration] info Connection userId established. connectionId:[::1]:5672-[::1]:37726 userId:'anonymous'
        2012-06-22 11:34:44 [Configuration] info Session created. sessionId:ummmm.21477.1 userId:anonymous connectionId:[::1]:5672-[::1]:37726
        2012-06-22 11:34:44 [Configuration] info Subscription created. subscriptionId:anonymous.ummmm.21477.1::rdest queueId:reply-ummmm.21477.1 sessionId:anonymous.ummmm.21477.1
        2012-06-22 11:34:44 [Configuration] info Subscription created. subscriptionId:anonymous.ummmm.21477.1::tdest queueId:topic-ummmm.21477.1 sessionId:anonymous.ummmm.21477.1
        2012-06-22 11:34:44 [Configuration] info Subscription created. subscriptionId:anonymous.ummmm.21477.1::v2dest queueId:qmfc-v2-ummmm.21477.1 sessionId:anonymous.ummmm.21477.1
        2012-06-22 11:34:44 [Configuration] info Subscription created. subscriptionId:anonymous.ummmm.21477.1::v2TopicUI queueId:qmfc-v2-ui-ummmm.21477.1 sessionId:anonymous.ummmm.21477.1
        2012-06-22 11:34:44 [Configuration] info Subscription created. subscriptionId:anonymous.ummmm.21477.1::v2TopicHB queueId:qmfc-v2-hb-ummmm.21477.1 sessionId:anonymous.ummmm.21477.1
        2012-06-22 11:34:48 [Configuration] info Session closed. sessionId:ummmm.21477.1 Statistics:

        {TxnCommits:0, TxnCount:0, TxnRejects:0, TxnStarts:0, clientCredit:0, unackedMessages:0}

        2012-06-22 11:34:48 [Configuration] info Subscription closed. subscriptionId:anonymous.ummmm.21477.1::v2dest Statistics:

        {delivered:1}

        2012-06-22 11:34:48 [Configuration] info Subscription closed. subscriptionId:anonymous.ummmm.21477.1::v2TopicUI Statistics:

        {delivered:2}

        2012-06-22 11:34:48 [Configuration] info Subscription closed. subscriptionId:anonymous.ummmm.21477.1::v2TopicHB Statistics:

        {delivered:0}

        2012-06-22 11:34:48 [Configuration] info Subscription closed. subscriptionId:anonymous.ummmm.21477.1::tdest Statistics:

        {delivered:4}

        2012-06-22 11:34:48 [Configuration] info Subscription closed. subscriptionId:anonymous.ummmm.21477.1::rdest Statistics:

        {delivered:60}

        2012-06-22 11:34:48 [Configuration] info Connection closed. connectionId:[::1]:5672-[::1]:37726 userId:'anonymous' Statistics:

        {bytesFromClient:9693, bytesToClient:40696, closing:False, framesFromClient:204, framesToClient:275, msgsFromClient:32, msgsToClient:67}

        ^C2012-06-22 11:35:20 [Configuration] info Broker shut down. Statistics:

        {abandoned:0, abandonedViaAlt:0, acquires:67, byteDepth:0, byteFtdDepth:0, byteFtdDequeues:0, byteFtdEnqueues:0, bytePersistDequeues:0, bytePersistEnqueues:0, byteTotalDequeues:31595, byteTotalEnqueues:31595, byteTxnDequeues:0, byteTxnEnqueues:0, discardsLvq:0, discardsNoRoute:73, discardsOverflow:0, discardsPurge:0, discardsRing:0, discardsSubscriber:0, discardsTtl:0, msgDepth:0, msgFtdDepth:0, msgFtdDequeues:0, msgFtdEnqueues:0, msgPersistDequeues:0, msgPersistEnqueues:0, msgTotalDequeues:67, msgTotalEnqueues:67, msgTxnDequeues:0, msgTxnEnqueues:0, queueCount:0, releases:0, reroutes:0, uptime:40002333607}

        2012-06-22 11:35:20 [Broker] notice Shut down

        Show
        Chuck Rolke added a comment - Here's some progress on this issue. I added a new log category "Configuration" in which to place all of 'wiring life cycle auditing' messages. The log messages are issued in the constructors and destructors (mostly) of the objects in question and are not part of the management object life cycles. However the log messages in the destructors pull the management statistics just before going out of scope. This log is feature-complete for objects connection, session, subscription, and broker. Still to come are queue, exchange, and binding. > ./qpidd --auth no --no-data-dir --log-enable notice+ --log-enable info+:Configuration 2012-06-22 11:34:39 [Broker] notice SASL disabled: No Authentication Performed 2012-06-22 11:34:39 [Network] notice Listening on TCP/TCP6 port 5672 2012-06-22 11:34:39 [Broker] notice Broker running 2012-06-22 11:34:44 [Configuration] info Connection created. connectionId: [::1] :5672- [::1] :37726 2012-06-22 11:34:44 [Configuration] info Connection userId established. connectionId: [::1] :5672- [::1] :37726 userId:'anonymous' 2012-06-22 11:34:44 [Configuration] info Session created. sessionId:ummmm.21477.1 userId:anonymous connectionId: [::1] :5672- [::1] :37726 2012-06-22 11:34:44 [Configuration] info Subscription created. subscriptionId:anonymous.ummmm.21477.1::rdest queueId:reply-ummmm.21477.1 sessionId:anonymous.ummmm.21477.1 2012-06-22 11:34:44 [Configuration] info Subscription created. subscriptionId:anonymous.ummmm.21477.1::tdest queueId:topic-ummmm.21477.1 sessionId:anonymous.ummmm.21477.1 2012-06-22 11:34:44 [Configuration] info Subscription created. subscriptionId:anonymous.ummmm.21477.1::v2dest queueId:qmfc-v2-ummmm.21477.1 sessionId:anonymous.ummmm.21477.1 2012-06-22 11:34:44 [Configuration] info Subscription created. subscriptionId:anonymous.ummmm.21477.1::v2TopicUI queueId:qmfc-v2-ui-ummmm.21477.1 sessionId:anonymous.ummmm.21477.1 2012-06-22 11:34:44 [Configuration] info Subscription created. subscriptionId:anonymous.ummmm.21477.1::v2TopicHB queueId:qmfc-v2-hb-ummmm.21477.1 sessionId:anonymous.ummmm.21477.1 2012-06-22 11:34:48 [Configuration] info Session closed. sessionId:ummmm.21477.1 Statistics: {TxnCommits:0, TxnCount:0, TxnRejects:0, TxnStarts:0, clientCredit:0, unackedMessages:0} 2012-06-22 11:34:48 [Configuration] info Subscription closed. subscriptionId:anonymous.ummmm.21477.1::v2dest Statistics: {delivered:1} 2012-06-22 11:34:48 [Configuration] info Subscription closed. subscriptionId:anonymous.ummmm.21477.1::v2TopicUI Statistics: {delivered:2} 2012-06-22 11:34:48 [Configuration] info Subscription closed. subscriptionId:anonymous.ummmm.21477.1::v2TopicHB Statistics: {delivered:0} 2012-06-22 11:34:48 [Configuration] info Subscription closed. subscriptionId:anonymous.ummmm.21477.1::tdest Statistics: {delivered:4} 2012-06-22 11:34:48 [Configuration] info Subscription closed. subscriptionId:anonymous.ummmm.21477.1::rdest Statistics: {delivered:60} 2012-06-22 11:34:48 [Configuration] info Connection closed. connectionId: [::1] :5672- [::1] :37726 userId:'anonymous' Statistics: {bytesFromClient:9693, bytesToClient:40696, closing:False, framesFromClient:204, framesToClient:275, msgsFromClient:32, msgsToClient:67} ^C2012-06-22 11:35:20 [Configuration] info Broker shut down. Statistics: {abandoned:0, abandonedViaAlt:0, acquires:67, byteDepth:0, byteFtdDepth:0, byteFtdDequeues:0, byteFtdEnqueues:0, bytePersistDequeues:0, bytePersistEnqueues:0, byteTotalDequeues:31595, byteTotalEnqueues:31595, byteTxnDequeues:0, byteTxnEnqueues:0, discardsLvq:0, discardsNoRoute:73, discardsOverflow:0, discardsPurge:0, discardsRing:0, discardsSubscriber:0, discardsTtl:0, msgDepth:0, msgFtdDepth:0, msgFtdDequeues:0, msgFtdEnqueues:0, msgPersistDequeues:0, msgPersistEnqueues:0, msgTotalDequeues:67, msgTotalEnqueues:67, msgTxnDequeues:0, msgTxnEnqueues:0, queueCount:0, releases:0, reroutes:0, uptime:40002333607} 2012-06-22 11:35:20 [Broker] notice Shut down
        Hide
        Chuck Rolke added a comment -

        Before doing another round of cumbersome code reviews I'd like to agree on a top-level design for this feature.

        I propose dividing the logs into two parts.

        Part 1 consists of [Model] logs at DEBUG level that are issued synchronously with the corresponding management Events. These logs have the same data fields as the events and require no logical additions to the model [See Note 1].

        <event "clientConnect" args="rhost, user"/>
        <event "clientConnectFail" args="rhost, user, reason"/>
        <event "clientDisconnect" args="rhost, user"/>
        <event "brokerLinkUp" args="rhost"/>
        <event "brokerLinkDown" args="rhost"/>
        <event "queueDeclare" args="rhost, user, qName, durable, excl, autoDel, altEx, args, disp"/>
        <event "queueDelete" args="rhost, user, qName"/>
        <event "exchangeDeclare" args="rhost, user, exName, exType, altEx, durable, autoDel, args, disp"/>
        <event "exchangeDelete" args="rhost, user, exName"/>
        <event "bind" args="rhost, user, exName, qName, key, args"/>
        <event "unbind" args="rhost, user, exName, qName, key"/>
        <event "subscribe" args="rhost, user, qName, dest, excl, args"/>
        <event "unsubscribe" args="rhost, user, dest"/>

        Part 2 consists of [Model] logs at TRACE level that are issued automatically during the construction and destruction of the management objects. The code to issue these logs is generated along with the management class sources.

        • The constructor log exposes the management id of the object.
        • The destructor log shows the management id and the statistics for the object.

        Logs from Part 1 use names as specified by users as they create objects. Logs from Part 2 use names generated by the management framework. There is no attempt to correlate the names between the two name spaces in the logging process.


        Note 1: There are no events that expose the creation and deletion of a Session. These could be added.

        Show
        Chuck Rolke added a comment - Before doing another round of cumbersome code reviews I'd like to agree on a top-level design for this feature. I propose dividing the logs into two parts. Part 1 consists of [Model] logs at DEBUG level that are issued synchronously with the corresponding management Events. These logs have the same data fields as the events and require no logical additions to the model [See Note 1] . <event "clientConnect" args="rhost, user"/> <event "clientConnectFail" args="rhost, user, reason"/> <event "clientDisconnect" args="rhost, user"/> <event "brokerLinkUp" args="rhost"/> <event "brokerLinkDown" args="rhost"/> <event "queueDeclare" args="rhost, user, qName, durable, excl, autoDel, altEx, args, disp"/> <event "queueDelete" args="rhost, user, qName"/> <event "exchangeDeclare" args="rhost, user, exName, exType, altEx, durable, autoDel, args, disp"/> <event "exchangeDelete" args="rhost, user, exName"/> <event "bind" args="rhost, user, exName, qName, key, args"/> <event "unbind" args="rhost, user, exName, qName, key"/> <event "subscribe" args="rhost, user, qName, dest, excl, args"/> <event "unsubscribe" args="rhost, user, dest"/> Part 2 consists of [Model] logs at TRACE level that are issued automatically during the construction and destruction of the management objects. The code to issue these logs is generated along with the management class sources. The constructor log exposes the management id of the object. The destructor log shows the management id and the statistics for the object. Logs from Part 1 use names as specified by users as they create objects. Logs from Part 2 use names generated by the management framework. There is no attempt to correlate the names between the two name spaces in the logging process. — Note 1: There are no events that expose the creation and deletion of a Session. These could be added.
        Hide
        Gordon Sim added a comment -

        Seems reasonable to me. One comment on having the log statements added to the generated code though (i.e. for part 2) is that the generator was at one time supposed to be usable for 'agents' other than the broker. Adding logging statements would add another point of coupling.

        Show
        Gordon Sim added a comment - Seems reasonable to me. One comment on having the log statements added to the generated code though (i.e. for part 2) is that the generator was at one time supposed to be usable for 'agents' other than the broker. Adding logging statements would add another point of coupling.
        Hide
        Chuck Rolke added a comment -

        Resolved with r1361262 and r1361353

        Show
        Chuck Rolke added a comment - Resolved with r1361262 and r1361353

          People

          • Assignee:
            Unassigned
            Reporter:
            Chuck Rolke
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development