PCBC-410: consolidate LCB and extension logging

Change-Id: Ia116a628efc977072d1c5abf600f1c181a847833
Reviewed-on: http://review.couchbase.org/67006
Tested-by: buildbot <build@couchbase.com>
Reviewed-by: Sergey Avseyev <sergey.avseyev@gmail.com>

Author: avsej

.clang-format

@@ -0,0 +1,5 @@
+# -*- mode: yaml; -*-
+
+BasedOnStyle: LLVM
+IndentWidth: 4
+BreakBeforeBraces: Linux

bucket.c

@@ -28,6 +28,9 @@
 #include "transcoding.h"
 #include "opcookie.h"
 
+extern struct pcbc_logger_st pcbc_logger;
+#define LOGARGS(instance, lvl) LCB_LOG_##lvl, instance, "pcbc/bucket", __FILE__, __LINE__
+
 zap_class_entry bucket_class;
 zend_class_entry *bucket_ce;
 char *pcbc_client_string = "PCBC/"PHP_COUCHBASE_VERSION;
@@ -176,6 +179,15 @@ PHP_METHOD(Bucket, __construct)
             throw_lcb_exception(err);
             RETURN_NULL();
         }
+        pcbc_log(LOGARGS(instance, INFO), "New lcb_t instance has been initialized");
+        err = lcb_cntl(instance, LCB_CNTL_SET, LCB_CNTL_LOGGER, &pcbc_logger);
+        if (err != LCB_SUCCESS) {
+            efree(connkey);
+            efree(name);
+            throw_lcb_exception(err);
+            RETURN_NULL();
+        }
+
         lcb_cntl(instance, LCB_CNTL_SET, LCB_CNTL_CLIENT_STRING, pcbc_client_string);
 
         lcb_install_callback3(instance, LCB_CALLBACK_GET, get_callback);
@@ -228,12 +240,14 @@ PHP_METHOD(Bucket, __construct)
             PCBCG(first_bconn) = conn;
             PCBCG(last_bconn) = conn;
         }
+        pcbc_log(LOGARGS(instance, INFO), "lcb_t instance has been connected");
     } else {
         if (dsn) efree(dsn);
         if (name) efree(name);
         if (password) efree(password);
 
         data->conn = conn_iter;
+        pcbc_log(LOGARGS(data->conn->lcb, INFO), "lcb_t instance has been fetched from cache");
     }
 
     efree(connkey);

bucket.h

