Syncthing-android: "Syncthing has crashed"

Created on 21 Mar 2017  路  34Comments  路  Source: syncthing/syncthing-android

Hi,

after running fine for a few weeks, syncthing now crashes on my Android device.

Device: Blackberry DTEK50 STH100-2, Android 6.0.1
Syncthing Android: 0.9.7 installed via Google Play

Log has these entries:

[ABCDE] 20:15:41 INFO: c.S.listenerSupervisor: Failed service 'dynamic+https://relays.syncthing.net/endpoint' (1.000000 failures of 2.000000), restarting: true, error: "{dynamic+https://relays.syncthing.net/endpoint dynamic+https://relays.syncthing.net/endpoint} returned unexpectedly", stacktrace: [unknown stack trace]
[ABCDE] 20:15:41 INFO: c.S.listenerSupervisor: Failed service 'dynamic+https://relays.syncthing.net/endpoint' (1.998999 failures of 2.000000), restarting: true, error: "{dynamic+https://relays.syncthing.net/endpoint dynamic+https://relays.syncthing.net/endpoint} returned unexpectedly", stacktrace: [unknown stack trace]
[ABCDE] 20:15:41 INFO: Entering the backoff state.
[ABCDE] 20:15:41 INFO: c.S.listenerSupervisor: Failed service 'dynamic+https://relays.syncthing.net/endpoint' (2.992680 failures of 2.000000), restarting: false, error: "{dynamic+https://relays.syncthing.net/endpoint dynamic+https://relays.syncthing.net/endpoint} returned unexpectedly", stacktrace: [unknown stack trace]
[ABCDE] 20:15:43 INFO: Exiting

Other incident, different bug report in log:

[ABCDE] 05:40:46 INFO: syncthing v0.14.24 "Dysprosium Dragonfly" (go1.8 linux-arm64) felix@P50 2017-02-23 06:47:07 UTC
[ABCDE] 05:40:46 INFO: My ID: ABCDE-------------------------------------
[ABCDE] 05:40:47 INFO: Single thread SHA256 performance is 421 MB/s using minio/sha256-simd (10 MB/s using crypto/sha256).
[ABCDE] 05:40:49 INFO: Hashing performance with weak hash is 99.27 MB/s
[ABCDE] 05:40:50 INFO: Hashing performance without weak hash is 308.89 MB/s
[ABCDE] 05:40:50 INFO: Weak hash disabled, as it has an unacceptable performance impact.
[ABCDE] 05:40:50 FATAL: Cannot open database: resource temporarily unavailable - Is another copy of Syncthing already running?
[ABCDE] 05:55:29 INFO: Disconnected from relay relay://195.154.107.80:22067
[ABCDE] 05:55:29 INFO: Exiting
frozen-due-to-age

Most helpful comment

@jebeld17 That was me you were talking to. You first sent a question about whether to report bugs to security@ given that the logs have Syncthing IDs in them. I responded like this:

Hi,

No, you report it on the Github issue tracker. The device ID by itself is not sensitive, but feel free to
redact it if you feel otherwise.

Best regards,
Jakob

You then sent me a log saying essentially "are you sure I can't report this crash here instead", to which I responded:

There is no crash in your log and this is not a security issue. Please use the forum for support.

Best regards,
Jakob

Certainly this is more curt than the first message, but you also didn't heed the first message. I'm not telling you to go fuck yourself. I'm telling you to use the channels for reporting things like they are intended.

All 34 comments

The first one just seems lack of internet, not really a crash. The second one seems to complain about an instance that is already running, potentially a run away process. Did you try restarting the phone?

Yes, I did.

Can you post the full log of the latest crash? The first one does not look like a crash but rather some misconfiguration/proxy magic as it simply can't connect anywhere.

Synthing Android is configured to run only while charging and only while on WiFi.

I will wait for the next crash and report back. Looking in the current log, it appears that duplicate startup of syncthing is the recurring problem I have here.

grep FATAL syncthing.log 
[ABCDE] 06:43:09 FATAL: Cannot open database: resource temporarily unavailable - Is another copy of Syncthing already running?
[ABCDE] 14:41:23 FATAL: Cannot open database: resource temporarily unavailable - Is another copy of Syncthing already running?
[ABCDE] 03:04:19 FATAL: Cannot open database: resource temporarily unavailable - Is another copy of Syncthing already running?
[ABCDE] 03:04:20 FATAL: Cannot open database: resource temporarily unavailable - Is another copy of Syncthing already running?
[ABCDE] 05:52:46 FATAL: Cannot open database: resource temporarily unavailable - Is another copy of Syncthing already running?
[ABCDE] 05:52:47 FATAL: Cannot open database: resource temporarily unavailable - Is another copy of Syncthing already running?
[ABCDE] 06:15:40 FATAL: Cannot open database: resource temporarily unavailable - Is another copy of Syncthing already running?
[ABCDE] 06:15:41 FATAL: Cannot open database: resource temporarily unavailable - Is another copy of Syncthing already running?
[ABCDE] 13:50:36 FATAL: Cannot open database: resource temporarily unavailable - Is another copy of Syncthing already running?
[ABCDE] 11:14:05 FATAL: Cannot open database: resource temporarily unavailable - Is another copy of Syncthing already running?

