ktcpsockettest again

[Andreas Hartmetz]

On Saturday 19 January 2013 12:21:57 David Faure wrote:
> 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?

I have tried to fix the test and explain what it does in commit 
df47f41bbd965e0a6e4233ad1ac272b22910d089.
The comments added in that commit should explain why the test does what it 
does, and how it is supposed to work. The test is still not bullet-proof, so 
let's see what happens on the CI system.