Android & Mac: Some Folders Sync Only Over Cellular Network

[zuzibivoxale]

I have installed BTSync 1.3.69 on a Mac OSX 10.9.2 and 1.3.67 manually on a Fairphone (OS 1.1, based on Android 4.2.2). Both were upgrades from earlier versions and there were 3 folder-pairs set up with only the "Search LAN"- and "Store deleted files in SyncArchive"-options enabled on the Mac's side. This worked fine.

 

Now with the 1.3 upgrade, a totally weird and IMHO inconsistent pattern of the folders finding each other & syncing. At first, the phone did not find the Mac in the same WiFi. Intermittently, one of the folders did, but lost connection. Then, activating cellular data on the phone and "Search Tracker" on the Mac yielded the folder "finding" and syncing within a few seconds. Deactivating cellular data and tracker again often has no effect: the devices still see each other for a while. But after a few hours, the same problem appears again, sometimes with different folder pairs than before. What does this sounds like to you? Problem with the "Search LAN"-option? Router problem (worked fine before v1.3)?

 

Deleting the sync folders, setting them up again with new keys and pairing the phone's folder again does not help.

[RomanZ]

zuzibivoxale,

 

There is a known issue in 1.3 related to devices discovery in LAN. We are looking for ways to resolve it, you can assist us by sending debug logs from both Mac and your Android device.

[zuzibivoxale]

Hello and thanks for looking into this problem.

 

How do I find the sync log on Android? The pinned topic doesn't say. In the logs on the Mac, a lot of this appears while Mac and Phone do not find each other:

 

bind port is _Mac_Port_
UPnP: Could not map UPnP Port on this pass, retrying.
NAT-PMP: Unable to map port with NAT-PMP.
UPnP: Could not map UPnP Port on this pass, retrying.
UPnP: Unable to map port _Mac_IP:Port_ with UPnP.

 

When they do see each other, these entries appear:

 

Checking connection to _Phone_IP:Port_:TCP

Lost tunnel to _Phone_IP:Port_:TCP, remaining tunnels: 0
Lost peer for folder /Users/...

Failed to open tunnel to _Phone_IP:Port_:TCP

 

Sometimes a new hope kindles:

 

Lost tunnel to _Phone_IP:Port_:uTP, remaining tunnels: 2
Best tunnel now is _Phone_IP:Port_:TCP
Found peer for folder /Users/... _Hash_ _Phone_IP:Port_ direct:1 transport:1
 

I hope these log fragments help. I'd prefer not to send the full ones, because they contain so much private data that would a PITA to remove, I'm sorry.

[GreatMarko]

How do I find the sync log on Android?

Within Sync, if you go to Settings -> Send Feedback, you'll have the option to attach debug logs to your report.

[RomanZ]

zuzibivoxale,

 

Would be great if in ticket sent thru Android you'll mention this forum topic.

[Jack Nihil]

I'm experiencing the same. Until upgrading to the recent update. all btsync devices (Win7, Linux, RasPi, Android) were suncing well. After the update all 3 Android devices will not sync. Win7/Linux/RasPi are okay.

[RomanZ]

Jack Nihil,

 

1.3.19, I presume? Can I get full debug logs from Android and some other peer that does not receive files?

[Jack Nihil]

It's version 1.3.86 (Linux - arm & amd64) and version 1.3.19.0 for Android 4.1.2/4.2.

 

I found by accident today that the Android devices will sync with the Linux machines ONCE if I restart btsync on the Linux side. After that one sync no more syncing amongst Android/Linux, though the Linux machines will happily sync with each other whenever changes are made to the folders. Curious.

 

I will try and find some time tomorrow and see if I can get a coherent set of debug logs from the machines.

[RomanZ]

Jack Nihil,

 

Debug logs would be wonderful. Alternatively - if you'll find any scenario for stable reproduction, we can try to reproduce it in lab or explore code to find a culprit.

[zuzibivoxale]

On my end, the problem seems to be solved by upgrading BTSync on the Mac to 1.3.87. Thanks and greetings!
 

[Jack Nihil]

Actually on the Linux side upgrading to 1.3.87 has made things worse.

Now The Android(s) will not sync even after the Linux machines (x2) restart. Linux however sync with each other as before.

Not sure if I'll have time to capture the debug logs tomorrow but I'll see if I can punch a hole in my schedule sometime soon.

[RomanZ]

