How can I tell if import/sync is working?

Support
, ,
1

I’ve installed PhotoStructure for Node on a headless Ubuntu server, moved my pictures into my library directory, and initiated a scan through the web UI. Now visiting the home page in the web UI shows me a message “Processing”, saying that it’s scanning my library directory, and the about page shows that PhotoStructure has been syncing that directory for the last 5 hours. There doesn’t seem to be any progress bar, and my library is still empty. How can I confirm that the import is working, other than waiting for it to finish?

I saw the similar question (How can I tell what it's doing?), but I can’t tell from those answers whether there’s a bug preventing the import from working, or just a bug preventing the progress bar from displaying. So I’m not sure whether I should let the sync continue, or instead update to the beta as the sync is not working.

Any advice would be appreciated!

2

I should also mention that I have run sudo journalctl --unit=photostructure, and there are no messages since the last time PhotoStructure started. (There are error messages from before, because I changed the ownership of some folders in the library (including the database) while a sync was happening, and the database became readonly. I don’t think this is the cause of my problems, because everything I can see is the same now as it was before I did this, and I have reset the ownership of the library folders.)

I have not tried increasing log verbosity (e.g. by setting the log level to warn or info), because I don’t want to interrupt the current sync by shutting PhotoStructure down – is this my only route forward?

3

Howdy @emdash, welcome to PhotoStructure!

(btw if your username is for an em dash, :clap: from a fellow typography nerd enthusiast)

Oof, apologies that PhotoStructure sync seems to have gotten “stuck”.

A couple bits of information might help track down what’s going on:

  1. what version of PhotoStructure are you running? (photostructure/server:stable, or :alpha?)
  2. what filesystems are you bind mounting? (do you have nfs? zfs? smb?)

Ah, good news: the sync work queue is persisted, so you can bounce PhotoStructure whenever you want, and when it restarts, it should pick up where it left off.

If you’re on :alpha, there’s a sync report that should explain the file import status for every file.

The next alpha build will also add new PS_LOG_SERVER and PS_LOG_SERVER_LEVEL settings that work well with a log aggregator like Graylog, if you want an alternative to logtail.

4

Thanks, I’m delighted with it so far! (Despite not having fully got it working yet.) The name is indeed for an em dash – glad you like it :slight_smile:

Ah, sorry – I wasn’t aware of the different versions, so I didn’t think to include this info. I am running the stable version.

No network filesystems involved, just a local ext4 filesystem on an SSD over SATA.

Excellent, thanks for the explanation! I will enable more verbose logging and restart, see if the logs give me any more info.

These look like useful new features, and I’m glad to see they’re in progress :slight_smile:

5

I have raised the log level (to info and then to debug), and it looks like the following is repeated in the logs:

2022-06-26T09:03:45.338Z sync-2866 debug DirectorySync(/home/photostructure/Pictures) percents(): { scannedPct: 0,
  processed: 0,
  pending: 0,
  p: { completePct: 0, incompletePct: 0, scanningPct: 100 } }
2022-06-26T09:03:45.339Z sync-2866 debug DirectorySync(/home/photostructure/Pictures) .progress() { result:
   { '$ctor': 'models.Progress',
     completePct: 0,
     createdAt: 1656234171484,
     dekJSON: '["Scanning /home/photostructure/Pictures"]',
     hed: 'Processing',
     hostname: 'apricot',
     id: 9,
     incompletePct: 0,
     pid: 2866,
     scanningPct: 100,
     state: 'processing',
     updatedAt: 1656234222339,
     uri: 'pslib:/',
     volume: '/home/photostructure/Pictures' } }
2022-06-26T09:03:45.430Z web-2860 debug AssetFile recentAssetIdsByUriRoot { method: 'select',
  options: {},
  timeout: false,
  cancelOnTimeout: false,
  bindings: [ 1656234205430, 1, 0, 'pslib:/%', 10 ],
  __knexQueryUid: '0UTJ2CUBetshLfqBQiMAZ',
  sql:
   'select distinct `AssetFile`.`assetId` from `AssetFile` inner join `Asset` on `Asset`.`id` = `AssetFile`.`assetId` where `AssetFile`.`updatedAt` > ? and `Asset`.`shown` = ? and `Asset`.`hidden` = ? and `AssetFile`.`uri` like ? order by `AssetFile`.`updatedAt` desc limit ?' }
2022-06-26T09:03:45.431Z web-2860 debug ProgressWithAssets recentProgressWithAssets() [ { id: 9,
    uri: 'pslib:/',
    volume: '/home/photostructure/Pictures',
    state: 'processing',
    hed: 'Processing',
    dek: [ 'Scanning /home/photostructure/Pictures' ],
    completePct: 0,
    incompletePct: 0,
    scanningPct: 100,
    recentAssetIds: [] } ]

Am I right to think it’s a bit strange that scanningPct is 100, and processed and pending are both 0?

For a higher-level view, here’s the recurring output at the info level:

LogTail(): Tailing /home/photostructure/.config/PhotoStructure/logs/**/*.log...
2022-06-26T08:54:00.726Z sync-1838 info  TagSql runTagMaintenance()
2022-06-26T08:54:09.728Z sync-1838 info  TagSql runTagMaintenance()
2022-06-26T08:54:18.731Z sync-1838 info  TagSql runTagMaintenance()
2022-06-26T08:54:27.732Z sync-1838 info  TagSql runTagMaintenance()
2022-06-26T08:54:36.735Z sync-1838 info  TagSql runTagMaintenance()
2022-06-26T08:54:45.736Z sync-1838 info  TagSql runTagMaintenance()
2022-06-26T08:54:53.289Z web-1832 info  Service(web) --health-check { ok: [ 'Library and support directories are OK', 'Memory by web (25 MB) is OK' ],
  warn: [ 'Nothing to scan: scanAllDrives is false and scanPaths is empty.⁸' ],
  bad: [],
  fail: [] }
2022-06-26T08:54:54.738Z sync-1838 info  TagSql runTagMaintenance()
2022-06-26T08:55:03.741Z sync-1838 info  TagSql runTagMaintenance()
2022-06-26T08:55:12.743Z sync-1838 info  TagSql runTagMaintenance()
2022-06-26T08:55:18.723Z web-1832 info  WebService Setting up library router for /home/photostructure/Pictures
2022-06-26T08:55:18.731Z web-1832 info  SpaRouter request { params: { '0': '' }, query: { seed: '38168' } }
2022-06-26T08:55:19.803Z web-1832 info  respErrHandler Error serving /apple-touch-icon.png: Error: aborted
2022-06-26T08:55:19.858Z web-1832 info  Handler.wrap() api/tag: request for []
2022-06-26T08:55:19.858Z web-1832 info  Handler.wrap() getOrPrngSeed() '38168'
2022-06-26T08:55:21.746Z sync-1838 info  TagSql runTagMaintenance()
2022-06-26T08:55:30.750Z sync-1838 info  TagSql runTagMaintenance()
2022-06-26T08:55:33.454Z web-1832 info  ffmpeg ffmpegVersion { version: '4.4.2-0ubuntu0.22.04.1',
  code: 0,
  stdout:
   'ffmpeg version 4.4.2-0ubuntu0.22.04.1 Copyright (c) 2000-2021 the FFmpeg developers' }
2022-06-26T08:55:33.511Z web-1832 info  SystemIds cpuid failed {}
2022-06-26T08:55:33.584Z web-1832 info  SyncPaths pathsToSync [ { nativePath: '/home/photostructure/Pictures', uri: 'pslib:/' } ]
2022-06-26T08:55:33.586Z web-1832 info  Operation getFirstPendingOp { result:
   { '$ctor': 'models.Operation',
     createdAt: 1656174993523,
     id: 8,
     name: 'forceRestartSync',
     updatedAt: 1656174993523,
     value: '' },
  pojo: { name: 'forceRestartSync' } }
2022-06-26T08:55:33.587Z web-1832 info  Progress minCreatedAt { result: 1656174993523,
  op:
   { '$ctor': 'models.Operation',
     createdAt: 1656174993523,
     id: 8,
     name: 'forceRestartSync',
     updatedAt: 1656174993523,
     value: '' } }
2022-06-26T08:55:33.591Z web-1832 info  Operation getFirstPendingOp { result:
   { '$ctor': 'models.Operation',
     createdAt: 1656174993523,
     id: 8,
     name: 'forceRestartSync',
     updatedAt: 1656174993523,
     value: '' },
  pojo: { name: 'forceRestartSync' } }
2022-06-26T08:55:33.591Z web-1832 info  SyncPaths bestStable(): returning most recently updated { nativePath: '/home/photostructure/Pictures',
  uri: 'pslib:/',
  lastUpdatedAt: 1656233730746,
  lastStartedAt: 1656174995365 }
2022-06-26T08:55:33.592Z web-1832 info  Operation getFirstPendingOp { result:
   { '$ctor': 'models.Operation',
     createdAt: 1656174993523,
     id: 8,
     name: 'forceRestartSync',
     updatedAt: 1656174993523,
     value: '' },
  pojo: { name: 'forceRestartSync' } }
2022-06-26T08:55:39.754Z sync-1838 info  TagSql runTagMaintenance()
2022-06-26T08:55:48.758Z sync-1838 info  TagSql runTagMaintenance()

(I’m assuming the warning about there being nothing to scan is fine, because the pictures are in the library directory and the settings page in the web UI says that PhotoStructure always scans the library directory.)

It reads to me like PhotoStructure is indeed stuck for some reason, but I can’t tell what the reason is from these logs. My plan now is to pause this sync, and start a new one from the command line on a small directory of photos, to see if there’s any change.

6

No luck with pausing and running a manual sync – I have a feeling the pause option in the web UI pauses all syncs, whereas I had assumed it would only pause the current sync. Unfortunately, resuming also showed no progress (though there were more log messages). The logs showed that something called a directory walker was started for my manual sync, but the directory only contained one photo and the import didn’t finish within a few minutes so I stopped it.

Shutting PhotoStructure down and examining the database showed that there are no entries in the Assets table, so pictures definitely aren’t being (successfully) imported.

An interesting thing in the output when I shut it down:

Jun 26 09:21:44 apricot systemd[1]: photostructure.service: Consumed 21.569s CPU time.

This is after running for a few minutes – shouldn’t it have consumed more CPU time than that? htop shows my CPU utilisation as basically 0, so I don’t think anything should be competing with PhotoStructure.

7

I have switched to the beta branch, and import is now working correctly. Not sure what’s changed, but happy to have pictures importing now!

(Note: I do now see a progress bar, which also has a time estimate – confirmation that there was supposed to be one.)