Meaningless error message: ...e",3];

[Bockeman]

How to use GitHub

• Please use the 👍 reaction to show that you are affected by the same issue.
• Please don't comment if you have no relevant information to add. It's just extra noise for everyone subscribed to this issue.
• Subscribe to receive notifications on status change and new comments.

Expected behaviour

Meaningful warnings or error messages when something goes wrong.

Actual behaviour

A red bar appears with the text ...e",3];
This happens frequently when new files are added to sync folder.

Steps to reproduce

1. Run Nextcloud-client as normal
2. Change or add files to a sync folder
3. Wait for silly red bar to appear with meaningless text: ...e",3];

Client configuration

Client version: 3.0.1
Operating system: Win10
OS language: English

Server configuration

Nextcloud version: 19.0.3

Storage backend (external storage): No external storage. Files are NFS mounted (gluster).

Logs

[er-vin]

OK... this is a first. Could we have debug logs from a sync exhibiting that odd error message?

[Bockeman]

Thanks for responding @er-vin
Please could you be a bit more explicit about what you mean by "debug logs", which logs, where located, how to enable, etc.

I googled "nextcloud-client debug logs", because I think you want to examine client side messages, but this search only revealed the server side insturctions:
https://docs.nextcloud.com/server/latest/admin_manual/configuration_server/logging_configuration.html

As it happens, the default configuration is "'loglevel' => 0,", so I do have some logging information:
egrep '2020-09-24T(1|2).*192.168.0.30.*Video' /srv/gluvol1/vault/nextcloud.log
{"reqId":"X2z5JPXayFutojffS-xGWAAAAJg","level":0,"time":"2020-09-24T19:53:08+00:00","remoteAddr":"192.168.0.30","user":"bobw","app":"webdav","method":"PROPFIND","url":"/verivault/remote.php/dav/files/bobw/Video","message":{"Exception":"Sabre\DAV\Exception\ServiceUnavailable","Message":"System in maintenance mode.","Code":0,"Trace":[{"file":"/srv/gluvol1/var/www/html/verivault/3rdparty/sabre/event/lib/WildcardEmitterTrait.php","line":89,"function":"checkMaintenanceMode","class":"OCA\DAV\Connector\Sabre\MaintenancePlugin","type":"->","args":[{"class":"Sabre\HTTP\Request"},{"class":"Sabre\HTTP\Response"}]},{"file":"/srv/gluvol1/var/www/html/verivault/3rdparty/sabre/dav/lib/DAV/Server.php","line":458,"function":"emit","class":"Sabre\DAV\Server","type":"->","args":["beforeMethod:PROPFIND",[{"class":"Sabre\HTTP\Request"},{"class":"Sabre\HTTP\Response"}]]},{"file":"/srv/gluvol1/var/www/html/verivault/3rdparty/sabre/dav/lib/DAV/Server.php","line":251,"function":"invokeMethod","class":"Sabre\DAV\Server","type":"->","args":[{"class":"Sabre\HTTP\Request"},{"class":"Sabre\HTTP\Response"}]},{"file":"/srv/gluvol1/var/www/html/verivault/3rdparty/sabre/dav/lib/DAV/Server.php","line":319,"function":"start","class":"Sabre\DAV\Server","type":"->","args":[]},{"file":"/srv/gluvol1/var/www/html/verivault/apps/dav/lib/Server.php","line":320,"function":"exec","class":"Sabre\DAV\Server","type":"->","args":[]},{"file":"/srv/gluvol1/var/www/html/verivault/apps/dav/appinfo/v2/remote.php","line":35,"function":"exec","class":"OCA\DAV\Server","type":"->","args":[]},{"file":"/srv/gluvol1/var/www/html/verivault/remote.php","line":167,"args":["/srv/gluvol1/var/www/html/verivault/apps/dav/appinfo/v2/remote.php"],"function":"require_once"}],"File":"/srv/gluvol1/var/www/html/verivault/apps/dav/lib/Connector/Sabre/MaintenancePlugin.php","Line":83,"CustomMessage":"--"},"userAgent":"Mozilla/5.0 (Windows) mirall/3.0.1stable-Win64 (build 20200828) (Nextcloud)","version":"19.0.3.1"}

As you can see, this is the only message after 10:00 on the day I reported this issue, associated with "Video" because that was the sync folder that I had captured the problem, and associated with the IP address of the device that showed the problem.
But this message line is clearly unrelated to the reported problem because it is a standard message for when the server was in maintenance mode -- which it was later in the day, and unrelated to the reported problem.

