How to enable debugging/tracing on synology diskstattion

I have an issue that Syncthing recently started utilising the CPU and continuously is performing disk io. I try to set STTRACE to all but have till now not able to set this correctly and catch the output to a file.

I tried to change the /var/packages/syncthing/script/start-stop-status file but till now without success. Anybody tips how to start the daemon to i can set STTRACE and redirect output to a log file ?

#!/bin/sh

# Package
PACKAGE="syncthing"
DNAME="Syncthing"

# Others
INSTALL_DIR="/usr/local/${PACKAGE}"
PATH="${INSTALL_DIR}/bin:${PATH}"
USER="syncthing"
SYNCTHING="${INSTALL_DIR}/bin/syncthing"
CONFIG_DIR="${INSTALL_DIR}/var"
SYNCTHING_OPTIONS="-home=${CONFIG_DIR}"

# Read additional startup options from /usr/local/syncthing/var/options.conf
if [ -f ${CONFIG_DIR}/options.conf ]; then
    source ${CONFIG_DIR}/options.conf
fi

start_daemon ()
{
    start-stop-daemon -b -o -c ${USER} -S -u ${USER} -k 002 -x env HOME=${CONFIG_DIR} ${SYNCTHING} -- ${SYNCTHING_OPTIONS}
}

You can just run syncthing from the command line pointing -home to where it’s config runs

Tried that one also, but that seems to fail because there may be a port mapping applied by the synology app. When i start syncthing from the commandline;

sudo su - syncthing
cd /usr/local/syncthing/bin
export STTRACE=all
./syncthing -home=/usr/local/syncthing/var | tee /tmp/synchting.dbg 

It does start with debugging output, but the web interface on port 7070 is not reachable.

