This crash happened shortly after login, while I was running Discover: kioslave5[169959]: ASSERT failure in void KIO::SlaveBasePrivate::verifyState(const char*): "timeoutSpecialCommand() did not call finished() or error()! Please fix the kio_http KIO slave", file /home/bernie/kde/src/kio/src/core/slavebase.cpp, line 196 Stack trace: [KCrash Handler] #5 0x00007fe8ccea14dc in ?? () from /usr/lib/libc.so.6 #6 0x00007fe8cce51998 in raise () from /usr/lib/libc.so.6 #7 0x00007fe8cce3b53d in abort () from /usr/lib/libc.so.6 #8 0x00007fe8cd49fede in QMessageLogger::fatal(char const*, ...) const () from /usr/lib/libQt5Core.so.5 #9 0x00007fe8cd49ff9d in qt_assert_x(char const*, char const*, char const*, int) () from /usr/lib/libQt5Core.so.5 #10 0x00007fe8cdeba025 in KIO::SlaveBasePrivate::verifyState (this=0x558d0bca0a90, cmdName=0x7fe8cdfaf8cc "timeoutSpecialCommand()") at /home/bernie/kde/src/kio/src/core/slavebase.cpp:196 #11 0x00007fe8cdeb2025 in KIO::SlaveBase::dispatchLoop (this=0x7ffef834bcb0) at /home/bernie/kde/src/kio/src/core/slavebase.cpp:318 #12 0x00007fe8c8e4a49c in kdemain (argc=4, argv=0x7ffef834bfc0) at /home/bernie/kde/src/kio/src/ioslaves/http/http.cpp:106 #13 0x0000558d0a4307e9 in main (argc=5, argv=0x7ffef834c118) at /home/bernie/kde/src/kio/src/kioslave/kioslave.cpp:152 [Inferior 1 (process 169481) detached]
I can confirm that this bug exist and i am hitting this one if i compile kio with Debug flag .
I have 90 of these crashes in /var/lib/systemd/coredump/
This is the check that fails: 194 void verifyState(const char *cmdName) 195 { 196 KIO_STATE_ASSERT(finalState(), 197 Q_FUNC_INFO, 198 qUtf8Printable(QStringLiteral("%1 did not call finished() or error()! Please fix the %2 KIO slave") 199 .arg(QLatin1String(cmdName)) 200 .arg(QCoreApplication::applicationName())));
The failing check was added in this commit: tree 74aa6a361d80ac78a36f4e9827cd88aed131a567 parent 7a267428fa3483137ee728ffc5bac6ba185d3052 author Harald Sitter <sitter@kde.org> Wed Aug 3 13:08:20 2022 +0200 committer Harald Sitter <sitter@kde.org> Tue Aug 9 19:15:01 2022 +0000 clear state after timeout'd special call this fixes a crash with the sftp worker. what happens is that when a worker uses the timeoutSpecialCommand infrastructure they'll get a special() call before the regular dispatch call. this would cause double-finished or double-errors emissions because we hadn't cleared the state after the timeout special call. to solve this problem we'll simply treat the timeout call like any other dispatch call and verify the state and then reset it back to idle we could also have continued but to prevent side effects of this fix I've opted to keep the previous control flow going where the timeout occurs in the same loop iteration as the dispatch. diff --git a/src/core/slavebase.cpp b/src/core/slavebase.cpp index 7f96bef8e..0ed1caf04 100644 --- a/src/core/slavebase.cpp +++ b/src/core/slavebase.cpp @@ -314,6 +314,9 @@ void SlaveBase::dispatchLoop() d->nextTimeout.invalidate(); d->timeoutData = QByteArray(); special(data); + // special calls finished(), verify and clear the state so the following dispatch starts with a clean slate + d->verifyState("timeoutSpecialCommand()"); + d->m_state = d->Idle; } Q_ASSERT(d->appConnection.inited());
This is the MR: https://invent.kde.org/frameworks/kio/-/merge_requests/946
Ok, perhaps something is special about the virtual override in HTTPProtocol::special() ? As far as I understand, `HTTPProtocol::httpClose(keepAlive = true)` will set timeoutData to 99, which causes special() to call httpCloseConnection(). Should it have called finished() afterwards? Elsewhere, I see calls to finished() just after httpClose()... but not everywhere: - HTTPProtocol::error(): the doc of finished() says you shouldn't call it after calling error(), so I guess this is ok? - HTTPProtocol::~HTTPProtocol(): Is it possible to destroy the instance while a timeout is still pending? - HTTPProtocol::proceedUntilResponseContent(): might return early is status != 0. Otherwise, it will call finish() either in sendHttpError() or outside.
I enabled debug logging in kio/src/ioslaves/http/http.cpp, and this is what I got: Sep 04 20:59:09 goreboot kioslave5[173862]: kf.kio.slaves.http: ============ Sending Header: Sep 04 20:59:09 goreboot kioslave5[173862]: kf.kio.slaves.http: "GET /rest/product/kde HTTP/1.1" Sep 04 20:59:09 goreboot kioslave5[173862]: kf.kio.slaves.http: "Host: bugs.kde.org" Sep 04 20:59:09 goreboot kioslave5[173862]: kf.kio.slaves.http: "Connection: keep-alive" Sep 04 20:59:09 goreboot kioslave5[173862]: kf.kio.slaves.http: "User-Agent: DrKonqi" Sep 04 20:59:09 goreboot kioslave5[173862]: kf.kio.slaves.http: "Pragma: no-cache" Sep 04 20:59:09 goreboot kioslave5[173862]: kf.kio.slaves.http: "Cache-control: no-cache" Sep 04 20:59:09 goreboot kioslave5[173862]: kf.kio.slaves.http: "Accept: application/json" Sep 04 20:59:09 goreboot kioslave5[173862]: kf.kio.slaves.http: "Accept-Encoding: gzip, deflate, x-gzip, x-deflate" Sep 04 20:59:09 goreboot kioslave5[173862]: kf.kio.slaves.http: "Accept-Charset: utf-8,*;q=0.5" Sep 04 20:59:09 goreboot kioslave5[173862]: kf.kio.slaves.http: "Accept-Language: en-US,en;q=0.9" Sep 04 20:59:09 goreboot kioslave5[173862]: kf.kio.slaves.http: "Content-Type: application/json" Sep 04 20:59:09 goreboot kioslave5[173862]: kf.kio.slaves.http: sent it! Sep 04 20:59:09 goreboot kioslave5[173862]: kf.kio.slaves.http: Sep 04 20:59:10 goreboot drkonqi[173769]: QJsonDocument({"akonadiserver":{"index":"15","key":"5e2ae85b669b42c19e30b4dcf419b9fb","project":"akonadiserver"},"baloo_file_extractor":{"index> Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: ============ Received Status Response: Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: "HTTP/1.1 200 OK" Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: QUrl("https://bugs.kde.org/rest/product/kde") response code: 200 previous response code: 0 Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: wasAuthError= false isAuthError= false sameAuthError= false Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: -- full response: "HTTP/1.1 200 OK\r\nDate: Mon, 05 Sep 2022 03:59:09 GMT\r\nServer: Apache/2.4.29 (Ubuntu)\r\nAccess-control-allow-headers: origin, content-t> Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: Content-type: "application/json" Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: Encoding-type: "charset" = "UTF-8" Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: before fixup "application/json" Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: after fixup "application/json" Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: parsed expire date from 'expires' header: "Mon, 05 Sep 2022 03:59:09 GMT" Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: Cache, adding QUrl("https://bugs.kde.org/rest/product/kde") Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: Emitting mimetype "application/json" Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: Previous Response: 0 Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: Current Response: 200 Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: "-1" bytes left. Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: Chunk size = 13240 bytes Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: bytesReceived: 4096 m_iSize: -1 Chunked: true BytesLeft: 9144 Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: Caching disabled because content size is too big. Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: bytesReceived: 4096 m_iSize: -1 Chunked: true BytesLeft: 5048 Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: bytesReceived: 4096 m_iSize: -1 Chunked: true BytesLeft: 952 Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: bytesReceived: 952 m_iSize: -1 Chunked: true BytesLeft: -1 Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: Chunk size = 0 bytes Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: bytesReceived: 0 m_iSize: -1 Chunked: true BytesLeft: 0 Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: EOD received! Left = "0" Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: keepAlive = true Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: keep alive ( 5 ) Sep 04 20:59:15 goreboot kioslave5[173862]: kf.kio.slaves.http: Sep 04 20:59:15 goreboot kioslave5[173862]: kf.kio.slaves.http: Sep 04 20:59:15 goreboot kioslave5[173862]: ASSERT failure in void KIO::SlaveBasePrivate::verifyState(const char*): "timeoutSpecialCommand() did not call finished() or error()! Please f>
As you can see from the timestamps, there's a gap of 5 seconds between the end of the request in HTTPProtocol::readBody() and the keepalive timeout: Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: EOD received! Left = "0" ... Sep 04 20:59:10 goreboot kioslave5[173862]: kf.kio.slaves.http: keep alive ( 5 ) Sep 04 20:59:15 goreboot kioslave5[173862]: kf.kio.slaves.http: Sep 04 20:59:15 goreboot kioslave5[173862]: kf.kio.slaves.http: Sep 04 20:59:15 goreboot kioslave5[173862]: ASSERT failure in void KIO::SlaveBasePrivate::verifyState(const char*): "timeoutSpecialCommand() did not call finished() or error()! Please f> This code seems to be expecting that an empty qCDebug() would print the function name, but it does not. Not knowing how to enable this, I'll add some more output manually...
I can reproduce this crash in plasma-discover too, it just takes longer because the keep-alive timeout is 60 seconds instead of 5 seconds.
Better debug trace: 2022-09-04 21:42:40.000 HTTPProtocol::readBody:4454: EOD received! Left = "0" 2022-09-04 21:42:40.000 HTTPProtocol::cacheFileClose:4875: HTTPProtocol::cacheFileClose() 2022-09-04 21:42:40.000 HTTPProtocol::httpClose:3923: keepAlive = true 2022-09-04 21:42:40.000 HTTPProtocol::cacheFileClose:4875: HTTPProtocol::cacheFileClose() 2022-09-04 21:42:40.000 HTTPProtocol::httpClose:3938: keep alive ( 60 ) 2022-09-04 21:42:40.000 KIO::SlaveBasePrivate::verifyState:196: verifyState() get() 2022-09-04 21:42:46.553 unknown:17: qrc:/qml/DiscoverPage.qml:17:13: QML InlineMessage: Cannot anchor to an item that isn't a parent or sibling. 2022-09-04 21:42:46.579 KIO::SlaveBasePrivate::verifyState:196: verifyState() fileSystemFreeSpace() 2022-09-04 21:42:46.579 KIO::SlaveBasePrivate::verifyState:196: verifyState() fileSystemFreeSpace() 2022-09-04 21:43:40.003 HTTPProtocol::special:3998: 2022-09-04 21:43:40.003 HTTPProtocol::httpCloseConnection:3958: 2022-09-04 21:43:40.004 KIO::SlaveBasePrivate::verifyState:196: verifyState() timeoutSpecialCommand() 2022-09-04 21:43:40.004 unknown:197: ASSERT failure in void KIO::SlaveBasePrivate::verifyState(const char*): "timeoutSpecialCommand() did not call finished() or error()! Please fix the kio_http KIO slave", file /home/bernie/kde/src/kio/src/core/slavebase.cpp, line 197
Worked around in master: https://invent.kde.org/frameworks/kio/-/commit/a9c3fc3caf8ff5e57f0dec81265911529f7c8b50 The proper fix will be porting to the new state system https://invent.kde.org/frameworks/kio/-/merge_requests/969