Mosquitto container log volume permission issue

[Habilya]

Hello, I've just discovered an issue with the Mosquitto container's log volume issue

My Raspberry Pi 3 Docker was installed through the docker sh installer script provided from Docker. It runs under root user on my Raspberry Pi, which is probably not a good thing... but will have to do for now.

So, the issue is with the mosquitto container as it cannot start properly. with this logged error

1575308247: Error: Unable to open log file /mosquitto/log/mosquitto.log for writing.

I've done quick checkups ls -la the volumes, it's owned by root:root

Then, I've checked the service.yml cat services/mosquitto/service.yml

  mosquitto:
    container_name: mosquitto
    image: eclipse-mosquitto
    restart: unless-stopped
    user: "1883"
    ports:
      - 1883:1883
      - 9001:9001
    volumes:
      - ./volumes/mosquitto/data:/mosquitto/data
      - ./volumes/mosquitto/log:/mosquitto/log
      - ./services/mosquitto/mosquitto.conf:/mosquitto/config/mosquitto.conf

This line caught my attention user: "1883"

Therefore, "dirty fixed" it using such commands

sudo touch volumes/mosquitto/log/mosquitto.log
sudo chmod o+w volumes/mosquitto/log/mosquitto.log
sudo chown 1883:1883 volumes/mosquitto/log -R

and restarted the container.

Please advise?

[Paraphraser]

Do you think the problem you are reporting might have the same underlying cause as #91?

I agree that the symptoms are slightly different because I'm not getting the "Unable to open log" message. I'm getting heaps of entries in the log but I can only view it from inside the container. It's the mapping to outside the container that seems to be broken.

I did my installation on November 10. Since then I've just been doing "git pull" and re-running the menu when that seems appropriate. When did you install yours? The reason I ask is to try to figure out whether the "Unable to open log" is more likely to be a fundamental RPi3 (you) vs RPi4 (me) issue, or the different way Docker was installed (you from Docker, me from IOTstack), or might be explained by a change made to the IOTstack installation process that occurred between our respective installation dates?

I definitely agree that the "user 1883" thing is weird. I'm about to add some more to the end of #91 because:

...Running directoryfix.sh on mosquitto

does not seem to have done anything.

[gcgarner]

Hi all The older template used to run under user: "0" and I changed it to user: "1883" The user 0 was a workaround so i didn't need to set the directory permissions. However as reported to me by @Paraphraser the it wasn't working.