Further information:
I have 13 sync folders. Total "in use" reported by nextcloud-client is 17,611 GB (yes ~17TB).
Identical or similar meaningless error messages have been occuring several times a day, dependent upon activity, and I just reported one that I captured.

I also looked at the log files on the client (via Samba mount). A snippet from before 10:00 does show some errors:
/mnt/veriulan/d/Data/BobW/AppData/Roaming/Nextcloud/Video_sync.log

08:15:54||Car_Bob/202x/2020/2008 540i/PARKING/20200827_104237/MDI_20200827_105525_2.avi|INST_NEW|Up|1598522144|17342a26ed8be3e488247ef17d9a0305|19264598|08436581oc3hd6f2u8cw|4||201|0|0||||
08:15:55||Car_Bob/202x/2020/2008 540i/PARKING/20200827_104237/MDI_20200827_113108_2.avi|INST_NEW|Up|1598524282|c49befda9263d8276089eabbb4596945|13796504|08436582oc3hd6f2u8cw|4||201|0|0||||
||Car_Bob/202x/2020/2008 540i/PARKING/20200827_104237/MDI_20200827_113125_2.avi|INST_NEW|Up|1598524306||19726424||2|Server replied "500 Internal Server Error" to "MOVE https:///verivault/remote.php/dav/uploads/bobw/2653625430/.file" (An exception occurred while executing 'UPDATE oc_filecache SET mtime = GREATEST(mtime, ?), etag = ? WHERE (storage = ?) AND (path_hash IN ('d41d8cd98f00b204e9800998ecf8427e', '45b963397aa40d4a0063e0d85e4fe7a1', '3abaf74f138bc80088f1cc5d3c7ae8be', '92eae875877e329aec9640ba25e0910b', 'd29c309de6483a77adf6a0aacc6eca2d', '3823220725166c1805c6326d09464cb6', '11a169a6f8fdddd48eda4c5657573247', '5bf6cf6e39ce0b01fabf2985b633b5da', 'de7cc7b51b2e495e7689fbfa7548c05b'))' with params [1600935361, "5f6c55c19bf6b", 3]:
SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction)|500|0|0||||
08:15:58||Car_Bob/202x/2020/2009 540i/INFINITE/20200827_111052/REC_20200827_111755_2.avi|INST_REMOVE|Up|1598523536|29773afcbdc96d09864306176bebc37a|93826106|08435810oc3hd6f2u8cw|4||204|0|0||||
08:15:58||Car_Bob/202x/2020/2009 540i/INFINITE/20200827_111052/REC_20200827_111856_2.avi|INST_REMOVE|Up|1598523596|887e5f6d6057479fb68475a109bb8d25|92754330|08435811oc3hd6f2u8cw|4||204|0|0||||
||Car_Bob/202x/2020/2009 540i/INFINITE/20200827_111052/REC_20200827_112258_2.avi|INST_REMOVE|Up|1598523838|4d0b54deb08a5f1ff249fab67fa607fa|93242498|08435826oc3hd6f2u8cw|2|Server replied "500 Internal Server Error" to "DELETE https:///verivault/remote.php/dav/files/bobw/Video/Car_Bob/202x/2020/2009 540i/INFINITE/20200827_111052/REC_20200827_112258_2.avi"|500|0|0||||
08:16:01||Car_Bob/202x/2020/2009 540i/INFINITE/20200827_111052/REC_20200827_111956_2.avi|INST_REMOVE|Up|1598523656|fd3acf293eb49b66ef74a4043776875a|93382656|08435809oc3hd6f2u8cw|4||204|0|0||||
08:16:01||Car_Bob/202x/2020/2009 540i/INFINITE/20200827_111052/REC_20200827_112056_2.avi|INST_REMOVE|Up|1598523718|767f28bc65c4132830ed95261c3a6404|93648016|08435814oc3hd6f2u8cw|4||204|0|0||||
||Car_Bob/202x/2020/2008 540i/PARKING/20200827_104237/MDI_20200827_113147_2.avi|INST_NEW|Up|1598524326||18301940||2|Server replied "500 Internal Server Error" to "MOVE https:///verivault/remote.php/dav/uploads/bobw/3866134849/.file" (An exception occurred while executing 'UPDATE oc_filecache SET mtime = GREATEST(mtime, ?), etag = ? WHERE (storage = ?) AND (path_hash IN ('d41d8cd98f00b204e9800998ecf8427e', '45b963397aa40d4a0063e0d85e4fe7a1', '3abaf74f138bc80088f1cc5d3c7ae8be', '92eae875877e329aec9640ba25e0910b', 'd29c309de6483a77adf6a0aacc6eca2d', '3823220725166c1805c6326d09464cb6', '11a169a6f8fdddd48eda4c5657573247', '5bf6cf6e39ce0b01fabf2985b633b5da', 'de7cc7b51b2e495e7689fbfa7548c05b'))' with params [1600935364, "5f6c55c4c7a03", 3]:
SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction)|500|0|0||||
08:16:02||Car_Bob/202x/2020/2009 540i/INFINITE/20200827_111052/REC_20200827_112157_2.avi|INST_REMOVE|Up|1598523778|c3ed78980494125030254d3b7d7073e0|93388760|08435824oc3hd6f2u8cw|4||204|0|0||||
08:16:05||Car_Bob/202x/2020/2009 540i/INFINITE/20200827_111052/REC_20200827_112759_2.avi|INST_REMOVE|Up|1598524140|c53d0937629e504eb09f88f2cf463d9d|93279848|08435842oc3hd6f2u8cw|4||204|0|0||||
08:16:05||Car_Bob/202x/2020/2009 540i/INFINITE/20200827_111052/REC_20200827_112659_2.avi|INST_REMOVE|Up|1598524080|a0f4769a1f81c1d2b4f1ec3db5eae693|93377326|08435836oc3hd6f2u8cw|4||204|0|0||||

