Syncthing binary crashed with error code 2 (V0.5.4, V0.5.2 was OK)

[pluby]

Syncthing binary crashed with error code 2 appears as a notification. It stops working and requires a forced stop.

Raised sepately to #92 relating to 0.4 as this appears to have been introduced between 0.5.2 (which works) to 0.5.4.

Android 4.4.3.

[Nutomic]

Need a logcat.

[pluby]

After happening 3 times in a row yesterday, I've not had the problem since trying to get a logcat. I may have restarted the phone so maybe it was just a glitch following the upgrade.

[Nutomic]

Nice. If you get it again, please reopen ;)

(tagging as invalid for now because there's nothing to be done)

[pluby]

Happened again.

Here's a logcat | grep -i syncthing run about an hour after the event. It doesn't look that helpful so let me know if there's a better way of getting the syncthing logs or if there are any debug options that you'd like me to enable (I'm not that familiar with Android debugging):

V/WindowManager( 2048):   #11: Token{437c7cf0 ActivityRecord{437c7b90 u0 com.nutomic.syncthingandroid/.activities.MainActivity t37}}
V/WindowManager( 2048):   #18: Window{4318f378 u0 com.nutomic.syncthingandroid/com.nutomic.syncthingandroid.activities.MainActivity}
V/WindowManager( 2048):   #11: Token{437c7cf0 ActivityRecord{437c7b90 u0 com.nutomic.syncthingandroid/.activities.MainActivity t37}}
V/WindowManager( 2048):   #17: Window{4318f378 u0 com.nutomic.syncthingandroid/com.nutomic.syncthingandroid.activities.MainActivity}
I/ActivityManager( 2048): START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=com.nutomic.syncthingandroid/.activities.MainActivity} from pid 2329
I/ActivityManager( 2048): START u0 {act=app_settings_fragment cmp=com.nutomic.syncthingandroid/.activities.SettingsActivity} from pid 27973
I/InputMethodManagerService( 2048): windowGainedFocus, packageName=com.nutomic.syncthingandroid, inputType=0x1
I/ActivityManager( 2048): START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=com.nutomic.syncthingandroid/.activities.MainActivity} from pid 2329
I/WindowManager( 2048): Screen frozen for +270ms due to Window{421af3a0 u0 com.nutomic.syncthingandroid/com.nutomic.syncthingandroid.activities.MainActivity}

[Nutomic]

grep is pretty bad for logcat because crash messages go over multiple lines.

Do you still have the full log?

[pluby]

I see what you mean about the multi-line entries, I did a grep with some context lines and there's a null pointer/value exception in there or similar. Sadly, when I ran logcat again so save them the entries had dropped off. I'll fish out the log entries as soon as it happens again. Thanks for your help.

[pluby]

I left logcat running overnight on USB but not no problem. Overnight logs did show some entries from the binary, to do with renewing the UPNP port mapping or something like that, no errors though and the app was running fine this morning with no sign of a crash, and connections to other devices were active.

Just now I got the problem immediately after trying to access the Web GUI (from the applications menu). It did render the page, then less than a second later the crash notification appeared in the status bar. However, this is not a reliable way to reproduce the problem, it was just a one-off I think.

I was able to get a logcat within a couple of minutes of the problem occuring. The only logs I get relate to the client app trying the access the rest API, I can't see anything relating to the binary.

Here's the first snippet where syncthing was mentioned:

10-20 17:32:31.575 D/PMS     ( 2048): releaseHCC(431b5c60): CPU_MIN_NUM PrismScroll_2 0x400
10-20 17:32:31.575 D/PMS     ( 2048): releaseHCC(429f1920): CPU_MIN_FREQ PrismScroll_2 0x100
10-20 17:32:31.715 D/PMS     ( 2048): acquireHCC(426f7c90): CPU_MIN_NUM PrismScroll_2 0x400 2329 10076
10-20 17:32:31.715 D/PMS     ( 2048): acquireHCC(4262d0c8): CPU_MIN_FREQ PrismScroll_2 0x100 2329 10076
10-20 17:32:31.725 W/CpuWake ( 2048): >>nativeAcquireCpuPerfWakeLock()
10-20 17:32:31.725 W/CpuWake ( 2048): <<nativeAcquireCpuPerfWakeLock()
10-20 17:32:31.725 I/ActivityManager( 2048): START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=com.nutomic.syncthingandroid/.activities.MainActivity} from pid 2329
10-20 17:32:31.725 D/PMS     ( 2048): acquireHCC(42c89de8): CPU_MIN_NUM PrismLaunchActivity_4 0x400 2329 10076
10-20 17:32:31.725 D/PMS     ( 2048): acquireHCC(432692c0): CPU_MIN_FREQ PrismLaunchActivity_4 0x100 2329 10076
10-20 17:32:31.765 D/PMS     ( 2048): acquireWL(42c7f0e8): PARTIAL_WAKE_LOCK  ActivityManager-Launch 0x1 2048 1000
10-20 17:32:31.775 D/PMS     ( 2048): releaseHCC(426f7c90): CPU_MIN_NUM PrismScroll_2 0x400

