Uploaded image for project: 'Couchbase Server'
  1. Couchbase Server
  2. MB-48655

DCP client with { or } in the name doesn't log DCP messages in memcached log

    XMLWordPrintable

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Fixed
    • 6.6.2, 7.0.0, 6.6.3, 7.0.2, 7.0.1
    • 7.1.0
    • couchbase-bucket
    • None
    • Triaged
    • 1
    • Unknown

    Description

      Observed that the kafka DCP connector connected, created a DCP producer and associated streams, yet none of this activity was logged.

      This occurs because the DCP name chosen includes "{" and "}" and that fails to log

      This is an issue for 6 and 7 but appears fixed in 7.1

      Attachments

        Issue Links

          For Gerrit Dashboard: MB-48655
          # Subject Branch Project Status CR V

          Activity

            jwalker Jim Walker created issue -
            jwalker Jim Walker made changes -
            Field Original Value New Value
            Link This issue is caused by CBSE-10781 [ CBSE-10781 ]
            jwalker Jim Walker added a comment -

            Reproduce with 6.6.3 and the following name

            eq_dcpq:{"i":"540AA7A2EA8ED9FE/D6558E4C4AA86D91","a":"kafka-connector/4.0.6 (test-couchbase-source) java-dcp-client/0.34.0 Java/17 (Homebrew; OpenJDK 64-Bit Server VM; 17+0) OS (Mac OS X; 10.15.7; x86_64)"}
            

            I see no stream request messages, but do have a connector and some backfill messages (logged with EP_LOG_INFO)

            jwalker Jim Walker added a comment - Reproduce with 6.6.3 and the following name eq_dcpq:{"i":"540AA7A2EA8ED9FE/D6558E4C4AA86D91","a":"kafka-connector/4.0.6 (test-couchbase-source) java-dcp-client/0.34.0 Java/17 (Homebrew; OpenJDK 64-Bit Server VM; 17+0) OS (Mac OS X; 10.15.7; x86_64)"} I see no stream request messages, but do have a connector and some backfill messages (logged with EP_LOG_INFO)
            jwalker Jim Walker added a comment -

            The kafka name which becomes the log prefix for the DCP logging upsets spdlog, in babysitter

            [*** LOG ERROR ***] [2021-09-29 09:32:00] [travel-sample.139713464761872] invalid format string
            

            jwalker Jim Walker added a comment - The kafka name which becomes the log prefix for the DCP logging upsets spdlog, in babysitter [*** LOG ERROR ***] [2021-09-29 09:32:00] [travel-sample.139713464761872] invalid format string
            jwalker Jim Walker made changes -
            Assignee Daniel Owen [ owend ] Jim Walker [ jwalker ]
            jwalker Jim Walker added a comment -

            Not yet reproducible in master (currently have a neo checkout), this could be fixed in a recent spdlog/fmtlib - to be confirmed

            jwalker Jim Walker added a comment - Not yet reproducible in master (currently have a neo checkout), this could be fixed in a recent spdlog/fmtlib - to be confirmed
            jwalker Jim Walker added a comment -

            Tested following names (using dcpdrain)

            • jim
            • {jim}
            • jim}
            • {jim

            So the use of { means we fail to log

            jwalker Jim Walker added a comment - Tested following names (using dcpdrain) jim { jim } jim } { jim So the use of { means we fail to log
            jwalker Jim Walker added a comment -

            7.0 fails as well, more detail in babysitter

            [ns_server:info,2021-09-29T10:41:47.352Z,babysitter_of_ns_1@cb.local:<0.129.0>:ns_port_server:log:221]memcached<0.129.0>: [*** LOG ERROR ***] [2021-09-29 10:41:47] [travel-sample.139658720304192] unmatched '}' in format string
            

            jwalker Jim Walker added a comment - 7.0 fails as well, more detail in babysitter [ns_server:info,2021-09-29T10:41:47.352Z,babysitter_of_ns_1@cb.local:<0.129.0>:ns_port_server:log:221]memcached<0.129.0>: [*** LOG ERROR ***] [2021-09-29 10:41:47] [travel-sample.139658720304192] unmatched '}' in format string
            jwalker Jim Walker made changes -
            Summary Kafka connector doesn't log expected DCP messages in memcached log DCP client with { or } in the name doesn't log DCP messages in memcached log
            jwalker Jim Walker made changes -
            Description Observed that the kafka DCP connector connected, created a DCP producer and associated streams, yet none of this activity was logged.

            The observed behaviour was very much as if it triggered the following FTS 'suppression' code that is present in 6.6.x

            https://github.com/couchbase/kv_engine/blob/v6.6.3/engines/ep/src/dcp/producer.cc#L211-L224

            * We do not see any {{logger->log}} messages
            * We do see some EP_LOG_WARN/EP_LOG_INFO messages (which are not subject to the suppression.

            Yet all observable information about the connection's DCP name suggests this clause should not have triggered.

            * From stats.log the producer's name does not contain {{eq_dcpq:fts}} which the code states is the search string (not copied the producer name here as it contains PII)


             
            Observed that the kafka DCP connector connected, created a DCP producer and associated streams, yet none of this activity was logged.

            This occurs because the DCP name chosen includes "{" and "}" and that fails to log

            This is an issue for 6 and 7 but appears fixed in 7.1
            jwalker Jim Walker made changes -
            Description Observed that the kafka DCP connector connected, created a DCP producer and associated streams, yet none of this activity was logged.

            This occurs because the DCP name chosen includes "{" and "}" and that fails to log

            This is an issue for 6 and 7 but appears fixed in 7.1
            Observed that the kafka DCP connector connected, created a DCP producer and associated streams, yet none of this activity was logged.

            This occurs because the DCP name chosen includes "\{" and "\}" and that fails to log

            This is an issue for 6 and 7 but appears fixed in 7.1
            jwalker Jim Walker added a comment -

            Fine in 7.1 (neo checked 7.1.0-1378)

            jwalker Jim Walker added a comment - Fine in 7.1 (neo checked 7.1.0-1378)
            jwalker Jim Walker made changes -
            Affects Version/s 7.0.1 [ 17104 ]
            Affects Version/s 7.0.0 [ 17233 ]
            Affects Version/s 6.6.2 [ 17103 ]
            Affects Version/s 7.0.2 [ 18012 ]
            tim.bradgate Tim Bradgate (Inactive) made changes -
            Link This issue causes KAFKAC-270 [ KAFKAC-270 ]
            drigby Dave Rigby made changes -
            Priority Minor [ 4 ] Major [ 3 ]
            drigby Dave Rigby added a comment -

            Bumping to major - for the versions which this affects; does cause issues in understanding what the DCP client is doing.

            drigby Dave Rigby added a comment - Bumping to major - for the versions which this affects; does cause issues in understanding what the DCP client is doing.
            drigby Dave Rigby made changes -
            Fix Version/s Neo [ 17615 ]
            drigby Dave Rigby added a comment -

            "Fixed" in Neo (the code in that area has changed and the '{' is escaped correctly). Resolving as this doesn't meet the criteria for backporting to previous releases.

            drigby Dave Rigby added a comment - "Fixed" in Neo (the code in that area has changed and the '{' is escaped correctly). Resolving as this doesn't meet the criteria for backporting to previous releases.
            drigby Dave Rigby made changes -
            Triage Untriaged [ 10351 ] Triaged [ 10350 ]
            Resolution Fixed [ 1 ]
            Status Open [ 1 ] Resolved [ 5 ]
            ritam.sharma Ritam Sharma made changes -
            Assignee Jim Walker [ jwalker ] Arunkumar Senthilnathan [ arunkumar ]
            ritam.sharma Ritam Sharma added a comment -

            Arunkumar Senthilnathan - Can one of your team member validate it from Kafka.

            ritam.sharma Ritam Sharma added a comment - Arunkumar Senthilnathan  - Can one of your team member validate it from Kafka.
            owend Daniel Owen made changes -
            Link This issue is triggering CBSE-11257 [ CBSE-11257 ]
            owend Daniel Owen made changes -
            Link This issue relates to CBSE-11255 [ CBSE-11255 ]
            James Flather James Flather (Inactive) made changes -
            Link This issue blocks CBSE-10897 [ CBSE-10897 ]
            arunkumar Arunkumar Senthilnathan (Inactive) made changes -
            Assignee Arunkumar Senthilnathan [ arunkumar ] Praneeth Bokka [ praneeth.bokka ]

            Verified with Enterprise Edition 7.1.0 build 2534 and we can see the Kafka DCP logs now:

            2022-03-28T08:09:20.758038-07:00 WARNING 80: (travel-sample) DCP (Producer) eq_dcpq:"i":"0B4C9109E91C764F/E5685E7FE807F790","a":"kafka-connector/4.1.6 (test-couchbase-source) java-dcp-client/0.40.0 Java/17.0.2 (Oracle Corporation; OpenJDK 64-Bit Server VM; 17.0.2+8-86) OS (Mac OS" - (vb:63) Stream closing, sent until seqno 963 remaining items 0, reason: The stream closed early because the conn was disconnected
            2022-03-28T08:09:21.560752-07:00 INFO 82: (travel-sample) DCP (Producer) eq_dcpq:"i":"0B4C9109E91C764F/81DE1ED0CEDBEE0C","a":"kafka-connector/4.1.6 (test-couchbase-source) java-dcp-client/0.40.0 Java/17.0.2 (Oracle Corporation; OpenJDK 64-Bit Server VM; 17.0.2+8-86) OS (Mac OS" - Destroying connection. Created 33 s ago. Paused 301 times, for 32 s total. Details: {"Initializing": {"count":1, "duration":"146 us"},"ReadyListEmpty": {"count":300, "duration":"32 s"}}
            2022-03-28T08:09:21.560787-07:00 INFO 80: (travel-sample) DCP (Producer) eq_dcpq:"i":"0B4C9109E91C764F/E5685E7FE807F790","a":"kafka-connector/4.1.6 (test-couchbase-source) java-dcp-client/0.40.0 Java/17.0.2 (Oracle Corporation; OpenJDK 64-Bit Server VM; 17.0.2+8-86) OS (Mac OS" - Destroying connection. Created 33 s ago. Paused 279 times, for 31 s total. Details: {"Initializing": {"count":1, "duration":"16 us"},"ReadyListEmpty": {"count":278, "duration":"31 s"}}

            praneeth.bokka Praneeth Bokka (Inactive) added a comment - Verified with Enterprise Edition 7.1.0 build 2534 and we can see the Kafka DCP logs now: 2022-03-28T08:09:20.758038-07:00 WARNING 80: (travel-sample) DCP (Producer) eq_dcpq:"i":"0B4C9109E91C764F/E5685E7FE807F790","a":"kafka-connector/4.1.6 (test-couchbase-source) java-dcp-client/0.40.0 Java/17.0.2 (Oracle Corporation; OpenJDK 64-Bit Server VM; 17.0.2+8-86) OS (Mac OS" - (vb:63) Stream closing, sent until seqno 963 remaining items 0, reason: The stream closed early because the conn was disconnected 2022-03-28T08:09:21.560752-07:00 INFO 82: (travel-sample) DCP (Producer) eq_dcpq:"i":"0B4C9109E91C764F/81DE1ED0CEDBEE0C","a":"kafka-connector/4.1.6 (test-couchbase-source) java-dcp-client/0.40.0 Java/17.0.2 (Oracle Corporation; OpenJDK 64-Bit Server VM; 17.0.2+8-86) OS (Mac OS" - Destroying connection. Created 33 s ago. Paused 301 times, for 32 s total. Details: {"Initializing": {"count":1, "duration":"146 us"},"ReadyListEmpty": {"count":300, "duration":"32 s"}} 2022-03-28T08:09:21.560787-07:00 INFO 80: (travel-sample) DCP (Producer) eq_dcpq:"i":"0B4C9109E91C764F/E5685E7FE807F790","a":"kafka-connector/4.1.6 (test-couchbase-source) java-dcp-client/0.40.0 Java/17.0.2 (Oracle Corporation; OpenJDK 64-Bit Server VM; 17.0.2+8-86) OS (Mac OS" - Destroying connection. Created 33 s ago. Paused 279 times, for 31 s total. Details: {"Initializing": {"count":1, "duration":"16 us"},"ReadyListEmpty": {"count":278, "duration":"31 s"}}
            praneeth.bokka Praneeth Bokka (Inactive) made changes -
            Status Resolved [ 5 ] Closed [ 6 ]

            People

              praneeth.bokka Praneeth Bokka (Inactive)
              jwalker Jim Walker
              Votes:
              0 Vote for this issue
              Watchers:
              8 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Gerrit Reviews

                  There are no open Gerrit changes

                  PagerDuty