Let me make sure I understand, because I think I am getting lost. If I were to monitor the logs that show deletions and additions (actually, there is no easy to extract log, as far as I can tell but I’ll see if I can find it), and use curl
and ls
on those, this would always be after the deletion happens, not while (or before) the deletion is happening. So all we could really get are the curl
and ls
between the deletion in one node and the addition. Is this right?
Yes, we need to verify that it’s syncthing marking the file as deleted (rather than it actually being missing on the filesystem), hence), hence we do ls
to prove that the file is on the disk, and we do curl
to prove that syncthing has marked the file as deleted.
If the file will actually be missing on the disk, then we have to blame the filesystem layer. Otherwise it could be syncthing.
Also, it might be useful to run syncthing on the phone with additional logging (STTRACE=scanner,model) but I am not sure you know how to get the logs out of the Android device.
This may be way over my head. Anyway, while trying it:
-
I am still not entirely sure, since if the
ls
andcurl
happen after the deletion, then they are already deleted in at least one device by the time those commands are issued. Moreover, since I do not see how to get the logs of deletions/additions, I’ll probably be forced to watching carefully for a few minutes and launching a script by hand, which means things will already be changed everywhere. -
As for the curl command and the port: if I have not changed anything, then the port should always be 22000?
-
Is that the syntax to use? I am trying something like (between the two computers)
curl http://ipaddress:22000/rest/db/file?folder=/home/ramon/adirectory&file=somefile
but I am getting curl: (56) Recv failure: Connection reset by peer
.
As for the additional logging: I can certainly run “adb logcat whatever” for the Android devices.
- That’s fine, we need to figure out if the file is gone because it’s really gone, or if it’s gone because syncthing falsely assumes it’s gone (but in reality it’s still on the disk).
- No this should be your GUI port, which is 8080 or 8384 if you are running the beta.
- Folder should be the folder ID not the path the folder path, and file should be the filepath relative to the folder root.
If I have my folder ID
myconfigs
with path/home/.config
and a file/home/.config/subdir/somefile
, then the request should be:curl http://ipaddress:8080/rest/db/file?folder=myconfigs&file=subdir/somefile
I am getting nowhere:
-
Seafile does not seem to provide those easily parseable logs (unless one has the pro edition, which I don’t). So I cannot have a script check the logs and trigger any action. And staring at the screen ain’t an option either (40 minutes have now gone by without events).
-
I still don’t get curl to work. For instance, using
http://192.168.1.34:8080/rest/db/file?folder=MobileOrg&file=myorg.org
I keep getting acurl: (7) Failed to connect to 192.168.1.34 port 8080: Connection refused
(and that address is really the address of one android device in a private lan, and that folder and file do really exist, and the file hangs directly from the folder, no intermediate directories in between). When I try to connect to another machine, I getConnection timed out
. (Using 8080 or 8334 made no difference). I guess all of this might be related to firewall settings, etc, but that is mostly beyond my control. And I cannot really usecurl
automagically anyway, as per 1. -
The only thing I can think of is to have a
ls -lRa
run, say, every 30 seconds (redirecting the output to a file) and later, once I see a delete/add happened, collect thels
outputs that bracket that event, locate the file (or its absence), and paste that here. Would this help without thecurl
output?
I did the ls
thing, and three deletion and addition events have taken
place in the last 12 hours. I will report here on the first case. There is
one Android device (A), a rooted Nexus 7 with stock Android 4.4.1, and two
computers (C1 to C2), but only C2 is directly in sync with the Android (C1
is synced with C2) [for my own records, C1 is burro, C2 coleonyx]
- File Patterns of somatic mutation in human cancer genomes/greenman-patterns-mutations-annotated.pdf, deleted at 00:21:55 (note that the deletion time is the deletion time registered by seafile, which is connected to C2; thus, this is a deletion time that has to be at least no earlier than when the deletion happens in C2).
1.1. A, 1.1.1. ls at 00:18:05 shows, for that file (and its including directory)
./Mendeley-pdfs-ds/Patterns of somatic mutation in human cancer genomes:
-rw-rw---- u0_a200 sdcard_r 298003 2015-04-05 00:29 greenman-patterns-mutations-annotated.pdf
-rw-rw---- u0_a200 sdcard_r 2695334 2015-04-05 00:29 greenman-patterns-mutations-s1.pdf
-rw-rw---- u0_a200 sdcard_r 287521 2015-04-05 00:29 greenman-patterns-mutations.pdf
1.1.2. ls at 00:21:55
./Mendeley-pdfs-ds/Patterns of somatic mutation in human cancer genomes:
-rw-rw---- u0_a200 sdcard_r 298003 2015-04-05 00:29 greenman-patterns-mutations-annotated.pdf
-rw-rw---- u0_a200 sdcard_r 2695334 2015-04-05 00:29 greenman-patterns-mutations-s1.pdf
-rw-rw---- u0_a200 sdcard_r 287521 2015-04-05 00:29 greenman-patterns-mutations.pdf
1.1.3. ls at 00:29:43
./Mendeley-pdfs-ds/Patterns of somatic mutation in human cancer genomes:
-rw-rw---- u0_a200 sdcard_r 298003 2015-04-05 00:29 greenman-patterns-mutations-annotated.pdf
-rw-rw---- u0_a200 sdcard_r 2695334 2015-04-05 00:29 greenman-patterns-mutations-s1.pdf
-rw-rw---- u0_a200 sdcard_r 287521 2015-04-05 00:29 greenman-patterns-mutations.pdf
1.2. C1, 1.2.1. ls at 00:21:24:
./Mendeley-pdfs/Patterns of somatic mutation in human cancer genomes:
total 3540
drwxrwxrwx 2 ramon ramon 149 Apr 7 12:33 .
drwx------ 3479 ramon ramon 290816 Apr 10 23:27 ..
-rw-rw-rw- 1 ramon ramon 298003 Apr 5 00:29 greenman-patterns-mutations-annotated.pdf
-rw-rw-rw- 1 ramon ramon 287521 Apr 5 00:29 greenman-patterns-mutations.pdf
-rw-rw-rw- 1 ramon ramon 2695334 Apr 5 00:29 greenman-patterns-mutations-s1.pdf
1.2.2. ls at 00:21:54: Note the file is gone (so it must have been deleted from C2 shortly before)
./Mendeley-pdfs/Patterns of somatic mutation in human cancer genomes:
total 3248
drwxrwxrwx 2 ramon ramon 97 Apr 11 00:21 .
drwx------ 3479 ramon ramon 290816 Apr 10 23:27 ..
-rw-rw-rw- 1 ramon ramon 287521 Apr 5 00:29 greenman-patterns-mutations.pdf
-rw-rw-rw- 1 ramon ramon 2695334 Apr 5 00:29 greenman-patterns-mutations-s1.pdf
1.2.3 ls at 00:22:25:
./Mendeley-pdfs/Patterns of somatic mutation in human cancer genomes:
total 3248
drwxrwxrwx 2 ramon ramon 97 Apr 11 00:21 .
drwx------ 3479 ramon ramon 290816 Apr 10 23:27 ..
-rw-rw-rw- 1 ramon ramon 287521 Apr 5 00:29 greenman-patterns-mutations.pdf
-rw--w-rw- 1 ramon ramon 2695334 Apr 5 00:29 greenman-patterns-mutations-s1.pdf
1.3. C2: (this is the computer directly connected to the Android) 1.3.1. ls at 00:21:30:
./Mendeley-pdfs/Patterns of somatic mutation in human cancer genomes:
total 3608
drwxr-xr-x 2 ramon ramon 4096 Dec 5 2012 .
drwxr-xr-x 3479 ramon ramon 401408 Apr 10 23:26 ..
-rw-r--r-- 1 ramon ramon 298003 Apr 5 00:29 greenman-patterns-mutations-annotated.pdf
-rw-r--r-- 1 ramon ramon 287521 Apr 5 00:29 greenman-patterns-mutations.pdf
-rw-r--r-- 1 ramon ramon 2695334 Apr 5 00:29 greenman-patterns-mutations-s1.pdf
1.3.2. ls at 00:22:00: file is gone
./Mendeley-pdfs/Patterns of somatic mutation in human cancer genomes:
total 3316
drwxr-xr-x 2 ramon ramon 4096 Apr 11 00:21 .
drwxr-xr-x 3479 ramon ramon 401408 Apr 10 23:26 ..
-rw-r--r-- 1 ramon ramon 287521 Apr 5 00:29 greenman-patterns-mutations.pdf
-rw-r--r-- 1 ramon ramon 2695334 Apr 5 00:29 greenman-patterns-mutations-s1.pdf
2.That file is added back at 00:31:06 2.1. A: 2.1.1. ls at 00:30:45
./Mendeley-pdfs-ds/Patterns of somatic mutation in human cancer genomes:
-rw-rw---- u0_a200 sdcard_r 298003 2015-04-05 00:29 greenman-patterns-mutations-annotated.pdf
-rw-rw---- u0_a200 sdcard_r 2695334 2015-04-05 00:29 greenman-patterns-mutations-s1.pdf
-rw-rw---- u0_a200 sdcard_r 287521 2015-04-05 00:29 greenman-patterns-mutations.pdf
2.1.2 ls at 00:31:31
./Mendeley-pdfs-ds/Patterns of somatic mutation in human cancer genomes:
-rw-rw---- u0_a200 sdcard_r 298003 2015-04-05 00:29 greenman-patterns-mutations-annotated.pdf
-rw-rw---- u0_a200 sdcard_r 2695334 2015-04-05 00:29 greenman-patterns-mutations-s1.pdf
-rw-rw---- u0_a200 sdcard_r 287521 2015-04-05 00:29 greenman-patterns-mutations.pdf
2.2. C1: (again, anything added here must be added through C2, below, as C1 is not connected to the android)
2.2.1 ls at 00:31:02 file still not here
./Mendeley-pdfs/Patterns of somatic mutation in human cancer genomes:
total 3248
drwxrwxrwx 2 ramon ramon 97 Apr 11 00:21 .
drwx------ 3479 ramon ramon 290816 Apr 10 23:27 ..
-rw-rw-rw- 1 ramon ramon 287521 Apr 5 00:29 greenman-patterns-mutations.pdf
-rw-rw-rw- 1 ramon ramon 2695334 Apr 5 00:29 greenman-patterns-mutations-s1.pdf
2.2.2 ls at 00:31:32 file is back
./Mendeley-pdfs/Patterns of somatic mutation in human cancer genomes:
total 3540
drwxrwxrwx 2 ramon ramon 149 Apr 11 00:31 .
drwx------ 3479 ramon ramon 290816 Apr 10 23:27 ..
-rw-rw-rw- 1 ramon ramon 298003 Apr 5 00:29 greenman-patterns-mutations-annotated.pdf
-rw-rw-rw- 1 ramon ramon 287521 Apr 5 00:29 greenman-patterns-mutations.pdf
-rw-rw-rw- 1 ramon ramon 2695334 Apr 5 00:29 greenman-patterns-mutations-s1.pdf
2.3 C2:
2.3.1 ls at 00:30:33: file still not here
./Mendeley-pdfs/Patterns of somatic mutation in human cancer genomes:
total 3316
drwxr-xr-x 2 ramon ramon 4096 Apr 11 00:21 .
drwxr-xr-x 3479 ramon ramon 401408 Apr 10 23:26 ..
-rw-r--r-- 1 ramon ramon 287521 Apr 5 00:29 greenman-patterns-mutations.pdf
-rw-r--r-- 1 ramon ramon 2695334 Apr 5 00:29 greenman-patterns-mutations-s1.pdf
2.3.2 ls at 00:31:34 the file is back
./Mendeley-pdfs/Patterns of somatic mutation in human cancer genomes:
total 3608
drwxr-xr-x 2 ramon ramon 4096 Apr 11 00:31 .
drwxr-xr-x 3479 ramon ramon 401408 Apr 10 23:26 ..
-rw-r--r-- 1 ramon ramon 298003 Apr 5 00:29 greenman-patterns-mutations-annotated.pdf
-rw-r--r-- 1 ramon ramon 287521 Apr 5 00:29 greenman-patterns-mutations.pdf
-rw-r--r-- 1 ramon ramon 2695334 Apr 5 00:29 greenman-patterns-mutations-s1.pdf
Another two cases have happened this night. In both of them, the file, as
reported by ls
in the Android device, is always there (it is
there in the ls
immediately before the removal and in the ls
immediately after the removal).
A few other comments of possibly related things:
-
Reconnection events of the android device (as shown by
Established secure connection to
in the ST logs) seem to happen shortly before an addition event (3 cases) and a deletion event (2 cases). -
I think some of this is also related to the
INFO: Puller (folder "whatever", dir "blablabla"): delete: remove /whatever/blablabla: directory not empty
issue referred to before. Strange INFO: Puller (folder “xyz”, dir “uwv”): delete: remove : directory not empty I just think a complete deletion is never triggered because the directory, as it says, is not empty. -
I am also experiencing, from time to time, the "interrupted system call" issue in the Androids ( https://github.com/syncthing/syncthing-android/issues/85 ) where I will be told by the ST web gui (or the ST android gui) that the directory just does not exist (when in fact it does).
Now, is there a way to disable inotify on the Android? I suspect if I could trigger a sync only at will I could avoid some of this. This might be specific to my use case, but since little file modification happens on the Androids (I read, and from time to time annotate, PDFs) I’d be happy to have the Androids only send back when I say so via a “Rescan” (after I’ve modified something), but have ST running all the time anyway, to passively receive things that are modify in other nodes.
I think the syscall interrupted could actually be the problem.
Right, it would be interesting to get the logcat (via adb) from the android device with STTRACE=scanner (debug options in android I think) setup, to see what the hell happens there.
Also, how do we know which node exactly the deletion started at?
I’ll try to get a logcat, but I have no idea how to do the STTRACE. Is this in the Android ST GUI, and I just write “STTRACE=scanner” on the Debug options? And just “adb logcat > some-huge-file.txt” until I see the problem? Any filtering criteria I can use? (I am asking, because the logcats I’ve seen so far have no clear indication of the time that would allow me to just keep the lines surrounding the time of the addition/deletion; so this is likely to be a big logcat).
Where the deletion started at? It must have started in (or triggered from) the Android. Why? When ST is not working on the Androids, none of this happens. But then, I have no proof of this, which is specially weird since ls
in the Android does not reveal anything disappearing. It is like ST think it is gone, when it ain’t.
If it helps, I can temporarily have just two nodes, one Android and the computer that is also a client to seafile (so I know when files get added/deleted).
I think you just write scanner
in the debug options
You can get a larger logcat and then grep out syncthing stuff.
Three deletion/addition events happened in the last 48 hours, while I have been running ST with scanner
in the Android device. One of them happens in the last 36 hourse, while I was also running ST with STTRACE=scanner,model
in the computer. If I am understanding the logs correctly (which I probably am not) it seems that the computer receives the order to delete, but there is no trace in the Android of an explicit delete (and the file is explicitly mentioned in the Android only before the re-addition, not before the delete).
(I am breaking the post into three pieces, because of the forum limits on number of characters).
Deletion event on 04-14 at 06:06 and addition at 06:34. Android logs
-
As I have emphasized before, the file (“A public service blablabla”) is there on the Android device. This is from several
ls
on the Android before and after the addition and deletionls at 05:30 ./Mendeley-pdfs-ds/A public service: -rw-rw---- u0_a200 sdcard_r 604229 2015-04-04 18:15 A public service - 2009 - Nature.pdf ls at 05:55 ./Mendeley-pdfs-ds/A public service: -rw-rw---- u0_a200 sdcard_r 604229 2015-04-04 18:15 A public service - 2009 - Nature.pdf ls at 06:11 ./Mendeley-pdfs-ds/A public service: -rw-rw---- u0_a200 sdcard_r 604229 2015-04-04 18:15 A public service - 2009 - Nature.pdf ls at 06:34 ./Mendeley-pdfs-ds/A public service: -rw-rw---- u0_a200 sdcard_r 604229 2015-04-04 18:15 A public service - 2009 - Nature.pdf ls at 06:55 ./Mendeley-pdfs-ds/A public service: -rw-rw---- u0_a200 sdcard_r 604229 2015-04-04 18:15 A public service - 2009 - Nature.pdf
-
Android logcat for that day with ST-related events, from 05:47 onwards
(there are many of the "Failed to call Rest API", over all directrories; I delete copious output from below). [ 04-14 05:47:30.447 2238: 2375 W/GetTask ] Failed to call Rest API at http://127.0.0.1:8080/rest/model?folder=Mendeley-pdfs org.apache.http.conn.HttpHostConnectException: Connection to http://127.0.0.1:8080 refused at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:183) at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:164) at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:119) at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:360) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:555) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:487) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:465) at com.nutomic.syncthingandroid.syncthing.b.a(Unknown Source) at com.nutomic.syncthingandroid.syncthing.b.doInBackground(Unknown Source) at android.os.AsyncTask$2.call(AsyncTask.java:288) at java.util.concurrent.FutureTask.run(FutureTask.java:237) at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:231) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587) at java.lang.Thread.run(Thread.java:841) Caused by: java.net.ConnectException: failed to connect to /127.0.0.1 (port 8080): connect failed: ECONNREFUSED (Connection refused) at libcore.io.IoBridge.connect(IoBridge.java:114) at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:192) at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:459) at java.net.Socket.connect(Socket.java:843) at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:119) at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:144) ... 14 more Caused by: libcore.io.ErrnoException: connect failed: ECONNREFUSED (Connection refused) at libcore.io.Posix.connect(Native Method) at libcore.io.BlockGuardOs.connect(BlockGuardOs.java:85) at libcore.io.IoBridge.connectErrno(IoBridge.java:127) at libcore.io.IoBridge.connect(IoBridge.java:112) ... 19 more [ 04-14 05:47:32.947 2238: 2375 W/GetTask ] Failed to call Rest API at http://127.0.0.1:8080/rest/model?folder=Mendeley-pdfs org.apache.http.conn.HttpHostConnectException: Connection to http://127.0.0.1:8080 refused at ... 19 more [ 04-14 05:47:33.587 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:47:33.604139 main.go:398: INFO: syncthing v0.10.30 (go1.4.2 linux-arm android) unknown-user@android.syncthing.net 2015-03-29 07:46:44 UTC [ 04-14 05:47:33.587 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:47:33.604752 main.go:399: INFO: My ID: QWFYVRW-blablabla [ 04-14 05:47:35.957 2238: 2375 W/GetTask ] Failed to call Rest API at http://127.0.0.1:8080/rest/model?folder=Mendeley-pdfs org.apache.http.conn.HttpHostConnectException: Connection to http://127.0.0.1:8080 refused at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:183) [ 04-14 05:47:39.217 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:47:39.226340 main.go:665: INFO: Starting web GUI on http://127.0.0.1:8080/ [ 04-14 05:47:39.467 2238: 2375 W/GetTask ] Failed to call Rest API at http://127.0.0.1:8080/rest/model?folder=Mendeley-pdfs org.apache.http.conn.HttpHostConnectException: Connection to http://127.0.0.1:8080 refused at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:183) at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:164) at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:119) [ 04-14 05:54:12.327 2238: 2375 W/GetTask ] Failed to call Rest API at http://127.0.0.1:8080/rest/model?folder=Mendeley-pdfs org.apache.http.conn.HttpHostConnectException: Connection to http://127.0.0.1:8080 refused at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:183) at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:164) [ 04-14 05:54:19.617 22535:16699 I/Fitness ] sync: Account {name=rdiaz02@gmail.com, type=com.google}, extras: Bundle[{sync_periodic=true}] [ 04-14 05:54:21.897 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:21.442714 upnp.go:97: INFO: Starting UPnP discovery... [ 04-14 05:54:27.947 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:27.952821 upnp.go:124: INFO: UPnP discovery complete (found 0 devices). [ 04-14 05:54:27.947 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:27.952967 main.go:916: INFO: Starting local discovery announcements [ 04-14 05:54:27.947 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:27.953604 main.go:921: INFO: Starting global discovery announcements [ 04-14 05:54:27.947 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:27.958382 main.go:479: OK: Ready to synchronize Files-to-tablet (read-write) [ 04-14 05:54:28.547 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:28.553037 connections.go:34: INFO: Established secure connection to IPAFCRC-blablabla at xyz:53584-uvw:22000 [ 04-14 05:54:29.677 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:29.655111 model.go:159: INFO: Folder "Files-to-tablet" is running with LenientMtimes workaround. Syncing may not work properly. [ 04-14 05:54:29.697 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:29.705090 model.go:545: INFO: Device IPAFCRC-blablabla client is "syncthing v0.10.30" [ 04-14 05:54:29.697 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:29.705874 model.go:550: INFO: Device IPAFCRC-blablabla name is "coleonyx" [ 04-14 05:54:30.667 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.681727 main.go:479: OK: Ready to synchronize Mendeley-pdfs (read-write) [ 04-14 05:54:30.697 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.708586 model.go:159: INFO: Folder "Mendeley-pdfs" is running with LenientMtimes workaround. Syncing may not work properly. [ 04-14 05:54:30.697 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.708985 main.go:479: OK: Ready to synchronize MobileOrg (read-write) [ 04-14 05:54:30.697 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.709294 model.go:159: INFO: Folder "MobileOrg" is running with LenientMtimes workaround. Syncing may not work properly. [ 04-14 05:54:30.697 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.709965 main.go:479: INFO: Device GE47POS-blablable is "Bufo" at [dynamic] [ 04-14 05:54:30.697 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.710553 main.go:479: INFO: Device IPAFCRC-blablabla is "coleonyx" at [uvw:22000] [ 04-14 05:54:30.697 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.711127 main.go:479: INFO: Device O6OUCZU-blablablo is "TF-201" at [dynamic] [ 04-14 05:54:30.697 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.711750 main.go:479: INFO: Device QWFYVRW-blablabla is "localhost" at [dynamic] [ 04-14 05:54:30.697 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.711961 main.go:479: INFO: No automatic upgrades; STNOUPGRADE environment variable defined. [ 04-14 05:54:30.717 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.729114 walk.go:82: DEBUG: Walk /storage/sdcard0/Android/data/com.nutomic.syncthingandroid/Mendeley-dbs 131072 &{[{0x10a5c4e0 false} {0x10a5c840 false} {0x10a5c900 false} {0x10a5ca20 false} {0x10a5cae0 true} {0x10a5cc00 true} {0x10a5ccc0 true} {0x10a5cea0 true} {0x10a5cf60 true} {0x10a5d020 true} {0x10a5d0e0 true} {0x10a5d1a0 true}] true 0x1104cc10 afb00ca01106c1935d077fb1abbd7925 0x10a3b840 {0 0}} [ 04-14 05:54:30.717 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.729661 walk.go:354: DEBUG: checkDir /storage/sdcard0/Android/data/com.nutomic.syncthingandroid/Mendeley-dbs &{Mendeley-dbs 4096 2147484152 {63564516479 433392001 0x7ae9f8} 0x11dc6f50} [ 04-14 05:54:30.717 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.731127 walk.go:149: DEBUG: ignored: .stfolder [ 04-14 05:54:30.717 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.731429 walk.go:149: DEBUG: ignored: .stignore [ 04-14 05:54:30.727 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.732990 walk.go:149: DEBUG: ignored: rdiaz02@gmail.com@www.mendeley.com.sqlite-journal [ 04-14 05:54:30.727 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.733894 rwfolder.go:123: INFO: Completed initial scan (rw) of folder Mendeley-dbs-Nexus7 [ 04-14 05:54:30.727 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.734980 walk.go:82: DEBUG: Walk /storage/emulated/0/Android/data/com.nutomic.syncthingandroid/Files-to-tablet 131072 &{[] true 0x10ab26d0 d41d8cd98f00b204e9800998ecf8427e 0x110ff5c0 {0 0}} [ 04-14 05:54:30.727 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.735426 walk.go:354: DEBUG: checkDir /storage/emulated/0/Android/data/com.nutomic.syncthingandroid/Files-to-tablet &{Files-to-tablet 4096 2147484152 {63564423451 359392000 0x7ae9f8} 0x10ddcaf0} [ 04-14 05:54:30.727 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.737940 walk.go:149: DEBUG: ignored: .stfolder [ 04-14 05:54:30.767 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.777587 walk.go:82: DEBUG: Walk /storage/sdcard0/Android/data/com.nutomic.syncthingandroid/Mendeley-pdfs-ds 131072 &{[] true 0x10ab2760 d41d8cd98f00b204e9800998ecf8427e 0x10b7bd00 {0 0}} [ 04-14 05:54:30.767 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.778174 walk.go:354: DEBUG: checkDir /storage/sdcard0/Android/data/com.nutomic.syncthingandroid/Mendeley-pdfs-ds &{Mendeley-pdfs-ds 270336 2147484152 {63564552027 143392000 0x7ae9f8} 0x11e35880} [ 04-14 05:54:30.827 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.831930 walk.go:82: DEBUG: Walk /storage/sdcard0/Android/data/com.nutomic.syncthingandroid/MobileOrg 131072 &{[] true 0x10ab2540 d41d8cd98f00b204e9800998ecf8427e 0x116dcf80 {0 0}} [ 04-14 05:54:30.827 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.832992 walk.go:354: DEBUG: checkDir /storage/sdcard0/Android/data/com.nutomic.syncthingandroid/MobileOrg &{MobileOrg 4096 2147484152 {63564551952 663392000 0x7ae9f8} 0x10ddcc40} [ 04-14 05:54:30.897 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:30.902153 walk.go:149: DEBUG: ignored: .stfolder [ 04-14 05:54:31.067 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:31.071929 rwfolder.go:123: INFO: Completed initial scan (rw) of folder MobileOrg [ 04-14 05:54:31.127 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:31.133631 rwfolder.go:123: INFO: Completed initial scan (rw) of folder Files-to-tablet [ 04-14 05:54:31.447 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:54:31.456390 walk.go:149: DEBUG: ignored: .stfolder [ 04-14 05:57:01.147 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 03:57:01.159007 model.go:631: INFO: Connection to IPAFCRC-blablabla closed: EOF [ 04-14 06:01:47.547 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:01:47.556165 main.go:1032: INFO: Paused state detected, possibly woke up from standby. Restarting in 1m0s. [ 04-14 06:06:39.647 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:06:39.661806 rwfolder.go:123: INFO: Completed initial scan (rw) of folder Mendeley-pdfs [ 04-14 06:06:40.887 1132: 1133 D/dalvikvm ] GC_CONCURRENT freed 429K, 11% free 9558K/10660K, paused 2ms+2ms, total 60ms [ 04-14 06:06:41.297 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:06:41.315303 connections.go:34: INFO: Established secure connection to IPAFCRC-blablabla at xyz:53585-uvw:22000 [ 04-14 06:06:41.367 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:06:41.381204 model.go:545: INFO: Device IPAFCRC-blablabla client is "syncthing v0.10.30" [ 04-14 06:06:41.367 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:06:41.382082 model.go:550: INFO: Device IPAFCRC-blablabla name is "coleonyx" [ 04-14 06:11:39.526 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:11:39.267901 main.go:902: INFO: Restarting [ 04-14 06:11:39.526 2238:16589 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:11:39.268123 main.go:479: OK: Exiting [ 04-14 06:11:39.526 2238: 458 I/SyncthingRunnable ] Restarting syncthing [ 04-14 06:11:39.566 2238: 2275 W/GetTask ] Failed to call Rest API at http://127.0.0.1:8080/rest/model?folder=Files-to-tablet org.apache.http.conn.HttpHostConnectException: Connection to http://127.0.0.1:8080 refused blablabla [ 04-14 06:11:40.076 2238: 2275 W/GetTask ] Failed to call Rest API at http://127.0.0.1:8080/rest/model?folder=Files-to-tablet org.apache.http.conn.HttpHostConnectException: Connection to http://127.0.0.1:8080 refused at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:183) blablabla [ 04-14 06:11:40.626 2238:16997 I/SyncthingRunnable-Nice ] ionice performed on libsyncthing.so [ 04-14 06:11:41.086 2238: 2275 W/GetTask ] Failed to call Rest API at http://127.0.0.1:8080/rest/model?folder=Files-to-tablet org.apache.http.conn.HttpHostConnectException: Connection to http://127.0.0.1:8080 refused at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:183) blablabla many more of these, as usual [ 04-14 06:16:22.186 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:16:22.198467 main.go:398: INFO: syncthing v0.10.30 (go1.4.2 linux-arm android) unknown-user@android.syncthing.net 2015-03-29 07:46:44 UTC [ 04-14 06:16:22.186 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:16:22.199847 main.go:399: INFO: My ID: QWFYVRW-blablabla [ 04-14 06:20:27.886 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:20:27.894821 main.go:665: INFO: Starting web GUI on http://127.0.0.1:8080/ Many more like this, with all of the folders [ 04-14 06:20:33.136 2238: 2275 W/GetTask ] Failed to call Rest API at http://127.0.0.1:8080/rest/model?folder=Mendeley-dbs-Nexus7 org.apache.http.conn.HttpHostConnectException: Connection to http://127.0.0.1:8080 refused [ 04-14 06:24:28.136 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:24:28.137963 upnp.go:97: INFO: Starting UPnP discovery... [ 04-14 06:30:00.906 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:00.915903 upnp.go:124: INFO: UPnP discovery complete (found 0 devices). [ 04-14 06:30:00.906 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:00.916371 main.go:916: INFO: Starting local discovery announcements [ 04-14 06:30:00.906 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:00.917264 main.go:921: INFO: Starting global discovery announcements [ 04-14 06:30:00.906 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:00.919447 main.go:479: OK: Ready to synchronize Files-to-tablet (read-write) [ 04-14 06:30:01.516 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:01.522586 connections.go:34: INFO: Established secure connection to IPAFCRC-blablabla at xyz:53586-uvw:22000 [ 04-14 06:30:01.516 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:01.523575 model.go:545: INFO: Device IPAFCRC-blablabla client is "syncthing v0.10.30" [ 04-14 06:30:01.516 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:01.524312 model.go:550: INFO: Device IPAFCRC-blablabla name is "coleonyx" [ 04-14 06:30:03.126 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:03.130797 model.go:159: INFO: Folder "Files-to-tablet" is running with LenientMtimes workaround. Syncing may not work properly. [ 04-14 06:30:03.136 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:03.142618 main.go:479: OK: Ready to synchronize Mendeley-dbs-Nexus7 (read-write) [ 04-14 06:30:04.096 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.106296 model.go:159: INFO: Folder "Mendeley-dbs-Nexus7" is running with LenientMtimes workaround. Syncing may not work properly. [ 04-14 06:30:04.096 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.106449 main.go:479: OK: Ready to synchronize Mendeley-pdfs (read-write) [ 04-14 06:30:04.096 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.107123 model.go:159: INFO: Folder "Mendeley-pdfs" is running with LenientMtimes workaround. Syncing may not work properly. [ 04-14 06:30:04.096 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.107214 main.go:479: OK: Ready to synchronize MobileOrg (read-write) [ 04-14 06:30:04.096 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.107283 model.go:159: INFO: Folder "MobileOrg" is running with LenientMtimes workaround. Syncing may not work properly. [ 04-14 06:30:04.096 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.107898 main.go:479: INFO: Device GE47POS-blablable is "Bufo" at [dynamic] [ 04-14 06:30:04.096 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.108361 main.go:479: INFO: Device IPAFCRC-blablabla is "coleonyx" at [uvw:22000] [ 04-14 06:30:04.096 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.108806 main.go:479: INFO: Device O6OUCZU-blablablo is "TF-201" at [dynamic] [ 04-14 06:30:04.096 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.109257 main.go:479: INFO: Device QWFYVRW-blablabla is "localhost" at [dynamic] [ 04-14 06:30:04.096 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.109326 main.go:479: INFO: No automatic upgrades; STNOUPGRADE environment variable defined. [ 04-14 06:30:04.106 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.110479 walk.go:82: DEBUG: Walk /storage/emulated/0/Android/data/com.nutomic.syncthingandroid/Files-to-tablet 131072 &{[] true 0x10af6520 d41d8cd98f00b204e9800998ecf8427e 0x10b115c0 {0 0}} [ 04-14 06:30:04.106 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.110689 walk.go:354: DEBUG: checkDir /storage/emulated/0/Android/data/com.nutomic.syncthingandroid/Files-to-tablet &{Files-to-tablet 4096 2147484152 {63564423451 359392000 0x7ae9f8} 0x119a42a0} [ 04-14 06:30:04.166 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.177088 walk.go:149: DEBUG: ignored: .stfolder [ 04-14 06:30:04.176 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.181253 walk.go:82: DEBUG: Walk /storage/sdcard0/Android/data/com.nutomic.syncthingandroid/Mendeley-dbs 131072 &{[{0x10a5c4e0 false} {0x10a5c840 false} {0x10a5c900 false} {0x10a5ca20 false} {0x10a5cae0 true} {0x10a5cc60 true} {0x10a5cd20 true} {0x10a5cf00 true} {0x10a5cfc0 true} {0x10a5d080 true} {0x10a5d140 true} {0x10a5d200 true}] true 0x10ae65c0 afb00ca01106c1935d077fb1abbd7925 0x10a3acc0 {0 0}} [ 04-14 06:30:04.176 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.182894 walk.go:354: DEBUG: checkDir /storage/sdcard0/Android/data/com.nutomic.syncthingandroid/Mendeley-dbs &{Mendeley-dbs 4096 2147484152 {63564516479 433392001 0x7ae9f8} 0x110120e0} [ 04-14 06:30:04.176 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.187146 walk.go:149: DEBUG: ignored: .stfolder [ 04-14 06:30:04.176 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.188128 walk.go:149: DEBUG: ignored: .stignore [ 04-14 06:30:04.216 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.222455 walk.go:82: DEBUG: Walk /storage/sdcard0/Android/data/com.nutomic.syncthingandroid/Mendeley-pdfs-ds 131072 &{[] true 0x10aee520 d41d8cd98f00b204e9800998ecf8427e 0x10c05d00 {0 0}} [ 04-14 06:30:04.216 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.222988 walk.go:354: DEBUG: checkDir /storage/sdcard0/Android/data/com.nutomic.syncthingandroid/Mendeley-pdfs-ds &{Mendeley-pdfs-ds 270336 2147484152 {63564552027 143392000 0x7ae9f8} 0x1185d260} [ 04-14 06:30:04.246 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.259512 walk.go:82: DEBUG: Walk /storage/sdcard0/Android/data/com.nutomic.syncthingandroid/MobileOrg 131072 &{[] true 0x10a388a0 d41d8cd98f00b204e9800998ecf8427e 0x10c05180 {0 0}} [ 04-14 06:30:04.246 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.260063 walk.go:354: DEBUG: checkDir /storage/sdcard0/Android/data/com.nutomic.syncthingandroid/MobileOrg &{MobileOrg 4096 2147484152 {63564551952 663392000 0x7ae9f8} 0x117021c0} [ 04-14 06:30:04.256 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.263282 walk.go:149: DEBUG: ignored: .stfolder [ 04-14 06:30:04.276 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.287421 walk.go:149: DEBUG: ignored: rdiaz02@gmail.com@www.mendeley.com.sqlite-journal [ 04-14 06:30:04.276 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.288708 rwfolder.go:123: INFO: Completed initial scan (rw) of folder Mendeley-dbs-Nexus7 [ 04-14 06:30:04.316 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.326943 rwfolder.go:123: INFO: Completed initial scan (rw) of folder MobileOrg [ 04-14 06:30:04.486 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.490820 rwfolder.go:123: INFO: Completed initial scan (rw) of folder Files-to-tablet [ 04-14 06:30:04.866 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:04.876789 walk.go:149: DEBUG: ignored: .stfolder
-
Note the only two explicit references to the deleted and added file. This is after it is shown as having been deleted, and shortly before it is shown as added in the other node.
[ 04-14 06:30:05.936 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:05.944717 walk.go:149: DEBUG: rescan: File{Name:"A public service/A public service - 2009 - Nature.pdf", Flags:0110666, Modified:1428164116, Version:31939939, Size:128, Blocks:[]} 1428164116 -rw-rw---- [ 04-14 06:30:05.936 2238:16995 I/SyncthingNativeCode ] [QWFYV] 2015/04/14 04:30:05.945152 walk.go:149: DEBUG: to hash: /storage/sdcard0/Android/data/com.nutomic.syncthingandroid/Mendeley-pdfs-ds/A public service/A public service - 2009 - Nature.pdf File{Name:"A public service/A public service - 2009 - Nature.pdf", Flags:0100666, Modified:1428164116, Version:31961395, Size:0, Blocks:[]}
Deletion event on 04-14 at 06:06 and addition at 06:34. Computer logs
-
Computer log, mentions of the file and folder (and surrounding entries) at the time of deletion
[IPAFC] 2015/04/14 06:06:43.212248 rwfolder.go:159: DEBUG: rwFolder/Mendeley-pdfs@0xc2094d82c0 skip (curVer == prevVer) 0 [IPAFC] 2015/04/14 06:06:44.212595 rwfolder.go:159: DEBUG: rwFolder/Mendeley-pdfs@0xc2094d82c0 skip (curVer == prevVer) 0 [IPAFC] 2015/04/14 06:06:45.212827 rwfolder.go:159: DEBUG: rwFolder/Mendeley-pdfs@0xc2094d82c0 skip (curVer == prevVer) 0 (similar entries for other folders) [IPAFC] 2015/04/14 06:06:45.839718 connections.go:115: INFO: Established secure connection to QWFYVRW-blablabla at uvw:22000-xyz:53585 [IPAFC] 2015/04/14 06:06:45.840135 model.go:920: DEBUG: sendIndexes for QWFYVRW-blablabla-uvw:22000-xyz:53585/"Mendeley-dbs-Nexus7" starting [IPAFC] 2015/04/14 06:06:45.840579 model.go:920: DEBUG: sendIndexes for QWFYVRW-blablabla-uvw:22000-xyz:53585/"Files-to-tablet" starting [IPAFC] 2015/04/14 06:06:45.840798 model.go:920: DEBUG: sendIndexes for QWFYVRW-blablabla-uvw:22000-xyz:53585/"Mendeley-pdfs" starting [IPAFC] 2015/04/14 06:06:45.841084 model.go:920: DEBUG: sendIndexes for QWFYVRW-blablabla-uvw:22000-xyz:53585/"MobileOrg" starting [IPAFC] 2015/04/14 06:06:45.841549 model.go:994: DEBUG: sendIndexes for QWFYVRW-blablabla-uvw:22000-xyz:53585/"MobileOrg": 56 files (small initial index) [IPAFC] 2015/04/14 06:06:45.841685 model.go:994: DEBUG: sendIndexes for QWFYVRW-blablabla-uvw:22000-xyz:53585/"Mendeley-dbs-Nexus7": 5 files (small initial index) [IPAFC] 2015/04/14 06:06:45.844366 model.go:994: DEBUG: sendIndexes for QWFYVRW-blablabla-uvw:22000-xyz:53585/"Files-to-tablet": 191 files (small initial index) [IPAFC] 2015/04/14 06:06:45.846088 model.go:970: DEBUG: sendIndexes for QWFYVRW-blablabla-uvw:22000-xyz:53585/"Mendeley-pdfs": 581 files (<256130 bytes) (initial index) [IPAFC] 2015/04/14 06:06:45.866303 model.go:978: DEBUG: sendIndexes for QWFYVRW-blablabla-uvw:22000-xyz:53585/"Mendeley-pdfs": 397 files (<260290 bytes) (batched update) [IPAFC] 2015/04/14 06:06:45.880051 model.go:978: DEBUG: sendIndexes for QWFYVRW-blablabla-uvw:22000-xyz:53585/"Mendeley-pdfs": 374 files (<263500 bytes) (batched update) [IPAFC] 2015/04/14 06:06:45.890552 model.go:978: DEBUG: sendIndexes for QWFYVRW-blablabla-uvw:22000-xyz:53585/"Mendeley-pdfs": 432 files (<256160 bytes) (batched update) [IPAFC] 2015/04/14 06:06:45.897720 rwfolder.go:159: DEBUG: rwFolder/Clases@0xc20847e160 skip (curVer == prevVer) 0 [IPAFC] 2015/04/14 06:06:45.952698 model.go:978: DEBUG: sendIndexes for QWFYVRW-blablabla-uvw:22000-xyz:53585/"Mendeley-pdfs": 406 files (<267500 bytes) (batched update) [IPAFC] 2015/04/14 06:06:46.031927 model.go:978: DEBUG: sendIndexes for QWFYVRW-blablabla-uvw:22000-xyz:53585/"Mendeley-pdfs": 455 files (<256270 bytes) (batched update) [IPAFC] 2015/04/14 06:06:46.111614 model.go:978: DEBUG: sendIndexes for QWFYVRW-blablabla-uvw:22000-xyz:53585/"Mendeley-pdfs": 888 files (<256040 bytes) (batched update) [IPAFC] 2015/04/14 06:06:46.116240 model.go:978: DEBUG: sendIndexes for QWFYVRW-blablabla-uvw:22000-xyz:53585/"Mendeley-pdfs": 886 files (<256260 bytes) (batched update) [IPAFC] 2015/04/14 06:06:46.120783 model.go:978: DEBUG: sendIndexes for QWFYVRW-blablabla-uvw:22000-xyz:53585/"Mendeley-pdfs": 580 files (<256040 bytes) (batched update) [IPAFC] 2015/04/14 06:06:46.142105 model.go:545: INFO: Device QWFYVRW-blablabla client is "syncthing v0.10.30" [IPAFC] 2015/04/14 06:06:46.142206 model.go:550: INFO: Device QWFYVRW-blablabla name is "localhost" [IPAFC] 2015/04/14 06:06:46.206881 model.go:414: DEBUG: IDX(in): QWFYVRW-blablabla "Files-to-tablet": 128 files [IPAFC] 2015/04/14 06:06:46.217571 rwfolder.go:159: DEBUG: rwFolder/Mendeley-pdfs@0xc2094d82c0 skip (curVer == prevVer) 0 [IPAFC] 2015/04/14 06:06:46.395960 model.go:414: DEBUG: IDX(in): QWFYVRW-blablabla "Mendeley-pdfs": 578 files [IPAFC] 2015/04/14 06:06:46.553056 model.go:467: DEBUG: model@0xc208d5f340 IDXUP(in): QWFYVRW-blablabla / "Mendeley-pdfs": 389 files [IPAFC] 2015/04/14 06:06:46.740571 model.go:467: DEBUG: model@0xc208d5f340 IDXUP(in): QWFYVRW-blablabla / "Mendeley-pdfs": 370 files [IPAFC] 2015/04/14 06:06:47.288236 rwfolder.go:332: DEBUG: rwFolder/Mendeley-pdfs@0xc2094d82c0 handling A public service/A public service - 2009 - Nature.pdf [IPAFC] 2015/04/14 06:06:47.306423 rwfolder.go:159: DEBUG: rwFolder/CharlasCursos@0xc2094d80b0 skip (curVer == prevVer) 0 [IPAFC] 2015/04/14 06:06:47.324888 rwfolder.go:430: DEBUG: Deleting file A public service/A public service - 2009 - Nature.pdf [IPAFC] 2015/04/14 06:06:47.341754 model.go:467: DEBUG: model@0xc208d5f340 IDXUP(in): QWFYVRW-blablabla / "Mendeley-pdfs": 455 files [IPAFC] 2015/04/14 06:06:47.385866 rwfolder.go:175: DEBUG: rwFolder/Mendeley-pdfs@0xc2094d82c0 changed 1 [IPAFC] 2015/04/14 06:06:47.385893 rwfolder.go:271: DEBUG: rwFolder/Mendeley-pdfs@0xc2094d82c0 c 1 p 16 [IPAFC] 2015/04/14 06:06:47.396049 model.go:467: DEBUG: model@0xc208d5f340 IDXUP(in): QWFYVRW-blablabla / "Mendeley-pdfs": 888 files [IPAFC] 2015/04/14 06:06:47.447292 rwfolder.go:175: DEBUG: rwFolder/Mendeley-pdfs@0xc2094d82c0 changed 0 [IPAFC] 2015/04/14 06:06:47.459792 rwfolder.go:197: DEBUG: rwFolder/Mendeley-pdfs@0xc2094d82c0 next pull in 10s [IPAFC] 2015/04/14 06:06:47.462213 model.go:467: DEBUG: model@0xc208d5f340 IDXUP(in): QWFYVRW-blablabla / "Mendeley-pdfs": 886 files [IPAFC] 2015/04/14 06:06:47.479430 progressemitter.go:135: DEBUG: progress emitter: bytes completed for Mendeley-pdfs: 0 [IPAFC] 2015/04/14 06:06:47.479464 model.go:356: DEBUG: model@0xc208d5f340 NeedSize("Mendeley-pdfs"): 0 0 [IPAFC] 2015/04/14 06:06:47.620591 model.go:467: DEBUG: model@0xc208d5f340 IDXUP(in): QWFYVRW-blablabla / "Mendeley-pdfs": 580 files [IPAFC] 2015/04/14 06:06:47.638712 model.go:279: DEBUG: model@0xc208d5f340 Completion(QWFYVRW-blablabla, "Mendeley-pdfs"): 30.079650 (5576848812 / 7976002399) [IPAFC] 2015/04/14 06:06:47.737817 model.go:935: DEBUG: sendIndexes for QWFYVRW-blablabla-uvw:22000-xyz:53579/"Mendeley-pdfs" exiting: connection closed [IPAFC] 2015/04/14 06:06:47.769201 model.go:467: DEBUG: model@0xc208d5f340 IDXUP(in): QWFYVRW-blablabla / "Mendeley-pdfs": 464 files [IPAFC] 2015/04/14 06:06:47.885696 model.go:467: DEBUG: model@0xc208d5f340 IDXUP(in): QWFYVRW-blablabla / "Mendeley-pdfs": 460 files [IPAFC] 2015/04/14 06:06:47.908213 rwfolder.go:159: DEBUG: rwFolder/Clases@0xc20847e160 skip (curVer == prevVer) 0 [IPAFC] 2015/04/14 06:06:48.001944 model.go:467: DEBUG: model@0xc208d5f340 IDXUP(in): QWFYVRW-blablabla / "Mendeley-pdfs": 417 files [IPAFC] 2015/04/14 06:06:48.110676 model.go:467: DEBUG: model@0xc208d5f340 IDXUP(in): QWFYVRW-blablabla / "Mendeley-pdfs": 522 files (similar entries for other folders, removed) [IPAFC] 2015/04/14 06:06:48.359915 model.go:467: DEBUG: model@0xc208d5f340 IDXUP(in): QWFYVRW-blablabla / "Mendeley-pdfs": 501 files [IPAFC] 2015/04/14 06:06:48.509970 model.go:467: DEBUG: model@0xc208d5f340 IDXUP(in): QWFYVRW-blablabla / "Mendeley-pdfs": 417 files (the next two nodes are now disconnected; I leave it here for completenness) [IPAFC] 2015/04/14 06:06:48.609809 model.go:279: DEBUG: model@0xc208d5f340 Completion(O6OUCZU-blablablo, "Mendeley-pdfs"): 0.000000 (7976002399 / 7976002399) [IPAFC] 2015/04/14 06:06:48.610026 model.go:279: DEBUG: model@0xc208d5f340 Completion(BRX3S3Y-blablablu, "Mendeley-pdfs"): 0.000000 (7976002399 / 7976002399) [IPAFC] 2015/04/14 06:06:48.634198 model.go:467: DEBUG: model@0xc208d5f340 IDXUP(in): QWFYVRW-blablabla / "Mendeley-pdfs": 564 files [IPAFC] 2015/04/14 06:06:48.824863 model.go:467: DEBUG: model@0xc208d5f340 IDXUP(in): QWFYVRW-blablabla / "Mendeley-pdfs": 411 files [IPAFC] 2015/04/14 06:06:48.908496 rwfolder.go:159: DEBUG: rwFolder/Clases@0xc20847e160 skip (curVer == prevVer) 0 [IPAFC] 2015/04/14 06:06:48.947579 model.go:467: DEBUG: model@0xc208d5f340 IDXUP(in): QWFYVRW-blablabla / "Mendeley-pdfs": 496 files [IPAFC] 2015/04/14 06:06:49.035709 model.go:467: DEBUG: model@0xc208d5f340 IDXUP(in): QWFYVRW-blablabla / "Mendeley-pdfs": 641 files [IPAFC] 2015/04/14 06:06:49.145012 model.go:467: DEBUG: model@0xc208d5f340 IDXUP(in): QWFYVRW-blablabla / "Mendeley-pdfs": 192 files
-
Computer log, mentions of the file (and surrounding entries) at the time of addition back
[IPAFC] 2015/04/14 06:34:08.903737 rwfolder.go:166: DEBUG: rwFolder/Mendeley-pdfs@0xc2094d82c0 pulling 33831 33835 [IPAFC] 2015/04/14 06:34:08.903826 rwfolder.go:271: DEBUG: rwFolder/Mendeley-pdfs@0xc2094d82c0 c 1 p 16 [IPAFC] 2015/04/14 06:34:08.915715 rwfolder.go:332: DEBUG: rwFolder/Mendeley-pdfs@0xc2094d82c0 handling A public service/A public service - 2009 - Nature.pdf [IPAFC] 2015/04/14 06:34:08.941451 blockqueue.go:43: DEBUG: open: open /home/ramon/Mendeley-pdfs/A public service/.syncthing.A public service - 2009 - Nature.pdf: no such file or directory [IPAFC] 2015/04/14 06:34:08.941475 rwfolder.go:749: DEBUG: rwFolder/Mendeley-pdfs@0xc2094d82c0 need file A public service/A public service - 2009 - Nature.pdf; copy 5, reused 0 [IPAFC] 2015/04/14 06:34:08.941490 progressemitter.go:106: DEBUG: progress emitter: registering Mendeley-pdfs A public service/A public service - 2009 - Nature.pdf [IPAFC] 2015/04/14 06:34:08.944164 sharedpullerstate.go:197: DEBUG: sharedPullerState Mendeley-pdfs A public service/A public service - 2009 - Nature.pdf pullNeeded start -> 1 [IPAFC] 2015/04/14 06:34:08.944468 model.go:1030: DEBUG: model@0xc208d5f340 REQ(out): QWFYVRW-blablabla: "Mendeley-pdfs" / "A public service/A public service - 2009 - Nature.pdf" o=0 s=131072 h=92869c2fcdbbb71e77bfa8240dffa67dede98e07aea91156ac62d002908c16e6 [IPAFC] 2015/04/14 06:34:08.944944 sharedpullerstate.go:197: DEBUG: sharedPullerState Mendeley-pdfs A public service/A public service - 2009 - Nature.pdf pullNeeded start -> 2 [IPAFC] 2015/04/14 06:34:08.945228 model.go:1030: DEBUG: model@0xc208d5f340 REQ(out): QWFYVRW-blablabla: "Mendeley-pdfs" / "A public service/A public service - 2009 - Nature.pdf" o=131072 s=131072 h=ddda086132a3fdc4f152b7c034a12a457ad9a060b9241a56adef8e74df339a69 [IPAFC] 2015/04/14 06:34:08.946162 sharedpullerstate.go:197: DEBUG: sharedPullerState Mendeley-pdfs A public service/A public service - 2009 - Nature.pdf pullNeeded start -> 3 [IPAFC] 2015/04/14 06:34:08.946374 model.go:1030: DEBUG: model@0xc208d5f340 REQ(out): QWFYVRW-blablabla: "Mendeley-pdfs" / "A public service/A public service - 2009 - Nature.pdf" o=262144 s=131072 h=4b3b2112e18b98e6ecd792cc459b43b0f76af40ad530cb0b6896f121d6e55c6c [IPAFC] 2015/04/14 06:34:08.946731 sharedpullerstate.go:197: DEBUG: sharedPullerState Mendeley-pdfs A public service/A public service - 2009 - Nature.pdf pullNeeded start -> 4 [IPAFC] 2015/04/14 06:34:08.947037 model.go:1030: DEBUG: model@0xc208d5f340 REQ(out): QWFYVRW-blablabla: "Mendeley-pdfs" / "A public service/A public service - 2009 - Nature.pdf" o=393216 s=131072 h=4ce20c11f17b15fee88a75d6b9f21c0502821f51003b38c118ecdcdb69d0221b [IPAFC] 2015/04/14 06:34:08.947446 sharedpullerstate.go:197: DEBUG: sharedPullerState Mendeley-pdfs A public service/A public service - 2009 - Nature.pdf pullNeeded start -> 5 [IPAFC] 2015/04/14 06:34:08.947600 model.go:1030: DEBUG: model@0xc208d5f340 REQ(out): QWFYVRW-blablabla: "Mendeley-pdfs" / "A public service/A public service - 2009 - Nature.pdf" o=524288 s=79941 h=1ff100cf3081d97a6cf8a07048f4049c5f8b1624b32e6ead8bc9976b6d0833ae [IPAFC] 2015/04/14 06:34:09.310987 sharedpullerstate.go:206: DEBUG: sharedPullerState Mendeley-pdfs A public service/A public service - 2009 - Nature.pdf pullNeeded done -> 4 [IPAFC] 2015/04/14 06:34:09.414921 sharedpullerstate.go:206: DEBUG: sharedPullerState Mendeley-pdfs A public service/A public service - 2009 - Nature.pdf pullNeeded done -> 3 [IPAFC] 2015/04/14 06:34:09.420013 rwfolder.go:159: DEBUG: rwFolder/CharlasCursos@0xc2094d80b0 skip (curVer == prevVer) 0 [IPAFC] 2015/04/14 06:34:09.442561 rwfolder.go:159: DEBUG: rwFolder/Clases@0xc20847e160 skip (curVer == prevVer) 0 [IPAFC] 2015/04/14 06:34:09.519022 sharedpullerstate.go:206: DEBUG: sharedPullerState Mendeley-pdfs A public service/A public service - 2009 - Nature.pdf pullNeeded done -> 2 [IPAFC] 2015/04/14 06:34:09.622919 sharedpullerstate.go:206: DEBUG: sharedPullerState Mendeley-pdfs A public service/A public service - 2009 - Nature.pdf pullNeeded done -> 1 [IPAFC] 2015/04/14 06:34:09.685626 sharedpullerstate.go:206: DEBUG: sharedPullerState Mendeley-pdfs A public service/A public service - 2009 - Nature.pdf pullNeeded done -> 0 [IPAFC] 2015/04/14 06:34:09.685694 rwfolder.go:1032: DEBUG: rwFolder/Mendeley-pdfs@0xc2094d82c0 closing A public service/A public service - 2009 - Nature.pdf [IPAFC] 2015/04/14 06:34:09.695522 progressemitter.go:119: DEBUG: progress emitter: deregistering Mendeley-pdfs A public service/A public service - 2009 - Nature.pdf
Two additional deletion and addtion events
(I was not tracing the computer in these cases, though.)
Deletion event on 04-12 at 20:37 and addition at 21:01.
- Nothing ST related in the Android logs between 19:03 and 21:15. I was not yet logging the computer at this time.
Deletion event on 04-12 at 22:27 and addition at 22:56.
-
The logs from 22:20 show:
[ 04-12 22:20:10.284 8428:29056 I/SyncthingNativeCode ] [QWFYV] 2015/04/12 20:20:10.293165 model.go:631: INFO: Connection to IPAFCRC-blablba closed: write tcp uvw:22000: connection reset by peer [ 04-12 22:27:25.088 8428:29056 I/SyncthingNativeCode ] [QWFYV] 2015/04/12 20:27:25.098180 main.go:1032: INFO: Paused state detected, possibly woke up from standby. Restarting in 1m0s. [ 04-12 22:27:25.488 8428:29056 I/SyncthingNativeCode ] [QWFYV] 2015/04/12 20:27:25.491795 rwfolder.go:123: INFO: Completed initial scan (rw) of folder Mendeley-pdfs [ 04-12 22:27:26.868 8428:29056 I/SyncthingNativeCode ] [QWFYV] 2015/04/12 20:27:26.883070 connections.go:34: INFO: Established secure connection to IPAFCRC-blablabla at xyzt:52490-u.v.w.s:22000 [ 04-12 22:27:26.938 8428:29056 I/SyncthingNativeCode ] [QWFYV] 2015/04/12 20:27:26.951194 model.go:545: INFO: Device IPAFCRC-blablabla client is "syncthing v0.10.30" [ 04-12 22:27:26.938 8428:29056 I/SyncthingNativeCode ] [QWFYV] 2015/04/12 20:27:26.951931 model.go:550: INFO: Device IPAFCRC-blablabla name is "coleonyx" [ 04-12 22:27:29.278 506: 3595 I/PowerManagerService ] Waking up from sleep...
Nothing else syncthing related until 22:37, long after the deletion. Then I see
[ 04-12 22:37:16.068 8428:29056 I/SyncthingNativeCode ]
[QWFYV] 2015/04/12 20:37:16.071989 main.go:902: INFO: Restarting
[ 04-12 22:37:16.068 8428:29056 I/SyncthingNativeCode ]
[QWFYV] 2015/04/12 20:37:16.073140 main.go:479: OK: Exiting
[ 04-12 22:37:16.088 8428:12049 I/SyncthingRunnable ]
Restarting syncthing
[ 04-12 22:37:16.118 8428: 8532 W/GetTask ]
Failed to call Rest API at http://127.0.0.1:8080/rest/model?folder=Mendeley-pdfs
org.apache.http.conn.HttpHostConnectException: Connection to http://127.0.0.1:8080 refused
at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:183)
at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:164)
at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:119)
etc, etc, etc
... 19 more
[ 04-12 22:37:16.118 8428: 8532 W/GetTask ]
Retrying GetTask Rest API call (0)
[ 04-12 22:37:16.128 8428: 8532 W/GetTask ]
Failed to call Rest API at http://127.0.0.1:8080/rest/model?folder=Mendeley-pdfs
org.apache.http.conn.HttpHostConnectException: Connection to http://127.0.0.1:8080 refused
at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:183)
at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:164)
at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:119)
at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:360)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:555)
etc, etc, etc
... 19 more
-
At 22:52, the logs mention the file that was deleted (but this file is not mentioned anywhere else in the logs)
[ 04-12 22:52:06.578 8428:29489 I/SyncthingNativeCode ] [QWFYV] 2015/04/12 20:52:06.588386 walk.go:149: DEBUG: rescan: File{Name:"Evaluating reproducibility of differential expression discoveries in microarray studies by considering correlated molecular changes/Evaluating reproducibility of differential expression discoveries in microarray studies by considering correlated molecular changes - 2009 - Bioinformatics.pdf", Flags:0110666, Modified:1428172606, Version:30632944, Size:128, Blocks:[]} 1428172606 -rw-rw---- [ 04-12 22:52:06.578 8428:29489 I/SyncthingNativeCode ] [QWFYV] 2015/04/12 20:52:06.588933 walk.go:149: DEBUG: to hash: /storage/sdcard0/Android/data/com.nutomic.syncthingandroid/Mendeley-pdfs-ds/Evaluating reproducibility of differential expression discoveries in microarray studies by considering correlated molecular changes/Evaluating reproducibility of differential expression discoveries in microarray studies by considering correlated molecular changes - 2009 - Bioinformatics.pdf File{Name:"Evaluating reproducibility of differential expression discoveries in microarray studies by considering correlated molecular changes/Evaluating reproducibility of differential expression discoveries in microarray studies by considering correlated molecular changes - 2009 - Bioinformatics.pdf", Flags:0100666, Modified:1428172606, Version:30656741, Size:0, Blocks:[]}
-
Nothing more ST related until 22:53
[ 04-12 22:53:55.535 8428:29489 I/SyncthingNativeCode ] [QWFYV] 2015/04/12 20:53:55.547214 model.go:631: INFO: Connection to IPAFCRC-blablaba closed: EOF [ 04-12 22:54:46.888 8428:29489 I/SyncthingNativeCode ] [QWFYV] 2015/04/12 20:54:46.897204 rwfolder.go:123: INFO: Completed initial scan (rw) of folder Mendeley-pdfs [ 04-12 22:54:47.418 8428:29489 I/SyncthingNativeCode ] [QWFYV] 2015/04/12 20:54:47.436131 connections.go:34: INFO: Established secure connection to IPAFCRC-blablba at xyz:52492-uvw:22000 [ 04-12 22:54:47.468 8428:29489 I/SyncthingNativeCode ] [QWFYV] 2015/04/12 20:54:47.481350 model.go:545: INFO: Device IPAFCRC-blabla client is "syncthing v0.10.30" [ 04-12 22:54:47.468 8428:29489 I/SyncthingNativeCode ] [QWFYV] 2015/04/12 20:54:47.482426 model.go:550: INFO: Device IPAFCRC-blablba name is "coleonyx"
Nothing else ST related until 22:58, more than 2 min after addition.
- No computer logs, since I was not logging the computer yet.
Well the file clearly disappears from the Android device and then later reappears judging from the flags in rescan
and to hash
log lines.
We don’t seem to be logging deletion evens in the log (we do fire off a REST event though), hence why you cannot see anything.
I can only conclude that this is due to the syscall interrupted issue.
So I guess we’ll just have to live with it? Anyway to minimize the chance of this happening?
I guess so, I don’t think syncthing should add EINTR loops around our Lstat calls , Go developers have refused to fix it:
OK. Thanks for the help anyway. (And, as I said, this seems not to be a fatal issue, as things get added again, so nothing is lost).
This is probably the cause yes, and seems to be Android being Android as usual (i.e. different and annoying). That said, I’m not sure why the Go teams stance is what it is, and perhaps it could be revisited. The root cause of the confusion is probably that lstat()
calls are not supposed to be returning EINTR on Linux. For example, the man page for lstat on Linux doesn’t list EINTR as a possible error, hence it’s not handled by Go or by us.
However, it is listed as a possible error return on for example Solaris, where Go also runs.
I guess you should reopen the issue and point them to the Solaris MAN page.
Alternatively, we could provide osutil.Stat osutil.Lstat
… but I’d rather not.
I dunno. Apparently (reading that issue closer) Go registers signal handlers with SA_RESTART
set, which means system calls should be automatically restarted when interrupted. However man sigaction
doesn’t mention lstat
being among the restarted system calls, which for example stat
is. So this is probably an Android bug, having syscalls return errors they normally shouldn’t because it does weird magic underneath those syscalls.
The “solution” is probably for us to retry the call a few times if the returned error code is EINTR. It ought to only be needed for os.Lstat
so it’s not really a heavy burden, even if it’s annoying.
(This was less of an issue before, because we required Lstat()
to return an error that return true for IsNotExist()
, so we didn’t interpret the “interrupted system call” return as a delete. We changed this because other error returns can also indicate a delete, i.e. “not a directory” can be returned for the previous children of a directory that has been replaced with a file.)
Because I love working around broken platforms: