Client not always stops when requested by Windows #8979

jnweiger · 2021-09-07T11:30:44Z

Seen (again) with 2.9.0-rc2

run any older version of the owncloud client
Download the msi installer of an update
click start the install.
It announces, it needs to shutdown owncloud and sometimes also explorer
when the user confirms. It usually fails to shut down one of the two.

After a second round it normally succeeds.

The text was updated successfully, but these errors were encountered:

michaelstingl · 2021-09-07T14:32:21Z

Anything in the MSI log?

github-actions · 2021-10-08T00:28:51Z

This issue was marked stale because it has been open for 30 days with no activity. Remove the stale label or comment or this will be closed in 7 days.

TheOneRing · 2021-10-08T07:02:24Z

TODO: Test how the client reacts to WM_CLOSE
@dschmidt I assume WM_CLOSE is what msi sends to the client?

TheOneRing · 2021-10-11T09:35:31Z

See:
https://www.advancedinstaller.com/user-guide/qa-vista-restart-manager.html
https://wixtoolset.org/documentation/manual/v3/xsd/util/restartresource.html

looks like we can add code to better handle this

Also see:
https://docs.microsoft.com/en-us/windows/win32/shutdown/wm-queryendsession
https://docs.microsoft.com/en-us/windows/win32/shutdown/wm-endsession

TheOneRing · 2021-11-16T15:06:42Z

The issue still occurs, in order to be able to receive the message, it appears that the window needs to shown at least once.

TheOneRing · 2021-11-17T12:07:05Z

Please test with close_window.zip.
close_window owncloud.exe

With older clients the expected behaviour is that the client keeps running, independent if the settings ui was shown or not.
Once #9220 was merged the client should shutdown cleanly.

Additionally please check whether the client closes cleanly when the user logs off, with an old client and a new client.
Please test what happens when the client is updated by the installer, does the running owncloud.exe close as expected?

A clean shutdown with the new change should look similar to:

11-17 13:06:38:279 [ info sync.utility ]:	Received WM_ENDSESSION quitting
11-17 13:06:39:143 [ info gui.account.manager ]:	Saving  0  unknown certs.
11-17 13:06:39:143 [ info gui.account.manager ]:	Saving cookies. "C:/Users/hanna/AppData/Local/ownCloud/cookies0.db"
11-17 13:06:39:360 [ info sync.credentials.manager ]:	set "ownCloud_credentials:demo.owncloud.com:6c982360-b627-4cad-9196-41d7fba841a9:http/oauthtoken"
11-17 13:06:39:361 [ info gui.account.manager ]:	Saving  0  unknown certs.
11-17 13:06:39:361 [ info gui.account.manager ]:	Saving cookies. "C:/Users/hanna/AppData/Local/ownCloud/cookies0.db"
11-17 13:06:39:576 [ info gui.account.manager ]:	Saved all account settings, status: QSettings::NoError
11-17 13:06:39:578 [ info sync.database ]:	Closing DB "C:/Users/hanna/ownCloud25/.sync_journal.db"

In a clean shutdown of an old client WM_ENDSESSION would be missing.

gabi18 · 2021-11-18T09:12:40Z

Tested testpilotcloud-2.9.2-rc3 on Windows 10 Version 20H2 (Build 19042.1348) VirtualBox VM:

as expected, close_window testpilotcloud.exe doesn't shutdown the client reliable (first attempt always fails, second attempt sometimes is successful)
on user logout the client shutdown isn't done cleanly, no message "Closing DB..." in log-file

gabi18 · 2021-11-18T11:27:36Z

Tested testpilotcloud-2.9.2-rc4.6086.x64 on Windows 10 Version 20H2 (Build 19042.1348) VirtualBox VM:

on close_window testpilotcloud.exe, a clean, reliable shutdown of the testpilotcloud (both tesetd: client settings UI shown/not shown) is done, the DB is closed correctly

