[frameworks-kio] [Bug 458448] timeoutSpecialCommand() did not call finished() or error()! Please fix the kio_http KIO slave
https://bugs.kde.org/show_bug.cgi?id=458448 Harald Sitter changed: What|Removed |Added Resolution|--- |FIXED Status|CONFIRMED |RESOLVED --- Comment #11 from Harald Sitter --- 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 -- You are receiving this mail because: You are watching all bug changes.
[frameworks-kio] [Bug 458448] timeoutSpecialCommand() did not call finished() or error()! Please fix the kio_http KIO slave
https://bugs.kde.org/show_bug.cgi?id=458448 --- Comment #10 from Bernie Innocenti --- 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 -- You are receiving this mail because: You are watching all bug changes.
[frameworks-kio] [Bug 458448] timeoutSpecialCommand() did not call finished() or error()! Please fix the kio_http KIO slave
https://bugs.kde.org/show_bug.cgi?id=458448 --- Comment #9 from Bernie Innocenti --- 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. -- You are receiving this mail because: You are watching all bug changes.
[frameworks-kio] [Bug 458448] timeoutSpecialCommand() did not call finished() or error()! Please fix the kio_http KIO slave
https://bugs.kde.org/show_bug.cgi?id=458448 --- Comment #8 from Bernie Innocenti --- 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... -- You are receiving this mail because: You are watching all bug changes.
[frameworks-kio] [Bug 458448] timeoutSpecialCommand() did not call finished() or error()! Please fix the kio_http KIO slave
https://bugs.kde.org/show_bug.cgi?id=458448
--- Comment #7 from Bernie Innocenti ---
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::SlaveBasePriv
[frameworks-kio] [Bug 458448] timeoutSpecialCommand() did not call finished() or error()! Please fix the kio_http KIO slave
https://bugs.kde.org/show_bug.cgi?id=458448 --- Comment #6 from Bernie Innocenti --- 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. -- You are receiving this mail because: You are watching all bug changes.
[frameworks-kio] [Bug 458448] timeoutSpecialCommand() did not call finished() or error()! Please fix the kio_http KIO slave
https://bugs.kde.org/show_bug.cgi?id=458448 --- Comment #5 from Bernie Innocenti --- This is the MR: https://invent.kde.org/frameworks/kio/-/merge_requests/946 -- You are receiving this mail because: You are watching all bug changes.
[frameworks-kio] [Bug 458448] timeoutSpecialCommand() did not call finished() or error()! Please fix the kio_http KIO slave
https://bugs.kde.org/show_bug.cgi?id=458448
Bernie Innocenti changed:
What|Removed |Added
CC||sit...@kde.org
--- Comment #4 from Bernie Innocenti ---
The failing check was added in this commit:
tree 74aa6a361d80ac78a36f4e9827cd88aed131a567
parent 7a267428fa3483137ee728ffc5bac6ba185d3052
author Harald Sitter Wed Aug 3 13:08:20 2022 +0200
committer Harald Sitter Tue Aug 9 19:15:01 2022 +
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());
--
You are receiving this mail because:
You are watching all bug changes.
[frameworks-kio] [Bug 458448] timeoutSpecialCommand() did not call finished() or error()! Please fix the kio_http KIO slave
https://bugs.kde.org/show_bug.cgi?id=458448
--- Comment #3 from Bernie Innocenti ---
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(;
--
You are receiving this mail because:
You are watching all bug changes.
[frameworks-kio] [Bug 458448] timeoutSpecialCommand() did not call finished() or error()! Please fix the kio_http KIO slave
https://bugs.kde.org/show_bug.cgi?id=458448 --- Comment #2 from Bernie Innocenti --- I have 90 of these crashes in /var/lib/systemd/coredump/ -- You are receiving this mail because: You are watching all bug changes.
[frameworks-kio] [Bug 458448] timeoutSpecialCommand() did not call finished() or error()! Please fix the kio_http KIO slave
https://bugs.kde.org/show_bug.cgi?id=458448 Ömer Fadıl USTA changed: What|Removed |Added Status|REPORTED|CONFIRMED Ever confirmed|0 |1 CC||omeru...@gmail.com --- Comment #1 from Ömer Fadıl USTA --- I can confirm that this bug exist and i am hitting this one if i compile kio with Debug flag . -- You are receiving this mail because: You are watching all bug changes.
