bookkeeper 4.4.0, PerChannelBookieClient connecting to bookie does not excute operationComplete()

[huangdongfa]

hdfs namenode use bookkeeper 4.4.0, PerChannelBookieClient connecting to bookie does not excute operationComplete() , but use netstat found connection state is ESTABLISHED

=========================================log====================
2018-10-10 13:51:31,586 INFO org.apache.bookkeeper.net.NetworkTopologyImpl: Adding a new node: /default-region/default-rack/10.22.43.25:3182
2018-10-10 13:51:31,586 INFO org.apache.bookkeeper.net.NetworkTopologyImpl: Adding a new node: /default-region/default-rack/10.22.43.26:3182
2018-10-10 13:51:31,586 INFO org.apache.bookkeeper.net.NetworkTopologyImpl: Adding a new node: /default-region/default-rack/10.22.44.43:3182
2018-10-10 13:51:31,587 INFO org.apache.bookkeeper.net.NetworkTopologyImpl: Adding a new node: /default-region/default-rack/10.22.42.195:3182
2018-10-10 13:51:31,587 INFO org.apache.bookkeeper.net.NetworkTopologyImpl: Adding a new node: /default-region/default-rack/10.22.44.41:3182
2018-10-10 13:51:31,587 INFO org.apache.bookkeeper.net.NetworkTopologyImpl: Adding a new node: /default-region/default-rack/10.22.42.196:3182
2018-10-10 13:51:31,587 INFO org.apache.bookkeeper.net.NetworkTopologyImpl: Adding a new node: /default-region/default-rack/10.22.44.42:3182
2018-10-10 14:00:20,448 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Start loading edits file BookKeeperLedger[ledgerId=566674,firstTxId=5695764412,lastTxId=5695945192]
2018-10-10 14:00:20,451 INFO org.apache.hadoop.hdfs.server.namenode.EditLogInputStream: Fast-forwarding stream 'BookKeeperLedger[ledgerId=566674,firstTxId=5695764412,lastTxId=5695945192]' to transaction ID 5695764412
2018-10-10 14:00:20,462 INFO org.apache.bookkeeper.proto.PerChannelBookieClient: Connecting to bookie: 10.22.44.42:3182
2018-10-10 14:00:20,487 INFO org.apache.bookkeeper.proto.PerChannelBookieClient: Connecting to bookie: 10.22.44.41:3182
2018-10-10 14:00:20,488 INFO org.apache.bookkeeper.proto.PerChannelBookieClient: Connecting to bookie: 10.22.42.196:3182
2018-10-10 14:00:20,489 INFO org.apache.bookkeeper.proto.PerChannelBookieClient: Connecting to bookie: 10.22.42.195:3182
2018-10-10 14:00:20,490 INFO org.apache.bookkeeper.proto.PerChannelBookieClient: Connecting to bookie: 10.22.43.26:3182
2018-10-10 14:00:20,490 INFO org.apache.bookkeeper.proto.PerChannelBookieClient: Channel connected (true) [id: 0x37df4618, /10.11.168.223:10952 => /10.22.44.42:3182]
2018-10-10 14:00:20,491 INFO org.apache.bookkeeper.proto.PerChannelBookieClient: Successfully connected to bookie: [id: 0x37df4618, /10.11.168.223:10952 => /10.22.44.42:3182]
2018-10-10 14:00:20,495 INFO org.apache.bookkeeper.proto.PerChannelBookieClient: Channel connected (true) [id: 0x534dde6a, /10.11.168.223:32220 => /10.22.43.26:3182]
2018-10-10 14:00:20,496 INFO org.apache.bookkeeper.proto.PerChannelBookieClient: Successfully connected to bookie: [id: 0x534dde6a, /10.11.168.223:32220 => /10.22.43.26:3182]

====================================================
$ netstat -napt | grep 3182
(Not all processes could be identified, non-owned process info
will not be shown, you would have to be root to see it all.)
tcp 0 0 10.11.168.223:30440 10.22.44.41:3182 ESTABLISHED 1557425/java
tcp 0 0 10.11.168.223:18644 10.22.42.195:3182 ESTABLISHED 1557425/java
tcp 0 0 10.11.168.223:10952 10.22.44.42:3182 ESTABLISHED 1557425/java
tcp 0 0 10.11.168.223:32220 10.22.43.26:3182 ESTABLISHED 1557425/java
tcp 0 0 10.11.168.223:59092 10.22.42.196:3182 ESTABLISHED 1557425/java