11-18 12:12:10:700 [ info sync.utility ]:	Received WM_ENDSESSION quitting
11-18 12:12:10:746 [ debug gui.account.manager ]	[ OCC::AccountManager::saveAccount ]:	Saving account "https://gm-owncloud-1080-test-server.owncloud.works/"
11-18 12:12:10:761 [ info gui.account.manager ]:	Saving  0  unknown certs.
11-18 12:12:10:761 [ info gui.account.manager ]:	Saving cookies. "C:/Users/gabi/AppData/Local/testpilotcloud/cookies0.db"
11-18 12:12:10:761 [ debug sync.cookiejar ]	[ OCC::CookieJar::save ]:	"C:/Users/gabi/AppData/Local/testpilotcloud/cookies0.db"
11-18 12:12:10:784 [ debug gui.account.manager ]	[ OCC::AccountManager::saveAccount ]:	Saved account settings, status: QSettings::NoError
11-18 12:12:10:784 [ info sync.credentials.manager ]:	set "testpilotcloud_credentials:gm-owncloud-1080-test-server.owncloud.works:b9a0fd8b-c797-460b-86b5-03f6133aa287:http/password"
11-18 12:12:10:784 [ info gui.account.manager ]:	Saving  0  unknown certs.
11-18 12:12:10:784 [ info gui.account.manager ]:	Saving cookies. "C:/Users/gabi/AppData/Local/testpilotcloud/cookies0.db"
11-18 12:12:10:784 [ debug sync.cookiejar ]	[ OCC::CookieJar::save ]:	"C:/Users/gabi/AppData/Local/testpilotcloud/cookies0.db"
11-18 12:12:10:784 [ info gui.account.manager ]:	Saved all account settings, status: QSettings::NoError
11-18 12:12:10:784 [ debug gui.folderwatcher ]	[ OCC::WatcherThread::watchChanges ]:	Received stop event, aborting folder watcher thread
11-18 12:12:10:784 [ info sync.database ]:	Closing DB "C:/Users/gabi/testpilotcloud/.sync_journal.db"
11-18 12:12:10:817 [ debug gui.socketapi ]	[ OCC::SocketApi::~SocketApi ]:	dtor

on user logout the behaviour is like before, same for restart and system shutdown

The logfile ends without "Closing DB..."

11-18 12:29:03:235 [ debug sync.database ]	[ OCC::SyncJournalDb::commitInternal ]:	Transaction commit "setSelectiveSyncList" and starting new transaction
11-18 12:29:03:238 [ info gui.application ]:	Sync state changed for folder  "https://gm-owncloud-1080-test-server.owncloud.works/remote.php/dav/files/demo/" :  "Success"

20211118_1229_owncloud.log.0_NOT_Closing_DB.gz

When starting testpilot on commandline with --logflush the last logline is:

11-18 13:06:09:545 [ debug sync.networkjob ]	[ OCC::AbstractNetworkJob::slotFinished ]:	Network job finished OCC::PropfindJob("https://gm-owncloud-1080-test-server.owncloud.works/remote.php/dav/files/demo/", "7359f6d9-89ba-416f-8e56-1bd3888cee47", "7359f6d9-89ba-416f-8e56-1bd3888cee47")
11-18 13:06:15:108 [ info sync.utility ]:	Received WM_ENDSESSION quitting

testpilot-logout.zip

Explorer shows that db was not closed correctly

gabi18 · 2021-11-22T12:01:23Z

Tested update from testpilotcloud-2.9.2-rc4.6086.x64 to testpilotcloud-2.9.2-rc4.6087.x64 on Windows 10 Version 20H2 (Build 19042.1348) VirtualBox VM

The testpilot-client is shutdown correctly when requested from msi installer:

12:51:41:907 [ info sync.utility ]:       Received WM_ENDSESSION quitting
11-22 12:51:41:955 [ debug gui.account.manager ]        [ OCC::AccountManager::saveAccount ]:   Saving account "https://gm-owncloud-1080-test-server.owncloud.works/"
11-22 12:51:41:970 [ info gui.account.manager ]:        Saving  0  unknown certs.
11-22 12:51:41:970 [ info gui.account.manager ]:        Saving cookies. "C:/Users/gabi/AppData/Local/testpilotcloud/cookies0.db"
11-22 12:51:41:970 [ debug sync.cookiejar ]     [ OCC::CookieJar::save ]:       "C:/Users/gabi/AppData/Local/testpilotcloud/cookies0.db"
11-22 12:51:41:970 [ debug gui.account.manager ]        [ OCC::AccountManager::saveAccount ]:   Saved account settings, status: QSettings::NoError
11-22 12:51:41:970 [ info sync.credentials.manager ]:   set "testpilotcloud_credentials:gm-owncloud-1080-test-server.owncloud.works:b9a0fd8b-c797-460b-86b5-03f6133aa287:http/password"
11-22 12:51:41:970 [ info gui.account.manager ]:        Saving  0  unknown certs.
11-22 12:51:41:970 [ info gui.account.manager ]:        Saving cookies. "C:/Users/gabi/AppData/Local/testpilotcloud/cookies0.db"
11-22 12:51:41:970 [ debug sync.cookiejar ]     [ OCC::CookieJar::save ]:       "C:/Users/gabi/AppData/Local/testpilotcloud/cookies0.db"
11-22 12:51:42:002 [ info gui.account.manager ]:        Saved all account settings, status: QSettings::NoError
11-22 12:51:42:002 [ debug gui.folderwatcher ]  [ OCC::WatcherThread::watchChanges ]:   Received stop event, aborting folder watcher thread
11-22 12:51:42:002 [ info sync.database ]:      Closing DB "C:/Users/gabi/testpilotcloud/.sync_journal.db"
11-22 12:51:42:017 [ debug gui.socketapi ]      [ OCC::SocketApi::~SocketApi ]: dtor
11-22 12:51:42:017 [ info gui.socketapi ]:      Lost connection  QLocalSocket(0x11fdc4b0d30)