Aaaaand, there it is again. A fresh crash from seconds ago.

[ABCDE] 09:49:28 FATAL: Cannot open database: resource temporarily unavailable - Is another copy of Syncthing already running?

I've been seeing this too... For the last week or two? Lady couple entries in the log are...

...&pingInterval=1m0s&networkTimeout=2m0s&sessionLimitBps=400000&globalLimitBps=3300000&statusAddr=:22070&providedBy=NorHed: dial tcp 46.162.101.4:22067: connect: network is unreachable
[3LAZV] 16:51:59 INFO: Could not connect to relay relay://104.192.170.102:22067/?id=redacted&pingInterval=1m0s&networkTimeout=2m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=:22070&providedBy=Sysadmin Recovery Ministries: dial tcp 104.192.170.102:22067: connect: network is unreachable
[3LAZV] 16:51:59 INFO: c.S.listenerSupervisor: Failed service 'dynamic+https://relays.syncthing.net/endpoint' (1.000000 failures of 2.000000), restarting: true, error: "{dynamic+https://relays.syncthing.net/endpoint dynamic+https://relays.syncthing.net/endpoint} returned unexpectedly", stacktrace: [unknown stack trace]
[3LAZV] 16:52:00 INFO: Exiting

This exiting thing is triggered by something else, I suspect it's the wrapper triggering it, but the problem of syncthing not having access to network is still visible in the logs.

The "Syncthing has crashed" notification was added here recently: https://github.com/syncthing/syncthing-android/commit/245470a9d40996f40119918f94c51f9c776e873a

I guess it's good for debugging, but "in general" it's a bit too much IMO. Especially on older, low memory devices it "crashes" quite frequently (seemingly auto-relaunches after a while).
Since 0.9.7, my friends/family with somewhat old phones, all complain that it "crashes" for them many times a day. Most of them are "not techy enough" to be able to submit reports, and mainly are just confused and annoyed by it.

Maybe it should be an "opt-in" thing, idk...

@scienmind Are you sure those arent valid crashes that should be fixed?

@scienmind This is a new device with decent specs, the DTEK50 was brought to market in mid 2016.

Are you sure those arent valid crashes that should be fixed?

Absolutely not sure. Those might be actual crashes that should be investigated.

What I was implying is that many "set it and forget it" setups are now producing a lots of "noise", while some users can't really act on this "noise" (hence my proposal to make it "opt-in).
For example - I've set ST for some of my relatives' phones more than a year ago. "Mostly" it is working, occasional disconnects here and there, but mainly working just fine. Files fly from PC to phone, from phone to PC.
But since 0.9.7, while it seemingly work as before (files fly around), now some of them have "crush" notifications about once every couple of hours.

BTW: I got logs of one such device, and it's mostly clean. lots of "restarting after sleep" (I guess that's the way it handles wifi-only run condition).
The only legitimate errors I've found are few of those:

[IDIDID] 11:39:23 INFO: Stopping folder "" (Documents) due to error: loading ignores: open /storage/emulated/0/Documents/.stignore: interrupted system call

and

[IDIDID] 11:39:15 WARNING: Stopping folder "" (Pictures) - folder path missing
[IDIDID] 11:39:23 INFO: Folder "Pictures" error is cleared, restarting

I noticed that I implemented the log file trimming wrong, so it would keep the first 10k lines of the log, instead of the last 10k. So if you check the log after Syncthing was started again, it might not actually contain the crash info.

@AudriusButkevicius @calmh Can these kind of errors cause a full restart of Syncthing? If so, how can I detect (and ignore) such errors?

What exact error are you referring to?