Jack Nihil,

 

Another thing to try is a new version of Android client, 1.3.20 - which may resolve your issue.

[Jack Nihil]

1.3.20 does not help.

My wife & kids are off with the inlaws next week, so I'll have time to collect the debug info then.

[Jack Nihil]

Packet capture on the Linux hosts revealed that they were not resonding to the upnp packets from the Andreoid:

 

Capturing on eth0
  0.000000 192.168.1.150 -> 239.255.255.250 SSDP 140 M-SEARCH * HTTP/1.1
  3.682471 192.168.1.150 -> 239.255.255.250 SSDP 140 M-SEARCH * HTTP/1.1
 

I enabled 'Use UPnP port mapping' on the Linux hosts which fixed the sync issue with the Android devices.

 

My understanding was that this parameter was to do with punching a hole in the router/firewall.

Looks as though I was mistaken.

Strange how the Linux hosts see each other with the parameter disabled...

 

Regards,

Jack.

[Jack Nihil]

I spoke too soon. The Linux hosts seem to still require a restart for the Androids to sync.

Do not have anymore time today to gather a debug log, but this is what I've observed:

 

1. Disabling auto-sleep on the Android prevents the sync issue (waiting didn't help).

2. Linux requires upnp enabled.

3. Restarting the Linux hosts initiates the sync with the Androids (provided upnp is enabled).

 

Hopefully this week will be a quiet one so I can get you the data needed.

[RomanZ]

Jack,

 

Linux clients should not answer UPnP or PMP protocols. They are target to routers first of all, not to other peers. Other peers should answer LAN discovery packets, they are sent over to port 3838 to 239.252.0.0 multicast address.

 

Do I understand correctly that as soon as you disable auto-sleep option, the issue with syncing Linux machines with Android is gone?

[Jack Nihil]

Hi RomanZ,

 

If auto-sleep is disabled on the Android, the sync is performed after restarting btsync on the Linux hosts. Sync is maintained if both Android/Linux remains on the LAN.

 

However, if the Android leaves the LAN (phone leaves the house, or goes into power-save and turns off the Wi-Fi radio), then returns to the LAN sometime later, the Androids do not see the Linux hosts until btsync is restarted on the Linux side whilst the Android is ON (meaning its wireless interface is UP and not OFF due to power-save).

 

So, a workaround of using cron to restarts btsync on Linux every hour will not work unless the Android device happens to be alive on the LAN at the same time of the Linux btsync restart.

 

Let me find some time this week and get a set of debug logs. I've got a backlog of work to get through, but I'm sure I'll find time.

 

Regards,

Jack.

Edited April 22, 2014 by Jack Nihil

[RomanZ]

@Jack,

 

Thanks for the details, it is much more clear now. Yes, please, the logs have good chances to find the root cause. Note, that I'll need at least one log from your Linux peer (turned on to full debug output) and one log from Android peer.

 

The event of "Android returning to home network" should be reflected in both logs. On Android just tap a Feedback to send logs, leave a link to this forum topic in the feedback form so it will be easier to associate the ticket with forum topic.

[Jack Nihil]

Hi RomanZ,

 

I had some time to investigate this issue today.

Setup:

Android 4.1.2/btsync 1.3.21.0 - IP:192.168.1.150
Ubuntu Linux 13.10 (kernel 3.8.0.31-lowtency)/btsync 1.3.94 - IP:192.168.1.111

This is the sequence of events, together with the sync.log from Linux.

I took the liberty of removing some info which looked 'private'.

1. At the beginning, I pause/un-pause bysync on Linux and then both devices sync:

[20140510 19:00:19.101] ping 192.168.1.150:58347
[20140510 19:00:19.101] Checking connection to 192.168.1.150:58347:TCP
[20140510 19:00:19.102] Checking connection to 192.168.1.150:58347:uTP
[20140510 19:00:19.102] Sending broadcast ping for 5 shares
[20140510 19:00:19.102] Failed to open tunnel to 192.168.1.150:58347:TCP
[20140510 19:00:19.377] Got tunnel to 192.168.1.150:58347:uTP, total tunnels: 1
[20140510 19:00:19.377] Best tunnel now is 192.168.1.150:58347:uTP
[20140510 19:00:19.880] Incoming connection from 192.168.1.150:58347
[20140510 19:00:19.883] Incoming connection from 192.168.1.150:58347
[20140510 19:00:20.000] Got id message from peer jnihil SC-06D 1.3.98
 .
 . etc
 .
[20140510 19:02:12.147] SyncFolderNotify: ".SyncID", event = "IN_CLOSE_WRITE"
[20140510 19:02:12.147] [OnNotifyFileChange] /home/jnihil/phone/.SyncID, source = NULL

Syncs. So far looks good.

2. The Android leaves the network:

[20140510 19:03:21.894] Lost tunnel to 192.168.1.150:34735:TCP
[20140510 19:03:22.241] ping 192.168.1.150:58347
[20140510 19:03:22.241] Checking connection to 192.168.1.150:58347:TCP
[20140510 19:03:22.241] Failed to open tunnel to 192.168.1.150:58347:TCP
 .
 . etc
 .
[20140510 19:04:22.138] ping 192.168.1.150:58347
[20140510 19:04:23.190] Lost peer for folder /home/jnihil/phone

Then btsync goes silent on Linux. So I wait.

Omitting the rescan log which took place. Then even more silence.

The Android device returns to the LAN at 19:19 (16 minutes after leaving).
I verified that the Linux box can icmp ping the Android.

3 minutes since the Android returning to the LAN and still nothing new in the Linux btsync log.

Still pinging the Android from Linux.
However I see the Android send out the following via a packet capture:

192.168.1.150 -> 239.255.255.250 SSDP 140 M-SEARCH * HTTP/1.1
192.168.1.150 -> 239.255.255.250 SSDP 140 M-SEARCH * HTTP/1.1

This happens every time I restart btsync on the Android, with nothing appearing on the Linux debug log. No response seen in the packet capture.

3. I then pause/unPause btsync on Linux and the connection establishes as the Linux box interrogates the LAN.

[20140510 20:31:09.167] Using IP address 192.168.1.111
 .
[20140510 20:31:09.168] Loading config file version 1.3.94
 .
 .
[20140510 20:31:11.171] Sending broadcast ping for 5 shares
[20140510 20:31:11.457] Got ping (broadcast: 0) from peer 192.168.1.150:60276
[20140510 20:31:11.460] Incoming connection from 192.168.1.150:35059
[20140510 20:31:11.658] Got tunnel to 192.168.1.150:35059:TCP, total tunnels: 1
[20140510 20:31:11.658] Best tunnel now is 192.168.1.150:35059:TCP
[20140510 20:31:11.658] Found peer for folder /home/jnihil/phone 192.168.1.150:35059 direct:1 transport:1
[20140510 20:31:12.158] Going to send state notify to peer 192.168.1.150:35059
[20140510 20:31:12.159] ping 192.168.1.150:60276
[20140510 20:31:12.159] Checking connection to 192.168.1.150:60276:TCP
 .
 .

and they sync.

So I see 2 issues:

1. btsync on Linux gives up on finding any new peers after losing contact with its inital peers
2. btsync on Android returning to the LAN is not able to re-establish communication with btsync on Linux.

Regards.
 

[RomanZ]

Hi Jack,

 

On your test #2 the SSDP protocol is not related to BTSync instance discovery - it is intended to find routers. I wonder, if you saw any multicast packets to address 239.192.0.0 over port 3838? These would be the packets responsible for device discovery.

 

In 1.2 BTSync was sending it on a regular basis to find devices in LAN.

In 1.3 BTSync sends multicast packets only for few seconds when it starts / joins new network.

 

Also, any chance to take a glance at your logs from both Android and Linux?

[Jack Nihil]

Thank you RomanZ, your comments on multicasts made me investigate the Wireless Access Point I use.

 

This AP has a feature called directed-multicasts, whereby it converts multicast packets to unicasts to achieve a higher data-rate on the air.

 

I disabled this feature and... BHAM!

The Droids and the Linux hosts are one happy, synchronized family.

 

Thanks for your help and patience.

Best Regards.

[RomanZ]

Jack,

 

Wow, really glad to hear that the issue is resolved now! Could you please also share the model of your router so we can identify same issue in future? BTW, was this feature on by default?

[Jack Nihil]

For the most part the multicast-to-unicast conversion works well - multicast is sent out at a low data-rate, consuming much air-time and low-throughput. Unicast conversion allows for a high-data-rate transfer to the client. However, some apps do not like this behavior. btsync must be one of them.

[RomanZ]

Thanks for info!