I added a new template with user 1883 (this is actually the user that is set by default in the container so I didn't need to set it, it could have just been removed.

In addition I had to add the directoryfix.sh to make sure that the permissions were correct for both new and old template. It would appear that it wasn't working as intended

Phil as mentioned in #91 the log that you showed says found user 0 so i can only deduce that you didn't update to the new template. Could you confirm.

I think i know what the issue may be. In the code where i check for user 1883 i don't create the data and log directory and i think therefore when docker creates it then it creates it with root ownership.

I will test it again and report back

[gcgarner]

This are my results:

$ ./menu.sh
~/IOTstack ~/IOTstack
checking for project update
From github.com:gcgarner/IOTstack
 * branch            master     -> FETCH_HEAD
Project is up to date
Adding portainer container
...portainer service not overwritten
Adding nodered container
...nodered service not overwritten
Adding influxdb container
...influxdb service not overwritten
Adding grafana container
...grafana service not overwritten
Adding mosquitto container
...mosquitto service not overwritten
...Running directoryfix.sh on mosquitto
...found user 1883

$ ls -al volumes/
total 92
drwxr-xr-x+ 23 root root 4096 Dec  3 11:45 .
drwxr-xr-x  10 pi   pi   4096 Dec  2 23:00 ..
drwxr-xr-x+  3 root root 4096 Nov 26 13:52 blynk-server
drwxr-xr-x+  2 root root 4096 Nov 28 16:35 diyhue
drwxr-xr-x+  4 root root 4096 Nov 28 12:15 gitea
drwxr-xr-x+  4 root root 4096 Nov  9 08:31 grafana
drwxr-xr-x+  3 root root 4096 Nov  9 08:31 influxdb
drwxr-xr-x+  3 root root 4096 Nov 29 15:37 mariadb
drwxrwxr-x+  2 1883 1883 4096 Dec  3 11:45 mosquitto

after docker-compose up -d (docker creates the data and log and root ... obviously because the s flag isn't set on the folder):

$ ls -al volumes/mosquitto
total 16
drwxrwxr-x+  4 1883 1883 4096 Dec  3 11:48 .
drwxr-xr-x+ 23 root root 4096 Dec  3 11:45 ..
drwxr-xr-x+  2 root root 4096 Dec  3 11:48 data
drwxr-xr-x+  2 root root 4096 Dec  3 11:48 log

rebuild the stack using the menu ...

$ ls -al volumes/mosquitto
total 16
drwxrwxr-x+  4 1883 1883 4096 Dec  3 11:48 .
drwxr-xr-x+ 23 root root 4096 Dec  3 11:45 ..
drwxr-xr-x+  2 1883 1883 4096 Dec  3 11:48 data
drwxr-xr-x+  2 1883 1883 4096 Dec  3 11:48 log

modified directoryfix.sh to create the data and log volumes.

#check user 1883
if [ $(grep -c 'user: \"1883\"' ./services/mosquitto/service.yml) -eq 1 ]; then
        echo "...found user 1883"
        sudo mkdir -p ./volumes/mosquitto/data/
        sudo mkdir -p ./volumes/mosquitto/log/
        sudo chown -R 1883:1883 ./volumes/mosquitto/
fi

docker-compose stop mosquitto
sudo rm -r volumes/mosquitto

rerun menu to build stack

$ ls -al volumes/mosquitto
total 16
drwxrwxr-x+  4 1883 1883 4096 Dec  3 11:55 .
drwxr-xr-x+ 23 root root 4096 Dec  3 11:55 ..
drwxrwxr-x+  2 1883 1883 4096 Dec  3 11:55 data
drwxrwxr-x+  2 1883 1883 4096 Dec  3 11:55 log

$ docker-compose up -d
nodered is up-to-date
Starting mosquitto ... 
influxdb is up-to-date
grafana is up-to-date
adminer is up-to-date
postgres is up-to-date
mariadb is up-to-date
pihole is up-to-date
nextcloud_db is up-to-date
portainer is up-to-date
Starting mosquitto ... done
$ ls -al volumes/mosquitto
total 16
drwxrwxr-x+  4 1883 1883 4096 Dec  3 11:55 .
drwxr-xr-x+ 23 root root 4096 Dec  3 11:55 ..
drwxrwxr-x+  2 1883 1883 4096 Dec  3 11:55 data
drwxrwxr-x+  2 1883 1883 4096 Dec  3 11:56 log

looks like that fixed it properly now. going to figure out how to install the ACL package and i will push a fix for it

[gcgarner]

I pushed the update, I just disabled the setfacl for now, its not critical now

[Paraphraser]

The first few times I did an update, I chose overwrite but it didn't seem to do anything (no differences in a compare of a saved-by-me copy of the yaml file with the one generated by running the menu, and nothing other than nothing-to-see-here results for each container) so I started to use the default of no overwrite.

Also, it isn't really clear what the three options do. I can surmise what they do but that's slightly different from knowing and, from that, being able to assess the risk of something going wrong and, say, the prudence of taking a backup immediately before doing anything.

This is another way of saying that an explanation of what the options do and when it is appropriate to use each one might be a useful addition to the wiki. Yes/no?

Anyway, I've just done a git pull and a menu run overwriting everything. This was the result:

$ docker-compose up -d
influxdb is up-to-date
Recreating nodered ... 
portainer is up-to-date
Recreating mosquitto ... 
grafana is up-to-date
Recreating pihole    ... 
WARNING: Service "mosquitto" is using volume "/mosquitto/data" from the previous container. Host mapping "/home/pi/IOTstack/volumes/mosquitto/data" has no effect. Remove the existing containers (with `docker-compose rm mosquitto`) to use Recreating nodered   ... done
Recreating mosquitto ... done
Recreating pihole    ... done

I wasn't sure whether to interpret that WARNING as an instruction or if it was advising me that the action had already been taken. I'm presuming the former but I'd like some guidance please. Is it as simple as "docker-compose rm mosquitto" followed by another "docker-compose up -d" or is there more to it?

Also, doesn't removal imply that the accumulated mosquitto log (which only exists inside the container) will be lost? Not that I care if it is lost - I just want to confirm my understanding.

For the record, the outside vs inside view of the mosquitto container is now:

$ ls -alR ~/IOTstack/volumes/mosquitto
/home/pi/IOTstack/volumes/mosquitto:
total 20
drwxr-xr-x+ 5 1883 1883 4096 Nov 24 19:16 .
drwxr-xr-x+ 8 root root 4096 Nov 11 11:18 ..
drwxr-xr-x+ 2 1883 1883 4096 Nov 10 21:30 config
drwxr-xr-x+ 2 1883 1883 4096 Nov 10 21:30 data
drwxr-xr-x+ 2 1883 1883 4096 Nov 10 21:30 log

/home/pi/IOTstack/volumes/mosquitto/config:
total 8
drwxr-xr-x+ 2 1883 1883 4096 Nov 10 21:30 .
drwxr-xr-x+ 5 1883 1883 4096 Nov 24 19:16 ..
-rwxr-xr-x  1 1883 1883    0 Nov 10 21:30 mosquitto.conf

/home/pi/IOTstack/volumes/mosquitto/data:
total 8
drwxr-xr-x+ 2 1883 1883 4096 Nov 10 21:30 .
drwxr-xr-x+ 5 1883 1883 4096 Nov 24 19:16 ..

/home/pi/IOTstack/volumes/mosquitto/log:
total 8
drwxr-xr-x+ 2 1883 1883 4096 Nov 10 21:30 .
drwxr-xr-x+ 5 1883 1883 4096 Nov 24 19:16 ..

There was also one unexpected behavioural difference inside the container:

$ docker exec -it mosquitto sh
$ ls -alR /mosquitto/
/mosquitto/:
total 20
drwxr-xr-x    5 mosquitt mosquitt      4096 Nov  7 01:49 .
drwxr-xr-x    1 root     root          4096 Dec  3 13:01 ..
drwxr-xr-x    2 mosquitt mosquitt      4096 Nov  7 01:49 config
drwxr-xr-x    2 mosquitt mosquitt      4096 Dec  3 13:01 data
drwxr-xr-x    2 mosquitt mosquitt      4096 Nov 12 12:16 log

/mosquitto/config:
total 12
drwxr-xr-x    2 mosquitt mosquitt      4096 Nov  7 01:49 .
drwxr-xr-x    5 mosquitt mosquitt      4096 Nov  7 01:49 ..
-rw-r--r--    1 1000     1000           138 Nov 10 10:12 mosquitto.conf

/mosquitto/data:
total 12
drwxr-xr-x    2 mosquitt mosquitt      4096 Dec  3 13:01 .
drwxr-xr-x    5 mosquitt mosquitt      4096 Nov  7 01:49 ..
-rw-------    1 mosquitt mosquitt        47 Dec  3 13:01 mosquitto.db

/mosquitto/log:
total 1248
drwxr-xr-x    2 mosquitt mosquitt      4096 Nov 12 12:16 .
drwxr-xr-x    5 mosquitt mosquitt      4096 Nov  7 01:49 ..
-rw-------    1 mosquitt mosquitt   1264856 Dec  3 13:06 mosquitto.log
$ 

A "$" prompt inside the container, rather than a "#". Expected?

[gcgarner]

Hello Phil, Sorry for the delay. I've been very busy for the last few days

The warning: WARNING: Service "mosquitto" is using volume "/mosquitto/data" from the previous container

is issued if you change the volume mapping and run docker-compose up -d without removing the container. The lazy method is docker-compose down to remove all containers. Your assessment of docker-compose rm mosquitto is correct. That is the method to remove a single container without removing the entire stack.

Unfortunately the because I messed up the volumes in the first place fixing the volumes will wipe whatever you had accumulated to date. What docker was doing in the background was preserving a separate set of internal volumes for mosquitto, this is defined in their Dockerfile.

The difference you see with the Raspbian user "1883" and container user "mosquitt" is as follows: The container has a user called mosquitt with an ID of 1883. What i could have done was create a user/group called "mosquitt" (i think its actually mosquitto and it displays a shorter version) with and ID of 1883 and did the chown of mosquitt instead of 1883:1883 that would have made the ls from rasbian and inside the container look the same.

RE:

A "$" prompt inside the container, rather than a "#". Expected?

yes this is. Mosquitto originally was running as user 0 (root) and therefor got a # shell, now that the user ID is no longer 0 it gets a user $ shell

---

Side note: If you look at nodered and grafana, I also had to specify the user 0 setting. if you were to omit the user 0 and unbind the volumes and use docker volumes then via the terminal you will see a $ shell with users node-red and grafana's user. There ID are something like 5## and 873 i think. I would need to make a Directoryfix.sh for each container that doenst run as root.

I believe that not running as root is the correct way to go for security reasons. However many stock containers will continue to run as root

[Paraphraser]

I had been focusing on something else and only just came back to this. Sorry for the delay.

To summarise:

• I applied the last update (five days ago).
• I followed-up by blowing away and recreating the mosquitto container, as instructed.
• The log now appears outside the container. 😎
• The config is still a problem. 🤬

The gory detail

I performed the steps you prescribed:

$ cd ~/IOTstack

$ docker-compose stop mosquitto

Stopping mosquitto ... done

$ docker-compose rm mosquitto

Going to remove mosquitto
Are you sure? [yN] y
Removing mosquitto ... done

$ docker-compose up -d

nodered is up-to-date
portainer is up-to-date
Creating mosquitto ... 
grafana is up-to-date
influxdb is up-to-date
Creating mosquitto ... done

The story outside the container:

$ ls -alR ~/IOTstack/volumes/mosquitto/
/home/pi/IOTstack/volumes/mosquitto/:
total 20
drwxr-xr-x+ 5 1883 1883 4096 Nov 24 19:16 .
drwxr-xr-x+ 8 root root 4096 Nov 11 11:18 ..
drwxr-xr-x+ 2 1883 1883 4096 Nov 10 21:30 config
drwxr-xr-x+ 2 1883 1883 4096 Nov 10 21:30 data
drwxr-xr-x+ 2 1883 1883 4096 Dec  8 10:24 log

/home/pi/IOTstack/volumes/mosquitto/config:
total 8
drwxr-xr-x+ 2 1883 1883 4096 Nov 10 21:30 .
drwxr-xr-x+ 5 1883 1883 4096 Nov 24 19:16 ..
-rwxr-xr-x  1 1883 1883    0 Nov 10 21:30 mosquitto.conf

/home/pi/IOTstack/volumes/mosquitto/data:
total 8
drwxr-xr-x+ 2 1883 1883 4096 Nov 10 21:30 .
drwxr-xr-x+ 5 1883 1883 4096 Nov 24 19:16 ..

/home/pi/IOTstack/volumes/mosquitto/log:
total 12
drwxr-xr-x+ 2 1883 1883 4096 Dec  8 10:24 .
drwxr-xr-x+ 5 1883 1883 4096 Nov 24 19:16 ..
-rw-rw-r--+ 1 1883 1883 2527 Dec  8 10:43 mosquitto.log

There's good news and bad news:

• mosquitto.conf is where it has always been (good) but it is still zero length (bad)
• no sign of mosquitto.db (can't decide good or bad)
• mosquitto.log has appeared (good)

Confirm the "empty" state of mosquitto.conf when viewed from outside the container:

$ cat ~/IOTstack/volumes/mosquitto/config/mosquitto.conf 
$

Confirm we can read the log from outside the container:

$ tail ~/IOTstack/volumes/mosquitto/log/mosquitto.log 
1575761537: New connection from 192.168.132.196 on port 1883.
1575761537: New client connected from 192.168.132.196 as SolarRelay (p2, c1, k10).
1575761542: Client SolarRelay disconnected.
1575761837: New connection from 192.168.132.196 on port 1883.
1575761837: New client connected from 192.168.132.196 as SolarRelay (p2, c1, k10).
1575761842: Client SolarRelay disconnected.
1575762137: New connection from 192.168.132.196 on port 1883.
1575762137: New client connected from 192.168.132.196 as SolarRelay (p2, c1, k10).
1575762142: Client SolarRelay disconnected.
1575762181: New connection from 192.168.132.194 on port 1883.

Yes - but the timestamps have reverted to epoch numbers. That'll have to be fixed. Again.

I'm going to open a separate issue about this.

Let's peek inside the container.

$ docker exec -it mosquitto sh

$ ls -alR mosquitto/
mosquitto/:
total 20
drwxr-xr-x    5 mosquitt mosquitt      4096 Nov  7 01:49 .
drwxr-xr-x    1 root     root          4096 Dec  7 23:24 ..
drwxr-xr-x    2 mosquitt mosquitt      4096 Nov  7 01:49 config
drwxr-xr-x    2 mosquitt mosquitt      4096 Nov 10 10:30 data
drwxr-xr-x    2 mosquitt mosquitt      4096 Dec  7 23:24 log

mosquitto/config:
total 12
drwxr-xr-x    2 mosquitt mosquitt      4096 Nov  7 01:49 .
drwxr-xr-x    5 mosquitt mosquitt      4096 Nov  7 01:49 ..
-rw-r--r--    1 1000     1000           138 Nov 10 10:12 mosquitto.conf

mosquitto/data:
total 8
drwxr-xr-x    2 mosquitt mosquitt      4096 Nov 10 10:30 .
drwxr-xr-x    5 mosquitt mosquitt      4096 Nov  7 01:49 ..

mosquitto/log:
total 12
drwxr-xr-x    2 mosquitt mosquitt      4096 Dec  7 23:24 .
drwxr-xr-x    5 mosquitt mosquitt      4096 Nov  7 01:49 ..
-rw-rw-r--    1 mosquitt mosquitt      2849 Dec  7 23:47 mosquitto.log

Same pattern as outside save that, as expected, mosquitto.conf has non-zero length. This also answers the "where's mosquitto.db" question. Ain't there yet.

Verify mosquitto.conf can be read inside the container:

$ cat mosquitto/config/mosquitto.conf 
persistence true
persistence_location /mosquitto/data/
log_dest file /mosquitto/log/mosquitto.log
#password_file /mosquitto/config/pwfile

Yes. Ditto for the log:

$ tail mosquitto/log/mosquitto.log 
1575761842: Client SolarRelay disconnected.
1575762137: New connection from 192.168.132.196 on port 1883.
1575762137: New client connected from 192.168.132.196 as SolarRelay (p2, c1, k10).
1575762142: Client SolarRelay disconnected.
1575762181: New connection from 192.168.132.194 on port 1883.
1575762181: New client connected from 192.168.132.194 as LoRaGateway (p2, c1, k10).
1575762181: Client LoRaGateway disconnected.
1575762437: New connection from 192.168.132.196 on port 1883.
1575762437: New client connected from 192.168.132.196 as SolarRelay (p2, c1, k10).
1575762442: Client SolarRelay disconnected.

Let's fix the log timestamp.

$ echo "log_timestamp_format %Y-%m-%dT%H:%M:%S" >>~/IOTstack/services/mosquitto/mosquitto.conf
$ docker restart mosquitto

The log entries across the transition are instructive. Being terminated causes mosquitto.db to come into being.

1575762657: mosquitto version 1.6.7 terminating
1575762657: Saving in-memory database to /mosquitto/data/mosquitto.db.
2019-12-07T23:51:00: mosquitto version 1.6.7 starting
2019-12-07T23:51:00: Config loaded from /mosquitto/config/mosquitto.conf.
2019-12-07T23:51:00: Opening ipv4 listen socket on port 1883.

Let's look at the situation from outside the container again:

$ ls -alR ~/IOTstack/volumes/mosquitto/
/home/pi/IOTstack/volumes/mosquitto/:
total 20
drwxr-xr-x+ 5 1883 1883 4096 Nov 24 19:16 .
drwxr-xr-x+ 8 root root 4096 Nov 11 11:18 ..
drwxr-xr-x+ 2 1883 1883 4096 Nov 10 21:30 config
drwxr-xr-x+ 2 1883 1883 4096 Dec  8 10:50 data
drwxr-xr-x+ 2 1883 1883 4096 Dec  8 10:24 log

/home/pi/IOTstack/volumes/mosquitto/config:
total 8
drwxr-xr-x+ 2 1883 1883 4096 Nov 10 21:30 .
drwxr-xr-x+ 5 1883 1883 4096 Nov 24 19:16 ..
-rwxr-xr-x  1 1883 1883    0 Nov 10 21:30 mosquitto.conf

/home/pi/IOTstack/volumes/mosquitto/data:
total 12
drwxr-xr-x+ 2 1883 1883 4096 Dec  8 10:50 .
drwxr-xr-x+ 5 1883 1883 4096 Nov 24 19:16 ..
-rw-rw-r--+ 1 1883 1883   47 Dec  8 10:50 mosquitto.db

/home/pi/IOTstack/volumes/mosquitto/log:
total 12
drwxr-xr-x+ 2 1883 1883 4096 Dec  8 10:24 .
drwxr-xr-x+ 5 1883 1883 4096 Nov 24 19:16 ..
-rw-rw-r--+ 1 1883 1883 3947 Dec  8 10:51 mosquitto.log

Can now see mosquitto.db (as expected). Both mosquitto.db and mosquitto.log have non-zero length.

But that damnably pesky zero-length mosquitto.conf is still a problem.

Bottom line: close but we're still not quite into cigar-lighting territory.

Again, I wonder about mosquitto.conf appearing in three places:

• outside: ~/IOTstack/services/mosquitto/mosquitto.conf
• outside: ~/IOTstack/volumes/mosquitto/config/mosquitto.conf
• inside: /mosquitto/config/mosquitto.conf

Portainer seems confused by this too:

The first line is mapping a file to a file. The next two lines are mapping directories to directories, but only "log" and "data". There is no mention of the "config" directory being mapped.

Speaking of Portainer...

In #91, my starting point for this journey was "Portainer > Containers > mosquitto > Logs" saying "No logs available". Even now that the log is showing up both inside and outside the container, Portainer still has no idea.

This makes mosquitto the odd container out when it comes to its log appearing in Portainer's UI.

[gcgarner]

Hi Phil

The /volumes/mosquitto/config was an artefact of how my original mapping. Because you had the old volume (where the user was 0) it had the effect of creating a garbage config folder. This folder can now be discarded. The new tree would look like this:

$ tree volumes/mosquitto
volumes/mosquitto
├── data
│   └── mosquitto.db
└── log
    └── mosquitto.log

2 directories, 2 files

looking at the yml file

    volumes:
      - ./volumes/mosquitto/data:/mosquitto/data
      - ./volumes/mosquitto/log:/mosquitto/log
      - ./services/mosquitto/mosquitto.conf:/mosquitto/config/mosquitto.conf

the conf file is now statically linked to the service directory as it should be and will no longer appear in the config folder.

I don't know why your mosquitto.db wasnt created, that seems a little odd to me.

Portainer logs: Unfortunately the log that portainer refers to is the Docker log for mosquitto not the same log as mosquitto.log That is in fact calling the command docker logs mosquitto. For what ever reason the creators of the container chose not to echo out the same information to the docker log as they did the mosquitto log

I like you addition of the time format for the logs, I'll add it to the default template

[Paraphraser]

Ahah! Stop mosquitto (to be on the safe side), remove the external config folder, start mosquitto.

All fine. All weirdness gone. Everything now working as it should be. Thanks.

As to mosquitto.db, that seems to only get created when mosquitto stops. I’m guessing that, if I did a clean install (ie no .db) then left it long enough, it might eventually decide to save the in-memory database to permanent storage but a stop/start definitely forces its hand.

[vlory73]

@gcgarner, would reinstating user 0 (instead of user 1883) be a solution? I'm having some trouble understanding the full write-up in the issue. I've just installed IOTstack and am having the same issue.