The logs posted by @scienmind say that Syncthing is restarting (or maybe I'm misunderstanding them).

Its restarting the folder in that specific case.

I noticed that I implemented the log file trimming wrong, so it would keep the first 10k lines of the log, instead of the last 10k. So if you check the log after Syncthing was started again, it might not actually contain the crash info.

That clarifies a lot actually 馃槈

Same problem here since the last (few) version(s).
In Android 6.0.1 and Android 7.1.1
Device Nexus 6 "shamu" with 3GB RAM.

[3B3RC] 14:48:32 FATAL: Cannot open database: resource temporarily unavailable - Is another copy of Syncthing already running?

and

[3B3RC] 14:31:42 INFO: c.S.listenerSupervisor: Failed service 'dynamic+https://relays.syncthing.net/endpoint' (1.000000 failures of 2.000000), restarting: true, error: "{dynamic+https://relays.syncthing.net/endpoint dynamic+https://relays.syncthing.net/endpoint} returned unexpectedly", stacktrace: [unknown stack trace]
[3B3RC] 14:31:42 INFO: c.S.listenerSupervisor: Failed service 'dynamic+https://relays.syncthing.net/endpoint' (1.999872 failures of 2.000000), restarting: true, error: "{dynamic+https://relays.syncthing.net/endpoint dynamic+https://relays.syncthing.net/endpoint} returned unexpectedly", stacktrace: [unknown stack trace]
[3B3RC] 14:31:42 INFO: Entering the backoff state.
[3B3RC] 14:31:42 INFO: c.S.listenerSupervisor: Failed service 'dynamic+https://relays.syncthing.net/endpoint' (2.999683 failures of 2.000000), restarting: false, error: "{dynamic+https://relays.syncthing.net/endpoint dynamic+https://relays.syncthing.net/endpoint} returned unexpectedly", stacktrace: [unknown stack trace]

Edit:
The log clock is 1 hour and 10 minutes behind my mobile phone clock?

I can confirm I'm getting the same problem on my rooted Nexus 9 running Marshmallow 6.0.1.
I contacted the original Syncthing team through their "Security" email group because my logs contain personal info, but they failed to acknowledge my bug report and told me to file a bug report here, stating it's not their job to handle a bug that is tied directly into logs on my device holding keys into my filesystem and app...
They basically told me to "go fuck" myself.
That kindof pissed me off.

@jebeld17, there is a misunderstanding here:
Syncthig's logs don't contain any "keys into filesystem". They do contain partial ID stings, but even full ID strings are not really sensitive - they are not the actual keys used to connect to your devices securely.

There is argument to be made about other things in logs: devices aliases, folders names, etc. It may create a privacy concern for some. Implementing auto-redacting is a legitimate request to be done at some point, but that's a whole other story.
For now if it bothers you you can always manually edit things out before posting the logs here.

Now regarding "where to submit the bug":
As stated - the "Security" channel is there exclusively for the purpose of reporting security bugs found in the software. It should not be used for other issues.
Any other issue is to be brought up in an appropriate github repository (this one for the android application).

I'm sorry for your bad experience, but please be more considerate next time. After all, people are here doing a lot of work in their spare time for free to provide us users with the software, platform, and support.

@jebeld17 That was me you were talking to. You first sent a question about whether to report bugs to security@ given that the logs have Syncthing IDs in them. I responded like this:

Hi,

No, you report it on the Github issue tracker. The device ID by itself is not sensitive, but feel free to
redact it if you feel otherwise.

Best regards,
Jakob

You then sent me a log saying essentially "are you sure I can't report this crash here instead", to which I responded:

There is no crash in your log and this is not a security issue. Please use the forum for support.

Best regards,
Jakob

Certainly this is more curt than the first message, but you also didn't heed the first message. I'm not telling you to go fuck yourself. I'm telling you to use the channels for reporting things like they are intended.

Sorry people, I drank a little and got a tad off-hand! xD
I apologize for my interruption.

https://www.youtube.com/watch?v=30kS2Kr7YjQ

I would really like the Syncthing Crashed notification to be opt-in also. I've installed Syncthing on several of my non-techie friends' phones to sync their photos with their PC, which works just fine even when Syncthing crashes every once in a while, and they shouldn't have to care about it.

I'm a "techie" and I thought syncthing became more unstable since i see the crash messages.
A notification about this chance would be nice.

I would prefer to see the crashes being fixed instead of removing the crash notification.

I'd love to, as soon as anyone provides a log showing a crash.

Here is my most recent crash log:
SyncthingCrash.txt

It looks like the line that matters is:
FATAL: Cannot open database: resource temporarily unavailable - Is another copy of Syncthing already running?

I get this type of crash several times every day. My run conditions are restricted to wifi on certain networks, and "Always run in background" and "Respect Android battery saving setting" are checked. My notification type is "Low Priority". Local discovery only, and I haven't checked any of the experimental options.

I don't know what my friends' logs look like, because they would rather just use their phones instead of having me trying to fix them all the time. They shouldn't have to see that crash notification, especially when the sync keeps on working anyway.

EDIT: CyanogenMod 11-20141112-SNAPSHOT-M12-jflte (Android 4.4.4) on Galaxy S4, if that helps
EDIT2: My friends' are on Lollipop and Marshmallow, but I don't know what exact version

That is not a crash, that is Syncthing being started while it is already running. Perhaps the wrapper is misunderstanding something and relaunching Syncthing when it has in fact not crashed?

The notification says "Syncthing has crashed. Click to view logs" Is sounds like you are probably right about the wrapper (you are referring to the adroid app, right?) misunderstanding something. But my main point is that I think the android app should not post a notification unless the user opts in for them.

I don't have an opinion on the notification as such, but it's enormously frustrating that we apparently keep telling people "Syncthing has crashed" and no one can produce any sort of trace of the alleged crashes. The android app needs to either collect the relevant data so we can fix the crashes, or fix whatever misunderstanding pops up these notifications without there being an actual crash involved.

How to provide a good trace?
My sycthing is runnig, while the display is off.
Sometimes, I see this error, while watching on my phone.

That's every information, I get.

@calmh Is there any way to tell from exit codes that Syncthing was stopped because another instance is already running?

And I will make an option for the crash notifications (off by default).

The startup failures are always exit code 1.

@Nutomic Thanks for the crash notification option!

You both made a little sheep feel happy.
There are no more crash warnings. :1st_place_medal:

Was this page helpful?
0 / 5 - 0 ratings