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?

Hello, I just wanted to give notice that I'm not ignoring this issue. I am 
merely quite busy this week and I'm going to look into it on the weekend.