local jwt backend - Not authorized with no debug messages

[DeveloperMarius]

Hello,

first of all thank you for this plugin!

I'm trying to run a docker container with mosquitto and jwt auth, but my MQTT Explorer and clients print that the "connection was refused: Not authorized" or "The configured broker responded with unauthorized.".

My setup is the following:

docker-compose:

version: '1'

services:
  mqtt:
    image: iegomez/mosquitto-go-auth
    volumes:
      - ${path}/mqtt/config/:/etc/mosquitto/
      - ${path}/development-environment/mqtt-logs:/mosquitto/log/
    networks:
      - internal
    ports:
      - 1883:1883
      - 9001:9001
    expose:
      - 1883
      - 9001
    restart: on-failure

mosquitto.conf:

listener 1883
protocol mqtt

listener 9001
protocol websockets

log_dest file /mosquitto/log/mosquitto.log

allow_anonymous false

auth_plugin /mosquitto/go-auth.so

auth_opt_hasher pbkdf2
auth_opt_backends jwt

auth_opt_jwt_mode local
auth_opt_jwt_db mysql
auth_opt_jwt_userfield Username
auth_opt_jwt_userquery SELECT COUNT(*) FROM (SELECT `email` AS `username` FROM `table1` UNION SELECT `name` AS `username` FROM `table2`) AS `users` WHERE `username` = ? LIMIT 1
auth_opt_jwt_secret KR#t:K!m@HGC=[6^CbS`P~C8Q(EP.?

auth_opt_jwt_mysql_host ***
auth_opt_jwt_mysql_port 3306
auth_opt_jwt_mysql_user ***
auth_opt_jwt_mysql_password ***
auth_opt_jwt_mysql_dbname ***

auth_opt_cache true
auth_opt_cache_reset true
auth_opt_cache_refresh true

auth_opt_auth_cache_seconds 30
auth_opt_acl_cache_seconds 30
auth_opt_auth_jitter_seconds 3
auth_opt_acl_jitter_seconds 3

auth_opt_log_level debug
auth_opt_log_dest file
auth_opt_log_file /mosquitto/log/mosquitto_backend.log

The setup works fine when I use the backend "files" but with "jwt" not. Using "files" the backend prints information about the login requests but the jwt backend does not.

When I start the container and log in I get the following:

mosquitto.log

1678661990: mosquitto version 2.0.15 starting
1678661990: Config loaded from /etc/mosquitto/mosquitto.conf.
1678661990: Loading plugin: /mosquitto/go-auth.so
1678661990:  ├── Username/password checking enabled.
1678661990:  ├── TLS-PSK checking enabled.
1678661990:  └── Extended authentication not enabled.
1678661990: Opening ipv4 listen socket on port 1883.
1678661990: Opening ipv6 listen socket on port 1883.
1678661990: Opening websockets listen socket on port 9001.
1678661990: mosquitto version 2.0.15 running
1678662143: Client mqtt-explorer-3c5b5d0c closed its connection.

mosquitto_backend.log

time="2023-03-12T22:59:50Z" level=info msg="Backend registered: JWT"
time="2023-03-12T22:59:50Z" level=info msg="registered acl checker: jwt"
time="2023-03-12T22:59:50Z" level=info msg="registered user checker: jwt"
time="2023-03-12T22:59:50Z" level=info msg="registered superuser checker: jwt"
time="2023-03-12T22:59:50Z" level=info msg="redisCache activated"
time="2023-03-12T22:59:50Z" level=info msg="started go-cache"
time="2023-03-12T22:59:50Z" level=info msg="flushed go-cache"

Like I sayed, not debug message in the backend log. My username is eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJVc2VybmFtZSI6ImVtYWlsQGRvbWFpbi5kZSJ9.NN_kGx9wmDaTwdjjo2TJ6JZtwdK8xoN16B2JfMjlAXI and my password any. jwt.io prints valid using the secret KR#t:K!m@HGC=[6^CbS`P~C8Q(EP.?.

I really don't know why the mosquitto log prints the logout but the backend nothing about the login. I hope you can help me and thank you in advance.

~ Marius

[DeveloperMarius]

It seems that when I change the jwt_secret to aaaaaaaaaaasddddddddddfffff I additionally get the following messages in the backend log:

time="2023-03-12T23:17:50Z" level=debug msg="checking auth cache for eyJ0eXAiO***************2FzdHJvdmlhLmRlIn0.Q30NGKwgucFDv-EQ*************L4bDOAM"
time="2023-03-12T23:17:50Z" level=debug msg="to auth record: [97 117 116 104 45 101 121 74 48 101 88 65 105 79 105 74 75 86 49 81 105 76 67 74 104 98 71 9********* 55 98 70 55 54 77 57 65 97 101 110 87 119 50 98 67 76 52 98 68 79 65 77 45 97 110 121 218 57 163 238 94 107 75 13 50 85 191 23*** 216 7 9]\n"
time="2023-03-12T23:17:50Z" level=debug msg="checking user eyJ0eXAiOiJKV1QiLCJhbGciO*****LmRlIn0.Q30NGKwgucFDv-EQL*********Ww2bCL4bDOAM with backend JWT"
time="2023-03-12T23:17:50Z" level=debug msg="setting auth cache for eyJ0eXAiO**********nRlY2huaWtAZ2FzdHJvdmlhLmRlIn0.Q30NGKwgucFD**********bDOAM"
time="2023-03-12T23:17:50Z" level=debug msg="to auth record: [97 117 116 104 45 101 121 74 48 101 88 65 105 79 105 74 75 86 49 81 105 76 67 74 104 98 71 99 105 79 105 74 73 *****************2 55 98 70 55 54 77 57 65 97 101 110 87 119 50 98 67 76 52 98 68 79 65 77 45 97 110 121 218 57 163 238 94 107 75 13 50 8*** 175 216 7 9]\n"

It looks like it was checking for an actual user with the jwt as the username. But I'm just clueless here^^

~ Marius

[DeveloperMarius]

Update: It seems that when I use a insert query as auth_opt_jwt_userquery the ? parameter is an empty string. Will take a deeper look at this. ~ Marius

[DeveloperMarius]

Fixed it,

after I looked at the code in https://github.com/iegomez/mosquitto-go-auth/blob/9e9d90b676c97ec069bd39d96fa2235269f83932/backends/jwt.go#L66 I found out that when I define auth_opt_jwt_userfield as Username with a capital letter it will use the jwt key username with a lower case start.

Still thank you for this plugin!

~ Marius