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

Always emit the first exception to the application log then summarize

    XMLWordPrintable

Details

    • Untriaged
    • 1
    • Unknown

    Description

      The developer experience for logging exceptions to the Application log (MB-31920) is poor.
       
      Right now when in a dev cycle working on a new script it is a bit perplexing when you wait on average 30 seconds (and up to 60 seconds) to see the exception (along with a count) be emitted.

      • We could always the very first message, i.e. count===1 immediately the first time we see the exception after any deployment or any resume.
      • Then we fall back to the current behaviour of summarization only on count === 2-N ( or minute two+ on 1-N) summarize and emit once per minute. 

       
      This would speed up initial debug feedback to the developer for quicker understanding of the issue and still limit overwhelming logging.
       

      Attachments

        Issue Links

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

          Activity

            Jeelan Poola, Jon Strabala:

            Made changes to accommodate this. Logs will appear as listed below:

             

            2021-04-26T13:58:52.906+05:30 [INFO] "Doc created/updated" "02-triggerReferenceError-0023"
            2021-04-26T13:58:52.907+05:30 [INFO] {"exception":"\"ReferenceError: b is not defined\"","file":"f01.js","line":24,"srcLine":"b()","stack":"ReferenceError: b is not defined\n    at triggerReferenceError02 (f01.js:25:5)\n    at OnUpdate (f01.js:8:9)"}
            

             

            The "Doc created/updated" msg will appear if such a log call is present in the App / Function, not otherwise.

             

            A couple comments:

            1. Regarding mention of "the very first message, i.e. count===1 immediately the first time" above - the count is reset once every logging period (60 seconds). This is not a only once per lifetime of the app deployment, but once per logging period.
            2. The 'first occurrence' of the exception is at a thread level, not a consumer level. If every consumer has 2 threads, then this could appear upto 2 times, if both the worker thread got a mutation that resulted in a given exception.

             

            Thanks!

             

            srinivasan.raman Srinivasan Raman added a comment - Jeelan Poola , Jon Strabala : Made changes to accommodate this. Logs will appear as listed below:   2021 - 04 -26T13: 58 : 52.906 + 05 : 30 [INFO] "Doc created/updated" "02-triggerReferenceError-0023" 2021 - 04 -26T13: 58 : 52.907 + 05 : 30 [INFO] { "exception" : "\"ReferenceError: b is not defined\"" , "file" : "f01.js" , "line" : 24 , "srcLine" : "b()" , "stack" : "ReferenceError: b is not defined\n    at triggerReferenceError02 (f01.js:25:5)\n    at OnUpdate (f01.js:8:9)" }   The "Doc created/updated" msg will appear if such a log call is present in the App / Function, not otherwise.   A couple comments: Regarding mention of "the very first message, i.e. count===1 immediately the first time" above - the count is reset once every logging period (60 seconds). This is not a only once per lifetime of the app deployment, but once per logging period. The 'first occurrence' of the exception is at a thread level, not a consumer level. If every consumer has 2 threads, then this could appear upto 2 times, if both the worker thread got a mutation that resulted in a given exception.   Thanks!  
            jeelan.poola Jeelan Poola added a comment -

            Ideally, we would like to do this cleanly with 'log-first-exception-since-deployment-only-once' approach rather than the quick 'log-first-exception-since-last-periodic-reset-once' approach. Hence deferring it to 7.0.1.

            jeelan.poola Jeelan Poola added a comment - Ideally, we would like to do this cleanly with 'log-first-exception-since-deployment-only-once' approach rather than the quick 'log-first-exception-since-last-periodic-reset-once' approach. Hence deferring it to 7.0.1.
            jon.strabala Jon Strabala added a comment -

            Keep in mind the summarize then log is already "chatty" as in one message per thread.  IMHO the additional messages that happen at the time of the initial issue are very useful - and the additional messages are acceptable until such time we collese them down to one message per node.

            jon.strabala Jon Strabala added a comment - Keep in mind the summarize then log is already "chatty" as in one message per thread.  IMHO the additional messages that happen at the time of the initial issue are very useful - and the additional messages are acceptable until such time we collese them down to one message per node.
            jeelan.poola Jeelan Poola added a comment -

            Ritam SharmaChanabasappa Ghali The fix here is good for developer experience. User does not have to wait for 30 secs to see the first occurrence of an exception in his code. We have a patch in-flight. Request inclusion in 7.0.1. Thank you!

            jeelan.poola Jeelan Poola added a comment - Ritam Sharma Chanabasappa Ghali The fix here is good for developer experience. User does not have to wait for 30 secs to see the first occurrence of an exception in his code. We have a patch in-flight. Request inclusion in 7.0.1. Thank you!
            ritam.sharma Ritam Sharma added a comment -

            Srinivasan Raman Jeelan Poola - We can take this for 7.0.2

            ritam.sharma Ritam Sharma added a comment - Srinivasan Raman Jeelan Poola - We can take this for 7.0.2

            Build couchbase-server-7.1.0-1157 contains eventing commit 3d67baf with commit message:
            MB-45874: New exceptions once every logging period by each thread

            build-team Couchbase Build Team added a comment - Build couchbase-server-7.1.0-1157 contains eventing commit 3d67baf with commit message: MB-45874 : New exceptions once every logging period by each thread

            Build couchbase-server-7.0.2-6531 contains eventing commit 7ce7ca1 with commit message:
            MB-45874: New exceptions once every logging period by each thread

            build-team Couchbase Build Team added a comment - Build couchbase-server-7.0.2-6531 contains eventing commit 7ce7ca1 with commit message: MB-45874 : New exceptions once every logging period by each thread
            sujay.gad Sujay Gad added a comment - - edited

            Verified using 7.0.2 - 6578.
            User no longer has to be wait 30 seconds on average to see the first exception and first exception can occur maximum 2 times. Following exceptions are summarized once per minute.

            2021-08-26T08:33:45.889+00:00 [INFO] {"count":100,"exception":"{\n  \"message\": \"LCB_ERR_UNSUPPORTED_OPERATION (214)\",\n  \"stack\": \"Error\\n    at OnUpdate (test.js:3:13)\"\n}","file":"test.js","line":2,"since":"2021-08-26T08:32:56","srcLine":"var q = N1QL('SELECT * FROM dst_bucket1;', {}, { 'consistency': 'none' });","stack":"Error\n    at OnUpdate (test.js:3:13)"}
             
            2021-08-26T08:32:56.935+00:00 [INFO] {"exception":"{\n  \"message\": \"LCB_ERR_UNSUPPORTED_OPERATION (214)\",\n  \"stack\": \"Error\\n    at OnUpdate (test.js:3:13)\"\n}","file":"test.js","line":2,"srcLine":"var q = N1QL('SELECT * FROM dst_bucket1;', {}, { 'consistency': 'none' });","stack":"Error\n    at OnUpdate (test.js:3:13)"}
             
            2021-08-26T08:32:56.932+00:00 [INFO] {"exception":"{\n  \"message\": \"LCB_ERR_UNSUPPORTED_OPERATION (214)\",\n  \"stack\": \"Error\\n    at OnUpdate (test.js:3:13)\"\n}","file":"test.js","line":2,"srcLine":"var q = N1QL('SELECT * FROM dst_bucket1;', {}, { 'consistency': 'none' });","stack":"Error\n    at OnUpdate (test.js:3:13)"}
            

            sujay.gad Sujay Gad added a comment - - edited Verified using 7.0.2 - 6578. User no longer has to be wait 30 seconds on average to see the first exception and first exception can occur maximum 2 times. Following exceptions are summarized once per minute. 2021 - 08 -26T08: 33 : 45.889 + 00 : 00 [INFO] { "count" : 100 , "exception" : "{\n \"message\": \"LCB_ERR_UNSUPPORTED_OPERATION (214)\",\n \"stack\": \"Error\\n at OnUpdate (test.js:3:13)\"\n}" , "file" : "test.js" , "line" : 2 , "since" : "2021-08-26T08:32:56" , "srcLine" : "var q = N1QL('SELECT * FROM dst_bucket1;', {}, { 'consistency': 'none' });" , "stack" : "Error\n at OnUpdate (test.js:3:13)" }   2021 - 08 -26T08: 32 : 56.935 + 00 : 00 [INFO] { "exception" : "{\n \"message\": \"LCB_ERR_UNSUPPORTED_OPERATION (214)\",\n \"stack\": \"Error\\n at OnUpdate (test.js:3:13)\"\n}" , "file" : "test.js" , "line" : 2 , "srcLine" : "var q = N1QL('SELECT * FROM dst_bucket1;', {}, { 'consistency': 'none' });" , "stack" : "Error\n at OnUpdate (test.js:3:13)" }   2021 - 08 -26T08: 32 : 56.932 + 00 : 00 [INFO] { "exception" : "{\n \"message\": \"LCB_ERR_UNSUPPORTED_OPERATION (214)\",\n \"stack\": \"Error\\n at OnUpdate (test.js:3:13)\"\n}" , "file" : "test.js" , "line" : 2 , "srcLine" : "var q = N1QL('SELECT * FROM dst_bucket1;', {}, { 'consistency': 'none' });" , "stack" : "Error\n at OnUpdate (test.js:3:13)" }

            People

              srinivasan.raman Srinivasan Raman
              jon.strabala Jon Strabala
              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