syncthing@somehost:/usr/local/syncthing/bin$ ./syncthing -home=/usr/local/syncthing/var | tee /tmp/synchting.dbg 
2017/10/16 22:33:55.882437 debug.go:39: DEBUG: Enabling lock logging at 100ms threshold
2017/10/16 22:33:55.889751 logfs.go:72: DEBUG: main.go:1163 basic /usr/local/syncthing/var/ MkdirAll . 448 <nil>
2017/10/16 22:33:55.889902 logfs.go:114: DEBUG: main.go:1168 basic /usr/local/syncthing/var/ Stat . {0xc420192680} <nil>
[monitor] 2017/10/16 22:33:55.890133 monitor.go:95: INFO: Starting syncthing
2017/10/16 22:33:55.892935 debug.go:39: DEBUG: Enabling lock logging at 100ms threshold
2017/10/16 22:33:55.900278 logfs.go:72: DEBUG: main.go:1163 basic /usr/local/syncthing/var/ MkdirAll . 448 <nil>
2017/10/16 22:33:55.900660 logfs.go:114: DEBUG: main.go:1168 basic /usr/local/syncthing/var/ Stat . {0xc420192680} <nil>
[start] 2017/10/16 22:33:55.901062 events.go:268: DEBUG: subscribe Unknown
[start] 2017/10/16 22:33:55.901199 events.go:268: DEBUG: subscribe Unknown
[HOVGC] 2017/10/16 22:33:55.917592 main.go:651: INFO: syncthing v0.14.39 "Dysprosium Dragonfly" (go1.9 linux-amd64) teamcity@build.syncthing.net 2017-09-25 06:05:21 UTC
[HOVGC] 2017/10/16 22:33:55.917670 main.go:652: INFO: My ID: HOVGCY5-3ZZMHT4-KXJZMEA-3OCEXYD-YIZNQOF-P3P4J3U-IV2DGSH-DL2WUQG
[monitor] 2017/10/16 22:33:56.386946 internal.go:51: DEBUG: Dialer logging disabled, as no proxy was detected
[HOVGC] 2017/10/16 22:33:56.397676 internal.go:51: DEBUG: Dialer logging disabled, as no proxy was detected
[HOVGC] 2017/10/16 22:33:57.000879 sha256.go:92: INFO: Single thread SHA256 performance is 98 MB/s using minio/sha256-simd (72 MB/s using crypto/sha256).
[HOVGC] 2017/10/16 22:33:57.001028 events.go:231: DEBUG: log 1 Starting map[home:/usr/local/syncthing/var myID:HOVGCY5-3ZZMHT4-KXJZMEA-3OCEXYD-YIZNQOF-P3P4J3U-IV2DGSH-DL2WUQG]
[HOVGC] 2017/10/16 22:33:58.120961 main.go:711: INFO: Hashing performance with weak hash is 84.48 MB/s
[HOVGC] 2017/10/16 22:33:59.233701 main.go:713: INFO: Hashing performance without weak hash is 95.45 MB/s
[HOVGC] 2017/10/16 22:33:59.233757 main.go:719: INFO: Weak hash enabled, as it has an acceptable performance impact.
[HOVGC] 2017/10/16 22:40:40.786859 progressemitter.go:196: DEBUG: progress emitter: updated interval 5s
[HOVGC] 2017/10/16 22:40:40.787906 progressemitter.go:62: DEBUG: progress emitter: timer - looking after 0
[HOVGC] 2017/10/16 22:40:40.787945 progressemitter.go:81: DEBUG: progress emitter: nothing new
[HOVGC] 2017/10/16 22:41:27.057511 leveldb_dbinstance.go:615: DEBUG: db check completed for "cc5it-4e3tl"
[HOVGC] 2017/10/16 22:41:39.448434 set.go:142: DEBUG: loaded sequence for "cc5it-4e3tl": 235972
[HOVGC] 2017/10/16 22:41:39.448629 logfs.go:78: DEBUG: ignore.go:294 basic /volume1/Syncthing/homedir_imedia_imedia/ Open .stignore <nil> open /volume1/Syncthing/homedir_imedia_imedia/.stignore: no such file or directory
[HOVGC] 2017/10/16 22:41:39.448723 sync.go:158: DEBUG: RWMutex held for 58.661254458s. Locked at model/model.go:315 unlocked at model/model.go:317
[HOVGC] 2017/10/16 22:41:39.448946 logfs.go:138: DEBUG: model.go:257 basic /volume1/Syncthing/homedir_imedia_imedia/ Hide .stfolder <nil>
[HOVGC] 2017/10/16 22:41:39.448975 logfs.go:138: DEBUG: model.go:258 basic /volume1/Syncthing/homedir_imedia_imedia/ Hide .stversions <nil>
[HOVGC] 2017/10/16 22:41:39.449000 logfs.go:138: DEBUG: model.go:259 basic /volume1/Syncthing/homedir_imedia_imedia/ Hide .stignore <nil>
[HOVGC] 2017/10/16 22:41:39.449076 model.go:182: INFO: Ready to synchronize "Homedir imedia imedia" (cc5it-4e3tl) (readwrite)

In the file /var/packages/syncthing/scripts/syncthing.sc there seems to be a port forwarding configuration ;

[syncthing]
title="Syncthing"
desc="Syncthing"
port_forward="yes"
dst.ports="22000,21027,7070/tcp,udp"

You need to stop the synology one obviously.

Yup indeed, did that otherwise the DB was locked and syncthing even would not start from the commandline.

The log now after 25 minutes;

