Setup timed out after 35 seconds

I’m getting this when I try to run PhotoStructure on one of my servers:

photostructure_1  | Please wait, setting up...
photostructure_1  | {"fatal":true,"exit":true,"status":13,"pid":14,"ppid":7,"error":"Setup timed out after 35 seconds.\nPlease visit https://photostructure.com/troubleshooting for help."}

The photos are mounted at /mnt/photos via NFS. However, I see barely any network traffic at all while PhotoStructure is starting up, so I don’t think that’s the cause of the issue. The NFS files are all owned by the same user I’m running PhotoStructure as (UID 112 and GID 116, which are for a system user called “photos”)

I looked through https://photostructure.com/faq/troubleshooting but it seems like the troubleshooting is primarily aimed at Windows issues :stuck_out_tongue: . The mount is healthy and df works:

root@chi03:/mnt/photos# df -h /mnt/photos
Filesystem                   Size  Used Avail Use% Mounted on
chi01.vpn.d.sb:/data/photos  2.0T  375G  1.5T  21% /mnt/photos

I don’t see much in the log:

root@chi03:/var/log/photostructure/2021-01-07# tail -n100 -f *.log
==> main-16-001.log <==
{"ts":1609998969437,"l":"info","ctx":"SettingsIO.importFileSettings(/ps/config/settings.toml)","msg":"loaded","meta":{"tomlMap":{"logLevel":"debug"},"imported":[{"name":"logLevel","value":"info","persist":false}]}}

==> main-17-001.log <==
{"ts":1609999020935,"l":"debug","ctx":"SettingsIO.importFileSettings(/ps/config/settings.toml)","msg":"ENV before","meta":{"NODE_ENV":"production","PS_CACHE_DIR":"/ps/tmp","PS_ENABLE_VIPS_CACHE":"1","PS_FORCE_LOCAL_DB_REPLICA":"1","PS_LIBRARY_PATH":"/ps/library","PS_LOG_COLOR":"true","PS_LOG_DIR":"/ps/logs","PS_LOG_LEVEL":"debug"}}
{"ts":1609999020951,"l":"debug","ctx":"SettingsIO","msg":"read(/ps/config/settings.toml)","meta":{"result":{"logLevel":"debug"}}}
{"ts":1609999020952,"l":"info","ctx":"SettingsIO.importFileSettings(/ps/config/settings.toml)","msg":"loaded","meta":{"tomlMap":{"logLevel":"debug"},"imported":[{"name":"logLevel","value":"debug","persist":false}]}}
{"ts":1609999020954,"l":"debug","ctx":"SettingsIO","msg":"libraryPathHasSettings","meta":{"result":true,"librarySettingsFile":"/ps/library/.photostructure/settings.toml"}}
{"ts":1609999020955,"l":"debug","ctx":"SettingsIO.importFileSettings(/ps/library/.photostructure/settings.toml)","msg":"ENV before","meta":{"NODE_ENV":"production","PS_CACHE_DIR":"/ps/tmp","PS_ENABLE_VIPS_CACHE":"1","PS_FORCE_LOCAL_DB_REPLICA":"1","PS_LIBRARY_PATH":"/ps/library","PS_LOG_COLOR":"true","PS_LOG_DIR":"/ps/logs","PS_LOG_LEVEL":"debug"}}
{"ts":1609999055947,"l":"info","ctx":"Service(main)","msg":"exit()","meta":{"status":13,"reason":"Setup timed out after 35 seconds.\nPlease visit https://photostructure.com/troubleshooting for help.","ending":false}}
{"ts":1609999055947,"l":"debug","ctx":"stdoutWrite","msg":"()","meta":{"obj":{"fatal":true,"exit":true,"status":13,"pid":17,"ppid":10,"error":"Setup timed out after 35 seconds.\nPlease visit https://photostructure.com/troubleshooting for help."},"ready":false}}
{"ts":1609999055948,"l":"info","ctx":"\u001b[35mEndable\u001b[39m","msg":"endEndables()","meta":{"isTest":false}}
{"ts":1609999055948,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"vacuumEndables()","meta":[["first",["Idle"]],["logger",["LogWriter(/ps/logs)"]],["service",["PromiseTimer"]]]}
{"ts":1609999055948,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"endEndables(): ending first"}
{"ts":1609999055949,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"Idle ending...","meta":{"timeoutMs":5000}}
{"ts":1609999055949,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"Idle.end() completed"}
{"ts":1609999055949,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"endEndables(): ending service"}
{"ts":1609999055949,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"PromiseTimer ending...","meta":{"timeoutMs":5000}}
{"ts":1609999055952,"l":"info","ctx":"PromiseTimer","msg":"timings:\n","meta":{"fs.readFile":{"mean":5,"mode":5,"max":5,"min":5,"k":1},"fs.stat":{"mean":0.5,"mode":0,"sd":0.71,"max":1,"min":0,"k":2}}}
{"ts":1609999055952,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"PromiseTimer.end() completed"}
{"ts":1609999055952,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"endEndables(): ending logger"}
{"ts":1609999055952,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"LogWriter(/ps/logs) ending...","meta":{"timeoutMs":15000}}

