Syncthing: Log spam and high CPU use if #include path is wrong in .stignore

Created on 29 Aug 2019 · 3Comments · Source: syncthing/syncthing

I have first reported this problem in the SyncTrayzor repository (https://github.com/canton7/SyncTrayzor/issues/526), as I use Syncthing mostly on Windows, but I am reporting it here too, as I believe that this is a general issue.

The problem is that if #include in .stignore is set to a non-existent file path, Syncthing continuously spams the log file with the following entries.

[***] **:**:** WARNING: Error on folder "***" (***-***): loading ignores: failed to load include file ***: open \\?\***: The system cannot find the path specified.
[***] **:**:** INFO: Cleared error on folder "***" (***-***)

Because of the log spam, Syncthing uses a lot of CPU which bogs down the whole system. If SyncTrayzor is open, it will actually use 100% of CPU and make everything unresponsive due to the console log display in SyncTrayzor itself. Without SyncTrayzor, it is just Syncthing.exe using ~50% of CPU in a mid-range 4 core system. Fortunately, the system is still responsive enough to operate, but this may not be the case on a slower device. Also, the folder status in the Web GUI keeps changing rapidly with no end to it. The only way to fix the issue seems to be to manually edit the .stignore file and fix the incorrect path there which as a result stops the log spam. Unfortunately, the Web GUI does not allow to edit the incorrect path directly, as the "Ignored Patterns" window is grayed out with a Failed to load ignored patterns. message.

Would it be possible to simply log the problem once so that the user knows of the incorrect path, and not spam the log with the error messages? Right now, even a simple spellling mistake in the #include path can cause this issue. I have not tested this in Android, but if the same thing happens there too, then stopping the log spam there will be major pain, as you would need either a 3rd party file manager or a terminal application to even be able to see and modify/delete the hidden .stignore files.

Version Information

Syncthing Version: v1.2.1
OS Version: Windows 7 Enterprise x64

bug frozen-due-to-age

Source

tomasz1986

Most helpful comment

Yeah, reproduced.

calmh on 30 Aug 2019

👍2

All 3 comments

I tried reproducing this but I cannot. When I have an invalid .stignore it fails to load just as in your example, but this happens once per scan. "Once per scan" is once per minute by default. We can argue about whether that constitutes log spam or not, but it does not result in high CPU usage for me. Maybe there's something specific about your folder configuration? One second rescan interval or something?

calmh on 30 Aug 2019

I have done some testing with a completely fresh, default configuration, and here is how you can reproduce the issue using just the Default Folder.

Start Syncthing.
Add #include with an incorrect file path to .stignore of the Default Folder.
Syncthing will stop with an error.
Press Rescan for the Default Folder.
The log spam begins.

I am sorry for not providing enough information in my posting above.

Also, during the testing, I have found out that adding just #include to .stignore, with no file path specified, crashes Syncthing completely. This is a log of the crash.

panic: runtime error: slice bounds out of range
goroutine 1 [running]:
github.com/syncthing/syncthing/lib/ignore.parseIgnoreFile(0x105a980, 0xc0001e7530, 0x3b57f8, 0xc000167ea0, 0xd7a731, 0x9, 0x1049780, 0xc000006198, 0xc00000d738, 0xc00000d6c8, ...)
    C:/BuildAgent/work/174e136266f8a219/lib/ignore/ignore.go:464 +0xb54
github.com/syncthing/syncthing/lib/ignore.(*Matcher).parseLocked(0xc000124090, 0x3b57f8, 0xc000167ea0, 0xd7a731, 0x9, 0xc000006198, 0x1054420)
    C:/BuildAgent/work/174e136266f8a219/lib/ignore/ignore.go:162 +0x102
github.com/syncthing/syncthing/lib/ignore.(*Matcher).Load(0xc000124090, 0xd7a731, 0x9, 0x0, 0x0)
    C:/BuildAgent/work/174e136266f8a219/lib/ignore/ignore.go:146 +0x220
github.com/syncthing/syncthing/lib/model.(*model).addFolderLocked(0xc0001e2160, 0xc0001f4858, 0x7, 0xc0001f4870, 0xe, 0x0, 0xc00002f6e0, 0x12, 0x0, 0xc00002c180, ...)
    C:/BuildAgent/work/174e136266f8a219/lib/model/model.go:380 +0x1eb
github.com/syncthing/syncthing/lib/model.(*model).AddFolder(0xc0001e2160, 0xc0001f4858, 0x7, 0xc0001f4870, 0xe, 0x0, 0xc00002f6e0, 0x12, 0x0, 0xc00002c180, ...)
    C:/BuildAgent/work/174e136266f8a219/lib/model/model.go:372 +0x182
github.com/syncthing/syncthing/lib/syncthing.(*App).startup(0xc0000aa120, 0x42f5e6, 0xc00010e130)
    C:/BuildAgent/work/174e136266f8a219/lib/syncthing/syncthing.go:247 +0x1125
github.com/syncthing/syncthing/lib/syncthing.(*App).Start.func1()
    C:/BuildAgent/work/174e136266f8a219/lib/syncthing/syncthing.go:102 +0x3a
sync.(*Once).Do(0xc0000aa220, 0xc0003f0f60)
    C:/Go/src/sync/once.go:44 +0xba
github.com/syncthing/syncthing/lib/syncthing.(*App).Start(0xc0000aa120)
    C:/BuildAgent/work/174e136266f8a219/lib/syncthing/syncthing.go:101 +0x5d
main.syncthingMain(0xc00002d480, 0x39, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xc00002c246, ...)
    C:/BuildAgent/work/174e136266f8a219/cmd/syncthing/main.go:655 +0x83f
main.main()
    C:/BuildAgent/work/174e136266f8a219/cmd/syncthing/main.go:390 +0x412
goroutine 6 [syscall]:
os/signal.signal_recv(0x0)
    C:/Go/src/runtime/sigqueue.go:139 +0xa3
os/signal.loop()
    C:/Go/src/os/signal/signal_unix.go:23 +0x29
created by os/signal.init.0
    C:/Go/src/os/signal/signal_unix.go:29 +0x48
goroutine 7 [chan receive]:
github.com/syncthing/notify.(*recursiveTree).dispatch(0xc0000a82d0)
    C:/BuildAgent/work/pkg/mod/github.com/syncthing/[email protected]/tree_recursive.go:125 +0xce
created by github.com/syncthing/notify.newRecursiveTree
    C:/BuildAgent/work/pkg/mod/github.com/syncthing/[email protected]/tree_recursive.go:119 +0x13a
goroutine 10 [select]:
github.com/syncthing/syncthing/lib/events.(*Logger).Serve(0xc000056540)
    C:/BuildAgent/work/174e136266f8a219/lib/events/events.go:260 +0x12d
created by github.com/syncthing/syncthing/lib/events.init.1
    C:/BuildAgent/work/174e136266f8a219/lib/events/events.go:234 +0x62
goroutine 12 [select]:
github.com/syndtr/goleveldb/leveldb/util.(*BufferPool).drain(0xc000142460)
    C:/BuildAgent/work/pkg/mod/github.com/syndtr/[email protected]/leveldb/util/buffer_pool.go:206 +0x128
created by github.com/syndtr/goleveldb/leveldb/util.NewBufferPool
    C:/BuildAgent/work/pkg/mod/github.com/syndtr/[email protected]/leveldb/util/buffer_pool.go:237 +0x17d
goroutine 13 [select]:
github.com/syndtr/goleveldb/leveldb.(*session).refLoop(0xc0001dc3c0)
    C:/BuildAgent/work/pkg/mod/github.com/syndtr/[email protected]/leveldb/session_util.go:189 +0x5ea
created by github.com/syndtr/goleveldb/leveldb.newSession
    C:/BuildAgent/work/pkg/mod/github.com/syndtr/[email protected]/leveldb/session.go:93 +0x2bc
goroutine 51 [select]:
github.com/syndtr/goleveldb/leveldb.(*DB).compactionError(0xc0000b1520)
    C:/BuildAgent/work/pkg/mod/github.com/syndtr/[email protected]/leveldb/db_compaction.go:90 +0xd4
created by github.com/syndtr/goleveldb/leveldb.openDB
    C:/BuildAgent/work/pkg/mod/github.com/syndtr/[email protected]/leveldb/db.go:142 +0x416
goroutine 52 [select]:
github.com/syndtr/goleveldb/leveldb.(*DB).mpoolDrain(0xc0000b1520)
    C:/BuildAgent/work/pkg/mod/github.com/syndtr/[email protected]/leveldb/db_state.go:101 +0xfd
created by github.com/syndtr/goleveldb/leveldb.openDB
    C:/BuildAgent/work/pkg/mod/github.com/syndtr/[email protected]/leveldb/db.go:143 +0x438
goroutine 53 [select]:
github.com/syndtr/goleveldb/leveldb.(*DB).tCompaction(0xc0000b1520)
    C:/BuildAgent/work/pkg/mod/github.com/syndtr/[email protected]/leveldb/db_compaction.go:825 +0x241
created by github.com/syndtr/goleveldb/leveldb.openDB
    C:/BuildAgent/work/pkg/mod/github.com/syndtr/[email protected]/leveldb/db.go:149 +0x58c
goroutine 54 [select]:
github.com/syndtr/goleveldb/leveldb.(*DB).mCompaction(0xc0000b1520)
    C:/BuildAgent/work/pkg/mod/github.com/syndtr/[email protected]/leveldb/db_compaction.go:762 +0x135
created by github.com/syndtr/goleveldb/leveldb.openDB
    C:/BuildAgent/work/pkg/mod/github.com/syndtr/[email protected]/leveldb/db.go:150 +0x5ae
goroutine 19 [chan receive]:
main.setupSignalHandling.func1(0xc0001963c0, 0xc0000aa120)
    C:/BuildAgent/work/174e136266f8a219/cmd/syncthing/main.go:681 +0x3b
created by main.setupSignalHandling
    C:/BuildAgent/work/174e136266f8a219/cmd/syncthing/main.go:680 +0xc6
goroutine 20 [chan receive]:
main.setupSignalHandling.func2(0xc000196420, 0xc0000aa120)
    C:/BuildAgent/work/174e136266f8a219/cmd/syncthing/main.go:691 +0x3b
created by main.setupSignalHandling
    C:/BuildAgent/work/174e136266f8a219/cmd/syncthing/main.go:690 +0x181
goroutine 21 [sleep]:
runtime.goparkunlock(...)
    C:/Go/src/runtime/proc.go:307
time.Sleep(0x2540be400)
    C:/Go/src/runtime/time.go:105 +0x16e
main.standbyMonitor(0xc0000aa120)
    C:/BuildAgent/work/174e136266f8a219/cmd/syncthing/main.go:848 +0x72
created by main.syncthingMain
    C:/BuildAgent/work/174e136266f8a219/cmd/syncthing/main.go:627 +0xaeb
goroutine 22 [select]:
net/http.(*persistConn).roundTrip(0xc0000aa240, 0xc000151d10, 0x0, 0x0, 0x0)
    C:/Go/src/net/http/transport.go:2192 +0x763
net/http.(*Transport).roundTrip(0x1649b80, 0xc0000e6200, 0xc000151ce0, 0xc0001f424c, 0xc0001f4260)
    C:/Go/src/net/http/transport.go:481 +0xa22
net/http.(*Transport).RoundTrip(0x1649b80, 0xc0000e6200, 0x1649b80, 0xbf52521ae838b378, 0x1a31d311b89)
    C:/Go/src/net/http/roundtrip.go:17 +0x3c
net/http.send(0xc0000e6100, 0x1036fc0, 0x1649b80, 0xbf52521ae838b378, 0x1a31d311b89, 0x1655100, 0xc00010a048, 0xbf52521ae838b378, 0x1, 0x0)
    C:/Go/src/net/http/client.go:250 +0x468
net/http.(*Client).send(0x1641e00, 0xc0000e6100, 0xbf52521ae838b378, 0x1a31d311b89, 0x1655100, 0xc00010a048, 0x0, 0x1, 0x2000)
    C:/Go/src/net/http/client.go:174 +0x102
net/http.(*Client).do(0x1641e00, 0xc0000e6100, 0x0, 0x0, 0x0)
    C:/Go/src/net/http/client.go:641 +0x280
net/http.(*Client).Do(...)
    C:/Go/src/net/http/client.go:509
github.com/syncthing/syncthing/lib/upgrade.insecureGet(0xc0002bd110, 0x28, 0x101fa04, 0x6, 0x16079a5, 0x1, 0xc0002bd110)
    C:/BuildAgent/work/174e136266f8a219/lib/upgrade/upgrade_supported.go:84 +0x283
github.com/syncthing/syncthing/lib/upgrade.FetchLatestReleases(0xc0002bd110, 0x28, 0x101fa04, 0x6, 0xc0002bd1d0, 0x24, 0x1)
    C:/BuildAgent/work/174e136266f8a219/lib/upgrade/upgrade_supported.go:90 +0x63
github.com/syncthing/syncthing/lib/upgrade.LatestRelease(0xc0002bd110, 0x28, 0x101fa04, 0x6, 0xc0001e6200, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
    C:/BuildAgent/work/174e136266f8a219/lib/upgrade/upgrade_supported.go:123 +0x89
main.autoUpgrade(0x105b380, 0xc000122400, 0xc0000aa120)
    C:/BuildAgent/work/174e136266f8a219/cmd/syncthing/main.go:886 +0x3e0
created by main.syncthingMain
    C:/BuildAgent/work/174e136266f8a219/cmd/syncthing/main.go:651 +0x980
goroutine 23 [select]:
github.com/thejerf/suture.(*Supervisor).Serve(0xc0001dcc30)
    C:/BuildAgent/work/pkg/mod/github.com/thejerf/[email protected]+incompatible/supervisor.go:454 +0x357
created by github.com/thejerf/suture.(*Supervisor).ServeBackground
    C:/BuildAgent/work/pkg/mod/github.com/thejerf/[email protected]+incompatible/supervisor.go:407 +0x46
goroutine 38 [chan receive]:
github.com/syncthing/syncthing/lib/events.(*bufferedSubscription).pollingLoop(0xc0000a8460)
    C:/BuildAgent/work/174e136266f8a219/lib/events/events.go:441 +0x94
created by github.com/syncthing/syncthing/lib/events.NewBufferedSubscription
    C:/BuildAgent/work/174e136266f8a219/lib/events/events.go:436 +0x15e
goroutine 39 [chan receive]:
github.com/syncthing/syncthing/lib/events.(*bufferedSubscription).pollingLoop(0xc0000a8500)
    C:/BuildAgent/work/174e136266f8a219/lib/events/events.go:441 +0x94
created by github.com/syncthing/syncthing/lib/events.NewBufferedSubscription
    C:/BuildAgent/work/174e136266f8a219/lib/events/events.go:436 +0x15e
goroutine 15 [select]:
net/http.setRequestCancel.func3(0x0, 0xc000151ce0, 0xc00018e0f0, 0xc0001f424c, 0xc00038c360)
    C:/Go/src/net/http/client.go:321 +0xd6
created by net/http.setRequestCancel
    C:/Go/src/net/http/client.go:320 +0x258
goroutine 40 [IO wait]:
internal/poll.runtime_pollWait(0x3b5538, 0x72, 0x1038740)
    C:/Go/src/runtime/netpoll.go:182 +0x5d
internal/poll.(*pollDesc).wait(0xc000028488, 0x72, 0x1601600, 0x0, 0x0)
    C:/Go/src/internal/poll/fd_poll_runtime.go:87 +0xa2
internal/poll.(*ioSrv).ExecIO(0x16512d0, 0xc0000282d8, 0xf42300, 0x4d12f4, 0x3, 0xc00003a570)
    C:/Go/src/internal/poll/fd_windows.go:228 +0x124
internal/poll.(*FD).Read(0xc0000282c0, 0xc000126000, 0xe4e, 0xe4e, 0x0, 0x0, 0x0)
    C:/Go/src/internal/poll/fd_windows.go:502 +0x26b
net.(*netFD).Read(0xc0000282c0, 0xc000126000, 0xe4e, 0xe4e, 0x101d141, 0x796e637468696e67, 0x2e6e657400050005)
    C:/Go/src/net/fd_windows.go:152 +0x56
net.(*conn).Read(0xc0000fa030, 0xc000126000, 0xe4e, 0xe4e, 0x0, 0x0, 0x0)
    C:/Go/src/net/net.go:177 +0x70
crypto/tls.(*atLeastReader).Read(0xc000388bc0, 0xc000126000, 0xe4e, 0xe4e, 0x28487d9ab11d619, 0x973a6c3472f29130, 0xc0003d9938)
    C:/Go/src/crypto/tls/conn.go:761 +0x67
bytes.(*Buffer).ReadFrom(0xc000051ad8, 0x1036360, 0xc000388bc0, 0x40a02c, 0xc90400, 0xd42460)
    C:/Go/src/bytes/buffer.go:207 +0xc4
crypto/tls.(*Conn).readFromUntil(0xc000051880, 0x3b5608, 0xc0000fa030, 0x5, 0xc0000fa030, 0x5e291f8ec4109a8c)
    C:/Go/src/crypto/tls/conn.go:783 +0xff
crypto/tls.(*Conn).readRecordOrCCS(0xc000051880, 0xf42e00, 0xc0000519b8, 0x0)
    C:/Go/src/crypto/tls/conn.go:590 +0x12c
crypto/tls.(*Conn).readRecord(...)
    C:/Go/src/crypto/tls/conn.go:558
crypto/tls.(*Conn).Read(0xc000051880, 0xc0003c0000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    C:/Go/src/crypto/tls/conn.go:1236 +0x13e
net/http.(*persistConn).Read(0xc0000aa240, 0xc0003c0000, 0x1000, 0x1000, 0x60, 0xc0003d9c88, 0x42f5e6)
    C:/Go/src/net/http/transport.go:1524 +0x82
bufio.(*Reader).fill(0xc0003a0840)
    C:/Go/src/bufio/bufio.go:100 +0x116
bufio.(*Reader).Peek(0xc0003a0840, 0x1, 0xc00038c2a0, 0xc0003d9d88, 0xc0003d9f28, 0x623c54, 0xc0003d9dc8)
    C:/Go/src/bufio/bufio.go:138 +0x56
net/http.(*persistConn).readLoop(0xc0000aa240)
    C:/Go/src/net/http/transport.go:1677 +0x1aa
created by net/http.(*Transport).dialConn
    C:/Go/src/net/http/transport.go:1357 +0xaef
goroutine 41 [select]:
net/http.(*persistConn).writeLoop(0xc0000aa240)
    C:/Go/src/net/http/transport.go:1976 +0x11a
created by net/http.(*Transport).dialConn
    C:/Go/src/net/http/transport.go:1358 +0xb14