syncthing@somehost:/usr/local/syncthing/bin$ ./syncthing -home=/usr/local/syncthing/var | tee /tmp/synchting.dbg 
2017/10/16 22:51:00.429551 debug.go:39: DEBUG: Enabling lock logging at 100ms threshold
2017/10/16 22:51:00.436791 logfs.go:72: DEBUG: main.go:1163 basic /usr/local/syncthing/var/ MkdirAll . 448 <nil>
2017/10/16 22:51:00.436877 logfs.go:114: DEBUG: main.go:1168 basic /usr/local/syncthing/var/ Stat . {0xc42019e4e0} <nil>
[monitor] 2017/10/16 22:51:00.437118 monitor.go:95: INFO: Starting syncthing
2017/10/16 22:51:00.439900 debug.go:39: DEBUG: Enabling lock logging at 100ms threshold
2017/10/16 22:51:00.446923 logfs.go:72: DEBUG: main.go:1163 basic /usr/local/syncthing/var/ MkdirAll . 448 <nil>
2017/10/16 22:51:00.447001 logfs.go:114: DEBUG: main.go:1168 basic /usr/local/syncthing/var/ Stat . {0xc420075a00} <nil>
[start] 2017/10/16 22:51:00.447314 events.go:268: DEBUG: subscribe Unknown
[start] 2017/10/16 22:51:00.447465 events.go:268: DEBUG: subscribe Unknown
[HOVGC] 2017/10/16 22:51:00.463137 main.go:651: INFO: syncthing v0.14.39 "Dysprosium Dragonfly" (go1.9 linux-amd64) teamcity@build.syncthing.net 2017-09-25 06:05:21 UTC
[HOVGC] 2017/10/16 22:51:00.463212 main.go:652: INFO: My ID: HOVGCY5-3ZZMHT4-KXJZMEA-3OCEXYD-YIZNQOF-P3P4J3U-IV2DGSH-DL2WUQG
[monitor] 2017/10/16 22:51:00.933983 internal.go:51: DEBUG: Dialer logging disabled, as no proxy was detected
[HOVGC] 2017/10/16 22:51:00.944331 internal.go:51: DEBUG: Dialer logging disabled, as no proxy was detected
[HOVGC] 2017/10/16 22:51:01.543815 sha256.go:92: INFO: Single thread SHA256 performance is 99 MB/s using minio/sha256-simd (72 MB/s using crypto/sha256).
[HOVGC] 2017/10/16 22:51:01.543977 events.go:231: DEBUG: log 1 Starting map[myID:HOVGCY5-3ZZMHT4-KXJZMEA-3OCEXYD-YIZNQOF-P3P4J3U-IV2DGSH-DL2WUQG home:/usr/local/syncthing/var]
[HOVGC] 2017/10/16 22:51:02.650825 main.go:711: INFO: Hashing performance with weak hash is 85.36 MB/s
[HOVGC] 2017/10/16 22:51:03.764173 main.go:713: INFO: Hashing performance without weak hash is 95.70 MB/s
[HOVGC] 2017/10/16 22:51:03.764228 main.go:719: INFO: Weak hash enabled, as it has an acceptable performance impact.
[HOVGC] 2017/10/16 22:57:44.893914 progressemitter.go:196: DEBUG: progress emitter: updated interval 5s
[HOVGC] 2017/10/16 22:57:44.894963 progressemitter.go:62: DEBUG: progress emitter: timer - looking after 0
[HOVGC] 2017/10/16 22:57:44.894997 progressemitter.go:81: DEBUG: progress emitter: nothing new
[HOVGC] 2017/10/16 22:59:23.805066 leveldb_dbinstance.go:615: DEBUG: db check completed for "ksqib-wf3xr"
[HOVGC] 2017/10/16 22:59:46.116991 set.go:142: DEBUG: loaded sequence for "ksqib-wf3xr": 157553
[HOVGC] 2017/10/16 22:59:46.191324 logfs.go:78: DEBUG: ignore.go:294 basic /volume1/Syncthing/chigatze_iii/ Open .stignore <nil> open /volume1/Syncthing/chigatze_iii/.stignore: no such file or directory
[HOVGC] 2017/10/16 22:59:46.191446 sync.go:158: DEBUG: RWMutex held for 2m1.297107374s. Locked at model/model.go:315 unlocked at model/model.go:317
[HOVGC] 2017/10/16 22:59:46.191701 logfs.go:138: DEBUG: model.go:257 basic /volume1/Syncthing/chigatze_iii/ Hide .stfolder <nil>
[HOVGC] 2017/10/16 22:59:46.191738 logfs.go:138: DEBUG: model.go:258 basic /volume1/Syncthing/chigatze_iii/ Hide .stversions <nil>
[HOVGC] 2017/10/16 22:59:46.191764 logfs.go:138: DEBUG: model.go:259 basic /volume1/Syncthing/chigatze_iii/ Hide .stignore <nil>
[HOVGC] 2017/10/16 22:59:46.191842 model.go:182: INFO: Ready to synchronize "Chigatze III" (ksqib-wf3xr) (readwrite)
[HOVGC] 2017/10/16 22:59:48.379183 leveldb_dbinstance.go:615: DEBUG: db check completed for "gktyk-zxmi5"
[HOVGC] 2017/10/16 22:59:48.980264 set.go:142: DEBUG: loaded sequence for "gktyk-zxmi5": 3907
[HOVGC] 2017/10/16 22:59:49.156628 logfs.go:78: DEBUG: ignore.go:294 basic /volume1/Syncthing/clouddrive_renate/ Open .stignore <nil> open /volume1/Syncthing/clouddrive_renate/.stignore: no such file or directory
[HOVGC] 2017/10/16 22:59:49.156770 sync.go:106: DEBUG: Mutex held for 176.32826ms. Locked at ignore/ignore.go:128 unlocked at ignore/ignore.go:138
[HOVGC] 2017/10/16 22:59:49.156833 sync.go:158: DEBUG: RWMutex held for 2.964895958s. Locked at model/model.go:315 unlocked at model/model.go:317
[HOVGC] 2017/10/16 22:59:49.157113 logfs.go:138: DEBUG: model.go:257 basic /volume1/Syncthing/clouddrive_renate/ Hide .stfolder <nil>
[HOVGC] 2017/10/16 22:59:49.157144 logfs.go:138: DEBUG: model.go:258 basic /volume1/Syncthing/clouddrive_renate/ Hide .stversions <nil>
[HOVGC] 2017/10/16 22:59:49.157170 logfs.go:138: DEBUG: model.go:259 basic /volume1/Syncthing/clouddrive_renate/ Hide .stignore <nil>
[HOVGC] 2017/10/16 22:59:49.157283 model.go:182: INFO: Ready to synchronize "Cloud Drive Renate" (gktyk-zxmi5) (readwrite)
[HOVGC] 2017/10/16 23:01:45.169090 leveldb_dbinstance.go:615: DEBUG: db check completed for "aey9j-sqcpe"
[HOVGC] 2017/10/16 23:02:15.365520 set.go:142: DEBUG: loaded sequence for "aey9j-sqcpe": 245530
[HOVGC] 2017/10/16 23:02:15.396954 logfs.go:78: DEBUG: ignore.go:294 basic /volume1/Syncthing/fotos_bibliotheek_renatevanderhorst_barcelona/ Open .stignore <nil> open /volume1/Syncthing/fotos_bibliotheek_renatevanderhorst_barcelona/.stignore: no such file or directory
[HOVGC] 2017/10/16 23:02:15.397080 sync.go:158: DEBUG: RWMutex held for 2m26.239522979s. Locked at model/model.go:315 unlocked at model/model.go:317
[HOVGC] 2017/10/16 23:02:15.397343 logfs.go:138: DEBUG: model.go:257 basic /volume1/Syncthing/fotos_bibliotheek_renatevanderhorst_barcelona/ Hide .stfolder <nil>
[HOVGC] 2017/10/16 23:02:15.397383 logfs.go:138: DEBUG: model.go:258 basic /volume1/Syncthing/fotos_bibliotheek_renatevanderhorst_barcelona/ Hide .stversions <nil>
[HOVGC] 2017/10/16 23:02:15.397409 logfs.go:138: DEBUG: model.go:259 basic /volume1/Syncthing/fotos_bibliotheek_renatevanderhorst_barcelona/ Hide .stignore <nil>
[HOVGC] 2017/10/16 23:02:15.397471 model.go:182: INFO: Ready to synchronize "Foto's Bibliotheek barcelona" (aey9j-sqcpe) (readwrite)
[HOVGC] 2017/10/16 23:02:56.883428 leveldb_dbinstance.go:615: DEBUG: db check completed for "cc5it-4e3tl"
[HOVGC] 2017/10/16 23:03:09.267472 set.go:142: DEBUG: loaded sequence for "cc5it-4e3tl": 235972
[HOVGC] 2017/10/16 23:03:09.267643 logfs.go:78: DEBUG: ignore.go:294 basic /volume1/Syncthing/homedir_imedia_imedia/ Open .stignore <nil> open /volume1/Syncthing/homedir_imedia_imedia/.stignore: no such file or directory
[HOVGC] 2017/10/16 23:03:09.267730 sync.go:158: DEBUG: RWMutex held for 53.870135549s. Locked at model/model.go:315 unlocked at model/model.go:317
[HOVGC] 2017/10/16 23:03:09.267939 logfs.go:138: DEBUG: model.go:257 basic /volume1/Syncthing/homedir_imedia_imedia/ Hide .stfolder <nil>
[HOVGC] 2017/10/16 23:03:09.267971 logfs.go:138: DEBUG: model.go:258 basic /volume1/Syncthing/homedir_imedia_imedia/ Hide .stversions <nil>
[HOVGC] 2017/10/16 23:03:09.267996 logfs.go:138: DEBUG: model.go:259 basic /volume1/Syncthing/homedir_imedia_imedia/ Hide .stignore <nil>
[HOVGC] 2017/10/16 23:03:09.268052 model.go:182: INFO: Ready to synchronize "Homedir imedia imedia" (cc5it-4e3tl) (readwrite)
[HOVGC] 2017/10/16 23:13:12.032916 sync.go:106: DEBUG: Mutex held for 298.739578ms. Locked at db/leveldb_dbinstance.go:852 unlocked at db/leveldb_dbinstance.go:859

