docker: ocat --list error "Cannot open requested directory"

[frootmig]

I used docker compose to setup a container running Mosquitto because I did not manage to use the Ubuntu Xenial package due to a systemD bug. Mosquitto did not start from systemctl, it just worked when staring direct on console.

However, I used this docker-compose.yml to fire up the container:

version: '3'
services:
  mosquitto-owntracks:
    image: owntracks/recorderd
    restart: always
    ports:
      - "192.168.1.1:1883:1883"
      - "192.168.1.1:8883:8883"
      - "192.168.1.1:18083:8083"
    volumes:
      - /home/docker/volumes/owntracks:/owntracks
    container_name: mosquitto-owntracks

I noticed that Recorder shows nothing in the GUI. According to the documentation I tried to use ocat to list all known users to start debugging the issue. The call failed, which might explain why Recorder shows nothing.

root@ea901ce61be1:/# ocat --list
{"error":"Cannot open requested directory"}
root@ea901ce61be1:/# ps aux | grep own
mosquit+    55  0.0  0.0  42280  5296 ?        S    13:42   0:08 /usr/sbin/mosquitto -c /owntracks/mosquitto/mosquitto.conf
owntrac+    56  0.1  0.0 975032 11532 ?        S    13:42   0:18 /usr/sbin/ot-recorder --http-host 0.0.0.0

These are the file system permissions as seen in the container:

root@ea901ce61be1:/# ls -ld /owntracks/recorder/
drwxr-xr-x 3 owntracks owntracks 4096 Aug 28 14:34 /owntracks/recorder/
root@ea901ce61be1:/# ls -ld /owntracks/recorder/*
drwxr-xr-x 4 owntracks owntracks 4096 Aug 29 17:24 /owntracks/recorder/store
root@ea901ce61be1:/# ls -ld /owntracks/recorder/store/*
drwxr-xr-x 2 owntracks owntracks 4096 Aug 28 14:35 /owntracks/recorder/store/ghash
drwxr-xr-x 3 owntracks owntracks 4096 Aug 28 14:35 /owntracks/recorder/store/last
-rw-r--r-- 1 owntracks root        31 Aug 29 17:24 /owntracks/recorder/store/monitor
root@ea901ce61be1:/# ls -ld /owntracks/recorder/store/last/*
drwxr-xr-x 3 owntracks owntracks 4096 Aug 28 14:35 /owntracks/recorder/store/last/ping
root@ea901ce61be1:/# ls -ld /owntracks/recorder/store/last/ping/*
drwxr-xr-x 2 owntracks owntracks 4096 Aug 29 17:25 /owntracks/recorder/store/last/ping/ping
root@ea901ce61be1:/# ls -ld /owntracks/recorder/store/last/ping/ping/*
-rw-r--r-- 1 owntracks root 175 Aug 29 17:25 /owntracks/recorder/store/last/ping/ping/ping-ping.json
root@ea901ce61be1:/# ls -ld /owntracks/recorder/store/ghash/*
-rw-r--r-- 1 owntracks owntracks 32768 Aug 28 14:37 /owntracks/recorder/store/ghash/data.mdb
-rw-r--r-- 1 owntracks owntracks  8192 Aug 29 17:25 /owntracks/recorder/store/ghash/lock.mdb
-rw-r--r-- 1 owntracks owntracks   112 Aug 28 14:36 /owntracks/recorder/store/ghash/missing

And these are the file system permissions as seen from the host system:

