rwfolder.go 35 KB

12345678910111213141516171819202122232425262728293031323334353637383940414243444546474849505152535455565758596061626364656667686970717273747576777879808182838485868788899091929394959697989910010110210310410510610710810911011111211311411511611711811912012112212312412512612712812913013113213313413513613713813914014114214314414514614714814915015115215315415515615715815916016116216316416516616716816917017117217317417517617717817918018118218318418518618718818919019119219319419519619719819920020120220320420520620720820921021121221321421521621721821922022122222322422522622722822923023123223323423523623723823924024124224324424524624724824925025125225325425525625725825926026126226326426526626726826927027127227327427527627727827928028128228328428528628728828929029129229329429529629729829930030130230330430530630730830931031131231331431531631731831932032132232332432532632732832933033133233333433533633733833934034134234334434534634734834935035135235335435535635735835936036136236336436536636736836937037137237337437537637737837938038138238338438538638738838939039139239339439539639739839940040140240340440540640740840941041141241341441541641741841942042142242342442542642742842943043143243343443543643743843944044144244344444544644744844945045145245345445545645745845946046146246346446546646746846947047147247347447547647747847948048148248348448548648748848949049149249349449549649749849950050150250350450550650750850951051151251351451551651751851952052152252352452552652752852953053153253353453553653753853954054154254354454554654754854955055155255355455555655755855956056156256356456556656756856957057157257357457557657757857958058158258358458558658758858959059159259359459559659759859960060160260360460560660760860961061161261361461561661761861962062162262362462562662762862963063163263363463563663763863964064164264364464564664764864965065165265365465565665765865966066166266366466566666766866967067167267367467567667767867968068168268368468568668768868969069169269369469569669769869970070170270370470570670770870971071171271371471571671771871972072172272372472572672772872973073173273373473573673773873974074174274374474574674774874975075175275375475575675775875976076176276376476576676776876977077177277377477577677777877978078178278378478578678778878979079179279379479579679779879980080180280380480580680780880981081181281381481581681781881982082182282382482582682782882983083183283383483583683783883984084184284384484584684784884985085185285385485585685785885986086186286386486586686786886987087187287387487587687787887988088188288388488588688788888989089189289389489589689789889990090190290390490590690790890991091191291391491591691791891992092192292392492592692792892993093193293393493593693793893994094194294394494594694794894995095195295395495595695795895996096196296396496596696796896997097197297397497597697797897998098198298398498598698798898999099199299399499599699799899910001001100210031004100510061007100810091010101110121013101410151016101710181019102010211022102310241025102610271028102910301031103210331034103510361037103810391040104110421043104410451046104710481049105010511052105310541055105610571058105910601061106210631064106510661067106810691070107110721073107410751076107710781079108010811082108310841085108610871088108910901091109210931094109510961097109810991100110111021103110411051106110711081109111011111112111311141115111611171118111911201121112211231124112511261127112811291130113111321133113411351136113711381139114011411142114311441145114611471148114911501151115211531154115511561157115811591160116111621163116411651166116711681169117011711172117311741175117611771178117911801181118211831184118511861187118811891190119111921193119411951196119711981199120012011202120312041205120612071208120912101211121212131214121512161217121812191220122112221223122412251226122712281229123012311232123312341235123612371238123912401241124212431244124512461247124812491250125112521253125412551256125712581259126012611262126312641265126612671268126912701271127212731274127512761277127812791280128112821283128412851286128712881289
  1. // Copyright (C) 2014 The Syncthing Authors.
  2. //
  3. // This Source Code Form is subject to the terms of the Mozilla Public
  4. // License, v. 2.0. If a copy of the MPL was not distributed with this file,
  5. // You can obtain one at http://mozilla.org/MPL/2.0/.
  6. package model
  7. import (
  8. "errors"
  9. "fmt"
  10. "io/ioutil"
  11. "math/rand"
  12. "os"
  13. "path/filepath"
  14. "time"
  15. "github.com/syncthing/protocol"
  16. "github.com/syncthing/syncthing/internal/config"
  17. "github.com/syncthing/syncthing/internal/db"
  18. "github.com/syncthing/syncthing/internal/events"
  19. "github.com/syncthing/syncthing/internal/ignore"
  20. "github.com/syncthing/syncthing/internal/osutil"
  21. "github.com/syncthing/syncthing/internal/scanner"
  22. "github.com/syncthing/syncthing/internal/symlinks"
  23. "github.com/syncthing/syncthing/internal/sync"
  24. "github.com/syncthing/syncthing/internal/versioner"
  25. )
  26. // TODO: Stop on errors
  27. const (
  28. pauseIntv = 60 * time.Second
  29. nextPullIntv = 10 * time.Second
  30. shortPullIntv = 5 * time.Second
  31. )
  32. // A pullBlockState is passed to the puller routine for each block that needs
  33. // to be fetched.
  34. type pullBlockState struct {
  35. *sharedPullerState
  36. block protocol.BlockInfo
  37. }
  38. // A copyBlocksState is passed to copy routine if the file has blocks to be
  39. // copied.
  40. type copyBlocksState struct {
  41. *sharedPullerState
  42. blocks []protocol.BlockInfo
  43. }
  44. var (
  45. activity = newDeviceActivity()
  46. errNoDevice = errors.New("no available source device")
  47. )
  48. type rwFolder struct {
  49. stateTracker
  50. model *Model
  51. progressEmitter *ProgressEmitter
  52. virtualMtimeRepo *db.VirtualMtimeRepo
  53. folder string
  54. dir string
  55. scanIntv time.Duration
  56. versioner versioner.Versioner
  57. ignorePerms bool
  58. copiers int
  59. pullers int
  60. shortID uint64
  61. order config.PullOrder
  62. stop chan struct{}
  63. queue *jobQueue
  64. dbUpdates chan protocol.FileInfo
  65. scanTimer *time.Timer
  66. pullTimer *time.Timer
  67. delayScan chan time.Duration
  68. remoteIndex chan struct{} // An index update was received, we should re-evaluate needs
  69. }
  70. func newRWFolder(m *Model, shortID uint64, cfg config.FolderConfiguration) *rwFolder {
  71. return &rwFolder{
  72. stateTracker: stateTracker{
  73. folder: cfg.ID,
  74. mut: sync.NewMutex(),
  75. },
  76. model: m,
  77. progressEmitter: m.progressEmitter,
  78. virtualMtimeRepo: db.NewVirtualMtimeRepo(m.db, cfg.ID),
  79. folder: cfg.ID,
  80. dir: cfg.Path(),
  81. scanIntv: time.Duration(cfg.RescanIntervalS) * time.Second,
  82. ignorePerms: cfg.IgnorePerms,
  83. copiers: cfg.Copiers,
  84. pullers: cfg.Pullers,
  85. shortID: shortID,
  86. order: cfg.Order,
  87. stop: make(chan struct{}),
  88. queue: newJobQueue(),
  89. pullTimer: time.NewTimer(shortPullIntv),
  90. scanTimer: time.NewTimer(time.Millisecond), // The first scan should be done immediately.
  91. delayScan: make(chan time.Duration),
  92. remoteIndex: make(chan struct{}, 1), // This needs to be 1-buffered so that we queue a notification if we're busy doing a pull when it comes.
  93. }
  94. }
  95. // Serve will run scans and pulls. It will return when Stop()ed or on a
  96. // critical error.
  97. func (p *rwFolder) Serve() {
  98. if debug {
  99. l.Debugln(p, "starting")
  100. defer l.Debugln(p, "exiting")
  101. }
  102. defer func() {
  103. p.pullTimer.Stop()
  104. p.scanTimer.Stop()
  105. // TODO: Should there be an actual FolderStopped state?
  106. p.setState(FolderIdle)
  107. }()
  108. var prevVer int64
  109. var prevIgnoreHash string
  110. rescheduleScan := func() {
  111. if p.scanIntv == 0 {
  112. // We should not run scans, so it should not be rescheduled.
  113. return
  114. }
  115. // Sleep a random time between 3/4 and 5/4 of the configured interval.
  116. sleepNanos := (p.scanIntv.Nanoseconds()*3 + rand.Int63n(2*p.scanIntv.Nanoseconds())) / 4
  117. intv := time.Duration(sleepNanos) * time.Nanosecond
  118. if debug {
  119. l.Debugln(p, "next rescan in", intv)
  120. }
  121. p.scanTimer.Reset(intv)
  122. }
  123. // We don't start pulling files until a scan has been completed.
  124. initialScanCompleted := false
  125. for {
  126. select {
  127. case <-p.stop:
  128. return
  129. case <-p.remoteIndex:
  130. prevVer = 0
  131. p.pullTimer.Reset(shortPullIntv)
  132. if debug {
  133. l.Debugln(p, "remote index updated, rescheduling pull")
  134. }
  135. case <-p.pullTimer.C:
  136. if !initialScanCompleted {
  137. if debug {
  138. l.Debugln(p, "skip (initial)")
  139. }
  140. p.pullTimer.Reset(nextPullIntv)
  141. continue
  142. }
  143. p.model.fmut.RLock()
  144. curIgnores := p.model.folderIgnores[p.folder]
  145. p.model.fmut.RUnlock()
  146. if newHash := curIgnores.Hash(); newHash != prevIgnoreHash {
  147. // The ignore patterns have changed. We need to re-evaluate if
  148. // there are files we need now that were ignored before.
  149. if debug {
  150. l.Debugln(p, "ignore patterns have changed, resetting prevVer")
  151. }
  152. prevVer = 0
  153. prevIgnoreHash = newHash
  154. }
  155. // RemoteLocalVersion() is a fast call, doesn't touch the database.
  156. curVer := p.model.RemoteLocalVersion(p.folder)
  157. if curVer == prevVer {
  158. if debug {
  159. l.Debugln(p, "skip (curVer == prevVer)", prevVer)
  160. }
  161. p.pullTimer.Reset(nextPullIntv)
  162. continue
  163. }
  164. if debug {
  165. l.Debugln(p, "pulling", prevVer, curVer)
  166. }
  167. p.setState(FolderSyncing)
  168. tries := 0
  169. for {
  170. tries++
  171. changed := p.pullerIteration(curIgnores)
  172. if debug {
  173. l.Debugln(p, "changed", changed)
  174. }
  175. if changed == 0 {
  176. // No files were changed by the puller, so we are in
  177. // sync. Remember the local version number and
  178. // schedule a resync a little bit into the future.
  179. if lv := p.model.RemoteLocalVersion(p.folder); lv < curVer {
  180. // There's a corner case where the device we needed
  181. // files from disconnected during the puller
  182. // iteration. The files will have been removed from
  183. // the index, so we've concluded that we don't need
  184. // them, but at the same time we have the local
  185. // version that includes those files in curVer. So we
  186. // catch the case that localVersion might have
  187. // decreased here.
  188. l.Debugln(p, "adjusting curVer", lv)
  189. curVer = lv
  190. }
  191. prevVer = curVer
  192. if debug {
  193. l.Debugln(p, "next pull in", nextPullIntv)
  194. }
  195. p.pullTimer.Reset(nextPullIntv)
  196. break
  197. }
  198. if tries > 10 {
  199. // We've tried a bunch of times to get in sync, but
  200. // we're not making it. Probably there are write
  201. // errors preventing us. Flag this with a warning and
  202. // wait a bit longer before retrying.
  203. l.Warnf("Folder %q isn't making progress - check logs for possible root cause. Pausing puller for %v.", p.folder, pauseIntv)
  204. if debug {
  205. l.Debugln(p, "next pull in", pauseIntv)
  206. }
  207. p.pullTimer.Reset(pauseIntv)
  208. break
  209. }
  210. }
  211. p.setState(FolderIdle)
  212. // The reason for running the scanner from within the puller is that
  213. // this is the easiest way to make sure we are not doing both at the
  214. // same time.
  215. case <-p.scanTimer.C:
  216. if err := p.model.CheckFolderHealth(p.folder); err != nil {
  217. l.Infoln("Skipping folder", p.folder, "scan due to folder error:", err)
  218. rescheduleScan()
  219. continue
  220. }
  221. if debug {
  222. l.Debugln(p, "rescan")
  223. }
  224. if err := p.model.ScanFolder(p.folder); err != nil {
  225. // Potentially sets the error twice, once in the scanner just
  226. // by doing a check, and once here, if the error returned is
  227. // the same one as returned by CheckFolderHealth, though
  228. // duplicate set is handled by setError.
  229. p.setError(err)
  230. rescheduleScan()
  231. continue
  232. }
  233. if p.scanIntv > 0 {
  234. rescheduleScan()
  235. }
  236. if !initialScanCompleted {
  237. l.Infoln("Completed initial scan (rw) of folder", p.folder)
  238. initialScanCompleted = true
  239. }
  240. case next := <-p.delayScan:
  241. p.scanTimer.Reset(next)
  242. }
  243. }
  244. }
  245. func (p *rwFolder) Stop() {
  246. close(p.stop)
  247. }
  248. func (p *rwFolder) IndexUpdated() {
  249. select {
  250. case p.remoteIndex <- struct{}{}:
  251. default:
  252. // We might be busy doing a pull and thus not reading from this
  253. // channel. The channel is 1-buffered, so one notification will be
  254. // queued to ensure we recheck after the pull, but beyond that we must
  255. // make sure to not block index receiving.
  256. }
  257. }
  258. func (p *rwFolder) String() string {
  259. return fmt.Sprintf("rwFolder/%s@%p", p.folder, p)
  260. }
  261. // pullerIteration runs a single puller iteration for the given folder and
  262. // returns the number items that should have been synced (even those that
  263. // might have failed). One puller iteration handles all files currently
  264. // flagged as needed in the folder.
  265. func (p *rwFolder) pullerIteration(ignores *ignore.Matcher) int {
  266. pullChan := make(chan pullBlockState)
  267. copyChan := make(chan copyBlocksState)
  268. finisherChan := make(chan *sharedPullerState)
  269. updateWg := sync.NewWaitGroup()
  270. copyWg := sync.NewWaitGroup()
  271. pullWg := sync.NewWaitGroup()
  272. doneWg := sync.NewWaitGroup()
  273. if debug {
  274. l.Debugln(p, "c", p.copiers, "p", p.pullers)
  275. }
  276. p.dbUpdates = make(chan protocol.FileInfo)
  277. updateWg.Add(1)
  278. go func() {
  279. // dbUpdaterRoutine finishes when p.dbUpdates is closed
  280. p.dbUpdaterRoutine()
  281. updateWg.Done()
  282. }()
  283. for i := 0; i < p.copiers; i++ {
  284. copyWg.Add(1)
  285. go func() {
  286. // copierRoutine finishes when copyChan is closed
  287. p.copierRoutine(copyChan, pullChan, finisherChan)
  288. copyWg.Done()
  289. }()
  290. }
  291. for i := 0; i < p.pullers; i++ {
  292. pullWg.Add(1)
  293. go func() {
  294. // pullerRoutine finishes when pullChan is closed
  295. p.pullerRoutine(pullChan, finisherChan)
  296. pullWg.Done()
  297. }()
  298. }
  299. doneWg.Add(1)
  300. // finisherRoutine finishes when finisherChan is closed
  301. go func() {
  302. p.finisherRoutine(finisherChan)
  303. doneWg.Done()
  304. }()
  305. p.model.fmut.RLock()
  306. folderFiles := p.model.folderFiles[p.folder]
  307. p.model.fmut.RUnlock()
  308. // !!!
  309. // WithNeed takes a database snapshot (by necessity). By the time we've
  310. // handled a bunch of files it might have become out of date and we might
  311. // be attempting to sync with an old version of a file...
  312. // !!!
  313. changed := 0
  314. fileDeletions := map[string]protocol.FileInfo{}
  315. dirDeletions := []protocol.FileInfo{}
  316. buckets := map[string][]protocol.FileInfo{}
  317. folderFiles.WithNeed(protocol.LocalDeviceID, func(intf db.FileIntf) bool {
  318. // Needed items are delivered sorted lexicographically. We'll handle
  319. // directories as they come along, so parents before children. Files
  320. // are queued and the order may be changed later.
  321. file := intf.(protocol.FileInfo)
  322. if ignores.Match(file.Name) {
  323. // This is an ignored file. Skip it, continue iteration.
  324. return true
  325. }
  326. if debug {
  327. l.Debugln(p, "handling", file.Name)
  328. }
  329. switch {
  330. case file.IsDeleted():
  331. // A deleted file, directory or symlink
  332. if file.IsDirectory() {
  333. dirDeletions = append(dirDeletions, file)
  334. } else {
  335. fileDeletions[file.Name] = file
  336. df, ok := p.model.CurrentFolderFile(p.folder, file.Name)
  337. // Local file can be already deleted, but with a lower version
  338. // number, hence the deletion coming in again as part of
  339. // WithNeed, furthermore, the file can simply be of the wrong
  340. // type if we haven't yet managed to pull it.
  341. if ok && !df.IsDeleted() && !df.IsSymlink() && !df.IsDirectory() {
  342. // Put files into buckets per first hash
  343. key := string(df.Blocks[0].Hash)
  344. buckets[key] = append(buckets[key], df)
  345. }
  346. }
  347. case file.IsDirectory() && !file.IsSymlink():
  348. // A new or changed directory
  349. if debug {
  350. l.Debugln("Creating directory", file.Name)
  351. }
  352. p.handleDir(file)
  353. default:
  354. // A new or changed file or symlink. This is the only case where we
  355. // do stuff concurrently in the background
  356. p.queue.Push(file.Name, file.Size(), file.Modified)
  357. }
  358. changed++
  359. return true
  360. })
  361. // Reorder the file queue according to configuration
  362. switch p.order {
  363. case config.OrderRandom:
  364. p.queue.Shuffle()
  365. case config.OrderAlphabetic:
  366. // The queue is already in alphabetic order.
  367. case config.OrderSmallestFirst:
  368. p.queue.SortSmallestFirst()
  369. case config.OrderLargestFirst:
  370. p.queue.SortLargestFirst()
  371. case config.OrderOldestFirst:
  372. p.queue.SortOldestFirst()
  373. case config.OrderNewestFirst:
  374. p.queue.SortOldestFirst()
  375. }
  376. // Process the file queue
  377. nextFile:
  378. for {
  379. fileName, ok := p.queue.Pop()
  380. if !ok {
  381. break
  382. }
  383. f, ok := p.model.CurrentGlobalFile(p.folder, fileName)
  384. if !ok {
  385. // File is no longer in the index. Mark it as done and drop it.
  386. p.queue.Done(fileName)
  387. continue
  388. }
  389. // Local file can be already deleted, but with a lower version
  390. // number, hence the deletion coming in again as part of
  391. // WithNeed, furthermore, the file can simply be of the wrong type if
  392. // the global index changed while we were processing this iteration.
  393. if !f.IsDeleted() && !f.IsSymlink() && !f.IsDirectory() {
  394. key := string(f.Blocks[0].Hash)
  395. for i, candidate := range buckets[key] {
  396. if scanner.BlocksEqual(candidate.Blocks, f.Blocks) {
  397. // Remove the candidate from the bucket
  398. lidx := len(buckets[key]) - 1
  399. buckets[key][i] = buckets[key][lidx]
  400. buckets[key] = buckets[key][:lidx]
  401. // candidate is our current state of the file, where as the
  402. // desired state with the delete bit set is in the deletion
  403. // map.
  404. desired := fileDeletions[candidate.Name]
  405. // Remove the pending deletion (as we perform it by renaming)
  406. delete(fileDeletions, candidate.Name)
  407. p.renameFile(desired, f)
  408. p.queue.Done(fileName)
  409. continue nextFile
  410. }
  411. }
  412. }
  413. // Not a rename or a symlink, deal with it.
  414. p.handleFile(f, copyChan, finisherChan)
  415. }
  416. // Signal copy and puller routines that we are done with the in data for
  417. // this iteration. Wait for them to finish.
  418. close(copyChan)
  419. copyWg.Wait()
  420. close(pullChan)
  421. pullWg.Wait()
  422. // Signal the finisher chan that there will be no more input.
  423. close(finisherChan)
  424. // Wait for the finisherChan to finish.
  425. doneWg.Wait()
  426. for _, file := range fileDeletions {
  427. if debug {
  428. l.Debugln("Deleting file", file.Name)
  429. }
  430. p.deleteFile(file)
  431. }
  432. for i := range dirDeletions {
  433. dir := dirDeletions[len(dirDeletions)-i-1]
  434. if debug {
  435. l.Debugln("Deleting dir", dir.Name)
  436. }
  437. p.deleteDir(dir)
  438. }
  439. // Wait for db updates to complete
  440. close(p.dbUpdates)
  441. updateWg.Wait()
  442. return changed
  443. }
  444. // handleDir creates or updates the given directory
  445. func (p *rwFolder) handleDir(file protocol.FileInfo) {
  446. var err error
  447. events.Default.Log(events.ItemStarted, map[string]interface{}{
  448. "folder": p.folder,
  449. "item": file.Name,
  450. "type": "dir",
  451. "action": "update",
  452. })
  453. defer func() {
  454. events.Default.Log(events.ItemFinished, map[string]interface{}{
  455. "folder": p.folder,
  456. "item": file.Name,
  457. "error": err,
  458. "type": "dir",
  459. "action": "update",
  460. })
  461. }()
  462. realName := filepath.Join(p.dir, file.Name)
  463. mode := os.FileMode(file.Flags & 0777)
  464. if p.ignorePerms {
  465. mode = 0755
  466. }
  467. if debug {
  468. curFile, _ := p.model.CurrentFolderFile(p.folder, file.Name)
  469. l.Debugf("need dir\n\t%v\n\t%v", file, curFile)
  470. }
  471. info, err := osutil.Lstat(realName)
  472. switch {
  473. // There is already something under that name, but it's a file/link.
  474. // Most likely a file/link is getting replaced with a directory.
  475. // Remove the file/link and fall through to directory creation.
  476. case err == nil && (!info.IsDir() || info.Mode()&os.ModeSymlink != 0):
  477. err = osutil.InWritableDir(osutil.Remove, realName)
  478. if err != nil {
  479. l.Infof("Puller (folder %q, dir %q): %v", p.folder, file.Name, err)
  480. return
  481. }
  482. fallthrough
  483. // The directory doesn't exist, so we create it with the right
  484. // mode bits from the start.
  485. case err != nil && os.IsNotExist(err):
  486. // We declare a function that acts on only the path name, so
  487. // we can pass it to InWritableDir. We use a regular Mkdir and
  488. // not MkdirAll because the parent should already exist.
  489. mkdir := func(path string) error {
  490. err = os.Mkdir(path, mode)
  491. if err != nil || p.ignorePerms {
  492. return err
  493. }
  494. return os.Chmod(path, mode)
  495. }
  496. if err = osutil.InWritableDir(mkdir, realName); err == nil {
  497. p.dbUpdates <- file
  498. } else {
  499. l.Infof("Puller (folder %q, dir %q): %v", p.folder, file.Name, err)
  500. }
  501. return
  502. // Weird error when stat()'ing the dir. Probably won't work to do
  503. // anything else with it if we can't even stat() it.
  504. case err != nil:
  505. l.Infof("Puller (folder %q, dir %q): %v", p.folder, file.Name, err)
  506. return
  507. }
  508. // The directory already exists, so we just correct the mode bits. (We
  509. // don't handle modification times on directories, because that sucks...)
  510. // It's OK to change mode bits on stuff within non-writable directories.
  511. if p.ignorePerms {
  512. p.dbUpdates <- file
  513. } else if err := os.Chmod(realName, mode); err == nil {
  514. p.dbUpdates <- file
  515. } else {
  516. l.Infof("Puller (folder %q, dir %q): %v", p.folder, file.Name, err)
  517. }
  518. }
  519. // deleteDir attempts to delete the given directory
  520. func (p *rwFolder) deleteDir(file protocol.FileInfo) {
  521. var err error
  522. events.Default.Log(events.ItemStarted, map[string]interface{}{
  523. "folder": p.folder,
  524. "item": file.Name,
  525. "type": "dir",
  526. "action": "delete",
  527. })
  528. defer func() {
  529. events.Default.Log(events.ItemFinished, map[string]interface{}{
  530. "folder": p.folder,
  531. "item": file.Name,
  532. "error": err,
  533. "type": "dir",
  534. "action": "delete",
  535. })
  536. }()
  537. realName := filepath.Join(p.dir, file.Name)
  538. // Delete any temporary files lying around in the directory
  539. dir, _ := os.Open(realName)
  540. if dir != nil {
  541. files, _ := dir.Readdirnames(-1)
  542. for _, file := range files {
  543. if defTempNamer.IsTemporary(file) {
  544. osutil.InWritableDir(osutil.Remove, filepath.Join(realName, file))
  545. }
  546. }
  547. }
  548. err = osutil.InWritableDir(osutil.Remove, realName)
  549. if err == nil || os.IsNotExist(err) {
  550. // It was removed or it doesn't exist to start with
  551. p.dbUpdates <- file
  552. } else if _, err = os.Lstat(realName); err != nil && !os.IsPermission(err) {
  553. // We get an error just looking at the directory, and it's not a
  554. // permission problem. Lets assume the error is in fact some variant
  555. // of "file does not exist" (possibly expressed as some parent being a
  556. // file and not a directory etc) and that the delete is handled.
  557. p.dbUpdates <- file
  558. } else {
  559. l.Infof("Puller (folder %q, dir %q): delete: %v", p.folder, file.Name, err)
  560. }
  561. }
  562. // deleteFile attempts to delete the given file
  563. func (p *rwFolder) deleteFile(file protocol.FileInfo) {
  564. var err error
  565. events.Default.Log(events.ItemStarted, map[string]interface{}{
  566. "folder": p.folder,
  567. "item": file.Name,
  568. "type": "file",
  569. "action": "delete",
  570. })
  571. defer func() {
  572. events.Default.Log(events.ItemFinished, map[string]interface{}{
  573. "folder": p.folder,
  574. "item": file.Name,
  575. "error": err,
  576. "type": "file",
  577. "action": "delete",
  578. })
  579. }()
  580. realName := filepath.Join(p.dir, file.Name)
  581. cur, ok := p.model.CurrentFolderFile(p.folder, file.Name)
  582. if ok && p.inConflict(cur.Version, file.Version) {
  583. // There is a conflict here. Move the file to a conflict copy instead
  584. // of deleting. Also merge with the version vector we had, to indicate
  585. // we have resolved the conflict.
  586. file.Version = file.Version.Merge(cur.Version)
  587. err = osutil.InWritableDir(moveForConflict, realName)
  588. } else if p.versioner != nil {
  589. err = osutil.InWritableDir(p.versioner.Archive, realName)
  590. } else {
  591. err = osutil.InWritableDir(osutil.Remove, realName)
  592. }
  593. if err == nil || os.IsNotExist(err) {
  594. // It was removed or it doesn't exist to start with
  595. p.dbUpdates <- file
  596. } else if _, err := os.Lstat(realName); err != nil && !os.IsPermission(err) {
  597. // We get an error just looking at the file, and it's not a permission
  598. // problem. Lets assume the error is in fact some variant of "file
  599. // does not exist" (possibly expressed as some parent being a file and
  600. // not a directory etc) and that the delete is handled.
  601. p.dbUpdates <- file
  602. } else {
  603. l.Infof("Puller (folder %q, file %q): delete: %v", p.folder, file.Name, err)
  604. }
  605. }
  606. // renameFile attempts to rename an existing file to a destination
  607. // and set the right attributes on it.
  608. func (p *rwFolder) renameFile(source, target protocol.FileInfo) {
  609. var err error
  610. events.Default.Log(events.ItemStarted, map[string]interface{}{
  611. "folder": p.folder,
  612. "item": source.Name,
  613. "type": "file",
  614. "action": "delete",
  615. })
  616. events.Default.Log(events.ItemStarted, map[string]interface{}{
  617. "folder": p.folder,
  618. "item": target.Name,
  619. "type": "file",
  620. "action": "update",
  621. })
  622. defer func() {
  623. events.Default.Log(events.ItemFinished, map[string]interface{}{
  624. "folder": p.folder,
  625. "item": source.Name,
  626. "error": err,
  627. "type": "file",
  628. "action": "delete",
  629. })
  630. events.Default.Log(events.ItemFinished, map[string]interface{}{
  631. "folder": p.folder,
  632. "item": target.Name,
  633. "error": err,
  634. "type": "file",
  635. "action": "update",
  636. })
  637. }()
  638. if debug {
  639. l.Debugln(p, "taking rename shortcut", source.Name, "->", target.Name)
  640. }
  641. from := filepath.Join(p.dir, source.Name)
  642. to := filepath.Join(p.dir, target.Name)
  643. if p.versioner != nil {
  644. err = osutil.Copy(from, to)
  645. if err == nil {
  646. err = osutil.InWritableDir(p.versioner.Archive, from)
  647. }
  648. } else {
  649. err = osutil.TryRename(from, to)
  650. }
  651. if err == nil {
  652. // The file was renamed, so we have handled both the necessary delete
  653. // of the source and the creation of the target. Fix-up the metadata,
  654. // and update the local index of the target file.
  655. p.dbUpdates <- source
  656. err = p.shortcutFile(target)
  657. if err != nil {
  658. l.Infof("Puller (folder %q, file %q): rename from %q metadata: %v", p.folder, target.Name, source.Name, err)
  659. return
  660. }
  661. } else {
  662. // We failed the rename so we have a source file that we still need to
  663. // get rid of. Attempt to delete it instead so that we make *some*
  664. // progress. The target is unhandled.
  665. err = osutil.InWritableDir(osutil.Remove, from)
  666. if err != nil {
  667. l.Infof("Puller (folder %q, file %q): delete %q after failed rename: %v", p.folder, target.Name, source.Name, err)
  668. return
  669. }
  670. p.dbUpdates <- source
  671. }
  672. }
  673. // handleFile queues the copies and pulls as necessary for a single new or
  674. // changed file.
  675. func (p *rwFolder) handleFile(file protocol.FileInfo, copyChan chan<- copyBlocksState, finisherChan chan<- *sharedPullerState) {
  676. events.Default.Log(events.ItemStarted, map[string]interface{}{
  677. "folder": p.folder,
  678. "item": file.Name,
  679. "type": "file",
  680. "action": "update",
  681. })
  682. curFile, ok := p.model.CurrentFolderFile(p.folder, file.Name)
  683. if ok && len(curFile.Blocks) == len(file.Blocks) && scanner.BlocksEqual(curFile.Blocks, file.Blocks) {
  684. // We are supposed to copy the entire file, and then fetch nothing. We
  685. // are only updating metadata, so we don't actually *need* to make the
  686. // copy.
  687. if debug {
  688. l.Debugln(p, "taking shortcut on", file.Name)
  689. }
  690. p.queue.Done(file.Name)
  691. var err error
  692. if file.IsSymlink() {
  693. err = p.shortcutSymlink(file)
  694. } else {
  695. err = p.shortcutFile(file)
  696. }
  697. events.Default.Log(events.ItemFinished, map[string]interface{}{
  698. "folder": p.folder,
  699. "item": file.Name,
  700. "error": err,
  701. "type": "file",
  702. "action": "update",
  703. })
  704. return
  705. }
  706. scanner.PopulateOffsets(file.Blocks)
  707. // Figure out the absolute filenames we need once and for all
  708. tempName := filepath.Join(p.dir, defTempNamer.TempName(file.Name))
  709. realName := filepath.Join(p.dir, file.Name)
  710. reused := 0
  711. var blocks []protocol.BlockInfo
  712. // Check for an old temporary file which might have some blocks we could
  713. // reuse.
  714. tempBlocks, err := scanner.HashFile(tempName, protocol.BlockSize)
  715. if err == nil {
  716. // Check for any reusable blocks in the temp file
  717. tempCopyBlocks, _ := scanner.BlockDiff(tempBlocks, file.Blocks)
  718. // block.String() returns a string unique to the block
  719. existingBlocks := make(map[string]struct{}, len(tempCopyBlocks))
  720. for _, block := range tempCopyBlocks {
  721. existingBlocks[block.String()] = struct{}{}
  722. }
  723. // Since the blocks are already there, we don't need to get them.
  724. for _, block := range file.Blocks {
  725. _, ok := existingBlocks[block.String()]
  726. if !ok {
  727. blocks = append(blocks, block)
  728. }
  729. }
  730. // The sharedpullerstate will know which flags to use when opening the
  731. // temp file depending if we are reusing any blocks or not.
  732. reused = len(file.Blocks) - len(blocks)
  733. if reused == 0 {
  734. // Otherwise, discard the file ourselves in order for the
  735. // sharedpuller not to panic when it fails to exclusively create a
  736. // file which already exists
  737. os.Remove(tempName)
  738. }
  739. } else {
  740. blocks = file.Blocks
  741. }
  742. s := sharedPullerState{
  743. file: file,
  744. folder: p.folder,
  745. tempName: tempName,
  746. realName: realName,
  747. copyTotal: len(blocks),
  748. copyNeeded: len(blocks),
  749. reused: reused,
  750. ignorePerms: p.ignorePerms,
  751. version: curFile.Version,
  752. mut: sync.NewMutex(),
  753. }
  754. if debug {
  755. l.Debugf("%v need file %s; copy %d, reused %v", p, file.Name, len(blocks), reused)
  756. }
  757. cs := copyBlocksState{
  758. sharedPullerState: &s,
  759. blocks: blocks,
  760. }
  761. copyChan <- cs
  762. }
  763. // shortcutFile sets file mode and modification time, when that's the only
  764. // thing that has changed.
  765. func (p *rwFolder) shortcutFile(file protocol.FileInfo) error {
  766. realName := filepath.Join(p.dir, file.Name)
  767. if !p.ignorePerms {
  768. if err := os.Chmod(realName, os.FileMode(file.Flags&0777)); err != nil {
  769. l.Infof("Puller (folder %q, file %q): shortcut: chmod: %v", p.folder, file.Name, err)
  770. return err
  771. }
  772. }
  773. t := time.Unix(file.Modified, 0)
  774. if err := os.Chtimes(realName, t, t); err != nil {
  775. // Try using virtual mtimes
  776. info, err := os.Stat(realName)
  777. if err != nil {
  778. l.Infof("Puller (folder %q, file %q): shortcut: unable to stat file: %v", p.folder, file.Name, err)
  779. return err
  780. }
  781. p.virtualMtimeRepo.UpdateMtime(file.Name, info.ModTime(), t)
  782. }
  783. // This may have been a conflict. We should merge the version vectors so
  784. // that our clock doesn't move backwards.
  785. if cur, ok := p.model.CurrentFolderFile(p.folder, file.Name); ok {
  786. file.Version = file.Version.Merge(cur.Version)
  787. }
  788. p.dbUpdates <- file
  789. return nil
  790. }
  791. // shortcutSymlink changes the symlinks type if necessary.
  792. func (p *rwFolder) shortcutSymlink(file protocol.FileInfo) (err error) {
  793. err = symlinks.ChangeType(filepath.Join(p.dir, file.Name), file.Flags)
  794. if err == nil {
  795. p.dbUpdates <- file
  796. } else {
  797. l.Infof("Puller (folder %q, file %q): symlink shortcut: %v", p.folder, file.Name, err)
  798. }
  799. return
  800. }
  801. // copierRoutine reads copierStates until the in channel closes and performs
  802. // the relevant copies when possible, or passes it to the puller routine.
  803. func (p *rwFolder) copierRoutine(in <-chan copyBlocksState, pullChan chan<- pullBlockState, out chan<- *sharedPullerState) {
  804. buf := make([]byte, protocol.BlockSize)
  805. for state := range in {
  806. if p.progressEmitter != nil {
  807. p.progressEmitter.Register(state.sharedPullerState)
  808. }
  809. dstFd, err := state.tempFile()
  810. if err != nil {
  811. // Nothing more to do for this failed file (the error was logged
  812. // when it happened)
  813. out <- state.sharedPullerState
  814. continue
  815. }
  816. folderRoots := make(map[string]string)
  817. p.model.fmut.RLock()
  818. for folder, cfg := range p.model.folderCfgs {
  819. folderRoots[folder] = cfg.Path()
  820. }
  821. p.model.fmut.RUnlock()
  822. for _, block := range state.blocks {
  823. buf = buf[:int(block.Size)]
  824. found := p.model.finder.Iterate(block.Hash, func(folder, file string, index int32) bool {
  825. fd, err := os.Open(filepath.Join(folderRoots[folder], file))
  826. if err != nil {
  827. return false
  828. }
  829. _, err = fd.ReadAt(buf, protocol.BlockSize*int64(index))
  830. fd.Close()
  831. if err != nil {
  832. return false
  833. }
  834. hash, err := scanner.VerifyBuffer(buf, block)
  835. if err != nil {
  836. if hash != nil {
  837. if debug {
  838. l.Debugf("Finder block mismatch in %s:%s:%d expected %q got %q", folder, file, index, block.Hash, hash)
  839. }
  840. err = p.model.finder.Fix(folder, file, index, block.Hash, hash)
  841. if err != nil {
  842. l.Warnln("finder fix:", err)
  843. }
  844. } else if debug {
  845. l.Debugln("Finder failed to verify buffer", err)
  846. }
  847. return false
  848. }
  849. _, err = dstFd.WriteAt(buf, block.Offset)
  850. if err != nil {
  851. state.fail("dst write", err)
  852. }
  853. if file == state.file.Name {
  854. state.copiedFromOrigin()
  855. }
  856. return true
  857. })
  858. if state.failed() != nil {
  859. break
  860. }
  861. if !found {
  862. state.pullStarted()
  863. ps := pullBlockState{
  864. sharedPullerState: state.sharedPullerState,
  865. block: block,
  866. }
  867. pullChan <- ps
  868. } else {
  869. state.copyDone()
  870. }
  871. }
  872. out <- state.sharedPullerState
  873. }
  874. }
  875. func (p *rwFolder) pullerRoutine(in <-chan pullBlockState, out chan<- *sharedPullerState) {
  876. for state := range in {
  877. if state.failed() != nil {
  878. continue
  879. }
  880. // Get an fd to the temporary file. Technically we don't need it until
  881. // after fetching the block, but if we run into an error here there is
  882. // no point in issuing the request to the network.
  883. fd, err := state.tempFile()
  884. if err != nil {
  885. continue
  886. }
  887. var lastError error
  888. potentialDevices := p.model.Availability(p.folder, state.file.Name)
  889. for {
  890. // Select the least busy device to pull the block from. If we found no
  891. // feasible device at all, fail the block (and in the long run, the
  892. // file).
  893. selected := activity.leastBusy(potentialDevices)
  894. if selected == (protocol.DeviceID{}) {
  895. if lastError != nil {
  896. state.fail("pull", lastError)
  897. } else {
  898. state.fail("pull", errNoDevice)
  899. }
  900. break
  901. }
  902. potentialDevices = removeDevice(potentialDevices, selected)
  903. // Fetch the block, while marking the selected device as in use so that
  904. // leastBusy can select another device when someone else asks.
  905. activity.using(selected)
  906. buf, lastError := p.model.requestGlobal(selected, p.folder, state.file.Name, state.block.Offset, int(state.block.Size), state.block.Hash, 0, nil)
  907. activity.done(selected)
  908. if lastError != nil {
  909. continue
  910. }
  911. // Verify that the received block matches the desired hash, if not
  912. // try pulling it from another device.
  913. _, lastError = scanner.VerifyBuffer(buf, state.block)
  914. if lastError != nil {
  915. continue
  916. }
  917. // Save the block data we got from the cluster
  918. _, err = fd.WriteAt(buf, state.block.Offset)
  919. if err != nil {
  920. state.fail("save", err)
  921. } else {
  922. state.pullDone()
  923. }
  924. break
  925. }
  926. out <- state.sharedPullerState
  927. }
  928. }
  929. func (p *rwFolder) performFinish(state *sharedPullerState) {
  930. var err error
  931. defer func() {
  932. events.Default.Log(events.ItemFinished, map[string]interface{}{
  933. "folder": p.folder,
  934. "item": state.file.Name,
  935. "error": err,
  936. "type": "file",
  937. "action": "update",
  938. })
  939. }()
  940. // Set the correct permission bits on the new file
  941. if !p.ignorePerms {
  942. err = os.Chmod(state.tempName, os.FileMode(state.file.Flags&0777))
  943. if err != nil {
  944. l.Warnln("Puller: final:", err)
  945. return
  946. }
  947. }
  948. // Set the correct timestamp on the new file
  949. t := time.Unix(state.file.Modified, 0)
  950. err = os.Chtimes(state.tempName, t, t)
  951. if err != nil {
  952. // First try using virtual mtimes
  953. if info, err := os.Stat(state.tempName); err != nil {
  954. l.Infof("Puller (folder %q, file %q): final: unable to stat file: %v", p.folder, state.file.Name, err)
  955. } else {
  956. p.virtualMtimeRepo.UpdateMtime(state.file.Name, info.ModTime(), t)
  957. }
  958. }
  959. if p.inConflict(state.version, state.file.Version) {
  960. // The new file has been changed in conflict with the existing one. We
  961. // should file it away as a conflict instead of just removing or
  962. // archiving. Also merge with the version vector we had, to indicate
  963. // we have resolved the conflict.
  964. state.file.Version = state.file.Version.Merge(state.version)
  965. err = osutil.InWritableDir(moveForConflict, state.realName)
  966. } else if p.versioner != nil {
  967. // If we should use versioning, let the versioner archive the old
  968. // file before we replace it. Archiving a non-existent file is not
  969. // an error.
  970. err = p.versioner.Archive(state.realName)
  971. } else {
  972. err = nil
  973. }
  974. if err != nil {
  975. l.Warnln("Puller: final:", err)
  976. return
  977. }
  978. // If the target path is a symlink or a directory, we cannot copy
  979. // over it, hence remove it before proceeding.
  980. stat, err := osutil.Lstat(state.realName)
  981. if err == nil && (stat.IsDir() || stat.Mode()&os.ModeSymlink != 0) {
  982. osutil.InWritableDir(osutil.Remove, state.realName)
  983. }
  984. // Replace the original content with the new one
  985. err = osutil.Rename(state.tempName, state.realName)
  986. if err != nil {
  987. l.Warnln("Puller: final:", err)
  988. return
  989. }
  990. // If it's a symlink, the target of the symlink is inside the file.
  991. if state.file.IsSymlink() {
  992. content, err := ioutil.ReadFile(state.realName)
  993. if err != nil {
  994. l.Warnln("Puller: final: reading symlink:", err)
  995. return
  996. }
  997. // Remove the file, and replace it with a symlink.
  998. err = osutil.InWritableDir(func(path string) error {
  999. os.Remove(path)
  1000. return symlinks.Create(path, string(content), state.file.Flags)
  1001. }, state.realName)
  1002. if err != nil {
  1003. l.Warnln("Puller: final: creating symlink:", err)
  1004. return
  1005. }
  1006. }
  1007. // Record the updated file in the index
  1008. p.dbUpdates <- state.file
  1009. }
  1010. func (p *rwFolder) finisherRoutine(in <-chan *sharedPullerState) {
  1011. for state := range in {
  1012. if closed, err := state.finalClose(); closed {
  1013. if debug {
  1014. l.Debugln(p, "closing", state.file.Name)
  1015. }
  1016. if err != nil {
  1017. l.Warnln("Puller: final:", err)
  1018. continue
  1019. }
  1020. p.queue.Done(state.file.Name)
  1021. if state.failed() == nil {
  1022. p.performFinish(state)
  1023. } else {
  1024. events.Default.Log(events.ItemFinished, map[string]interface{}{
  1025. "folder": p.folder,
  1026. "item": state.file.Name,
  1027. "error": state.failed(),
  1028. "type": "file",
  1029. "action": "update",
  1030. })
  1031. }
  1032. p.model.receivedFile(p.folder, state.file.Name)
  1033. if p.progressEmitter != nil {
  1034. p.progressEmitter.Deregister(state)
  1035. }
  1036. }
  1037. }
  1038. }
  1039. // Moves the given filename to the front of the job queue
  1040. func (p *rwFolder) BringToFront(filename string) {
  1041. p.queue.BringToFront(filename)
  1042. }
  1043. func (p *rwFolder) Jobs() ([]string, []string) {
  1044. return p.queue.Jobs()
  1045. }
  1046. func (p *rwFolder) DelayScan(next time.Duration) {
  1047. p.delayScan <- next
  1048. }
  1049. // dbUpdaterRoutine aggregates db updates and commits them in batches no
  1050. // larger than 1000 items, and no more delayed than 2 seconds.
  1051. func (p *rwFolder) dbUpdaterRoutine() {
  1052. const (
  1053. maxBatchSize = 1000
  1054. maxBatchTime = 2 * time.Second
  1055. )
  1056. batch := make([]protocol.FileInfo, 0, maxBatchSize)
  1057. tick := time.NewTicker(maxBatchTime)
  1058. defer tick.Stop()
  1059. loop:
  1060. for {
  1061. select {
  1062. case file, ok := <-p.dbUpdates:
  1063. if !ok {
  1064. break loop
  1065. }
  1066. file.LocalVersion = 0
  1067. batch = append(batch, file)
  1068. if len(batch) == maxBatchSize {
  1069. p.model.updateLocals(p.folder, batch)
  1070. batch = batch[:0]
  1071. }
  1072. case <-tick.C:
  1073. if len(batch) > 0 {
  1074. p.model.updateLocals(p.folder, batch)
  1075. batch = batch[:0]
  1076. }
  1077. }
  1078. }
  1079. if len(batch) > 0 {
  1080. p.model.updateLocals(p.folder, batch)
  1081. }
  1082. }
  1083. func (p *rwFolder) inConflict(current, replacement protocol.Vector) bool {
  1084. if current.Concurrent(replacement) {
  1085. // Obvious case
  1086. return true
  1087. }
  1088. if replacement.Counter(p.shortID) > current.Counter(p.shortID) {
  1089. // The replacement file contains a higher version for ourselves than
  1090. // what we have. This isn't supposed to be possible, since it's only
  1091. // we who can increment that counter. We take it as a sign that
  1092. // something is wrong (our index may have been corrupted or removed)
  1093. // and flag it as a conflict.
  1094. return true
  1095. }
  1096. return false
  1097. }
  1098. func invalidateFolder(cfg *config.Configuration, folderID string, err error) {
  1099. for i := range cfg.Folders {
  1100. folder := &cfg.Folders[i]
  1101. if folder.ID == folderID {
  1102. folder.Invalid = err.Error()
  1103. return
  1104. }
  1105. }
  1106. }
  1107. func removeDevice(devices []protocol.DeviceID, device protocol.DeviceID) []protocol.DeviceID {
  1108. for i := range devices {
  1109. if devices[i] == device {
  1110. devices[i] = devices[len(devices)-1]
  1111. return devices[:len(devices)-1]
  1112. }
  1113. }
  1114. return devices
  1115. }
  1116. func moveForConflict(name string) error {
  1117. ext := filepath.Ext(name)
  1118. withoutExt := name[:len(name)-len(ext)]
  1119. newName := withoutExt + time.Now().Format(".sync-conflict-20060102-150405") + ext
  1120. err := os.Rename(name, newName)
  1121. if os.IsNotExist(err) {
  1122. // We were supposed to move a file away but it does not exist. Either
  1123. // the user has already moved it away, or the conflict was between a
  1124. // remote modification and a local delete. In either way it does not
  1125. // matter, go ahead as if the move succeeded.
  1126. return nil
  1127. }
  1128. return err
  1129. }