ktcpsockettest again

[David Faure]

Hi Andreas,

Can you shed some light on the intent of this famous test?

    s->write(HTTPREQUEST);
    s->waitForReadyRead();
    s->close();
    //What happens is that during waitForReadyRead() the write buffer is written out
    //completely so that the socket can shut down without having to wait for writeout.
    QCOMPARE(stateToString(s->state()), stateToString(KTcpSocket::UnconnectedState));

What the comment says above, doesn't appear to be true. We get "ClosingState" now and then.
If I check s->bytesAvailable() after waitForReadyRead(), it's 4344.

Here's debug output from when it works:

QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::close()
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::disconnectFromHost()
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::disconnectFromHost() emits stateChanged()(ClosingState)
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::disconnectFromHost() disconnecting immediately
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocketPrivate::resetSocketLayer()
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::bytesAvailable() == 4344
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::disconnectFromHost() disconnected!
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::disconnectFromHost() closed!
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::close()
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::~QAbstractSocket()
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::~QAbstractSocket()

And here's debug output from when it fails:

QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::close()
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::disconnectFromHost()
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::disconnectFromHost() emits stateChanged()(ClosingState)
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::disconnectFromHost() delaying disconnect
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::close()
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::disconnectFromHost()
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::disconnectFromHost() return from delayed close
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::disconnectFromHost() delaying disconnect
FAIL!  : KTcpSocketTest::statesIana() Compared values are not the same
   Actual (stateToString(s->state())): ClosingState
   Expected (stateToString(KTcpSocket::UnconnectedState)): UnconnectedState
   Loc: [/d/kde/src/4/kde/kdelibs/kdecore/tests/ktcpsockettest.cpp(245)]
PASS   : KTcpSocketTest::cleanupTestCase()

We go into "delaying disconnect" because  d->writeBuffer.size()==38 (the whole HTTP request
is still in the write buffer).

Hmm, isn't the problem that the test makes a first request, waits for data to be available, but doesn't read
it, so readyRead is still true when making the 2nd request? Added a s->readData() ... not better.
Here's the full log, please advise:

PASS   : KTcpSocketTest::initTestCase()
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::QAbstractSocket(TcpSocket, QAbstractSocketPrivate == 0x1c50d90, parent == 0x0)
QDEBUG : KTcpSocketTest::statesIana() "ktcpsockettest"  ( 21234 ) connects to bus "qt_default_session_bus" QDBusConnectionPrivate(0x1cf3c90) 
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::QAbstractSocket(TcpSocket, QAbstractSocketPrivate == 0x1cfdfb0, parent == 0x1c49de0)
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::connectToHost("www.iana.org", 80, 3)...
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::connectToHost("www.iana.org", 80) == false (connection in progress)
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::writeData(0x1cff0e8 "GET / HTTP/1.1\nHost: www.example...", 38) == 38
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::waitForBytesWritten(2500)
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::waitForConnected(2500)
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::waitForConnected(2500) doing host name lookup
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocketPrivate::_q_startConnecting(hostInfo == {192.0.32.8, 2620:0:2D0:200::8})
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocketPrivate::_q_connectToNextAddress(), connecting to 192.0.32.8:80, 3 left to try
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocketPrivate::resetSocketLayer()
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocketPrivate::initSocketLayer(TcpSocket, IPv4Protocol) success
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::waitForConnected(2500) waiting 2.50 secs for connection attempt #1
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocketPrivate::fetchConnectionParameters() connection to 192.0.32.8:80 established
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::waitForConnected(2500) == true
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocketPrivate::canWriteNotification() flushing
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocketPrivate::flush() 38 bytes written to the network
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::waitForBytesWritten returns true
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::waitForReadyRead(2500)
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocketPrivate::canReadNotification()
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocketPrivate::readFromSocket() about to read 2896 bytes
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocketPrivate::readFromSocket() got 2896 bytes, buffer size = 2896
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::bytesAvailable() == 2896
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::readData(0x1d10058 'H (0x48)', 16384) == 2896 [buffer]
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::bytesAvailable() == 0
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::bytesAvailable() == 0
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::writeData(0x1cfe648 "GET / HTTP/1.1\nHost: www.example...", 38) == 38
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::waitForReadyRead(2500)
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocketPrivate::canReadNotification()
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocketPrivate::readFromSocket() about to read 1448 bytes
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocketPrivate::readFromSocket() got 1448 bytes, buffer size = 1448
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::bytesAvailable() == 1448
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::close()
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::disconnectFromHost()
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::disconnectFromHost() emits stateChanged()(ClosingState)
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::disconnectFromHost() delaying disconnect due to d->writeBuffer.size()= 38 
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::close()
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::disconnectFromHost()
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::disconnectFromHost() return from delayed close
QDEBUG : KTcpSocketTest::statesIana() QAbstractSocket::disconnectFromHost() delaying disconnect due to d->writeBuffer.size()= 38 
FAIL!  : KTcpSocketTest::statesIana() Compared values are not the same
   Actual (stateToString(s->state())): ClosingState

Clearly the 2nd request hasn't been written out, so I'm not sure why canReadNotification is called immediately.

But before I spend more time on this, I want to ask: why do we care for this specific behavior of QTcpSocket,
i.e. do we really care that closing is immediate in this unusual case? What's the purpose of the test?

-- 
David Faure, faure at kde.org, http://www.davidfaure.fr
Sponsored by BlueSystems and KDAB to work on KDE Frameworks