root@asgard:/home/docker/volumes/owntracks# ls -l
total 16
drwxr-xr-x 2 root    root    4096 Aug 29 15:42 certs
drwxr-xr-x 3 root    root    4096 Aug 28 16:34 etc
drwxr-xr-x 2 unbound nogroup 4096 Aug 29 19:12 mosquitto
drwxr-xr-x 3 nagios  docker  4096 Aug 28 16:34 recorder
root@asgard:/home/docker/volumes/owntracks# cd recorder/
root@asgard:/home/docker/volumes/owntracks/recorder# ls -l
total 4
drwxr-xr-x 4 nagios docker 4096 Aug 29 19:27 store
root@asgard:/home/docker/volumes/owntracks/recorder# cd store/
root@asgard:/home/docker/volumes/owntracks/recorder/store# ls -l
total 12
drwxr-xr-x 2 nagios docker 4096 Aug 28 16:35 ghash
drwxr-xr-x 3 nagios docker 4096 Aug 28 16:35 last
-rw-r--r-- 1 nagios root     31 Aug 29 19:27 monitor
root@asgard:/home/docker/volumes/owntracks/recorder/store# cd last/
root@asgard:/home/docker/volumes/owntracks/recorder/store/last# ls -l
total 4
drwxr-xr-x 3 nagios docker 4096 Aug 28 16:35 ping
root@asgard:/home/docker/volumes/owntracks/recorder/store/last# cd ping
root@asgard:/home/docker/volumes/owntracks/recorder/store/last/ping# ls -l
total 4
drwxr-xr-x 2 nagios docker 4096 Aug 29 19:27 ping
root@asgard:/home/docker/volumes/owntracks/recorder/store/last/ping# cd ping/
root@asgard:/home/docker/volumes/owntracks/recorder/store/last/ping/ping# ls -l
total 4
-rw-r--r-- 1 nagios root 175 Aug 29 19:27 ping-ping.json
root@asgard:/home/docker/volumes/owntracks/recorder/store/last/ping/ping# cd /home/docker/volumes/owntracks/recorder/store
root@asgard:/home/docker/volumes/owntracks/recorder/store# ls -l
total 12
drwxr-xr-x 2 nagios docker 4096 Aug 28 16:35 ghash
drwxr-xr-x 3 nagios docker 4096 Aug 28 16:35 last
-rw-r--r-- 1 nagios root     31 Aug 29 19:28 monitor
root@asgard:/home/docker/volumes/owntracks/recorder/store# cd ghash/
root@asgard:/home/docker/volumes/owntracks/recorder/store/ghash# ls -l
total 40
-rw-r--r-- 1 nagios docker 32768 Aug 28 16:37 data.mdb
-rw-r--r-- 1 nagios docker  8192 Aug 29 19:28 lock.mdb
-rw-r--r-- 1 nagios docker   112 Aug 28 16:36 missing

Any ideas how to debug the problem further?

[jpmens]

I don't see an ocat -v output there. Please show it, and kindly put console output between lines of three backticks each (code fences).

[frootmig]

I updated the formating of the console output. There the requested output:

root@ea901ce61be1:/# ocat -v
This is OwnTracks Recorder, version 0.7.6
built with:
        WITH_MQTT = yes
        WITH_HTTP = yes
        WITH_LUA  = yes
        WITH_ENCRYPT = yes
        WITH_PING = yes
        WITH_KILL = yes
        CONFIGFILE = "/etc/default/ot-recorder"
        STORAGEDEFAULT = "/var/spool/owntracks/recorder/store"
        STORAGEDIR = "/owntracks/recorder/store"
        DOCROOT = "/usr/share/owntracks/recorder/htdocs"
        GHASHPREC = 7
        DEFAULT_HISTORY_HOURS = 6
        JSON_INDENT = "NULL"
        LIBMOSQUITTO_VERSION = 1.4.12
        MDB VERSION = LMDB 0.9.16: (August 14, 2015)
        SODIUM VERSION = 1.0.8
        GIT VERSION = 0.7.6-0-g345305a002

Looking at all paths/files, only the htdocs folder is not writable:

root@ea901ce61be1:/# ls -ld  "/etc/default/ot-recorder"
-rw-r--r-- 1 root root 230 Aug 29 13:42 /etc/default/ot-recorder
root@ea901ce61be1:/# ls -ld "/var/spool/owntracks/recorder/store"
drwxr-xr-x 4 owntracks owntracks 4096 Apr 30 12:02 /var/spool/owntracks/recorder/store
root@ea901ce61be1:/# ls -ld "/owntracks/recorder/store"
drwxr-xr-x 4 owntracks owntracks 4096 Aug 29 20:48 /owntracks/recorder/store
root@ea901ce61be1:/# ls -ld "/usr/share/owntracks/recorder/htdocs"
drwxr-xr-x 7 root root 4096 Apr 30 12:02 /usr/share/owntracks/recorder/htdocs

[jpmens]

My docker knowlege is minimal, so I really can't follow what's happening here. What I would do is to try and launch the Recorder (ot-recorder) manually and look at it's console. See if you can identify how it connects to Mosquitto locally, and then publish a position from your device. You should see that arrive in Mosquitto (verify with a mosquitto_sub) and you should see it being read via MQTT from the Recorder.

The resulting data will be put in a file called <STORE>/rec/<username>/<devicename>/2018-08.rec (if you do it in August of this year).

[frootmig]

I can try to debug the Docker container. But I'm not familiar with Mosquitto and Recorder so far. But I want to use it. :-)

I tried to have a look at the Recorder console, however I needed to start a second instance for the test on a different port:

root@ea901ce61be1:/# /usr/sbin/ot-recorder --http-host 0.0.0.0 --http-port 12345
ot-recorder[7797]: version 0.7.6 starting with STORAGEDIR=/owntracks/recorder/store
ot-recorder[7797]: connecting to MQTT on localhost:1883 as clientID ot-recorder-ea901ce61be1-7797 without TLS
ot-recorder[7797]: HTTP listener started on 0.0.0.0:12345
ot-recorder[7797]: Using storage at /owntracks/recorder/store with precision 7
ot-recorder[7797]: Subscribing to owntracks/# (qos=2)

As far as I can see, this should be the same output as seen with docker-compose logs. That's why I assume there is simply no output and Recorder does not receive any messages.

I am not sure if the syntax is correct, but this does not return output, too:

root@ea901ce61be1:/# mosquitto_sub -t 'owntracks/#'

When I run the test, I can see these log outputs.

mosquitto-owntracks    | 1535621162: New connection from 80.187.XXX.XXX on port 8883.
mosquitto-owntracks    | 1535621162: Client owntracksVolkersiPhone disconnected.
mosquitto-owntracks    | 1535621162: New client connected from 80.187.XXX.XXX as owntracksVolkersiPhone (c0, k60, u'owntracks').
mosquitto-owntracks    | 1535621162: Sending CONNACK to owntracksVolkersiPhone (1, 0)
mosquitto-owntracks    | 1535621164: Received PUBLISH from owntracksVolkersiPhone (d0, q1, r1, m15, 'owntracks/owntracks/Volkers iPhone', ... (178 bytes))
mosquitto-owntracks    | 1535621164: ACL denying access to client with dangerous client id "mosqsub/7871-ea901ce61b"
mosquitto-owntracks    | 1535621164: Sending PUBACK to owntracksVolkersiPhone (Mid: 15)
mosquitto-owntracks    | 1535621164: Sending PUBLISH to owntracksVolkersiPhone (d0, q1, r0, m63, 'owntracks/owntracks/Volkers iPhone', ... (178 bytes))
mosquitto-owntracks    | 1535621164: Received PUBACK from owntracksVolkersiPhone (Mid: 63)
mosquitto-owntracks    | 1535621166: Received PUBLISH from owntracksVolkersiPhone (d0, q1, r1, m16, 'owntracks/owntracks/Volkers iPhone', ... (178 bytes))
mosquitto-owntracks    | 1535621166: ACL denying access to client with dangerous client id "mosqsub/7871-ea901ce61b"
mosquitto-owntracks    | 1535621166: Sending PUBACK to owntracksVolkersiPhone (Mid: 16)
mosquitto-owntracks    | 1535621166: Sending PUBLISH to owntracksVolkersiPhone (d0, q1, r0, m64, 'owntracks/owntracks/Volkers iPhone', ... (178 bytes))
mosquitto-owntracks    | 1535621166: Received PUBACK from owntracksVolkersiPhone (Mid: 64)
mosquitto-owntracks    | 1535621168: Received DISCONNECT from owntracksVolkersiPhone
mosquitto-owntracks    | 1535621168: Client owntracksVolkersiPhone disconnected.
mosquitto-owntracks    | 1535621187: Socket error on client mosqsub/7871-ea901ce61b, disconnecting.
mosquitto-owntracks    | ot-recorder[7581]: http: POST /pub
mosquitto-owntracks    | ot-recorder[7581]: gcache_get: mdb_txn_begin: (-30783) MDB_BAD_RSLOT: Invalid reuse of reader locktable slot
mosquitto-owntracks    | ot-recorder[7581]: gcache_json_get: mdb_txn_begin: (-30783) MDB_BAD_RSLOT: Invalid reuse of reader locktable slot
mosquitto-owntracks    | ot-recorder[7581]: gcache_get: mdb_txn_begin: (-30783) MDB_BAD_RSLOT: Invalid reuse of reader locktable slot
mosquitto-owntracks    | ot-recorder[7581]: http: POST /api/0/last
mosquitto-owntracks    | ot-recorder[7581]: gcache_json_get: mdb_txn_begin: (-30783) MDB_BAD_RSLOT: Invalid reuse of reader locktable slot
mosquitto-owntracks    | 1535621210: Received PINGREQ from ot-recorder-ea901ce61be1-7581
mosquitto-owntracks    | 1535621210: Sending PINGRESP to ot-recorder-ea901ce61be1-7581