The following log entries were repeated over and over again, several per second:

10-20 17:32:54.465 D/libc    (24491): [NET] getaddrinfo+,hn 9(0x3132372e302e30),sn(),family 0,flags 4
10-20 17:32:54.465 D/libc    (24491): [NET] getaddrinfo-, SUCCESS
10-20 17:32:54.465 D/libc    (24491): [NET] getaddrinfo+,hn 9(0x3132372e302e30),sn(),family 0,flags 4
10-20 17:32:54.465 D/libc    (24491): [NET] getaddrinfo-, SUCCESS
10-20 17:32:54.465 D/libc    (24491): [NET] getaddrinfo+,hn 9(0x3132372e302e30),sn(),family 0,flags 4
10-20 17:32:54.465 D/libc    (24491): [NET] getaddrinfo-, SUCCESS
10-20 17:32:54.465 I/global  (24491): call createSocket() return a new socket.
10-20 17:32:54.465 D/libc    (24491): [NET] getaddrinfo+,hn 9(0x3132372e302e30),sn(),family 0,flags 4
10-20 17:32:54.465 D/libc    (24491): [NET] getaddrinfo-, SUCCESS
10-20 17:32:54.465 W/GetTask (24491): Failed to call Rest API at http://127.0.0.1:8080/rest/model?folder=pictures
10-20 17:32:54.465 W/GetTask (24491): org.apache.http.conn.HttpHostConnectException: Connection to http://127.0.0.1:8080 refused
10-20 17:32:54.465 W/GetTask (24491):   at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:183)
10-20 17:32:54.465 W/GetTask (24491):   at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:164)
10-20 17:32:54.465 W/GetTask (24491):   at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:119)
10-20 17:32:54.465 W/GetTask (24491):   at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:367)
10-20 17:32:54.465 W/GetTask (24491):   at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:754)
10-20 17:32:54.465 W/GetTask (24491):   at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:519)
10-20 17:32:54.465 W/GetTask (24491):   at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:497)
10-20 17:32:54.465 W/GetTask (24491):   at com.nutomic.syncthingandroid.syncthing.GetTask.doInBackground(GetTask.java:62)
10-20 17:32:54.465 W/GetTask (24491):   at com.nutomic.syncthingandroid.syncthing.GetTask.doInBackground(GetTask.java:26)
10-20 17:32:54.465 W/GetTask (24491):   at android.os.AsyncTask$2.call(AsyncTask.java:288)
10-20 17:32:54.465 W/GetTask (24491):   at java.util.concurrent.FutureTask.run(FutureTask.java:237)
10-20 17:32:54.465 W/GetTask (24491):   at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:231)
10-20 17:32:54.465 W/GetTask (24491):   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
10-20 17:32:54.465 W/GetTask (24491):   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
10-20 17:32:54.465 W/GetTask (24491):   at java.lang.Thread.run(Thread.java:864)
10-20 17:32:54.465 W/GetTask (24491): Caused by: java.net.ConnectException: failed to connect to /127.0.0.1 (port 8080): connect failed: ECONNREFUSED (Connection refused)
10-20 17:32:54.465 W/GetTask (24491):   at libcore.io.IoBridge.connect(IoBridge.java:114)
10-20 17:32:54.465 W/GetTask (24491):   at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:192)
10-20 17:32:54.465 W/GetTask (24491):   at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:459)
10-20 17:32:54.465 W/GetTask (24491):   at java.net.Socket.connect(Socket.java:873)
10-20 17:32:54.465 W/GetTask (24491):   at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:125)
10-20 17:32:54.465 W/GetTask (24491):   at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:144)
10-20 17:32:54.465 W/GetTask (24491):   ... 14 more
10-20 17:32:54.465 W/GetTask (24491): Caused by: libcore.io.ErrnoException: connect failed: ECONNREFUSED (Connection refused)
10-20 17:32:54.465 W/GetTask (24491):   at libcore.io.Posix.connect(Native Method)
10-20 17:32:54.465 W/GetTask (24491):   at libcore.io.BlockGuardOs.connect(BlockGuardOs.java:85)
10-20 17:32:54.465 W/GetTask (24491):   at libcore.io.IoBridge.connectErrno(IoBridge.java:127)
10-20 17:32:54.465 W/GetTask (24491):   at libcore.io.IoBridge.connect(IoBridge.java:112)
10-20 17:32:54.465 W/GetTask (24491):   ... 19 more

