blocking forever in libssh2_channel_read

[programmerjake]

In blocking mode, when I use libssh2_channel_read(channel, buffer, 4), the 4 bytes are read from the socket, but libssh2_channel_read doesn't return.

void startup()
{
    session = libssh2_session_init();
    if(!session)
    {
        throw ConnectionError("libssh2_session_init failed");
    }
    try
    {
        connection = openConnection(std::move(serverAddress));
    }
    catch(...)
    {
        libssh2_session_free(session);
        throw;
    }
    int error = libssh2_session_handshake(session, connection);
    if(error != 0)
    {
        libssh2_session_free(session);
        closeConnection(connection);
        throw ConnectionError("libssh2_session_handshake failed: " +
                              getLibSSH2ErrorString(error));
    }
    libssh2_trace(session, ~0);
    libssh2_trace_sethandler(session, nullptr, [](LIBSSH2_SESSION *session, void *,
                                                  const char *data, std::size_t length)
                             {
                                 std::cerr << std::string(data, length) << std::endl;
                             });
#warning finish implementing known_hosts check
    const auto userName = "codepoint-db";
    error = libssh2_userauth_publickey_frommemory(
        session, userName, std::strlen(userName), sshPublicKey, std::strlen(sshPublicKey),
        sshPrivateKey, std::strlen(sshPrivateKey), nullptr);
    if(error != 0)
    {
        libssh2_session_disconnect_ex(session, SSH_DISCONNECT_AUTH_CANCELLED_BY_USER,
                                      "database error shutdown", "");
        libssh2_session_free(session);
        closeConnection(connection);
        throw ConnectionError("libssh2_knownhost_init failed: " + getLibSSH2ErrorString(error));
    }
    channel = libssh2_channel_open_session(session);
    if(channel == nullptr)
    {
        libssh2_session_disconnect(session, "database error shutdown");
        libssh2_session_free(session);
        closeConnection(connection);
        throw ConnectionError("libssh2_channel_open_session failed");
    }
    error = libssh2_channel_exec(channel, "codepoint-db");
    if(error != 0)
    {
        libssh2_channel_free(channel);
        libssh2_session_disconnect(session, "database error shutdown");
        libssh2_session_free(session);
        closeConnection(connection);
        throw ConnectionError("libssh2_channel_exec failed: " + getLibSSH2ErrorString(error));
    }
    try
    {
        bool isFlush = false;
        readPacket(isFlush);
        if(!isFlush)
            throw ConnectionError("reading initial flush failed");
    }
    catch(...)
    {
        libssh2_channel_free(channel);
        libssh2_session_disconnect(session, "database error shutdown");
        libssh2_session_free(session);
        closeConnection(connection);
        throw;
    }
}
std::string readBytes(std::size_t maxByteCount, bool canReadLess)
{
    if(maxByteCount == 0)
        return "";
    std::string retval;
    retval.resize(maxByteCount);
    char *bufPtr = &retval[0];
    std::size_t sizeLeft = maxByteCount;
    do
    {
        auto readRetval = libssh2_channel_read(channel, bufPtr, sizeLeft);
        if(readRetval < 0)
        {
            throw ConnectionError("libssh2_channel_read failed: " +
                                  getLibSSH2ErrorString(readRetval));
        }
        sizeLeft -= readRetval;
        bufPtr += readRetval;
    } while(sizeLeft > 0 && !canReadLess);
    retval.resize(maxByteCount - sizeLeft);
    return retval;
}
std::string readPacket(bool &isFlush)
{
    auto packetHeader = readBytes(4, false);
    for(char ch : packetHeader)
    {
        if(!std::isxdigit(ch))
            throw ConnectionError("bad packet header");
    }
    std::istringstream ss(packetHeader);
    ss >> std::hex;
    std::size_t packetLength;
    ss >> packetLength;
    if(packetLength == 0)
    {
        isFlush = true;
        return "";
    }
    if(packetLength < 4)
        throw ConnectionError("bad packet header");
    isFlush = false;
    return readBytes(packetLength - 4, false);
}

trace:
...
[libssh2] 0.263924 Transport: Packet type 52 received, length=1
[libssh2] 0.263936 Transport: Looking for packet of type: 52
[libssh2] 0.263946 Userauth: Publickey authentication successful
[libssh2] 2.716543 Conn: Allocated new channel ID#0
[libssh2] 2.716580 Conn: Opening Channel - win 2097152 pack 32768
=> libssh2_transport_write plain (24 bytes)

0000: 5A 00 00 00 07 73 65 73 73 69 6F 6E 00 00 00 00 : Z....session....

0010: 00 20 00 00 00 00 80 00 : . ......

[libssh2] 2.716721 Socket: Sent 80/80 bytes at 0x879f70
=> libssh2_transport_write send() (80 bytes)

