Qpid
  1. Qpid
  2. QPID-3902

Add formal message categories to C++ Broker log messages

    Details

    • Type: Improvement Improvement
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 0.17
    • Component/s: None
    • Labels:
      None

      Description

      This is a proposal to add log categories to C++ Broker log messages.

      Problem Statement

      There are difficulties working with C++ Broker logging when appplying a log filter criterion. What precise FILTERTEXT can a user specify for:

      --log-enable debug+:FILTERTEXT
      

      Even after the fix from QPID-3891 it is not intuitive what to specify for a FILTERTEXT and any useful filter requires detailed knowledge of the source code.

      Proposal

      A log category is a high-level classification of the nature of the logged event that is not tied to a particular source module or code function name. This log category would become the target for FILTERTEXT log filters.

      The following list is the proposed log category definition. Each log category name is followed by a list of source code directory names that would generally produce logs using that log category.

      Category Source code directory
      Security acl ssl gssapi sasl cyrus
      Broker broker
      Management agent console qmf
      Amqp amqp_0_10 framing
      System log sys types xml thread mutex fork pipe time ...
      HA cluster ha replication
      Messaging messaging client
      Store store
      IO tcp rdma AsynchIO socket epoll
      Test  
      Unspecified  

      There is no strict rule that a module produce only log entries of a specific category.

      The category would be inserted into each log message after the time of day but before the message text.

      2012-03-06 16:55:38 [Management] SEND PackageInd package=org.apache.qpid.broker to=schema.package
      

      A user could then filter log messages by using the category names:

      --log-enable debug+:Management
      

      This scheme would have a number of benefits:

      1. On a per-message basis the filter comparisons would be using enumeration values and not strings.
      2. The feature could be documented sensibly.
      3. Log files would be easier to interpret manually or by event management systems.

      The classifications could be phased in gradually. The current
      QPID_LOG(LEVEL, MESSAGE) would produce [Unspecfied] events while the new
      QPID_LOG_CAT(LEVEL, CATEGORY, MESSAGE) would produce events using an actual category.
      Similar additions are made for the QPID_MSG entries.

        Activity

        Hide
        Chuck Rolke added a comment -

        The basic categories are in place. They are calculated based on the path/filename of the source module in which the QPID_LOG resides.

        Comments on this issue suggest good ideas and further work in this area, particularly sub-categories.

        Show
        Chuck Rolke added a comment - The basic categories are in place. They are calculated based on the path/filename of the source module in which the QPID_LOG resides. Comments on this issue suggest good ideas and further work in this area, particularly sub-categories.
        Hide
        Rajith Attapattu added a comment -

        Instead of classifying categories by source dirs, can we not get each Header file to define the category it wants to be logged under?
        (The categories could be some sort of int index for fast comparing as Alan suggested).

        My suggestion on breaking the files under "broker" dir is not going to be possible without something along the lines described above.
        In the java world this seems to be used quite successfully.

        Show
        Rajith Attapattu added a comment - Instead of classifying categories by source dirs, can we not get each Header file to define the category it wants to be logged under? (The categories could be some sort of int index for fast comparing as Alan suggested). My suggestion on breaking the files under "broker" dir is not going to be possible without something along the lines described above. In the java world this seems to be used quite successfully.
        Hide
        Rajith Attapattu added a comment - - edited

        I echo Justin's comment about Network and Protocol instead of IO and AMQP.

        For Protocol we should really have something like [Protocol][

        {PROTOCOL_NAME}

        -

        {VERSION}

        ]... bcos we will mostly likely end up with supporting multiple protocol versions in the same broker. So it will be very useful to filter by a specific version. Ex. [Protocol][AMQP-0-10]

        I also think that BROKER is too broad a category to be really useful. A lot of things are lumped in there. I'm not sure if the following is possible , but if you can have more granular categories for BROKER it might be more useful.

        Ex. QUEUEING – for logs related in putting/pulling messages from queues, flow control etc..
        ROUTING – logs related to routing messages (would be more relevant going forward)
        SUBSCRIPTION – logs related to subscription state (capacity, acks ..etc)

        Another general category could be CONFIGURATION. Often times customers wants to see logs to verify if they've got the config right. It's really a separate category from any of the above. We currently don't have much here.

        Show
        Rajith Attapattu added a comment - - edited I echo Justin's comment about Network and Protocol instead of IO and AMQP. For Protocol we should really have something like [Protocol] [ {PROTOCOL_NAME} - {VERSION} ]... bcos we will mostly likely end up with supporting multiple protocol versions in the same broker. So it will be very useful to filter by a specific version. Ex. [Protocol] [AMQP-0-10] I also think that BROKER is too broad a category to be really useful. A lot of things are lumped in there. I'm not sure if the following is possible , but if you can have more granular categories for BROKER it might be more useful. Ex. QUEUEING – for logs related in putting/pulling messages from queues, flow control etc.. ROUTING – logs related to routing messages (would be more relevant going forward) SUBSCRIPTION – logs related to subscription state (capacity, acks ..etc) Another general category could be CONFIGURATION. Often times customers wants to see logs to verify if they've got the config right. It's really a separate category from any of the above. We currently don't have much here.
        Hide
        Justin Ross added a comment -

        I have a slight preference for "Network" over "IO" and "Protocol" over "Amqp". The former because it's slightly more descriptive, and the latter because it identifies a general role as the other categories do.

        Show
        Justin Ross added a comment - I have a slight preference for "Network" over "IO" and "Protocol" over "Amqp". The former because it's slightly more descriptive, and the latter because it identifies a general role as the other categories do.
        Hide
        Chuck Rolke added a comment -

        I've attached a tab-delimited text file suitable for viewing in a spreadsheet. It shows the "category" as derived from the source file path and name. The categorization appears to be usable as-is but any QPID_LOG message can be adjusted to having any category.

        Internally the category is derived with a series of awful string compares. But this is done only once for each log entry statement when it is first instantiated.

        The net result of work in this branch produces calculated categories that make a broker log appear like this:

        2012-05-17 16:01:37 [IO] info Listening to: 0.0.0.0:5672
        2012-05-17 16:01:37 [IO] debug Listened to: 5672
        2012-05-17 16:01:37 [IO] info Listening to: [::]:5672
        2012-05-17 16:01:37 [IO] debug Listened to: 5672
        2012-05-17 16:01:37 [IO] notice Listening on TCP/TCP6 port 5672
        2012-05-17 16:01:37 [Management] debug ManagementAgent added package org.apache.qpid.acl
        2012-05-17 16:01:37 [Management] debug SEND PackageInd package=org.apache.qpid.acl to=schema.package
        2012-05-17 16:01:37 [Management] debug ManagementAgent added class org.apache.qpid.acl:acl
        2012-05-17 16:01:37 [Management] debug ManagementAgent added class org.apache.qpid.acl:allow
        2012-05-17 16:01:37 [Management] debug ManagementAgent added class org.apache.qpid.acl:deny
        2012-05-17 16:01:37 [Management] debug ManagementAgent added class org.apache.qpid.acl:connectionDeny
        2012-05-17 16:01:37 [Management] debug ManagementAgent added class org.apache.qpid.acl:fileLoaded
        2012-05-17 16:01:37 [Management] debug ManagementAgent added class org.apache.qpid.acl:fileLoadFailed
        2012-05-17 16:01:37 [Management] debug Management object (V1) added: org.apache.qpid.acl:acl:org.apache.qpid.broker:broker:amqp-broker
        2012-05-17 16:01:37 [Security] notice ACL: Read file "/home/chug/svn/qpid/cpp/src/tests/policy.acl"
        2012-05-17 16:01:37 [Security] debug ACL: Group list: 0 groups found:
        2012-05-17 16:01:37 [Security] debug ACL: name list: 1 names found:
        2012-05-17 16:01:37 [Security] debug ACL: *
        2012-05-17 16:01:37 [Security] debug ACL: Rule list: 1 ACL rules found:
        2012-05-17 16:01:37 [Security] debug ACL: 1 allow [*] *
        2012-05-17 16:01:37 [Security] debug ACL: Load Rules
        2012-05-17 16:01:37 [Security] debug ACL: Processing 1 allow [*] *
        2012-05-17 16:01:37 [Security] debug ACL: FoundMode allow
        2012-05-17 16:01:37 [Management] debug SEND raiseEvent (v1) class=org.apache.qpid.acl.fileLoaded
        2012-05-17 16:01:37 [Management] debug SEND raiseEvent (v2) class=org.apache.qpid.acl.fileLoaded
        2012-05-17 16:01:37 [Security] info ACL Plugin loaded
        2012-05-17 16:01:37 [Broker] notice Broker running
        2012-05-17 16:01:42 [IO] debug RECV [[::1]:5672-[::1]:53468]: INIT(0-10)
        2012-05-17 16:01:42 [Security] debug SASL: No Authentication Performed
        2012-05-17 16:01:42 [Broker] debug LinkRegistry::notifyConnection(); key=[::1]:5672-[::1]:53468
        2012-05-17 16:01:42 [Security] trace ACL ConnectionCounter connection IP:[::1]:5672-[::1]:53468, userId:
        2012-05-17 16:01:42 [Management] debug Management object (V1) added: org.apache.qpid.broker:connection:[::1]:5672-[::1]:53468
        2012-05-17 16:01:42 [Amqp] trace SENT [[::1]:5672-[::1]:53468]: INIT(0-10)
        2012-05-17 16:01:42 [Amqp] trace SENT [[::1]:5672-[::1]:53468]: Frame[BEbe; channel=0; {ConnectionStartBody: server-properties=

        {qpid.federation_tag:V2:36:str16(5787d304-441c-4266-9702-11ecc9a521bc)}

        ; mechanisms=str16

        {V2:9:str16(ANONYMOUS), V2:5:str16(PLAIN)}

        ; locales=str16

        {V2:5:str16(en_US)}

        ; }]
        2012-05-17 16:01:42 [Amqp] trace RECV [[::1]:5672-[::1]:53468]: Frame[BEbe; channel=0; {ConnectionStartOkBody: client-properties=

        {platform:V2:5:str16(posix),product:V2:18:str16(qpid python client),qpid.client_pid:F8:int64(28802),qpid.client_ppid:F8:int64(1994),qpid.client_process:V2:9:str16(qpid-tool),version:V2:11:str16(development)}

        ; mechanism=ANONYMOUS; }]
        2012-05-17 16:01:42 [Management] debug SEND raiseEvent (v1) class=org.apache.qpid.broker.clientConnect
        2012-05-17 16:01:42 [Management] debug SEND raiseEvent (v2) class=org.apache.qpid.broker.clientConnect
        2012-05-17 16:01:42 [Amqp] trace SENT [[::1]:5672-[::1]:53468]: Frame[BEbe; channel=0;

        {ConnectionTuneBody: channel-max=32767; max-frame-size=65535; heartbeat-min=0; heartbeat-max=120; }

        ]
        2012-05-17 16:01:42 [Amqp] trace RECV [[::1]:5672-[::1]:53468]: Frame[BEbe; channel=0;

        {ConnectionTuneOkBody: }

        ]
        2012-05-17 16:01:42 [Amqp] trace RECV [[::1]:5672-[::1]:53468]: Frame[BEbe; channel=0;

        {ConnectionOpenBody: }

        ]
        2012-05-17 16:01:42 [Security] trace ACL ConnectionCounter Opened IP:[::1]:5672-[::1]:53468, userId:anonymous
        2012-05-17 16:01:42 [Amqp] trace SENT [[::1]:5672-[::1]:53468]: Frame[BEbe; channel=0; {ConnectionOpenOkBody: known-hosts=str16

        {V2:49:str16(amqp:tcp:10.16.185.91:5672,tcp:192.168.122.1:5672)}

        ; }]
        2012-05-17 16:01:42 [Amqp] trace RECV [[::1]:5672-[::1]:53468]: Frame[BEbe; channel=1;

        {SessionAttachBody: name=ummmm.28802.1; }

        ]
        2012-05-17 16:01:42 [Broker] debug SessionState::SessionState anonymous.ummmm.28802.1: 0x7ffff0044960
        2012-05-17 16:01:42 [Management] debug Management object (V1) added: org.apache.qpid.broker:session:ummmm.28802.1
        2012-05-17 16:01:42 [Broker] debug anonymous.ummmm.28802.1: attached on broker.
        2012-05-17 16:01:42 [Amqp] debug Attached channel 1 to anonymous.ummmm.28802.1
        2012-05-17 16:01:42 [Broker] debug anonymous.ummmm.28802.1: ready to send, activating output.

        Show
        Chuck Rolke added a comment - I've attached a tab-delimited text file suitable for viewing in a spreadsheet. It shows the "category" as derived from the source file path and name. The categorization appears to be usable as-is but any QPID_LOG message can be adjusted to having any category. Internally the category is derived with a series of awful string compares. But this is done only once for each log entry statement when it is first instantiated. The net result of work in this branch produces calculated categories that make a broker log appear like this: 2012-05-17 16:01:37 [IO] info Listening to: 0.0.0.0:5672 2012-05-17 16:01:37 [IO] debug Listened to: 5672 2012-05-17 16:01:37 [IO] info Listening to: [::] :5672 2012-05-17 16:01:37 [IO] debug Listened to: 5672 2012-05-17 16:01:37 [IO] notice Listening on TCP/TCP6 port 5672 2012-05-17 16:01:37 [Management] debug ManagementAgent added package org.apache.qpid.acl 2012-05-17 16:01:37 [Management] debug SEND PackageInd package=org.apache.qpid.acl to=schema.package 2012-05-17 16:01:37 [Management] debug ManagementAgent added class org.apache.qpid.acl:acl 2012-05-17 16:01:37 [Management] debug ManagementAgent added class org.apache.qpid.acl:allow 2012-05-17 16:01:37 [Management] debug ManagementAgent added class org.apache.qpid.acl:deny 2012-05-17 16:01:37 [Management] debug ManagementAgent added class org.apache.qpid.acl:connectionDeny 2012-05-17 16:01:37 [Management] debug ManagementAgent added class org.apache.qpid.acl:fileLoaded 2012-05-17 16:01:37 [Management] debug ManagementAgent added class org.apache.qpid.acl:fileLoadFailed 2012-05-17 16:01:37 [Management] debug Management object (V1) added: org.apache.qpid.acl:acl:org.apache.qpid.broker:broker:amqp-broker 2012-05-17 16:01:37 [Security] notice ACL: Read file "/home/chug/svn/qpid/cpp/src/tests/policy.acl" 2012-05-17 16:01:37 [Security] debug ACL: Group list: 0 groups found: 2012-05-17 16:01:37 [Security] debug ACL: name list: 1 names found: 2012-05-17 16:01:37 [Security] debug ACL: * 2012-05-17 16:01:37 [Security] debug ACL: Rule list: 1 ACL rules found: 2012-05-17 16:01:37 [Security] debug ACL: 1 allow [*] * 2012-05-17 16:01:37 [Security] debug ACL: Load Rules 2012-05-17 16:01:37 [Security] debug ACL: Processing 1 allow [*] * 2012-05-17 16:01:37 [Security] debug ACL: FoundMode allow 2012-05-17 16:01:37 [Management] debug SEND raiseEvent (v1) class=org.apache.qpid.acl.fileLoaded 2012-05-17 16:01:37 [Management] debug SEND raiseEvent (v2) class=org.apache.qpid.acl.fileLoaded 2012-05-17 16:01:37 [Security] info ACL Plugin loaded 2012-05-17 16:01:37 [Broker] notice Broker running 2012-05-17 16:01:42 [IO] debug RECV [ [::1] :5672- [::1] :53468]: INIT(0-10) 2012-05-17 16:01:42 [Security] debug SASL: No Authentication Performed 2012-05-17 16:01:42 [Broker] debug LinkRegistry::notifyConnection(); key= [::1] :5672- [::1] :53468 2012-05-17 16:01:42 [Security] trace ACL ConnectionCounter connection IP: [::1] :5672- [::1] :53468, userId: 2012-05-17 16:01:42 [Management] debug Management object (V1) added: org.apache.qpid.broker:connection: [::1] :5672- [::1] :53468 2012-05-17 16:01:42 [Amqp] trace SENT [ [::1] :5672- [::1] :53468]: INIT(0-10) 2012-05-17 16:01:42 [Amqp] trace SENT [ [::1] :5672- [::1] :53468]: Frame[BEbe; channel=0; {ConnectionStartBody: server-properties= {qpid.federation_tag:V2:36:str16(5787d304-441c-4266-9702-11ecc9a521bc)} ; mechanisms=str16 {V2:9:str16(ANONYMOUS), V2:5:str16(PLAIN)} ; locales=str16 {V2:5:str16(en_US)} ; }] 2012-05-17 16:01:42 [Amqp] trace RECV [ [::1] :5672- [::1] :53468]: Frame[BEbe; channel=0; {ConnectionStartOkBody: client-properties= {platform:V2:5:str16(posix),product:V2:18:str16(qpid python client),qpid.client_pid:F8:int64(28802),qpid.client_ppid:F8:int64(1994),qpid.client_process:V2:9:str16(qpid-tool),version:V2:11:str16(development)} ; mechanism=ANONYMOUS; }] 2012-05-17 16:01:42 [Management] debug SEND raiseEvent (v1) class=org.apache.qpid.broker.clientConnect 2012-05-17 16:01:42 [Management] debug SEND raiseEvent (v2) class=org.apache.qpid.broker.clientConnect 2012-05-17 16:01:42 [Amqp] trace SENT [ [::1] :5672- [::1] :53468]: Frame[BEbe; channel=0; {ConnectionTuneBody: channel-max=32767; max-frame-size=65535; heartbeat-min=0; heartbeat-max=120; } ] 2012-05-17 16:01:42 [Amqp] trace RECV [ [::1] :5672- [::1] :53468]: Frame[BEbe; channel=0; {ConnectionTuneOkBody: } ] 2012-05-17 16:01:42 [Amqp] trace RECV [ [::1] :5672- [::1] :53468]: Frame[BEbe; channel=0; {ConnectionOpenBody: } ] 2012-05-17 16:01:42 [Security] trace ACL ConnectionCounter Opened IP: [::1] :5672- [::1] :53468, userId:anonymous 2012-05-17 16:01:42 [Amqp] trace SENT [ [::1] :5672- [::1] :53468]: Frame[BEbe; channel=0; {ConnectionOpenOkBody: known-hosts=str16 {V2:49:str16(amqp:tcp:10.16.185.91:5672,tcp:192.168.122.1:5672)} ; }] 2012-05-17 16:01:42 [Amqp] trace RECV [ [::1] :5672- [::1] :53468]: Frame[BEbe; channel=1; {SessionAttachBody: name=ummmm.28802.1; } ] 2012-05-17 16:01:42 [Broker] debug SessionState::SessionState anonymous.ummmm.28802.1: 0x7ffff0044960 2012-05-17 16:01:42 [Management] debug Management object (V1) added: org.apache.qpid.broker:session:ummmm.28802.1 2012-05-17 16:01:42 [Broker] debug anonymous.ummmm.28802.1: attached on broker. 2012-05-17 16:01:42 [Amqp] debug Attached channel 1 to anonymous.ummmm.28802.1 2012-05-17 16:01:42 [Broker] debug anonymous.ummmm.28802.1: ready to send, activating output.
        Hide
        Alan Conway added a comment -

        The existing scheme has the advantage of being open-ended. As new plugins or features are added you can log them selectively. I think we want to allow each plugin or feature to specify a category string so that we keep the open-endedness.

        The broker could compile an integer index of all the registered log categories at run time and use those indexes rather than string comparisons to test log messages - that would be a big improvement over existing substring match.

        Show
        Alan Conway added a comment - The existing scheme has the advantage of being open-ended. As new plugins or features are added you can log them selectively. I think we want to allow each plugin or feature to specify a category string so that we keep the open-endedness. The broker could compile an integer index of all the registered log categories at run time and use those indexes rather than string comparisons to test log messages - that would be a big improvement over existing substring match.

          People

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

            Dates

            • Created:
              Updated:
              Resolved:

              Development