Here are the "beginning of" bits:

--------- beginning of /dev/log/system
10-20 17:08:57.865 D/PMS     ( 2048): acquireWL(42b8f468): PARTIAL_WAKE_LOCK  *net_scheduler* 0x1 2750 10029
10-20 17:08:57.865 D/qdlights( 2048): [LedInfo] write attr ok name=/sys/class/leds/amber/blink string=0,len=1
10-20 17:08:57.865 D/qdlights( 2048): [LedInfo] write attr ok name=/sys/class/leds/amber/off_timer string=0 0,len=3
10-20 17:08:57.875 D/qdlights( 2048): [LedInfo] write attr ok name=/sys/class/leds/green/brightness string=1,len=1
10-20 17:08:57.875 D/qdlights( 2048): [LedInfo] write attr ok name=/sys/class/leds/green/blink string=0,len=1

--------- beginning of /dev/log/main
10-20 17:32:54.465 D/libc    (24491): [NET] getaddrinfo+,hn 9(0x3132372e302e30),sn(),family 0,flags 4
10-20 17:32:54.465 D/libc    (24491): [NET] getaddrinfo-, SUCCESS
10-20 17:32:54.465 D/libc    (24491): [NET] getaddrinfo+,hn 9(0x3132372e302e30),sn(),family 0,flags 4
10-20 17:32:54.465 D/libc    (24491): [NET] getaddrinfo-, SUCCESS
10-20 17:32:54.465 D/libc    (24491): [NET] getaddrinfo+,hn 9(0x3132372e302e30),sn(),family 0,flags 4
10-20 17:32:54.465 D/libc    (24491): [NET] getaddrinfo-, SUCCESS
10-20 17:32:54.465 I/global  (24491): call createSocket() return a new socket.
10-20 17:32:54.465 D/libc    (24491): [NET] getaddrinfo+,hn 9(0x3132372e302e30),sn(),family 0,flags 4
10-20 17:32:54.465 D/libc    (24491): [NET] getaddrinfo-, SUCCESS
10-20 17:32:54.465 W/GetTask (24491): Failed to call Rest API at http://127.0.0.1:8080/rest/model?folder=pictures
10-20 17:32:54.465 W/GetTask (24491): org.apache.http.conn.HttpHostConnectException: Connection to http://127.0.0.1:8080 refused

I'm no expert with Android logs but judging by the start time on the main log, and the number and freqency of the exception mesages coming from the UI, I think that the original crash log may be long gone in seconds, which may be why I keep missing it.

Is there any way to reduce the logging/retry rate of the UI?

PS: Is there anywhere on here to upload a file so I can send you the whole thing? Or is there something I can search for?

[Nutomic]

You should try adb logcat -s SyncthingNativeCode:v. These logs contain nothing helpful, unfortunately.

You can send the log via pastebin, gist or whatever you like ;)

[pluby]

Will that command above read old log entries after the UI has overwritten the log buffer? I didn't think it was possible.

I'm unable to leave a logcat running on a phone terminal (like ConnectBot) as I don't have root so other applications don't see those messages.

I'm unable to leave a logcat running over the adb shell as the crash doesn't not seem to happen in that state (maybe it's a power or sleep related event).

I'm unable to leave it running after disconnecting from the adb shell because there's no "nohup" command (any suggestions welcome).

I can't get the messages after the crash because the UI overwrites the entire log buffer in seconds (literally seconds, I'm not exaggerating). By the time I get the cable plugged in they're long gone.

[Nutomic]

You should be able to use adb over wifi which is in developer settings.

There should also usually be a "report crash" dialog, you can send it there and I'll receive it trhough Google Play (best write the issue number with the report).

[Zillode]

Closing this as many changes happened in this codebase and in upstream, which means it is probably solved;)