0000: DB F0 C9 30 4D 2F C4 43 0F FA 27 DB 02 B5 64 5E : ...0M/.C..'...d^

0010: 85 B4 A2 7F 39 AA 6A 38 4B DB DF E7 66 05 9A 6C : ....9.j8K...f..l

0020: 75 04 CB 44 EA 96 68 54 22 36 C6 13 69 53 8B 1C : u..D..hT"6..iS..

0030: 16 BF 56 AD 53 59 15 9C F2 D0 1A B6 1A A9 56 5F : ..V.SY........V_

0040: C4 77 D0 DB 17 A3 FC C8 90 8E 1D 5B 4E 90 4C CA : .w.........[N.L.

[libssh2] 2.716786 Transport: Looking for packet of type: 91
[libssh2] 2.716796 Transport: Looking for packet of type: 92
[libssh2] 2.717301 Socket: Recved 64/16384 bytes to 0x875f30+0
=> libssh2_transport_read() raw (64 bytes)

0000: 5B 60 65 75 27 0C F9 BA 9F FC DE 64 E1 6D 1D 8A : [`eu'......d.m..

0010: C3 0F 21 10 62 C0 51 1E 9F EF F3 E2 96 61 82 48 : ..!.b.Q......a.H

0020: 33 62 42 D6 D2 55 7D 5B 13 68 2A 05 81 5A 68 54 : 3bB..U}[.h*..ZhT

0030: 57 6D 5E 9F 76 79 3F 14 15 4C E4 10 99 C5 3D C6 : Wm^.vy?..L....=.

=> libssh2_transport_read() plain (17 bytes)

0000: 5B 00 00 00 00 00 00 00 00 00 00 00 00 00 00 80 : [...............

0010: 00 : .

[libssh2] 2.717413 Transport: Packet type 91 received, length=17
[libssh2] 2.717424 Transport: Looking for packet of type: 91
[libssh2] 2.717434 Conn: Connection Established - ID: 0/0 win: 0/2097152 pack: 32768/32768
[libssh2] 3.844098 Conn: starting request(exec) on channel 0/0, message=codepoint-db
=> libssh2_transport_write plain (18 bytes)

0000: 62 00 00 00 00 00 00 00 04 65 78 65 63 01 00 00 : b........exec...

0010: 00 0C : ..

=> libssh2_transport_write plain2 (12 bytes)

0000: 63 6F 64 65 70 6F 69 6E 74 2D 64 62 : codepoint-db

[libssh2] 3.844258 Socket: Sent 80/80 bytes at 0x879f70
=> libssh2_transport_write send() (80 bytes)

0000: 96 C2 4E 9F 32 1A 41 FA 3B AA 9A D5 F7 36 8A BC : ..N.2.A.;....6..

0010: 22 7A 15 28 15 4E 25 17 8B 84 01 E1 34 85 77 D6 : "z.(.N%.....4.w.

0020: 20 65 8A EE 8F EE 12 D1 C5 69 7A 60 9F 96 C0 1D : e.......iz`....

0030: F2 14 E3 4D 98 11 B7 18 EE EA 95 65 55 AA A1 2F : ...M.......eU../

0040: 2F 25 98 B2 5B 6E CE D8 14 B2 D6 B0 B0 E4 8F 37 : /%..[n.........7

[libssh2] 3.844320 Transport: Looking for packet of type: 99
[libssh2] 3.844329 Transport: Looking for packet of type: 100
[libssh2] 3.845355 Socket: Recved 112/16384 bytes to 0x875f30+0
=> libssh2_transport_read() raw (112 bytes)

0000: 64 43 D9 E2 47 69 53 71 AD 58 7A 62 7D F9 8B E9 : dC..GiSq.Xzb}...

0010: 1A 7E 25 E7 D6 8A 8B D7 61 AF 8D 65 7C 4E 9F 7D : .~%.....a..e|N.}

0020: 9B 0E D2 D2 71 F3 F1 BE 18 31 B9 E3 74 AC 66 6F : ....q....1..t.fo

0030: 8B 20 9B 05 B0 A1 92 D9 FC 42 E7 16 81 7B D2 1D : . .......B...{..

0040: 73 B4 58 69 CE 7E E3 00 77 78 7E C0 CE 26 7A 57 : s.Xi...wx..&zW

0050: AA DC C9 77 9F 9E 83 1E 1E 81 1E 70 BF B1 0B 57 : ...w.......p...W

0060: 2A CD D6 53 A8 C0 62 A5 63 ED C2 D5 49 E0 8C 96 : *..S..b.c...I...

=> libssh2_transport_read() plain (9 bytes)

0000: 5D 00 00 00 00 00 20 00 00 : ]..... ..

[libssh2] 3.845461 Transport: Packet type 93 received, length=9
[libssh2] 3.845469 Conn: Window adjust for channel 0/0, adding 2097152 bytes, new window_size=2097152
=> libssh2_transport_read() plain (5 bytes)

0000: 63 00 00 00 00 : c....

[libssh2] 3.845498 Transport: Packet type 99 received, length=5
[libssh2] 3.845506 Transport: Looking for packet of type: 99
[libssh2] 52.163502 Conn: channel_read() wants 4 bytes from channel 0/0 stream #0
[libssh2] 109.702121 Socket: Recved 64/16384 bytes to 0x875f30+0
=> libssh2_transport_read() raw (64 bytes)

0000: AA 65 79 71 DB 76 BC 0D AD F4 CF A8 F1 99 FA 25 : .eyq.v.........%

0010: F2 E2 7C 3A 30 04 85 73 7C 2C 0D 22 C2 B6 F0 79 : ..|:0..s|,."...y

0020: 2B 1F 92 CF 73 CF 00 85 01 8F 9E 52 CF A1 F9 D1 : +...s......R....

0030: 60 86 C5 E5 A1 4D 07 B9 1C 54 28 6A A6 BB 8F A6 : `....M...T(j....

=> libssh2_transport_read() plain (13 bytes)

0000: 5E 00 00 00 00 00 00 00 04 30 30 30 30 : ^........0000

[libssh2] 193.860262 Transport: Packet type 94 received, length=13
[libssh2] 193.860309 Conn: 4 bytes packet_add() for 0/0/0
[libssh2] 193.860322 Conn: increasing read_avail by 4 bytes to 4/2097152
------------------ blocks here ---------------------------

makefile:

.PHONY: all clean distclean

SOURCES := $(wildcard src/.cpp) $(wildcard src//.cpp)
HEADERS := $(wildcard src/.h) $(wildcard src//.h)
OBJECTS := $(patsubst %.cpp,%.o,$(SOURCES))
PROGRAM := codepoint-v2-generator
OPENSSL := openssl-1.0.2g

all: codepoint-v2-generator

$(OPENSSL)/libcrypto.a:
tar -xzf $(OPENSSL).tar.gz
+cd $(OPENSSL) && ./config no-shared no-ssl2 no-ssl3 no-comp && $(MAKE) depend && $(MAKE)

$(OPENSSL)/libssl.a: $(OPENSSL)/libcrypto.a

libssh2_build/src/libssh2.a: $(OPENSSL)/libssl.a $(OPENSSL)/libcrypto.a
tar -xzf libssh2-1.7.0.tar.gz
mkdir -p libssh2_build
cd libssh2_build && cmake -DCMAKE_BUILD_TYPE=Debug -DBUILD_SHARED_LIBS=OFF -DCRYPTO_BACKEND=OpenSSL -DOPENSSL_CRYPTO_LIBRARY=$(OPENSSL)/libcrypto.a -DOPENSSL_SSL_LIBRARY=$(OPENSSL)/libssl.a -DOPENSSL_INCLUDE_DIR=$(OPENSSL)/include -DENABLE_DEBUG_LOGGING=ON ../libssh2-1.7.0
cd libssh2_build && $(MAKE) libssh2

codepoint-v2-generator: $(OBJECTS) libssh2_build/src/libssh2.a
g++ -g -o codepoint-v2-generator $(OBJECTS) -Llibssh2_build/src -L$(OPENSSL) -lssh2 -lssl -lcrypto -ldl

%.o: %.cpp $(HEADERS)
g++ -std=c++11 -Wall -g -c -Ilibssh2-1.7.0/include -o "$(@)" "$(<)"

distclean: clean
rm -rf libssh2_build $(OPENSSL)

clean:
rm -rf codepoint-v2-generator $(OBJECTS)

[salva]

Have you enabled trace for everything (i.e. libssh2_trace(session, ~0)) ?

Is the program busy (100% CPU usage) or waiting for I/O?

Could you try to running the program under the debugger and trying to find where and how it is hanging?

[programmerjake]

trace for everything is enabled, I posted the trace after authentication. it blocks inside a read socket syscall, and never returns. the loop in channel read is missing a check to see if it read enough:

libssh2/src/channel.c

Line 1803 in 4138f1e

rc = _libssh2_transport_read(session);

[programmerjake]

a workaround is to put the socket in non-blocking mode.

[salva]

the loop in channel read is missing a check to see if it read enough

That is made on purpose in order to improve performance.

Could you include a backtrace at the point where the program is blocked in the read syscall?

[salva]

BTW, the socket is already set into non-blocking in libssh2_session_handshake. Setting it also from the outside shouldn't make any difference. Maybe the problem is there.

[gmanasi13]

Has this issue been addressed/fixed? I am also facing the same problem. For my application, I cannot set the socket to non-blocking mode. It has to be in blocking mode.

[gmanasi13]

I was able to resolve the problem by using the function "libssh2_session_set_timeout" which is to be used for blocking mode.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.