Still the syncthing status page at port 7070 is not availble, and all other clients report that this host is disconnected.

So need a way to modify the start-stop-status file to set STTRACE to all and redirect the logging.

It looks like the UI is simply disabled. Best if you post the config.

Hi Audrius,

When i start Syncthing on the Synology DSM from the Package Center the home is set to /usr/local/syncthing/var. The web interface than is accessible.

peter@somehost:~$ ps -ef | grep -i syncth
syncthi+ 14630     1  0 Oct16 ?        00:00:01 /usr/local/syncthing/bin/syncthing -home=/usr/local/syncthing/var
syncthi+ 14644 14630 99 Oct16 ?        14:09:46 /usr/local/syncthing/bin/syncthing -home=/usr/local/syncthing/var
peter    18761 18732  0 07:41 pts/11   00:00:00 grep --color=auto -i syncth

When i do start it from the commandline using the same host it is not available.

Because I am not convinced you are using the same config. If you started it before while the one managed by the package manager was running, it would have chosen a different port for the UI. Anyways, it does print in normal non-debug logs where the UI is available if its enabled.

Looks like it just takes a long time to start up?

Configuration is; Which is used when starting Syncthing from the command center and command line

<configuration version="23">
    <folder id="ksqib-wf3xr" label="Chigatze III" path="/volume1/Syncthing/chigatze_iii" type="readwrite" rescanIntervalS="300" ignorePerms="false" autoNormalize="true">
        <filesystemType>basic</filesystemType>