I’m using docker-compose with the following config:

version: "3.7"
services:
  photostructure:
    image: photostructure/server
    restart: on-failure
    stop_grace_period: 2m
    user: 112:116

    volumes:
      # This is where your PhotoStructure Library will be stored.
      # It must be readable, writable, and have sufficient free space.
      # If it is a remote volume, uncomment the PS_FORCE_LOCAL_DB_REPLICA
      # environment line below.
      - type: bind
        source: /mnt/photos
        target: /ps/library

      # This must be fast, local disk with many gigabytes free.
      # PhotoStructure will use this directory for file caching
      # and for storing a temporary database replica when your
      # library is on a remote volume.
      - type: bind
        source: "/var/tmp/photostructure"
        target: /ps/tmp

      # This directory stores your "system settings"
      - type: bind
        source: "/etc/photostructure"
        target: /ps/config

      # This directory stores PhotoStructure logfiles.
      - type: bind
        source: "/var/log/photostructure/"
        target: /ps/logs

      # Example additional directories to import into your library.
      # Add as many as you'd like, or remove one or both of these examples.

      # Set the target to /media/... or /mnt/...
      # (the name doesn't matter, as long as it is unique)

      #- type: bind
      #  source: "/mnt/Photos backup" # < CHANGE THIS LINE
      #  target: /var/photos-backup

      # Here's another example directory to scan:
      # - type: bind
      #   source: /home/jamie/Pictures
      #   target: /var/home-jamie-pictures

    ports:
      - "127.0.0.1:1787:1787"
      - "10.123.1.41:1787:1787"

    environment:
      # PhotoStructure has _tons_ of settings. See
      # <https://photostructure.com/faq/environment-variables/>
      - "PS_LOG_LEVEL=debug"
      - "PS_FORCE_LOCAL_DB_REPLICA=1"
      - "PS_ENABLE_VIPS_CACHE=1"

    labels:
      # See https://containrrr.dev/watchtower/container-selection/
      - "com.centurylinklabs.watchtower.enable=true"

  watchtower:
    image: containrrr/watchtower
    volumes:
      - /var/run/docker.sock:/var/run/docker.sock
    # Check for updates every couple hours: (3h * 60m * 60s)
    command: --interval 10800
    environment:
      - "WATCHTOWER_LABEL_ENABLE=true"

Any ideas?

Debian Testing (Buster)
Docker version 20.10.2, build 2291f61