gabi18 · 2021-11-23T09:28:25Z

Confirmed that testpilot is shutdown correctly when updating testpilotcloud-2.9.2-rc4 -> testpilotcloud-2.9.2-rc5.6114.x64.msi

11-18 09:45:01:343 [ info sync.utility ]:       Received WM_ENDSESSION quitting
11-18 09:45:01:390 [ debug gui.account.manager ]        [ OCC::AccountManager::saveAccount ]:   Saving account "https://gm-owncloud-1080-test-server.owncloud.works/"
11-18 09:45:01:421 [ info gui.account.manager ]:        Saving  0  unknown certs.
11-18 09:45:01:421 [ info gui.account.manager ]:        Saving cookies. "C:/Users/gabi/AppData/Local/testpilotcloud/cookies0.db"
11-18 09:45:01:427 [ debug sync.cookiejar ]     [ OCC::CookieJar::save ]:       "C:/Users/gabi/AppData/Local/testpilotcloud/cookies0.db"
11-18 09:45:01:460 [ debug gui.account.manager ]        [ OCC::AccountManager::saveAccount ]:   Saved account settings, status: QSettings::NoError
11-18 09:45:01:460 [ info sync.credentials.manager ]:   set "testpilotcloud_credentials:gm-owncloud-1080-test-server.owncloud.works:b9a0fd8b-c797-460b-86b5-03f6133aa287:http/password"
11-18 09:45:01:460 [ info gui.account.manager ]:        Saving  0  unknown certs.
11-18 09:45:01:460 [ info gui.account.manager ]:        Saving cookies. "C:/Users/gabi/AppData/Local/testpilotcloud/cookies0.db"
11-18 09:45:01:460 [ debug sync.cookiejar ]     [ OCC::CookieJar::save ]:       "C:/Users/gabi/AppData/Local/testpilotcloud/cookies0.db"
11-18 09:45:01:492 [ info gui.account.manager ]:        Saved all account settings, status: QSettings::NoError
11-18 09:45:01:506 [ debug gui.folderwatcher ]  [ OCC::WatcherThread::watchChanges ]:   Received stop event, aborting folder watcher thread
11-18 09:45:01:506 [ info sync.database ]:      Closing DB "C:/Users/gabi/testpilotcloud/.sync_journal.db"
11-18 09:45:01:527 [ debug gui.socketapi ]      [ OCC::SocketApi::~SocketApi ]: dtor

gabi18 · 2021-11-23T10:57:56Z

Scenario "User logout" tested with testpilotcloud-2.9.2-rc5.6114.x64.msi:

after user logout and login in again there isn't a message "Received WM_ENDSESSION quitting" nor a logline "Closing DB ..." in the logs.
mostly the db is closed
but it also occured that it remains open:

testpilot2.zip

TheOneRing · 2021-11-23T11:56:27Z

In that scenario using --logfile won't work as expected as the console process might get killed before us.
Please use the internal log file.

gabi18 · 2021-11-23T13:03:41Z

The internal logfile when the db is closed after user logout/login also doesn't contain the line "Closing DB ..."

20211122_1047_owncloud.log.zip

but the db is closed:

gabi18 · 2021-11-23T13:28:17Z

Summary for testscenario "User logout" testpilotcloud-2.9.2-rc5.6114.x64.msi on Windows 10 Version 20H2 (Build 19042.1348) VirtualBox VM:

works almost reliable, Client not always stops when requested by Windows #8979 (comment) is not reproducible
db is closed - but logfile doesn't contain "Closing DB..."
20211123_1414_owncloud.log.zip

gabi18 · 2021-11-23T14:09:12Z

Finally got a logfile with "Closing DB..." (--logflush was missing)