@@ -52,11 +52,11 @@ typedef struct bucket_object {
 
 #define PCBC_PHP_THISOBJ() zap_fetch_this(bucket_object)
 
-#define pcbc_assert_number_of_commands(cmd, nscheduled, ntotal)         \
+#define pcbc_assert_number_of_commands(lcb, cmd, nscheduled, ntotal)    \
     if (nscheduled != ntotal) {                                         \
-        php_error_docref(NULL TSRMLS_CC, E_WARNING,                     \
-                         "Failed to schedule %s commands (%d out of %d sent)", \
-                         cmd, nscheduled, ntotal);                      \
+        pcbc_log(LOGARGS(lcb, ERROR),                                   \
+                 "Failed to schedule %s commands (%d out of %d sent)",  \
+                 cmd, nscheduled, ntotal);                              \
     }
 
 zval* bop_get_return_doc(zval *return_value, zapval *key, int is_mapped);

cbft.c

@@ -27,6 +27,8 @@
 #include "transcoding.h"
 #include "opcookie.h"
 
+#define LOGARGS(instance, lvl) LCB_LOG_##lvl, instance, "pcbc/cbft", __FILE__, __LINE__
+
 typedef struct {
     opcookie_res header;
     lcb_U16 rflags;
@@ -40,11 +42,8 @@ static void ftsrow_callback(lcb_t instance, int ignoreme, const lcb_RESPFTS *res
 
     result->header.err = resp->rc;
     if (result->header.err == LCB_HTTP_ERROR) {
-        php_error_docref(NULL TSRMLS_CC, E_WARNING,
-                         "failed to search in index. %d: %.*s",
-                         (int)resp->htresp->htstatus,
-                         (int)resp->nrow,
-                         (char *)resp->row);
+        pcbc_log(LOGARGS(instance, ERROR), "Failed to search in index. %d: %.*s",
+                         (int)resp->htresp->htstatus, (int)resp->nrow, (char *)resp->row);
     }
     result->rflags = resp->rflags;
     zapval_alloc_stringl(result->row, resp->row, resp->nrow);

config.m4

@@ -37,7 +37,7 @@ if test "$PHP_COUCHBASE" != "no"; then
 
   PHP_SUBST(COUCHBASE_SHARED_LIBADD)
 
-  COUCHBASE_FILES="bucket.c cas.c cluster.c couchbase.c docfrag.c exception.c get.c unlock.c metadoc.c opcookie.c paramparser.c transcoding.c touch.c remove.c subdoc.c store.c n1ql.c http.c counter.c durability.c n1ix_spec.c n1ix_list.c n1ix_create.c n1ix_drop.c cbft.c token.c"
+  COUCHBASE_FILES="bucket.c cas.c cluster.c couchbase.c docfrag.c exception.c get.c unlock.c metadoc.c opcookie.c paramparser.c transcoding.c touch.c remove.c subdoc.c store.c n1ql.c http.c counter.c durability.c n1ix_spec.c n1ix_list.c n1ix_create.c n1ix_drop.c cbft.c token.c log.c"
 
   if test "$PHP_SYSTEM_FASTLZ" != "no"; then
     AC_CHECK_HEADERS([fastlz.h])

config.w32

@@ -13,6 +13,7 @@ if (PHP_COUCHBASE != "no") {
         "exception.c " +
         "get.c " +
         "http.c " +
+        "log.c " +
         "metadoc.c " +
         "n1ix_create.c " +
         "n1ix_drop.c " +

couchbase.c

@@ -34,11 +34,53 @@
 #include <zlib.h>
 #endif
 
+#define LOGARGS(lvl) LCB_LOG_##lvl, NULL, "pcbc/ext", __FILE__, __LINE__
+
 typedef unsigned char uint8_t;
 typedef unsigned int uint32_t;
 
 ZEND_DECLARE_MODULE_GLOBALS(couchbase)
 
+extern struct pcbc_logger_st pcbc_logger;
+
+static PHP_INI_MH(OnUpdateLogLevel)
+{
+    const char *str_val =
+#if PHP_VERSION_ID >= 70000
+        ZSTR_VAL(new_value);
+#else
+        new_value;
+#endif
+    if (!new_value) {
+        pcbc_logger.minlevel = LCB_LOG_WARN;
+    } else if (!strcmp(new_value, "TRACE") || !strcmp(new_value, "TRAC")) {
+        pcbc_logger.minlevel = LCB_LOG_TRACE;
+    } else if (!strcmp(new_value, "DEBUG") || !strcmp(new_value, "DEBG")) {
+        pcbc_logger.minlevel = LCB_LOG_DEBUG;
+    } else if (!strcmp(new_value, "INFO")) {
+        pcbc_logger.minlevel = LCB_LOG_INFO;
+    } else if (!strcmp(new_value, "WARN")) {
+        pcbc_logger.minlevel = LCB_LOG_WARN;
+    } else if (!strcmp(new_value, "ERROR") || !strcmp(new_value, "EROR")) {
+        pcbc_logger.minlevel = LCB_LOG_ERROR;
+    } else if (!strcmp(new_value, "FATAL") || !strcmp(new_value, "FATL")) {
+        pcbc_logger.minlevel = LCB_LOG_FATAL;
+    } else {
+        return FAILURE;
+    }
+
+#if PHP_VERSION_ID >= 70000
+    return OnUpdateString(entry, new_value, mh_arg1, mh_arg2, mh_arg3, stage);
+#else
+    return OnUpdateString(entry, new_value, new_value_length, mh_arg1, mh_arg2, mh_arg3, stage TSRMLS_CC);
+#endif
+}
+
+PHP_INI_BEGIN()
+STD_PHP_INI_ENTRY(PCBC_INIENT_LOG_LEVEL, PCBC_INIDFL_LOG_LEVEL, PHP_INI_ALL,
+                  OnUpdateLogLevel, log_level, zend_couchbase_globals, couchbase_globals)
+PHP_INI_END()
+
 #define PCBC_LONG_CONSTANT(key, val) \
 	REGISTER_LONG_CONSTANT("COUCHBASE_"key, val, CONST_CS | CONST_PERSISTENT)
 #define PCBC_REGISTER_CONST(c) \
@@ -55,6 +97,7 @@ static void php_extname_init_globals(zend_couchbase_globals *couchbase_globals)
 PHP_MINIT_FUNCTION(couchbase)
 {
 	ZEND_INIT_MODULE_GLOBALS(couchbase, php_extname_init_globals, NULL);
+        REGISTER_INI_ENTRIES();
 
 	couchbase_init_exceptions(INIT_FUNC_ARGS_PASSTHRU);
 	couchbase_init_metadoc(INIT_FUNC_ARGS_PASSTHRU);
@@ -132,6 +175,7 @@ PHP_MINIT_FUNCTION(couchbase)
 PHP_MSHUTDOWN_FUNCTION(couchbase)
 {
 	couchbase_shutdown_bucket(SHUTDOWN_FUNC_ARGS_PASSTHRU);
+        UNREGISTER_INI_ENTRIES();
 
 	return SUCCESS;
 }
@@ -151,7 +195,7 @@ PHP_RINIT_FUNCTION(couchbase)
         pcbc_stub_data *this_stub = &PCBC_PHP_CODESTR[stub_idx];
         int retval = zend_eval_string((char*)this_stub->data, NULL, (char*)this_stub->filename TSRMLS_CC);
         if (retval != SUCCESS) {
-            php_error_docref(NULL TSRMLS_CC, E_WARNING, "Failed to inject Couchbase stub: %s.", (char *)this_stub->filename);
+            pcbc_log(LOGARGS(ERROR), "Failed to inject Couchbase stub: %s.", (char *)this_stub->filename);
             return FAILURE;
         }
     }
@@ -273,6 +317,7 @@ static PHP_MINFO_FUNCTION(couchbase)
     php_info_print_table_row(2, "libcouchbase runtime version", buf);
     php_info_print_table_row(2, "libcouchbase headers version", LCB_VERSION_STRING " (git: " LCB_VERSION_CHANGESET ")");
     php_info_print_table_end();
+    DISPLAY_INI_ENTRIES();
 }
 
 static zend_function_entry couchbase_functions[] = {

couchbase.h

@@ -29,6 +29,7 @@
 #include <php.h>
 #include <zend_exceptions.h>
 #include "php_couchbase.h"
+#include "log.h"
 
 enum pcbc_constants {
 	PERSISTTO_ONE = 1,
@@ -51,6 +52,7 @@ ZEND_BEGIN_MODULE_GLOBALS(couchbase)
 	// Linked list of bucket connections
 	pcbc_lcb *first_bconn;
 	pcbc_lcb *last_bconn;
+	char *log_level;
 ZEND_END_MODULE_GLOBALS(couchbase)
 ZEND_EXTERN_MODULE_GLOBALS(couchbase)
 
@@ -66,4 +68,7 @@ void couchbase_init_bucket(INIT_FUNC_ARGS);
 
 void couchbase_shutdown_bucket(SHUTDOWN_FUNC_ARGS);
 
+#define PCBC_INIENT_LOG_LEVEL "couchbase.log_level"
+#define PCBC_INIDFL_LOG_LEVEL "WARN"
+
 #endif /* COUCHBASE_H_ */

counter.c

@@ -28,6 +28,8 @@
 #include "transcoding.h"
 #include "opcookie.h"
 
+#define LOGARGS(instance, lvl) LCB_LOG_##lvl, instance, "pcbc/counter", __FILE__, __LINE__
+
 typedef struct {
     opcookie_res header;
     zapval key;
@@ -147,7 +149,7 @@ PHP_METHOD(Bucket, counter)
         }
         nscheduled++;
     }
-    pcbc_assert_number_of_commands("counter", nscheduled, ncmds);
+    pcbc_assert_number_of_commands(data->conn->lcb, "counter", nscheduled, ncmds);
 
     if (nscheduled) {
         lcb_wait(data->conn->lcb);

get.c

@@ -26,6 +26,8 @@
 #include "docfrag.h"
 #include "transcoding.h"
 
+#define LOGARGS(instance, lvl) LCB_LOG_##lvl, instance, "pcbc/get", __FILE__, __LINE__
+
 typedef struct {
     opcookie_res header;
     zapval key;
@@ -141,7 +143,7 @@ PHP_METHOD(Bucket, get)
 
         nscheduled++;
     }
-    pcbc_assert_number_of_commands("get", nscheduled, ncmds);
+    pcbc_assert_number_of_commands(data->conn->lcb, "get", nscheduled, ncmds);
 
     if (nscheduled) {
         lcb_wait(data->conn->lcb);
@@ -205,7 +207,7 @@ PHP_METHOD(Bucket, getFromReplica)
         }
         nscheduled++;
     }
-    pcbc_assert_number_of_commands("get_from_replica", nscheduled, ncmds);
+    pcbc_assert_number_of_commands(data->conn->lcb, "get_from_replica", nscheduled, ncmds);
 
     if (nscheduled) {
         lcb_wait(data->conn->lcb);

log.c

@@ -0,0 +1,96 @@
+/**
+ *     Copyright 2016 Couchbase, Inc.
+ *
+ *   Licensed under the Apache License, Version 2.0 (the "License");
+ *   you may not use this file except in compliance with the License.
+ *   You may obtain a copy of the License at
+ *
+ *       http://www.apache.org/licenses/LICENSE-2.0
+ *
+ *   Unless required by applicable law or agreed to in writing, software
+ *   distributed under the License is distributed on an "AS IS" BASIS,
+ *   WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ *   See the License for the specific language governing permissions and
+ *   limitations under the License.
+ */
+
+#include <libcouchbase/couchbase.h>
+#include <php.h>
+
+#include "zap.h"
+#include "log.h"
+
+static const char *level_to_string(int severity)
+{
+    switch (severity) {
+    case LCB_LOG_TRACE:
+        return "TRAC";
+    case LCB_LOG_DEBUG:
+        return "DEBG";
+    case LCB_LOG_INFO:
+        return "INFO";
+    case LCB_LOG_WARN:
+        return "WARN";
+    case LCB_LOG_ERROR:
+        return "EROR";
+    case LCB_LOG_FATAL:
+        return "FATL";
+    default:
+        return "";
+    }
+}
+
+static void log_handler(struct lcb_logprocs_st *procs, unsigned int iid,
+                        const char *subsys, int severity, const char *srcfile,
+                        int srcline, const char *fmt, va_list ap)
+{
+    struct pcbc_logger_st *logger = (struct pcbc_logger_st *)procs;
+    char *buf = NULL;
+    char *msg = NULL;
+    TSRMLS_FETCH();
+
+    if (severity < logger->minlevel) {
+        return;
+    }
+
+    vspprintf(&msg, 0, fmt, ap);
+    spprintf(&buf, 0, "[cb,%s] (%s L:%d I:%d) %s", level_to_string(severity),
+             subsys, srcline, iid, msg);
+    efree(msg);
+    php_log_err(buf TSRMLS_CC);
+    efree(buf);
+}
+
+struct pcbc_logger_st pcbc_logger = {
+    {0 /* version */, {{log_handler} /* v1 */} /*v*/},
+    /** Minimum severity */
+    LCB_LOG_INFO};
+
+void pcbc_log(int severity, lcb_t instance, const char *subsys,
+              const char *srcfile, int srcline, const char *fmt, ...)
+{
+    va_list ap;
+    char *msg = NULL;
+    char *buf = NULL;
+    TSRMLS_FETCH();
+
+    if (severity < pcbc_logger.minlevel) {
+        return;
+    }
+
+    va_start(ap, fmt);
+    vspprintf(&msg, 0, fmt, ap);
+    va_end(ap);
+    if (instance) {
+        spprintf(&buf, 0, "[cb,%s] (%s L:%d) %s. I=%p",
+                 level_to_string(severity), subsys, srcline, msg,
+                 (void *)instance);
+    } else {
+        spprintf(&buf, 0, "[cb,%s] (%s L:%d) %s", level_to_string(severity),
+                 subsys, srcline, msg);
+    }
+    efree(msg);
+
+    php_log_err(buf TSRMLS_CC);
+    efree(buf);
+}

log.h

@@ -0,0 +1,31 @@
+/**
+ *     Copyright 2016 Couchbase, Inc.
+ *
+ *   Licensed under the Apache License, Version 2.0 (the "License");
+ *   you may not use this file except in compliance with the License.
+ *   You may obtain a copy of the License at
+ *
+ *       http://www.apache.org/licenses/LICENSE-2.0
+ *
+ *   Unless required by applicable law or agreed to in writing, software
+ *   distributed under the License is distributed on an "AS IS" BASIS,
+ *   WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ *   See the License for the specific language governing permissions and
+ *   limitations under the License.
+ */
+
+#ifndef LOG_H_
+#define LOG_H_
+
+#include <libcouchbase/couchbase.h>
+#include <php.h>
+
+struct pcbc_logger_st {
+    struct lcb_logprocs_st base;
+    int minlevel;
+};
+
+void pcbc_log(int severity, lcb_t instance, const char *subsys,
+              const char *srcfile, int srcline, const char *fmt, ...);
+
+#endif // LOG_H_