But I do not think these are relevant.

egrep '2020-09-24T(1|2)' /mnt/veriulan/d/Data/BobW/AppData/Roaming/Nextcloud/Video_sync.log
#=#=#=# Syncrun started 2020-09-24T10:37:46Z
#=#=#=#=# Propagation starts 2020-09-24T10:38:03Z (last step: 17125 msec, total: 17125 msec)
#=#=#=# Syncrun finished 2020-09-24T10:38:03Z (last step: 303 msec, total: 17428 msec)
#=#=#=# Syncrun started 2020-09-24T12:38:08Z
#=#=#=#=# Propagation starts 2020-09-24T12:38:26Z (last step: 17591 msec, total: 17591 msec)
#=#=#=# Syncrun finished 2020-09-24T12:38:26Z (last step: 280 msec, total: 17872 msec)
#=#=#=# Syncrun started 2020-09-24T12:38:33Z
#=#=#=#=# Propagation starts 2020-09-24T12:38:36Z (last step: 3516 msec, total: 3516 msec)
#=#=#=# Syncrun finished 2020-09-24T12:38:36Z (last step: 272 msec, total: 3788 msec)
#=#=#=# Syncrun started 2020-09-24T14:38:41Z
#=#=#=#=# Propagation starts 2020-09-24T14:38:58Z (last step: 17549 msec, total: 17549 msec)
#=#=#=# Syncrun finished 2020-09-24T14:38:58Z (last step: 298 msec, total: 17847 msec)
#=#=#=# Syncrun started 2020-09-24T14:39:05Z
#=#=#=#=# Propagation starts 2020-09-24T14:39:09Z (last step: 3494 msec, total: 3494 msec)
#=#=#=# Syncrun finished 2020-09-24T14:39:09Z (last step: 308 msec, total: 3803 msec)
#=#=#=# Syncrun started 2020-09-24T15:39:13Z
#=#=#=#=# Propagation starts 2020-09-24T15:39:32Z (last step: 19164 msec, total: 19164 msec)
#=#=#=# Syncrun finished 2020-09-24T15:39:32Z (last step: 304 msec, total: 19469 msec)
#=#=#=# Syncrun started 2020-09-24T17:39:42Z
#=#=#=#=# Propagation starts 2020-09-24T17:39:59Z (last step: 16849 msec, total: 16849 msec)
#=#=#=# Syncrun finished 2020-09-24T17:39:59Z (last step: 272 msec, total: 17122 msec)
#=#=#=# Syncrun started 2020-09-24T17:40:06Z
#=#=#=#=# Propagation starts 2020-09-24T17:40:09Z (last step: 3410 msec, total: 3410 msec)
#=#=#=# Syncrun finished 2020-09-24T17:40:09Z (last step: 273 msec, total: 3684 msec)
#=#=#=# Syncrun started 2020-09-24T19:29:48Z
#=#=#=#=# Propagation starts 2020-09-24T19:30:05Z (last step: 17281 msec, total: 17281 msec)
#=#=#=# Syncrun finished 2020-09-24T19:30:05Z (last step: 284 msec, total: 17566 msec)
#=#=#=# Syncrun started 2020-09-24T19:33:35Z
#=#=#=#=# Propagation starts 2020-09-24T19:33:52Z (last step: 16899 msec, total: 16899 msec)
#=#=#=# Syncrun finished 2020-09-24T19:33:52Z (last step: 279 msec, total: 17179 msec)
#=#=#=# Syncrun started 2020-09-24T19:53:07Z
#=#=#=# Syncrun finished 2020-09-24T19:53:08Z (last step: 616 msec, total: 616 msec)
#=#=#=# Syncrun started 2020-09-24T19:53:34Z
#=#=#=#=# Propagation starts 2020-09-24T19:53:37Z (last step: 3347 msec, total: 3347 msec)
#=#=#=# Syncrun finished 2020-09-24T19:53:38Z (last step: 284 msec, total: 3631 msec)
#=#=#=# Syncrun started 2020-09-24T21:53:59Z
#=#=#=#=# Propagation starts 2020-09-24T21:54:26Z (last step: 26950 msec, total: 26950 msec)
#=#=#=# Syncrun finished 2020-09-24T21:54:27Z (last step: 346 msec, total: 27297 msec)
#=#=#=# Syncrun started 2020-09-24T21:55:01Z
#=#=#=#=# Propagation starts 2020-09-24T21:55:04Z (last step: 3448 msec, total: 3448 msec)
#=#=#=# Syncrun finished 2020-09-24T21:55:04Z (last step: 306 msec, total: 3754 msec)