11-23 14:50:47:743 [ debug gui.folderwatcher ]  [ OCC::WatcherThread::watchChanges ]:   Received stop event, aborting folder watcher thread
11-23 14:50:47:743 [ info sync.database ]:      Closing DB "C:/Users/gabi/testpilotcloud/.sync_journal.db"
11-23 14:50:47:758 [ debug gui.socketapi ]      [ OCC::SocketApi::~SocketApi ]: dtor
11-23 14:50:47:758 [ info gui.socketapi ]:      Lost connection  QLocalSocket(0x1cdca7022f0)
11-23 14:50:47:773 [ debug sync.utility ]       [ `anonymous-namespace'::startShutdownWatcher::::operator() ]:  app closed
11-23 14:50:47:773 [ info sync.utility ]:       WM_ENDSESSION successfully shut down 28472197

20211123_1448_owncloud.log.zip

TheOneRing · 2021-11-25T09:44:14Z

@gabi18 Can we close this one?

gabi18 · 2021-11-25T13:12:49Z

Yes, I think so.
I have just retested update 2.9.2 rc5 to v2.9.2, the msi installer shutdown works reliable.
Also on system shutdown the db is closed successfully.

11-25 13:46:45:370 [ info sync.database ]:      Closing DB "C:/Users/gabi/testpilotcloud/.sync_journal.db"
11-25 13:46:45:430 [ debug gui.socketapi ]      [ OCC::SocketApi::~SocketApi ]: dtor
11-25 13:46:45:430 [ info gui.socketapi ]:      Lost connection  QLocalSocket(0x21f53cf49a0)
11-25 13:46:45:430 [ debug sync.utility ]       [ `anonymous-namespace'::startShutdownWatcher::::operator() ]:  app closed
11-25 13:46:45:430 [ info sync.utility ]:       WM_ENDSESSION successfully shut down 3292762

jnweiger mentioned this issue Sep 7, 2021

Release Desktop 2.9 #8869

Closed

39 tasks

github-actions bot added the Stale label Oct 8, 2021

TheOneRing removed the Stale label Oct 8, 2021

TheOneRing added this to the 2.9.2 milestone Oct 8, 2021

TheOneRing self-assigned this Oct 11, 2021

TheOneRing changed the title ~~[QA] manual update in win10 often fails to stop the application~~ Client not always stops when requested by Windows Oct 13, 2021

TheOneRing added the Windows label Oct 13, 2021

TheOneRing mentioned this issue Oct 13, 2021

Fix application shutdown during Windows logout #9142

Merged

TheOneRing mentioned this issue Nov 16, 2021

Ensure we have a window to receive the nativeEvents #9219

Closed

TheOneRing linked a pull request Nov 17, 2021 that will close this issue

Ensure we receive WM_ENDSESSION #9220

Merged

gabi18 closed this as completed Nov 25, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Client not always stops when requested by Windows #8979

Client not always stops when requested by Windows #8979

jnweiger commented Sep 7, 2021

michaelstingl commented Sep 7, 2021 •

edited

Loading

github-actions bot commented Oct 8, 2021

TheOneRing commented Oct 8, 2021

TheOneRing commented Oct 11, 2021

TheOneRing commented Nov 16, 2021

TheOneRing commented Nov 17, 2021 •

edited

Loading

gabi18 commented Nov 18, 2021 •

edited

Loading

gabi18 commented Nov 18, 2021 •

edited

Loading

gabi18 commented Nov 22, 2021

gabi18 commented Nov 23, 2021 •

edited

Loading

gabi18 commented Nov 23, 2021 •

edited

Loading

TheOneRing commented Nov 23, 2021

gabi18 commented Nov 23, 2021 •

edited

Loading

gabi18 commented Nov 23, 2021 •

edited

Loading

gabi18 commented Nov 23, 2021

TheOneRing commented Nov 25, 2021

gabi18 commented Nov 25, 2021

Client not always stops when requested by Windows #8979

Client not always stops when requested by Windows #8979

Comments

jnweiger commented Sep 7, 2021

michaelstingl commented Sep 7, 2021 • edited Loading

github-actions bot commented Oct 8, 2021

TheOneRing commented Oct 8, 2021

TheOneRing commented Oct 11, 2021

TheOneRing commented Nov 16, 2021

TheOneRing commented Nov 17, 2021 • edited Loading

gabi18 commented Nov 18, 2021 • edited Loading

gabi18 commented Nov 18, 2021 • edited Loading

gabi18 commented Nov 22, 2021

gabi18 commented Nov 23, 2021 • edited Loading

gabi18 commented Nov 23, 2021 • edited Loading

TheOneRing commented Nov 23, 2021

gabi18 commented Nov 23, 2021 • edited Loading

gabi18 commented Nov 23, 2021 • edited Loading

gabi18 commented Nov 23, 2021

TheOneRing commented Nov 25, 2021

gabi18 commented Nov 25, 2021

michaelstingl commented Sep 7, 2021 •

edited

Loading

TheOneRing commented Nov 17, 2021 •

edited

Loading

gabi18 commented Nov 18, 2021 •

edited

Loading

gabi18 commented Nov 18, 2021 •

edited

Loading

gabi18 commented Nov 23, 2021 •

edited

Loading

gabi18 commented Nov 23, 2021 •

edited

Loading

gabi18 commented Nov 23, 2021 •

edited

Loading

gabi18 commented Nov 23, 2021 •

edited

Loading