BTW: I had now created the /owntracks/recorder/store/rec/ folder inside of the container and set the permission. No content in the folder after this test. But the ocat --list is now no longer returning an error, but {"results":[]}

I assume that ocat just had a problem that Recorder had not yet received any data.

I noticed that there are messages that might state an error, but I cannot understand right now what this error means. Perhaps I can dig into the code later.

[frootmig]

Okay, I caused the MDB_BAD_RSLOT errors by spinning up the second recorder instance.

That means, that Recorder does not get/read any data from Mosquitto. Da regular run does not show any activity from Recorder beside the POST requests seen in the log, what appears to be a ping.

mosquitto-owntracks    | 2018-08-30 09:50:56,609 INFO success: recorder entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
mosquitto-owntracks    | ot-recorder[35]: http: POST /pub
mosquitto-owntracks    | ot-recorder[35]: http: POST /api/0/last
mosquitto-owntracks    | 1535622693: New connection from 80.187.106.137 on port 8883.
mosquitto-owntracks    | 1535622693: Client owntracksVolkersiPhone disconnected.
mosquitto-owntracks    | 1535622693: New client connected from 80.187.106.137 as owntracksVolkersiPhone (c0, k60, u'owntracks').
mosquitto-owntracks    | 1535622693: Sending CONNACK to owntracksVolkersiPhone (1, 0)
mosquitto-owntracks    | 1535622694: Received PUBLISH from owntracksVolkersiPhone (d0, q1, r1, m17, 'owntracks/owntracks/Volkers iPhone', ... (177 bytes))
mosquitto-owntracks    | 1535622694: Sending PUBACK to owntracksVolkersiPhone (Mid: 17)
mosquitto-owntracks    | 1535622694: Sending PUBLISH to owntracksVolkersiPhone (d0, q1, r0, m65, 'owntracks/owntracks/Volkers iPhone', ... (177 bytes))
mosquitto-owntracks    | 1535622694: Received PUBACK from owntracksVolkersiPhone (Mid: 65)
mosquitto-owntracks    | 1535622701: Received PUBLISH from owntracksVolkersiPhone (d0, q1, r1, m18, 'owntracks/owntracks/Volkers iPhone', ... (178 bytes))
mosquitto-owntracks    | 1535622701: Sending PUBACK to owntracksVolkersiPhone (Mid: 18)
mosquitto-owntracks    | 1535622701: Sending PUBLISH to owntracksVolkersiPhone (d0, q1, r0, m66, 'owntracks/owntracks/Volkers iPhone', ... (178 bytes))
mosquitto-owntracks    | 1535622701: Received PUBACK from owntracksVolkersiPhone (Mid: 66)
mosquitto-owntracks    | 1535622703: Received PUBLISH from owntracksVolkersiPhone (d0, q1, r1, m19, 'owntracks/owntracks/Volkers iPhone', ... (176 bytes))
mosquitto-owntracks    | 1535622703: Sending PUBACK to owntracksVolkersiPhone (Mid: 19)
mosquitto-owntracks    | 1535622703: Sending PUBLISH to owntracksVolkersiPhone (d0, q1, r0, m67, 'owntracks/owntracks/Volkers iPhone', ... (176 bytes))
mosquitto-owntracks    | 1535622703: Received PUBACK from owntracksVolkersiPhone (Mid: 67)
mosquitto-owntracks    | 1535622705: Received PUBLISH from owntracksVolkersiPhone (d0, q1, r1, m20, 'owntracks/owntracks/Volkers iPhone', ... (178 bytes))
mosquitto-owntracks    | 1535622705: Sending PUBACK to owntracksVolkersiPhone (Mid: 20)
mosquitto-owntracks    | 1535622705: Sending PUBLISH to owntracksVolkersiPhone (d0, q1, r0, m68, 'owntracks/owntracks/Volkers iPhone', ... (178 bytes))
mosquitto-owntracks    | 1535622705: Received PUBACK from owntracksVolkersiPhone (Mid: 68)
mosquitto-owntracks    | 1535622708: Received DISCONNECT from owntracksVolkersiPhone
mosquitto-owntracks    | 1535622708: Client owntracksVolkersiPhone disconnected.
mosquitto-owntracks    | ot-recorder[35]: http: POST /pub
mosquitto-owntracks    | ot-recorder[35]: http: POST /api/0/last
mosquitto-owntracks    | 1535622715: Received PINGREQ from ot-recorder-ea901ce61be1-35
mosquitto-owntracks    | 1535622715: Sending PINGRESP to ot-recorder-ea901ce61be1-35

As of the folder has been created in the Docker volume it's still there after the restart and ocat still does not show any users.

root@asgard:/home/docker/test/mosquitto# docker-compose exec mosquitto-owntracks bash
root@ea901ce61be1:/# ocat --list
{"results":[]}

[jpmens]

1. Please set clientId with mosquitto_sub to avoid ACL denying access to client with dangerous client id
2. Until you see your phone publish a location and you see it in mosquitto_sub output, there is no need to continue. If the broker doesn't get the publish, the Recorder won't either.
3. Your username is configured to be called "owntracks" and your device "Volkers iPhone" (with a space in it); while that's ok (I hope), it is maximizing confusion, at least to me ;-)

[frootmig]

The username did not only confuse you, me too. I just understand why. A topic is owntracks because of the software, slash username (chosen like the software), slash device name. Neither

mosquitto_sub -i debug -t 'owntracks/owntracks/Volkers iPhone'

nor

mosquitto_sub -i debug -t 'owntracks/owntracks/Volkers iPhone/#'

Does return any output. If these calls are correct, the problem is Mosquitto related? At least these log output is generated, when I publish my position:

mosquitto-owntracks    | 1535625754: Sending PUBACK to owntracksVolkersiPhone (Mid: 26)
mosquitto-owntracks    | 1535625754: Sending PUBLISH to owntracksVolkersiPhone (d0, q1, r0, m74, 'owntracks/owntracks/Volkers iPhone', ... (179 bytes))
mosquitto-owntracks    | 1535625754: Received PUBACK from owntracksVolkersiPhone (Mid: 74)