Is there some debug option that I can enable, or other logs that you might want to see?

[er-vin]

Yes, what you want is to run the client from the command line with the --logdebug and --logfile C:\nextcloud-log.txt options on the command line, make sure the issue happens and then quite properly.

[Bockeman]

I've now added those options to the properties of the Win10 client shortcut. Exit Nextcloud and launch again via this shortcut.
Logging is going fine, but none of these meaningless error messages seen as yet.

Is there a config option or similar so that when the Win10 machine starts, debug logging is enabled by default (nextcloud is launched automatically on startup - as Settings > Apps > Startup > Nextcloud > On with no command line options available)?

[er-vin]

Sure, you can alternatively do something like the following in the General group of nextcloud.cfg (the / instead of \ is intentional):
logDebug=true
logDir=C:/nextcloud-logs
logExpire=24

Then it will log all the time and keep the last 24h of logs.

[Bockeman]

@er-vin Kevin, I captured another failure! I hope I have enough for you to start understanding this problem.

Some notes:

1. Turning on this debugging is definitely not something to do by default, the log files are M A S S I V E , about 450MB for a couple of hours debugging.

2. I cut this down to the last minute when the meaningless error message appeared.
   grep 2020-09-29\ 16:37 /mnt/veriulan/d/Data/BobW/AppData/Roaming/Nextcloud/nextcloud.log \

/mnt/veriulan/d/Data/BobW/AppData/Roaming/Nextcloud/nextcloud_200929_1637.log
du -sm /mnt/veriulan/d/Data/BobW/AppData/Roaming/Nextcloud/nextcloud.log*
439 /mnt/veriulan/d/Data/BobW/AppData/Roaming/Nextcloud/nextcloud.log
2 /mnt/veriulan/d/Data/BobW/AppData/Roaming/Nextcloud/nextcloud_200929_1637.log

3. This meaningless error message happens to occur at the same time as a conflict. Please ignore stuff related to the conflict, it is wrong anyway, and has been reported separately.
   Nextcloud-Client creating conflicts when it should not #2467

4. There are 43 lines containing "Error" excluding "successfully"
   grep Error /mnt/veriulan/d/Data/BobW/AppData/Roaming/Nextcloud/nextcloud.log_200929_1637
   | egrep -v successfully | wc -l
   34

5. The screen grab is
   

6. The last minute of logging is:
   nextcloud_200929_1637.log

[er-vin]

OK, so interestingly this seems tied to an overly long and complicated error from the server which we try to display there. This is during the propagation of Firefox/Profiles/6qw6a8eb.default/cookies.sqlite-shm at 2020-09-29 16:37:19:251 and later. I spotted it by looking for that odd "3]:" which felt like a piece of JSON or such.

I'm unsure how to deal with it but at least that narrows down where that occurs.

BTW this is about a deadlock on the server side and so you get a 500 for the upload of that file... unsure if that's normal or not.

[github-actions]

This bug report did not receive an update in the last 4 weeks. Please take a look again and update the issue with new details, otherwise the issue will be automatically closed in 2 weeks. Thank you!

[Bockeman]

I'm now on Nextcould Client version 3.1.3.
I've not seen this error message recently, so I assume it has been fixed.

[github-actions]

This bug report did not receive an update in the last 4 weeks. Please take a look again and update the issue with new details, otherwise the issue will be automatically closed in 2 weeks. Thank you!