I haven’t tested docker under Buster: I wonder if the v0.9.1 docker detection is misbehaving? (You can tell by looking at one of the first log messages emitted for every service: there should be a isDocker: true line.

If it’s false, add PS_IS_DOCKER=1 to your environment variables to force-fix the “isDocker” behavior (this is set by default in the next release).

Feel free to DM me the logs, there might be something else in there.

I think I posted the full logs above; is there a log file I missed? I can take a closer look tomorrow / later this week :slight_smile:

I don’t see any isDocker even after adding "PS_IS_DOCKER=1" :confused:

The docker-compose environment is set as follows:

    environment:
      # PhotoStructure has _tons_ of settings. See
      # <https://photostructure.com/faq/environment-variables/>
      - "PS_LOG_LEVEL=debug"
      - "PS_FORCE_LOCAL_DB_REPLICA=1"
      - "PS_ENABLE_VIPS_CACHE=1"
      - "PS_IS_DOCKER=1"

Output from docker-compose up:

root@chi03:~/docker# docker-compose up
Starting docker_photostructure_1 ... done
Starting docker_watchtower_1     ... done
Attaching to docker_watchtower_1, docker_photostructure_1
watchtower_1      | time="2021-01-07T17:33:50Z" level=info msg="Starting Watchtower and scheduling first run: 2021-01-07 20:33:50 +0000 UTC m=+10800.726457712"
photostructure_1  | Please wait, setting up...
photostructure_1  | {"fatal":true,"exit":true,"status":13,"pid":15,"ppid":8,"error":"Setup timed out after 35 seconds.\nPlease visit https://photostructure.com/troubleshooting for help."}

Output from tail -f *.log:

root@chi03:/var/log/photostructure/2021-01-07# tail -f -n1000 *.log
==> main-15-001.log <==
{"ts":1610040830045,"l":"debug","ctx":"SettingsIO.importFileSettings(/ps/config/settings.toml)","msg":"ENV before","meta":{"NODE_ENV":"production","PS_CACHE_DIR":"/ps/tmp","PS_ENABLE_VIPS_CACHE":"1","PS_FORCE_LOCAL_DB_REPLICA":"1","PS_LIBRARY_PATH":"/ps/library","PS_LOG_COLOR":"true","PS_LOG_DIR":"/ps/logs","PS_LOG_LEVEL":"debug"}}
{"ts":1610040830072,"l":"debug","ctx":"SettingsIO","msg":"read(/ps/config/settings.toml)","meta":{"result":{"logLevel":"debug"}}}
{"ts":1610040830074,"l":"info","ctx":"SettingsIO.importFileSettings(/ps/config/settings.toml)","msg":"loaded","meta":{"tomlMap":{"logLevel":"debug"},"imported":[{"name":"logLevel","value":"debug","persist":false}]}}
{"ts":1610040830078,"l":"debug","ctx":"SettingsIO","msg":"libraryPathHasSettings","meta":{"result":true,"librarySettingsFile":"/ps/library/.photostructure/settings.toml"}}
{"ts":1610040830079,"l":"debug","ctx":"SettingsIO.importFileSettings(/ps/library/.photostructure/settings.toml)","msg":"ENV before","meta":{"NODE_ENV":"production","PS_CACHE_DIR":"/ps/tmp","PS_ENABLE_VIPS_CACHE":"1","PS_FORCE_LOCAL_DB_REPLICA":"1","PS_LIBRARY_PATH":"/ps/library","PS_LOG_COLOR":"true","PS_LOG_DIR":"/ps/logs","PS_LOG_LEVEL":"debug"}}

==> main-16-001.log <==
{"ts":1609998969437,"l":"info","ctx":"SettingsIO.importFileSettings(/ps/config/settings.toml)","msg":"loaded","meta":{"tomlMap":{"logLevel":"debug"},"imported":[{"name":"logLevel","value":"info","persist":false}]}}

==> main-15-001.log <==
{"ts":1610040865056,"l":"info","ctx":"Service(main)","msg":"exit()","meta":{"status":13,"reason":"Setup timed out after 35 seconds.\nPlease visit https://photostructure.com/troubleshooting for help.","ending":false}}
{"ts":1610040865056,"l":"debug","ctx":"stdoutWrite","msg":"()","meta":{"obj":{"fatal":true,"exit":true,"status":13,"pid":15,"ppid":8,"error":"Setup timed out after 35 seconds.\nPlease visit https://photostructure.com/troubleshooting for help."},"ready":false}}
{"ts":1610040865057,"l":"info","ctx":"\u001b[35mEndable\u001b[39m","msg":"endEndables()","meta":{"isTest":false}}
{"ts":1610040865057,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"vacuumEndables()","meta":[["first",["Idle"]],["logger",["LogWriter(/ps/logs)"]],["service",["PromiseTimer"]]]}
{"ts":1610040865057,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"endEndables(): ending first"}
{"ts":1610040865057,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"Idle ending...","meta":{"timeoutMs":5000}}
{"ts":1610040865058,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"Idle.end() completed"}
{"ts":1610040865058,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"endEndables(): ending service"}
{"ts":1610040865058,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"PromiseTimer ending...","meta":{"timeoutMs":5000}}
{"ts":1610040865059,"l":"info","ctx":"PromiseTimer","msg":"timings:\n","meta":{"fs.readFile":{"mean":11,"mode":11,"max":11,"min":11,"k":1},"fs.stat":{"mean":0.5,"mode":1,"sd":0.71,"max":1,"min":0,"k":2}}}
{"ts":1610040865060,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"PromiseTimer.end() completed"}
{"ts":1610040865060,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"endEndables(): ending logger"}
{"ts":1610040865060,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"LogWriter(/ps/logs) ending...","meta":{"timeoutMs":15000}}

I don’t see any mention of PS_IS_DOCKER in there either… Not sure if that’s expected or not.

It’s weird… There doesn’t seem to be any log entries between when it starts and the “Setup timed out after 35 seconds” message. What is it supposed to be doing during that time?

There should be a info log message at the start of every process log with a bunch of (hopefully helpful) info:

  private logStartup() {
    this.logger.info("setup()", {
      version,
      start,
      argv: p.argv,
      arch: p.arch,
      platform: p.platform,
      isDocker: isDocker(),
      isPacked,
      isElectron,
      versions: p.versions,
      settings: {
        logLevel: Settings.logLevel.valueOrDefault,
        httpPort: Settings.httpPort.valueOrDefault,
        rpcPort: Settings.rpcPort.valueOrDefault,
        libraryPath: Settings.libraryPath.valueOrDefault
      },
      ...psenv()
    })
  }

I’m still banging on CI to go green (my mac and windows test runners got borked by a recent power surge), but after that’s up, I can spin back up my docker-compose test library and give some better help.

Yeah for some reason that line is totally missing from my log? I moved all the old logs away and ran docker-compose again. I got a single log file (main-15-001.log.gz) and this was the first line:

{"ts":1610045453009,"l":"debug","ctx":"SettingsIO.importFileSettings(/ps/config/settings.toml)","msg":"ENV before","meta":{"NODE_ENV":"production","PS_CACHE_DIR":"/ps/tmp","PS_ENABLE_VIPS_CACHE":"1","PS_FORCE_LOCAL_DB_REPLICA":"1","PS_LIBRARY_PATH":"/ps/library","PS_LOG_COLOR":"true","PS_LOG_DIR":"/ps/logs","PS_LOG_LEVEL":"debug"}}

I misspoke: it’ll be one of the first several log messages (certainly one of the first ~10 info messages).

This is the entire log file (I moved all other log files to a different location before starting the Docker container again, so this is definitely the most recent log):

{"ts":1610151784552,"l":"debug","ctx":"SettingsIO.importFileSettings(/ps/config/settings.toml)","msg":"ENV before","meta":{"NODE_ENV":"production","PS_CACHE_DIR":"/ps/tmp","PS_ENABLE_VIPS_CACHE":"1","PS_FORCE_LOCAL_DB_REPLICA":"1","PS_LIBRARY_PATH":"/ps/library","PS_LOG_COLOR":"true","PS_LOG_DIR":"/ps/logs","PS_LOG_LEVEL":"debug"}}
{"ts":1610151784577,"l":"debug","ctx":"SettingsIO","msg":"read(/ps/config/settings.toml)","meta":{"result":{"logLevel":"debug"}}}
{"ts":1610151784578,"l":"info","ctx":"SettingsIO.importFileSettings(/ps/config/settings.toml)","msg":"loaded","meta":{"tomlMap":{"logLevel":"debug"},"imported":[{"name":"logLevel","value":"debug","persist":false}]}}
{"ts":1610151784581,"l":"debug","ctx":"SettingsIO","msg":"libraryPathHasSettings","meta":{"result":true,"librarySettingsFile":"/ps/library/.photostructure/settings.toml"}}
{"ts":1610151784582,"l":"debug","ctx":"SettingsIO.importFileSettings(/ps/library/.photostructure/settings.toml)","msg":"ENV before","meta":{"NODE_ENV":"production","PS_CACHE_DIR":"/ps/tmp","PS_ENABLE_VIPS_CACHE":"1","PS_FORCE_LOCAL_DB_REPLICA":"1","PS_LIBRARY_PATH":"/ps/library","PS_LOG_COLOR":"true","PS_LOG_DIR":"/ps/logs","PS_LOG_LEVEL":"debug"}}
{"ts":1610151819563,"l":"info","ctx":"Service(main)","msg":"exit()","meta":{"status":13,"reason":"Setup timed out after 35 seconds.\nPlease visit https://photostructure.com/troubleshooting for help.","ending":false}}
{"ts":1610151819563,"l":"debug","ctx":"stdoutWrite","msg":"()","meta":{"obj":{"fatal":true,"exit":true,"status":13,"pid":15,"ppid":8,"error":"Setup timed out after 35 seconds.\nPlease visit https://photostructure.com/troubleshooting for help."},"ready":false}}
{"ts":1610151819564,"l":"info","ctx":"\u001b[35mEndable\u001b[39m","msg":"endEndables()","meta":{"isTest":false}}
{"ts":1610151819564,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"vacuumEndables()","meta":[["first",["Idle"]],["logger",["LogWriter(/ps/logs)"]],["service",["PromiseTimer"]]]}
{"ts":1610151819564,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"endEndables(): ending first"}
{"ts":1610151819564,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"Idle ending...","meta":{"timeoutMs":5000}}
{"ts":1610151819565,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"Idle.end() completed"}
{"ts":1610151819565,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"endEndables(): ending service"}
{"ts":1610151819565,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"PromiseTimer ending...","meta":{"timeoutMs":5000}}
{"ts":1610151819566,"l":"info","ctx":"PromiseTimer","msg":"timings:\n","meta":{"fs.readFile":{"mean":16,"mode":16,"max":16,"min":16,"k":1},"fs.mkdirp":{"mean":3,"mode":3,"max":3,"min":3,"k":1},"fs.stat":{"mean":0,"mode":0,"sd":0,"max":0,"min":0,"k":3}}}
{"ts":1610151819566,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"PromiseTimer.end() completed"}
{"ts":1610151819566,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"endEndables(): ending logger"}
{"ts":1610151819566,"l":"debug","ctx":"\u001b[35mEndable\u001b[39m","msg":"LogWriter(/ps/logs) ending...","meta":{"timeoutMs":15000}}

It looks like it’s getting stuck in SettingsIO.importFileSettings:

async function importFileSettings(f: BaseFile): PromiseMaybe<Setting<any>[]> {
  const log = mkLogger("SettingsIO.importFileSettings(" + f.nativePath + ")")
  try {
    log.debug("ENV before", psenv())

    const tomlMap = await read(f)
    if (tomlMap == null) {
      if (await f.isNonEmpty()) throw new Error("Failed to read " + f)
      else return []
    }
    const settings = new Map<string, Setting<any>>(
      entries(Settings)
        .filter(([, v]) => v instanceof Setting && !v.transient)
        .map(([k, v]) => [k.toLowerCase(), v])
    )
    const imported = compact(
      entries(tomlMap).map(([key, value]) => {
        const s = settings.get(toS(key).toLowerCase())
        if (s == null) {
          log.warn("Failed to import (no setting with this name)", {
            key
          })
        } else {
          s.importFromFile(value)
        }
        return s
      })
    )
    log.info("loaded", {
      tomlMap,
      imported: imported.map(s => pick(s, "name", "value", "persist"))
    })
    return imported
  } catch (err) {
    log.error("Cannot read" + errorToVerbose(err))
    return
  }
}

So I expect there should have been either an error thrown, or a “loaded” message emitted. Is your bind-mount for /ps/library/ read/write? (If you docker exec into the container, can you touch /ps/library/.photostructure/settings.toml?)

(either way, though, I’d expect file I/O to either succeed or fail quickly (like in milliseconds).

Seems like it’s read-write:

root@chi03:~/docker# docker exec -it docker_photostructure_1 /bin/sh
/ps/app $ cd /ps/library/.photostructure
/ps/library/.photostructure $ touch hello-world
/ps/library/.photostructure $ ls -lah
total 72K
drwxr-xr-x  5 112 116 4.0K Jan  9 00:52 .
drwxr-xr-x 18 112 116 4.0K Jan  7 03:51 ..
-rw-r--r--  1 112 116  129 Jan  3 20:20 .NoMedia
-rw-r--r--  1 112 116  617 Jan  4 19:32 README.txt
-rw-r--r--  1 112 116    0 Jan  9 00:52 hello-world
drwxr-xr-x  4 112 116 4.0K Jan  4 19:36 models
drwxr-xr-x  2 112 116 4.0K Jan  7 05:51 opened-by
drwxr-xr-x  3 112 116 4.0K Jan  3 20:20 previews
-rw-r--r--  1 112 116  37K Jan  4 03:09 settings.toml
-rw-r--r--  1 112 116   88 Jan  3 20:21 uid.json

cat /ps/config/settings.toml works too (doesn’t hang).

Ah, so it was able to write to the settings.toml, at least at some point. Is the uid and gid correct? (docker exec should fork /bin/sh with the correct uid/gid, right?)

Yeah. I have a user and group called “photos”:

root@chi03:~/docker# id photos
uid=112(photos) gid=116(photos) groups=116(photos)

My docker-composer.yml is configured with these IDs:

user: 112:116
1 Like

Ah: Does running info wedge up trying to read settings?

Also: was the settings.toml copied over from a windows run? (I can’t imagine that it’s a CR/NL issue, but hey, I’m out of ideas here, everything’s on the table).

What’s head -2 /ps/config/settings.toml | cat -vet output?

Good catch; info also got stuck.

I’m not entirely sure what happened, but I rebooted the server and now it starts fine?? :thinking: I’m pretty sure I tried that before! I’ll let you know if the issue happens again.

1 Like

Thanks for the status update!

I just had to reboot yesterday because I mistyped sudo mount -a as sudo umount -a. Bad things happened. Snap never recovered.

Heh, at least that’s recoverable through a boot :slight_smile:
I once meant to run crontab -e (edit the crontab) but accidentally ran crontab -r (delete the crontab) instead. Whose idea was it to have a delete option using the key directly next to e, with no confirmation prompt?? I had to restore the crontabs from backup. At least I had daily backups :slight_smile:

1 Like

Of course, now I think of this, but if this ever happens again, can you run strace ... info? That should tell us what system call it’s hanging on.

:+1: