Collecting Information and Logging in the PHP SDK with Couchbase Server

    +
    The PHP SDK logs its own and libcouchbase events using the default logger implementation in PHP.

    Logging

    The Couchbase PHP SDK has no hard dependency on a specific logger implementation. By default it uses built-in means to report events. The only thing you may change is the log level, which is controlled by couchbase.log_level in php.ini. The default log level is WARN.

    The following log levels are supported (in order of increasing amount of information logged):

    1. FATAL

    2. ERROR

    3. WARN

    4. INFO

    5. DEBUG

    6. TRACE

    The PHP SDK is configured to send logs to standard output (when error_log is set to NULL). You can set it to syslog to redirect all logs (including libcouchbase and PHP SDK) to the syslog device. For example, the script below:

    $cluster = new CouchbaseCluster('couchbase://localhost');
    $bucket = $cluster->openBucket('default');
    $bucket->get('foo');

    …​along with this php.ini snippet:

    error_log = syslog
    
    extension = couchbase.so
    couchbase.log_level = DEBUG

    Could be observed like this (assuming Linux with systemd):

    $ sudo journalctl -t php
     Sep 07 01:24:21 mars.local php[17655]: [cb,INFO] (pcbc/bucket L:182) New lcb_t instance has been initialized. I=0x5646d40a3dc0
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (confmon L:89 I:0) Preparing providers (this may be called multiple times)
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (confmon L:99 I:0) Provider FILE is DISABLED
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (confmon L:96 I:0) Provider CCCP is ENABLED
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (confmon L:96 I:0) Provider HTTP is ENABLED
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (confmon L:99 I:0) Provider MCRAW is DISABLED
     Sep 07 01:24:21 mars.local php[17655]: [cb,INFO] (cccp L:118 I:0) Requesting connection to node localhost:11210 for CCCP configuration
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (lcbio_mgr L:416 I:0) <localhost:11210> (HE=0x5646d40a9eb0) Creating new connection because none are available in the pool
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (lcbio_mgr L:321 I:0) <localhost:11210> (HE=0x5646d40a9eb0) Starting connection on I=0x5646d40aa420
     Sep 07 01:24:21 mars.local php[17655]: [cb,INFO] (connection L:450 I:0) <localhost:11210> (SOCK=0x5646d40aa4f0) Starting. Timeout=2000000us
     Sep 07 01:24:21 mars.local php[17655]: [cb,INFO] (connection L:116 I:0) <localhost:11210> (SOCK=0x5646d40aa4f0) Connected
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (connection L:123 I:0) <localhost:11210> (SOCK=0x5646d40aa4f0) Successfuly set TCP_NODELAY
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (lcbio_mgr L:271 I:0) <localhost:11210> (HE=0x5646d40a9eb0) Received result for I=0x5646d40aa420,C=0x5646d40aa4f0; E=0x0
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (lcbio_mgr L:223 I:0) <localhost:11210> (HE=0x5646d40a9eb0) Assigning R=0x5646d40a9e60 SOCKET=0x5646d40aa4f0
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (ioctx L:101 I:0) <localhost:11210> (CTX=0x5646d40abb10,unknown) Pairing with SOCK=0x5646d40aa4f0
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (negotiation L:368 I:0) <localhost:11210> (SASLREQ=0x5646d40aa3e0) Found feature 0x3 (TCP NODELAY)
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (ioctx L:151 I:0) <localhost:11210> (CTX=0x5646d40abb10,sasl) Destroying. PND=0,ENT=1,SORC=1
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (ioctx L:101 I:0) <localhost:11210> (CTX=0x5646d40abd50,unknown) Pairing with SOCK=0x5646d40aa4f0
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (ioctx L:151 I:0) <localhost:11210> (CTX=0x5646d40abd50,bc_cccp) Destroying. PND=0,ENT=1,SORC=1
     Sep 07 01:24:21 mars.local php[17655]: [cb,INFO] (lcbio_mgr L:491 I:0) <localhost:11210> (HE=0x5646d40a9eb0) Placing socket back into the pool. I=0x5646d40aa420,C=0x5646d40aa4f0
     Sep 07 01:24:21 mars.local php[17655]: [cb,INFO] (confmon L:174 I:0) Setting new configuration. Received via CCCP
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (bootstrap L:55 I:0) Instance configured!
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (confmon L:89 I:0) Preparing providers (this may be called multiple times)
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (confmon L:99 I:0) Provider FILE is DISABLED
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (confmon L:96 I:0) Provider CCCP is ENABLED
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (confmon L:99 I:0) Provider HTTP is DISABLED
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (confmon L:99 I:0) Provider MCRAW is DISABLED
     Sep 07 01:24:21 mars.local php[17655]: [cb,INFO] (pcbc/bucket L:243) lcb_t instance has been connected. I=0x5646d40a3dc0
     Sep 07 01:24:21 mars.local php[17655]: [cb,INFO] (lcbio_mgr L:407 I:0) <localhost:11210> (HE=0x5646d40a9eb0) Found ready connection in pool. Reusing socket and not creating new connection
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (lcbio_mgr L:223 I:0) <localhost:11210> (HE=0x5646d40a9eb0) Assigning R=0x5646d40ab290 SOCKET=0x5646d40aa4f0
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (ioctx L:101 I:0) <localhost:11210> (CTX=0x5646d40abc50,unknown) Pairing with SOCK=0x5646d40aa4f0
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (server L:552 I:0) <localhost:11210> (SRV=0x5646d40b8820,IX=0) Setting initial timeout=2499ms
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (server L:747 I:0) <localhost:11210> (SRV=0x5646d40b8820,IX=0) Finalizing ctx 0x5646d40abc50
     Sep 07 01:24:21 mars.local php[17655]: [cb,DEBG] (ioctx L:151 I:0) <localhost:11210> (CTX=0x5646d40abc50,memcached) Destroying. PND=0,ENT=0,SORC=1

    In this example, the part before the first column belongs to journald/syslog formatter. Everything else is described in the table below:

    Format Description

    [cb,LEVEL]

    A string representing the severity of the level

    (subsystem - L:line I:n)

    The subsystem that produced this message, followed by the source code line at which this message was created. The subsystem will typically, but not always, resemble the source code file. It is a small string describing what the current line is doing.

    The identifier n of the lcb_t object associated with the current message. This allows you to determine the origin of the message in the case where the application contains multiple such lcb_t objects. The number is incremented for each call to lcb_create().

    <host:port>

    The host and port, if any, associated with the message. This is supplied for messages that relate to the state of a particular connection.

    By default, php-fpm redirects the standard output and error streams to /dev/null for performance and FastCGI conformance reasons. In order to capture the logs in this setup, you must explicitly configure catch_workers_output = yes.