...
        <paused>false</paused>
        <weakHashThresholdPct>25</weakHashThresholdPct>
    </folder>
    <device id="DWMUF3Y-VBEVGPD-TFN7L5Q-ILLEYWF-H7PKQCX-WYMAW3H-ID5OKZ6-M65KGAX" name="HMCTAB-B7BB92A9" compression="metadata" introducer="false" skipIntroductionRemovals="false" introducedBy="">
...
    </device>
    <gui enabled="true" tls="false" debugging="false">
        <address>0.0.0.0:7070</address>
        <user>SyncAdmin</user>
        <password>$2a$10$0ZXr.vuCPSAmhHquUwfhseCXn72Ws7HreReJL0W2omvlGUxykalQ6</password>
        <apikey>ujWNuW4SAyfCYSL7ZNNhVGqPriHfHQkC</apikey>
        <theme>default</theme>
    </gui>
    <options>
        <listenAddress>default</listenAddress>
        <globalAnnounceServer>default</globalAnnounceServer>
        <globalAnnounceEnabled>true</globalAnnounceEnabled>
        <localAnnounceEnabled>true</localAnnounceEnabled>
        <localAnnouncePort>21027</localAnnouncePort>
        <localAnnounceMCAddr>[ff12::8384]:21027</localAnnounceMCAddr>
        <maxSendKbps>0</maxSendKbps>
        <maxRecvKbps>0</maxRecvKbps>
        <reconnectionIntervalS>60</reconnectionIntervalS>
        <relaysEnabled>true</relaysEnabled>
        <relayReconnectIntervalM>10</relayReconnectIntervalM>
        <startBrowser>false</startBrowser>
        <natEnabled>true</natEnabled>
        <natLeaseMinutes>60</natLeaseMinutes>
        <natRenewalMinutes>30</natRenewalMinutes>
        <natTimeoutSeconds>10</natTimeoutSeconds>
        <urAccepted>2</urAccepted>
        <urUniqueID>nyT64Eji</urUniqueID>
        <urURL>https://data.syncthing.net/newdata</urURL>
        <urPostInsecurely>false</urPostInsecurely>
        <urInitialDelayS>1800</urInitialDelayS>
        <restartOnWakeup>true</restartOnWakeup>
        <autoUpgradeIntervalH>12</autoUpgradeIntervalH>
        <upgradeToPreReleases>true</upgradeToPreReleases>
        <keepTemporariesH>24</keepTemporariesH>
        <cacheIgnoredFiles>false</cacheIgnoredFiles>
        <progressUpdateIntervalS>5</progressUpdateIntervalS>
        <limitBandwidthInLan>false</limitBandwidthInLan>
        <minHomeDiskFree unit="%">1</minHomeDiskFree>
        <releasesURL>https://upgrades.syncthing.net/meta.json</releasesURL>
        <overwriteRemoteDeviceNamesOnConnect>false</overwriteRemoteDeviceNamesOnConnect>
        <tempIndexMinBlocks>10</tempIndexMinBlocks>
        <trafficClass>0</trafficClass>
        <weakHashSelectionMethod>auto</weakHashSelectionMethod>
        <stunServer>default</stunServer>
        <stunKeepaliveSeconds>24</stunKeepaliveSeconds>
        <defaultKCPEnabled>false</defaultKCPEnabled>
        <kcpNoDelay>false</kcpNoDelay>
        <kcpUpdateIntervalMs>25</kcpUpdateIntervalMs>
        <kcpFastResend>false</kcpFastResend>
        <kcpCongestionControl>true</kcpCongestionControl>
        <kcpSendWindowSize>128</kcpSendWindowSize>
        <kcpReceiveWindowSize>128</kcpReceiveWindowSize>
        <defaultFolderPath>~</defaultFolderPath>
        <minHomeDiskFreePct>0</minHomeDiskFreePct>
    </options>
</configuration>

Yes, seems so, but when starting from the Package Center it starts within minutes and the web interface becomes available. When starting from the command-line the web interface and service do not become available.

Still prefer to enable STTRACE and logging redirection from the stop-start-status script.

Finally succeeded in enabling STTRACE and redirecting the stdout when starting syncthing from the synology package manager

After changing the line
start-stop-daemon -b -o -c ${USER} -S -u ${USER} -k 002 -x env HOME=${CONFIG_DIR} ${SYNCTHING} -- ${SYNCTHING_OPTIONS}
to
start-stop-daemon -b -o -c ${USER} -S -u ${USER} -k 002 -x /bin/bash -- -c "env HOME=${CONFIG_DIR} env STTRACE=all ${SYNCTHING} ${SYNCTHING_OPTIONS} > /tmp/syncthing.dbg.log 2>&1"
in /var/packages/syncthing/scripts/start-stop-status

i was able to start synchting through the synology package manager. This can be done from the commandline using de synopkgctl command; /usr/syno/sbin/synopkgctl start syncthing

I now can debug my issue which i reported in thread Continous disk activity

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.