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 increasing amount of information):

  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 and php.ini snippet:

$cluster = new CouchbaseCluster('couchbase://localhost');
$bucket = $cluster->openBucket('default');
$bucket->get('foo');
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. And 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.