[sijie]

@huangdongfa do you have any jstack on the hdfs namenode that shows operationComplete is not called?

btw, 4.4.0 is a almost 3-years old release :(

[huangdongfa]

this is stack file,
bookkeeper-client.jstack.txt

relevant code, look like netty don't callback operationComplete()：

private void connect() {
        LOG.info("Connecting to bookie: {}", addr);
        // Set up the ClientBootStrap so we can create a new Channel connection
        // to the bookie.
        ClientBootstrap bootstrap = new ClientBootstrap(channelFactory);
        bootstrap.setPipelineFactory(this);
        bootstrap.setOption("tcpNoDelay", conf.getClientTcpNoDelay());
        bootstrap.setOption("keepAlive", true);
        bootstrap.setOption("connectTimeoutMillis", conf.getClientConnectTimeoutMillis());
        bootstrap.setOption("child.sendBufferSize", conf.getClientSendBufferSize());
        bootstrap.setOption("child.receiveBufferSize", conf.getClientReceiveBufferSize());
        bootstrap.setOption("writeBufferLowWaterMark", conf.getClientWriteBufferLowWaterMark());
        bootstrap.setOption("writeBufferHighWaterMark", conf.getClientWriteBufferHighWaterMark());
        SocketAddress bookieAddr = addr.getSocketAddress();        
        if (channelFactory instanceof LocalClientChannelFactory) {
            bookieAddr = addr.getLocalAddress();
        }
        ChannelFuture future = bootstrap.connect(bookieAddr);
        future.addListener(new ChannelFutureListener() {
            @Override
            public void operationComplete(ChannelFuture future) throws Exception {
                LOG.info("Channel connected ({}) {}", future.isSuccess(), future.getChannel());
                int rc;
                Queue<GenericCallback<PerChannelBookieClient>> oldPendingOps;

                synchronized (PerChannelBookieClient.this) {
                    if (future.isSuccess() && state == ConnectionState.CONNECTING) {
                        LOG.info("Successfully connected to bookie: {}", future.getChannel());
                        rc = BKException.Code.OK;
                        channel = future.getChannel();
                        state = ConnectionState.CONNECTED;
                    } else if (future.isSuccess() && (state == ConnectionState.CLOSED
                                                      || state == ConnectionState.DISCONNECTED)) {
                        LOG.warn("Closed before connection completed, clean up: {}, current state {}",
                                 future.getChannel(), state);
                        closeChannel(future.getChannel());
                        rc = BKException.Code.BookieHandleNotAvailableException;
                        channel = null;
                    } else if (future.isSuccess() && state == ConnectionState.CONNECTED) {
                        LOG.debug("Already connected with another channel({}), so close the new channel({})",
                                  channel, future.getChannel());
                        closeChannel(future.getChannel());
                        return; // pendingOps should have been completed when other channel connected
                    } else {
                        LOG.error("Could not connect to bookie: {}/{}, current state {} : ",
                                  new Object[] { future.getChannel(), addr,
                                                 state, future.getCause() });
                        rc = BKException.Code.BookieHandleNotAvailableException;
                        closeChannel(future.getChannel());
                        channel = null;
                        if (state != ConnectionState.CLOSED) {
                            state = ConnectionState.DISCONNECTED;
                        }
                    }

                    // trick to not do operations under the lock, take the list
                    // of pending ops and assign it to a new variable, while
                    // emptying the pending ops by just assigning it to a new
                    // list
                    oldPendingOps = pendingOps;
                    pendingOps = new ArrayDeque<GenericCallback<PerChannelBookieClient>>();
                }

                for (GenericCallback<PerChannelBookieClient> pendingOp : oldPendingOps) {
                    completeOperation(pendingOp, rc);
                }
            }
        });
    }

[huangdongfa]

It seems to work well after I tried to upgrade to 4.6.2 :)

[eolivelli]

Great to see BK used really with HDFS !
I thought it was only a prototype

[sijie]

@huangdongfa glad to hear that it works after upgrading 4.6.2 :)

4.4.0 is a many-years-old release already :)

[sijie]

closed this issue since the issue was resolved after upgrading from 4.4.0 to 4.6.2