Repeated "interrupted system call" on multiple Android devices

I have a problem with “interrupted system call” errors on multiple Android devices. This seems to happen when a large number of small files is being scanned, e.g. when starting Syncthing. I have experienced the issue on three Android devices. All of them run Android 4.4.4 and Syncthing Fork 1.3.4.0. The file system in all cases is the default ext4.

I have searched around and found the old issue https://github.com/syncthing/syncthing-android/issues/85, which is supposed to have been fixed in 2015, so I am not sure whether these are related or not.

2020-03-10 03:36:27 Scanner (folder xxxxx-xxxxxx, item "xxxxxxxxx/xxxxxxxx/xxxxxxx/xxxxxxxxx/xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx/xxxxxx-xxxxxxx/xxxx-xxx-xxxxxxxx/xxxxxxxxx"): scan: readdirent: interrupted system call

@Catfriend1 Do you build with Go 1.14? If so, I’d hold off on that a while.

1 Like

According to https://github.com/Catfriend1/syncthing-android/blob/master/syncthing/build-syncthing.py I’m currently on Go 1.13.5 . Thanks for the info, ok will do that.

Hmm… the system call interrupted problem has a “dirty” but very effective workaround in place here: https://github.com/syncthing/syncthing/blob/master/lib/fs/lstat_broken.go

I wasn’t part of the team when this was made, so cannot say anything about it in detail. Maybe @calmh @AudriusButkevicius still might remember this ?

Looking at the issue, the lstat lobotomisation is due to a broken android filesystem/fuse implementation. That lobotomisation is not used by the third-party fs watcher library. Given this hasn’t come up anymore, I assume the underlying error in Android has been fixed sometime after Android 4.4.4. Given that’s ancient and long-time unsupported, I don’t think it’s worth investing any time in fixing this. You’ll just have to disable watching for changes.

2 Likes

Given the lack of other reports of this issue maybe that means we can retire that specific hack now. Not that it particularly hurts to have in there, either.

Could we have a RC to gather feedback from users on this? I also expect this isn’t important anymore… Android 4.4 devices also became rare and those who have one often lack enough RAM to run Syncthing with a collection of photos and music (just not telling about XY GB repos here).

Every change goes into an RC.

Well, I can disable watching for changes, but I believe that the problem is something else than that.

I have removed the files on the devices in order to try to sync everything again. On one device, I have replaced Syncthing Fork with the official Syncthing application. The synchronisation completed successfully.

However, on another device, I have tried to synchronise the files again with Syncthing Fork, and after a few hours the application has silently crashed. This is what the log file looks like. It seems that all file operations end with “interrupted system call”.

[EEYCH] INFO: Puller (folder "XXX" (xxxxx-xxxxx), item "xxxxx/xxxxx"): opening temp file: open /storage/sdcard0/xxxxx/XXX/xxxxx/.xxxxxthing.xxxxx.tmp: interrupted system call
[EEYCH] INFO: Puller (folder "XXX" (xxxxx-xxxxx), item "xxxxx/xxxxx"): save: write /storage/sdcard0/xxxxx/XXX/xxxxx/.syncthing.xxxxx.tmp: interrupted system call
[EEYCH] INFO: Puller (folder "XXX" (xxxxx-xxxxx), item "xxxxx/xxxxx"): rename /storage/sdcard0/xxxxx/XXX/xxxxx/.syncthing.xxxxx.tmp /storage/sdcard0/xxxxx/XXX/xxxxx/xxxxx: interrupted system call
[EEYCH] INFO: Puller (folder "XXX" (xxxxx-xxxxx), item "xxxxx/xxxxx"): dst write: write /storage/sdcard0/xxxxx/XXX/xxxxx/.syncthing.xxxxx.tmp: interrupted system call
[EEYCH] INFO: Listen (BEP/relay): TLS handshake: read tcp x.x.x.x:43081->47.75.3.168:22067: i/o timeout

I have one thing in mind, which may possibly be the culprit and is completely unrelated to Syncthing. All the devices use the same specific I/O scheduler. I will try to change it to a different one, and then see whether there is any difference.

Please make sure that the code has in fact been fixed in newer versions of Android. There may be no reports because the hack is actually working and doing its job :wink:.

1 Like

Thing is the hack is only for one specific operation, and it’s not used by the file system watcher which is the default now. Your problem seems much more pervasive than anything we’ve ever seen on stock android before.

I have used both Syncthing and Syncthing Fork on Android for several months, but this problem has only started to show up very recently when I started to sync thousands of small files. Before, when the number of files was counted in hundreds, everything seemed to work fine.

