problems in http kioslave, where to debug?

[David Faure]

On Wednesday 21 May 2014 18:19:57 Marco Martin wrote:
> Hi all,
> I'm writing here too since I'm kinda out of ideas ;)
> I was indagating about this bug in Plasma Next:
> https://bugs.kde.org/show_bug.cgi?id=332499
> 
> i tought it was probably a problem in ghns, but seems that instead, a copy
> process with the http kio, always fails wether
> KIO::file_copy is used
> my findings so far are summarized here
> https://bugs.kde.org/show_bug.cgi?id=334767
> 
> interestingly enough, KIO::get works just fine (since ghns successfully
> downloads the xml metadat file)
> 
> an anybody replicate the same problem? (just try kioclient5 copy any valid
> http url)
> 
> and has any idea where may be the problem?

Yes, this is the complex Qt bug (race) affecting the suspend/resume mechanism
used by KIO sockets in file_copy, which I've been debugging for some time.

Here's the current status of my investigation (from a mail I sent to Thiago on May 10).

===============

The debug output from the application looks like this:

KIO::TransferJobPrivate::internalResume: 
KIO::SocketConnectionBackend::setSuspended: KLocalSocket(0x1ec38c0)  resuming
KIO::SocketConnectionBackend::setSuspended: Calling setReadBufferSize 32768
QAbstractSocket::setReadBufferSize: KLocalSocket(0x1ec38c0) 32768 readSocketNotifierCalled= false
QAbstractSocket::setReadBufferSize:     buffer.size= 0 readbuffersize= 32768
QAbstractSocket::setReadBufferSize:      setReadNotificationEnabled(true)
QAbstractSocket::bytesAvailable: KLocalSocket(0x1ec38c0) QAbstractSocket::bytesAvailable() == 0
QAbstractSocket::bytesAvailable: KLocalSocket(0x1ec38c0) QAbstractSocket::bytesAvailable() == 0
QAbstractSocket::readData: KLocalSocket(0x1ec38c0) readData(maxSize= 16384 )
QAbstractSocket::readData:     QAbstractSocket::readData(0x1ec9cc0 "     0_65_", 16384) == 10 [engine]
KIO::SocketConnectionBackend::setSuspended: KLocalSocket(0x1ec38c0) read 1 bytes
KIO::SocketConnectionBackend::setSuspended: ungetChar

(and then nothing else happens).
The app waits in the event loop for the next readyRead signal, which never happens.
The data definitely made it to the app, it's the "    0_65_ " data (10 bytes).

When it works (same unittest, different run -- it's definitely a race) :

KIO::TransferJobPrivate::internalResume: 
KIO::SocketConnectionBackend::setSuspended: KLocalSocket(0x22638c0)  resuming
KIO::SocketConnectionBackend::setSuspended: Calling setReadBufferSize 32768
QAbstractSocket::setReadBufferSize: KLocalSocket(0x22638c0) 32768 readSocketNotifierCalled= false
QAbstractSocket::setReadBufferSize:     buffer.size= 0 readbuffersize= 32768
QAbstractSocket::setReadBufferSize:      setReadNotificationEnabled(true)
QAbstractSocket::bytesAvailable: KLocalSocket(0x22638c0) QAbstractSocket::bytesAvailable() == 0
QAbstractSocket::bytesAvailable: KLocalSocket(0x22638c0) QAbstractSocket::bytesAvailable() == 0
QAbstractSocket::readData: KLocalSocket(0x22638c0) readData(maxSize= 16384 )
QAbstractSocket::readData:     QAbstractSocket::readData(0x22697d0 "     0_65_", 16384) == 10 [engine]
KIO::SocketConnectionBackend::setSuspended: KLocalSocket(0x22638c0) read 1 bytes
KIO::SocketConnectionBackend::setSuspended: ungetChar
QAbstractSocketPrivate::canReadNotification: KLocalSocket(0x22638c0)
QAbstractSocketPrivate::readFromSocket: QAbstractSocketPrivate::readFromSocket() about to read 4096 bytes
QAbstractSocket::bytesAvailable: KLocalSocket(0x22638c0) QAbstractSocket::bytesAvailable() == 10
KIO::SocketConnectionBackend::socketReadyRead: KLocalSocket(0x22638c0) Got 10 bytes
QAbstractSocket::bytesAvailable: KLocalSocket(0x22638c0) QAbstractSocket::bytesAvailable() == 10
QAbstractSocket::readData: KLocalSocket(0x22638c0) readData(maxSize= 0 )
KIO::SocketConnectionBackend::socketReadyRead: KIO::SocketConnectionBackend(0x22605d0) Beginning of command 65 of size 0
[...]

What I don't understand is how readData() can get 10 bytes from the socket engine and yet the
code in kio (socketconnectionbackend.cpp) gets bytesAvailable()==0 so it reads only 1 char
(in both cases)

        // We read all bytes here, but we don't use readAll() because we need
        // to read at least one byte (even if there isn't any) so that the
        // socket notifier is reenabled
        QByteArray data = socket->read(socket->bytesAvailable() + 1);
        qDebug() << socket << "read" << data.size() << "bytes";
        for (int i = data.size(); --i >= 0;) {
            qDebug() << "ungetChar";
            socket->ungetChar(data[i]);
        }

Anyhow this code getting only 1 char isn't the issue (since it happens in both cases),
but rather the fact that readyRead() isn't always emitted afterwards. 

=====

If anyone is interested in helping to debug this, apply this patch (debug output + forcing the use of the
data pump even for kio_file transfers) to kio
http://www.davidfaure.fr/2014/kio_debug.diff
and run kio's jobtest, or run `testkioarchive testExtractFileFromTar` in workspace/kio-extras/archive/tests
(less confusing because it runs one kio_file and one kio_archive, rather than two kio_file processes).

http://www.davidfaure.fr/2014/qtbase.diff for the debug output coming from Qt itself.

====

OK, writing this email gave me an idea for a workaround, at least. Can you test it?
(attached).

-- 
David Faure, faure at kde.org, http://www.davidfaure.fr
Working on KDE Frameworks 5
-------------- next part --------------
A non-text attachment was scrubbed...
Name: 0001-Ensure-readyRead-is-emitted-after-resuming-a-socket.patch
Type: text/x-patch
Size: 855 bytes
Desc: not available
URL: <http://mail.kde.org/pipermail/kde-frameworks-devel/attachments/20140601/8aecaf7c/attachment-0001.patch>