[jpmens]

I think it's time for you to study a bit of our Booklet ...

Try:

mosquitto_sub -v -t '#'

[frootmig]

There is no output from

mosquitto_sub -i debug -v -t '#'

Next up: tear down Docker volume and start from scratch.

Do you recommend something special from the Booklet. I already read as far as I know all pages regarding the setup.

[frootmig]

Digging deeper into Mosquitto, I assume an ACL issue. I wrote a new ACL file:

root@ea901ce61be1:/# cat /owntracks/mosquitto/mosquitto.acl 
# This affects access control for clients with no username.
topic read $SYS/#

user voja
topic readwrite owntracks/voja/#

user ot-recorder
topic read owntracks/#

Is it possible that the default ACL file would not allow Recorder access? I have changed the ot-recorder config in /etc/default/ot-recorder, too and added OTR_USER:

OTR_STORAGEDIR = "/owntracks/recorder/store"
OTR_TOPICS = "owntracks/#"
OTR_USER="ot-recorder"

I restarted the Docker container and I get a not expected OTR_USER in the logs:

mosquitto-owntracks    | 1535628742: Received PINGREQ from ot-recorder-ea901ce61be1-32
mosquitto-owntracks    | 1535628742: Sending PINGRESP to ot-recorder-ea901ce61be1-32

Ist the OTR_USER ot-recorder-ea901ce61be1-32 in this case?

[frootmig]

This works:

root@ea901ce61be1:/# mosquitto_sub -i debug -u voja -P *** -v -t '#'

Output as soon as I publish my position.

So it's a problem with the ACL file and/or Recorder using the wrong user?

[frootmig]

Got it. Updated /etc/default/ot-recorder in the volume:

OTR_STORAGEDIR = "/owntracks/recorder/store"
OTR_TOPICS = "owntracks/#"
OTR_USER = "recorder"
OTR_PASS = "***"

When using this ACL file /owntracks/mosquitto/mosquitto.acl:

# This affects access control for clients with no username.
topic read $SYS/#

user voja
topic readwrite owntracks/voja/#

user recorder
topic read owntracks/#

Plus /owntracks/mosquitto/mosquitto.conf activated the password file:

password_file /owntracks/mosquitto/mosquitto.passwd

And created two accounts, one for the recorder and one for the iPhone.

ocat --list runs without error, too:

{"results":["voja"]}

I am now just seeing OVER_QUERY_LIMIT errors. Will check if there is something in the Booklet, too.

[jpmens]

OVER_QUERY_LIMIT indicates Google reverse-geocoding doesn't want to see you any more; you'll need an appropriate key. I suggest switching to OpenCage and OSM, and this is described in the Recorder README.

[frootmig]

Is it correct, that the Docker container does not support OpenCage? At least I was not able to find the LUA file in the image. The Recorder maps are already OSM, so no need to change that. :-)

Would it be useful to add additonal setup instructions to the Docker image? E.g. an extended ACL file, instructions how to setup passwords and how to activate OpenCage (and perhaps add the LUA scripts per default?)
Found an issue that the container might need work: owntracks/docker-recorder#13
But I don't know how you feel about splitting the services into two container images.

Finally I need to say, that I was able to track my way home today and I liked it to see it in Recorder. :-)

[jpmens]

The docker image is indeed slightly older, and yes: documentation improvements are always welcome. The issue you reference is probably the place to start.

[frootmig]

Are there any guidelines how to contribute? I'd fork the project, make a doc and a dev branch and then try to improve. Then PR and hope to get reviewed?

[frootmig]

Okay, there is a lua versioning problem. The Docker container uses lua 5.2. The luarocks call installs something, that needs to be fixed for 5.2 usage as mentioned here: mpx/lua-cjson#54
I might be able to find out more later.

[jpmens]

This is no longer the place to discuss this. Please take it to the recorderd repository.