I have done more testing:

  1. The scan: readdirent: interrupted system call related to File Watcher happens both in Syncthing and Syncthing Fork.
  2. The other interrupted system call errors have so far only occurred in Syncthing Fork, although I am not sure yet whether there is any correlation here, or just a pure luck.
  3. Right now, I have managed to complete the scanning of 22,000+ files on two devices with no errors. I switched to the official Syncthing application in both cases. I also disabled File Watcher.
  4. Changing the I/O scheduler in Android does not make any difference.

On a side note, I have also another issue, where Syncthing seems to crash during a long scanning operation on the device with 512 MB of RAM. I suspect the low amount of memory as the culprit, as there are no crashes on the two other devices with 1 GB and 2 GB of RAM respectively.

Unfortunately, the log file produced by the Syncthing application seems to be overwritten and restarted during the crash, so there is no information there about what exactly has happened. Is it possible to have the Android application keep the old log files, as it is the case with the Windows version of Syncthing (other than running the Linux version directly from terminal)?

1 Like

I have disabled watching for changes on all three devices, and right now all of them have successfully completed the initial synchronisation.

Two of them are using the official Syncthing application, while the third I have left on Syncthing Fork. I like the Fork mainly due to its ability to start and stop Syncthing on demand, but will probably leave everything in this state for now, just to see whether everything works correctly for a longer period of time.

I am still not sure though whether the issue is limited just to this specific version of Android, as it only manifested itself when trying to sync such a large number of files. There had been no such issues when the number of files was low, and I doubt that there are many other people also trying to sync tens of thousands of files on Android.

I may try to sync the same files on a newer version of Android later and see what happens there.

Edit

I have just seen this on the third device running Syncthing Fork with watching for changes disabled.

2020-03-12 06:12:04 Scanner (folder xxxxx-xxxxx, item "xxxxx/xxxxx"): scan: readdirent: interrupted system call

I guess that this would mean that it is unrelated to the file watcher… The two other devices running the official Syncthing have shown no errors so far.

1 Like

Thanks for the extensive testing and write up of the results first. I’ll keep an eye on that, but currently have no clue why the fork’s SyncthingNative should be “more” susceptible to fail with readdirent_interrupted than the official. I guess the wrapper does not cause it.

It would be interesting what Syncthing-Fork>Menu>About shows as max open file handle count on the different Android devices. You would not need to setup the fork to sync anything to get that value. It could be even grabbed via ADB shell.

I also use this APP, but doesnt find “About” in the upper left Menu. What I have seen under others is “Last Changes”

Ah sorry , it is Syncthing-Fork>Menu>Settings>About

Yeah, I am also not sure whether the Fork is actually responsible for the errors. However, for the last 2 days there have been no errors on the two devices with the official Syncthing application. The overall configuration is exactly the same - watching for changes disabled with 1h rescan interval.

Unfortunately, the values seem to be unavailable. They are shown as “N/A”.

image

Oh, so the shell calls made by the app to get the limit failed or outputted something unexpected what leads to n/a :thinking:

The results after a few days of testing:

  1. The errors have also shown up on the two other devices running the official Syncthing application, but it was usually only a single file, and they went away after some time. This probably means that the errors are unrelated to the Android wrapper.
  2. Since the errors seem to go away by themselves, Syncthing in this state is still usable.
  3. Turning watching for changes on makes the errors appear almost immediately. With watching for changes turned off, the errors seem to appear much less frequently.

However, I have also experienced the same errors in Android 7.1 with Syncthing Fork 1.3.4.

2020-03-17 06:11:44 Scanner (folder xxxxx-xxxxx, item "xxxxx"): scan: readdirent: interrupted system call

In this case, there are only 2200 files, but almost all of them are tiny small files. My guess would be that the errors appear when Syncthing is scanning through a large number of small files very quickly.

1 Like

I wanted to refresh this topic, as I have been experimenting heavily with Android in the recent days, and have some new findings regarding the interrupted system call problem.

I can only speak for Android 4.4 and 7.1, because these are the versions that I have access to right now, but it seems that the whole issue has nothing to do with Syncthing per se. I was doing basic file operations on the same files, e.g.

rm -r folder_with_30000_files

and during the deletion process I got

rm failed for folder_with_30000_files, Interrupted system call

I got the same error messages both on EXT4 and F2FS partitions, so at this point, I would just say that this is a problem with Android being unable to process a large number of files at the same time. In other words, Android is just being Android, and nothing can probably be done about this.

Nevertheless, Syncthing still works, and the files are processed again during consecutive scans, so I am going to just leave this be and not bother any more.

Lastly, I just want to say thank you to everyone who has helped with investigating this issue :slightly_smiling_face:.

3 Likes

I have been trying to update my devices to the newest versions of Android available, and during the testing I got these panic logs. A dozen logs has been created in a short time span, but some of them are empty. The rest are either about interrupted system call or cannot allocate memory.

Please let me know whether these are worth anything.

panic: write /sdcard/.config/syncthing/index-v0.14.0.db/000025.log: interrupted system call

goroutine 33360 [running]:
github.com/syncthing/syncthing/lib/db.(*FileSet).Update(0x2818920, 0xffffffff, 0xffffffff, 0xffffffff, 0xffffffff, 0xffffffff, 0xffffffff, 0xffffffff, 0xffffffff, 0x2c12000, ...)
	syncthing/lib/db/set.go:144 +0x47c
github.com/syncthing/syncthing/lib/model.(*folder).updateLocals(0x2012680, 0x2c12000, 0x4, 0x3e8)
	syncthing/lib/model/folder.go:833 +0x58
github.com/syncthing/syncthing/lib/model.(*folder).updateLocalsFromPulling(0x2012680, 0x2c12000, 0x4, 0x3e8)
	syncthing/lib/model/folder.go:827 +0x34
github.com/syncthing/syncthing/lib/model.(*sendReceiveFolder).dbUpdaterRoutine.func1(0x2c12000, 0x4, 0x3e8, 0x22f, 0xea32accb)
	syncthing/lib/model/folder_sendrecv.go:1604 +0x314
github.com/syncthing/syncthing/lib/model.(*fileInfoBatch).flush(0x3b7bdd4, 0x3b7bd9c, 0x2)
	syncthing/lib/model/model.go:2699 +0x40
github.com/syncthing/syncthing/lib/model.(*sendReceiveFolder).dbUpdaterRoutine(0x2012680, 0x2422040)
	syncthing/lib/model/folder_sendrecv.go:1646 +0x3f4
github.com/syncthing/syncthing/lib/model.(*sendReceiveFolder).pullerIteration.func1(0x2012680, 0x2422040, 0xb4dc70, 0x32bcd50)
	syncthing/lib/model/folder_sendrecv.go:238 +0x24
created by github.com/syncthing/syncthing/lib/model.(*sendReceiveFolder).pullerIteration
	syncthing/lib/model/folder_sendrecv.go:236 +0x320

panic-20200428-193910.log (86.5 KB)

panic: open /sdcard/.config/syncthing/index-v0.14.0.db/000087.ldb: cannot allocate memory

goroutine 66 [running]:
github.com/syncthing/syncthing/lib/db.(*Snapshot).WithNeedTruncated(0x3f6f320, 0x199a071f, 0xf2a718f0, 0x5758b0d9, 0xfe07b19a, 0x541128d7, 0x76d84bca, 0xf37c72f9, 0x227660bd, 0x3f6f340)
	syncthing/lib/db/set.go:186 +0x204
github.com/syncthing/syncthing/lib/model.(*model).Completion(0x18241a0, 0x199a071f, 0xf2a718f0, 0x5758b0d9, 0xfe07b19a, 0x541128d7, 0x76d84bca, 0xf37c72f9, 0x227660bd, 0x1b07350, ...)
	syncthing/lib/model/model.go:795 +0x2a0
github.com/syncthing/syncthing/lib/model.(*folderSummaryService).sendSummary(0x1864e70, 0xb4ea30, 0x1b163c0, 0x1b07350, 0xb)
	syncthing/lib/model/folder_summary.go:351 +0x310
github.com/syncthing/syncthing/lib/model.(*folderSummaryService).calculateSummaries(0x1864e70, 0xb4ea30, 0x1b163c0)
	syncthing/lib/model/folder_summary.go:278 +0x190
github.com/syncthing/syncthing/lib/util.AsService.func1(0xb4ea30, 0x1b163c0, 0x1ae3040, 0x0)
	syncthing/lib/util/utils.go:183 +0x2c
github.com/syncthing/syncthing/lib/util.(*service).Serve(0x185b2f0)
	syncthing/lib/util/utils.go:247 +0x124
github.com/thejerf/suture.(*Supervisor).runService.func1(0x1894be0, 0x1, 0x40174210, 0x185b2f0)
	go/pkg/mod/github.com/thejerf/suture@v3.0.2+incompatible/supervisor.go:600 +0x34
created by github.com/thejerf/suture.(*Supervisor).runService
	go/pkg/mod/github.com/thejerf/suture@v3.0.2+incompatible/supervisor.go:588 +0x44

panic-20200428-210027.log (71.2 KB)