Hi, @RogerioCassares.
Sorry for the late reply, I just got back. I’m currently quite busy with some urgent stuff at work, so please give me a couple of days to take a look at this. For now, I just pushed some changes so that Postgres’ initialization and user, superuser and acl checks get logged with some more information.
Hello @iegomez!
The error happenned again at 6.25 am! Please check the logs when i ran mannualy the plugin! This log is just a part of debug window.
DEBU[142353] Superuser check with backend Postgres
DEBU[142353] Checking Postgres for superuser with username loragw
DEBU[142353] PG get superuser error: pq: invalid byte sequence for encoding "UTF8": 0xee 0xb7 0x30
DEBU[142353] Acl check with backend Files
INFO[142353] Files acl check with user loragw, topic: gateway/7276ff00080801db/rx, clientid: 74834c45-cd91-4913-b436-44f12e88e3a8 and acc: 2
INFO[142353] Files acl check passed.
DEBU[142353] user loragw acl authenticated with backend Files
DEBU[142353] setting acl cache (granted = true) for loragw
DEBU[142353] Acl is %!s(bool=true) for user loragw
DEBU[142353] checking acl cache for loraserver
DEBU[142353] Superuser check with backend Files
DEBU[142353] Superuser check with backend Postgres
DEBU[142353] Checking Postgres for superuser with username loraserver
DEBU[142353] PG get superuser error: pq: invalid byte sequence for encoding "UTF8": 0xee 0xb7 0x30
DEBU[142353] Acl check with backend Files
INFO[142353] Files acl check with user loraserver, topic: gateway/7276ff00080801db/rx, clientid: cf03d60d-11be-4fe2-86ba-97e6790c4be4 and acc: 1
INFO[142353] Files acl check passed.
DEBU[142353] user loraserver acl authenticated with backend Files
DEBU[142353] setting acl cache (granted = true) for loraserver
DEBU[142353] Acl is %!s(bool=true) for user loraserver
DEBU[142354] checking acl cache for loraappserver
DEBU[142354] Superuser check with backend Files
DEBU[142354] Superuser check with backend Postgres
DEBU[142354] Checking Postgres for superuser with username loraappserver
DEBU[142354] PG get superuser error: pq: invalid byte sequence for encoding "UTF8": 0xee 0xb7 0x30
DEBU[142354] Acl check with backend Files
INFO[142354] Files acl check with user loraappserver, topic: application/1/node/0004a30b001e8b8e/rx, clientid: 65fcb67e-8077-46c3-812c-368a585cde71 and acc: 2
INFO[142354] Files acl check passed.
DEBU[142354] user loraappserver acl authenticated with backend Files
DEBU[142354] setting acl cache (granted = true) for loraappserver
DEBU[142354] Acl is %!s(bool=true) for user loraappserver
DEBU[142354] checking acl cache for CPDET
DEBU[142354] Superuser check with backend Files
DEBU[142354] Superuser check with backend Postgres
DEBU[142354] Checking Postgres for superuser with username CPDET
DEBU[142354] PG get superuser error: pq: invalid byte sequence for encoding "UTF8": 0xee 0xb7 0x30
DEBU[142354] Acl check with backend Files
INFO[142354] Files acl check with user CPDET, topic: application/1/node/0004a30b001e8b8e/rx, clientid: mqtt_7c10e46a.fc20ac and acc: 1
WARN[142354] Files acl check failed.
DEBU[142354] Acl check with backend Postgres
DEBU[142354] Checking Postgres for ACL for username CPDET, clientid mqtt_7c10e46a.fc20ac, topic application/1/node/0004a30b001e8b8e/rx and access 1
DEBU[142354] PG check acl error: pq: invalid message format
DEBU[142354] setting acl cache (granted = false) for CPDET
DEBU[142354] Acl is %!s(bool=false) for user CPDET
DEBU[142367] checking auth cache for det
DEBU[142367] found in cache: det
DEBU[142377] checking acl cache for loragw
DEBU[142377] Superuser check with backend Files
DEBU[142377] Superuser check with backend Postgres
DEBU[142377] Checking Postgres for superuser with username loragw
DEBU[142377] PG get superuser error: pq: invalid byte sequence for encoding "UTF8": 0xee 0xb7 0x30
DEBU[142377] Acl check with backend Files
INFO[142377] Files acl check with user loragw, topic: gateway/7276ff00080801db/stats, clientid: 74834c45-cd91-4913-b436-44f12e88e3a8 and acc: 2
INFO[142377] Files acl check passed.
DEBU[142377] user loragw acl authenticated with backend Files
DEBU[142377] setting acl cache (granted = true) for loragw
DEBU[142377] Acl is %!s(bool=true) for user loragw
DEBU[142377] checking acl cache for loraserver
DEBU[142377] found in cache: loraserver
DEBU[142387] checking auth cache for det
DEBU[142387] found in cache: det
DEBU[142404] checking acl cache for loragw
DEBU[142404] Superuser check with backend Files
DEBU[142404] Superuser check with backend Postgres
DEBU[142404] Checking Postgres for superuser with username loragw
DEBU[142404] PG get superuser error: pq: invalid byte sequence for encoding "UTF8": 0xee 0xb7 0x30
DEBU[142404] Acl check with backend Files
INFO[142404] Files acl check with user loragw, topic: gateway/7276ff00080801db/rx, clientid: 74834c45-cd91-4913-b436-44f12e88e3a8 and acc: 2
INFO[142404] Files acl check passed.
DEBU[142404] user loragw acl authenticated with backend Files
DEBU[142404] setting acl cache (granted = true) for loragw
DEBU[142404] Acl is %!s(bool=true) for user loragw
DEBU[142404] checking acl cache for loraserver
DEBU[142404] Superuser check with backend Files
DEBU[142404] Superuser check with backend Postgres
DEBU[142404] Checking Postgres for superuser with username loraserver
DEBU[142404] PG get superuser error: pq: invalid byte sequence for encoding "UTF8": 0xee 0xb7 0x30
DEBU[142404] Acl check with backend Files
INFO[142404] Files acl check with user loraserver, topic: gateway/7276ff00080801db/rx, clientid: cf03d60d-11be-4fe2-86ba-97e6790c4be4 and acc: 1
INFO[142404] Files acl check passed.
DEBU[142404] user loraserver acl authenticated with backend Files
DEBU[142404] setting acl cache (granted = true) for loraserver
DEBU[142404] Acl is %!s(bool=true) for user loraserver
DEBU[142404] checking acl cache for loraappserver
DEBU[142404] Superuser check with backend Files
DEBU[142404] Superuser check with backend Postgres
DEBU[142404] Checking Postgres for superuser with username loraappserver
DEBU[142404] PG get superuser error: pq: invalid byte sequence for encoding "UTF8": 0xee 0xb7 0x30
DEBU[142404] Acl check with backend Files
INFO[142404] Files acl check with user loraappserver, topic: application/1/node/0004a30b001eb809/rx, clientid: 65fcb67e-8077-46c3-812c-368a585cde71 and acc: 2
INFO[142404] Files acl check passed.
DEBU[142404] user loraappserver acl authenticated with backend Files
DEBU[142404] setting acl cache (granted = true) for loraappserver
DEBU[142404] Acl is %!s(bool=true) for user loraappserver
DEBU[142404] checking acl cache for CPDET
DEBU[142404] Superuser check with backend Files
DEBU[142404] Superuser check with backend Postgres
DEBU[142404] Checking Postgres for superuser with username CPDET
DEBU[142404] PG get superuser error: pq: invalid byte sequence for encoding "UTF8": 0xee 0xb7 0x30
DEBU[142404] Acl check with backend Files
INFO[142404] Files acl check with user CPDET, topic: application/1/node/0004a30b001eb809/rx, clientid: mqtt_7c10e46a.fc20ac and acc: 1
WARN[142404] Files acl check failed.
DEBU[142404] Acl check with backend Postgres
DEBU[142404] Checking Postgres for ACL for username CPDET, clientid mqtt_7c10e46a.fc20ac, topic application/1/node/0004a30b001eb809/rx and access 1
DEBU[142404] PG check acl error: pq: invalid message format
DEBU[142404] setting acl cache (granted = false) for CPDET
DEBU[142404] Acl is %!s(bool=false) for user CPDET
DEBU[142407] checking auth cache for det
DEBU[142407] found in cache: det
DEBU[142407] checking acl cache for loragw
DEBU[142407] found in cache: loragw
DEBU[142407] checking acl cache for loraserver
DEBU[142407] found in cache: loraserver
DEBU[142427] checking auth cache for det
DEBU[142427] found in cache: det
DEBU[142437] checking acl cache for loragw
DEBU[142437] Superuser check with backend Files
DEBU[142437] Superuser check with backend Postgres
DEBU[142437] Checking Postgres for superuser with username loragw
DEBU[142437] PG get superuser error: pq: invalid byte sequence for encoding "UTF8": 0xee 0xb7 0x30
DEBU[142437] Acl check with backend Files
INFO[142437] Files acl check with user loragw, topic: gateway/7276ff00080801db/stats, clientid: 74834c45-cd91-4913-b436-44f12e88e3a8 and acc: 2
INFO[142437] Files acl check passed.
DEBU[142437] user loragw acl authenticated with backend Files
DEBU[142437] setting acl cache (granted = true) for loragw
DEBU[142437] Acl is %!s(bool=true) for user loragw
DEBU[142437] checking acl cache for loraserver
DEBU[142437] Superuser check with backend Files
DEBU[142437] Superuser check with backend Postgres
DEBU[142437] Checking Postgres for superuser with username loraserver
DEBU[142437] PG get superuser error: pq: invalid byte sequence for encoding "UTF8": 0xee 0xb7 0x30
DEBU[142437] Acl check with backend Files
INFO[142437] Files acl check with user loraserver, topic: gateway/7276ff00080801db/stats, clientid: cf03d60d-11be-4fe2-86ba-97e6790c4be4 and acc: 1
INFO[142437] Files acl check passed.
DEBU[142437] user loraserver acl authenticated with backend Files
DEBU[142437] setting acl cache (granted = true) for loraserver
DEBU[142437] Acl is %!s(bool=true) for user loraserver
DEBU[142448] checking auth cache for det
DEBU[142448] found in cache: det
DEBU[142467] checking acl cache for loragw
DEBU[142467] found in cache: loragw
DEBU[142467] checking acl cache for loraserver
DEBU[142467] found in cache: loraserver
DEBU[142471] checking auth cache for det
DEBU[142471] found in cache: det
DEBU[142492] checking acl cache for loragw
DEBU[142492] Superuser check with backend Files
DEBU[142492] Superuser check with backend Postgres
DEBU[142492] Checking Postgres for superuser with username loragw
DEBU[142492] PG get superuser error: pq: invalid byte sequence for encoding "UTF8": 0xee 0xb7 0x30
DEBU[142492] Acl check with backend Files
INFO[142492] Files acl check with user loragw, topic: gateway/7276ff00080801db/rx, clientid: 74834c45-cd91-4913-b436-44f12e88e3a8 and acc: 2
INFO[142492] Files acl check passed.
DEBU[142492] user loragw acl authenticated with backend Files
DEBU[142492] setting acl cache (granted = true) for loragw
DEBU[142492] Acl is %!s(bool=true) for user loragw
DEBU[142492] checking acl cache for loraserver
DEBU[142492] Superuser check with backend Files
DEBU[142492] Superuser check with backend Postgres
DEBU[142492] Checking Postgres for superuser with username loraserver
DEBU[142492] PG get superuser error: pq: invalid byte sequence for encoding "UTF8": 0xee 0xb7 0x30
DEBU[142492] Acl check with backend Files
INFO[142492] Files acl check with user loraserver, topic: gateway/7276ff00080801db/rx, clientid: cf03d60d-11be-4fe2-86ba-97e6790c4be4 and acc: 1
INFO[142492] Files acl check passed.
DEBU[142492] user loraserver acl authenticated with backend Files
DEBU[142492] setting acl cache (granted = true) for loraserver
DEBU[142492] Acl is %!s(bool=true) for user loraserver
DEBU[142492] checking acl cache for loraappserver
DEBU[142492] Superuser check with backend Files
DEBU[142492] Superuser check with backend Postgres
DEBU[142492] Checking Postgres for superuser with username loraappserver
DEBU[142492] PG get superuser error: pq: invalid byte sequence for encoding "UTF8": 0xee 0xb7 0x30
DEBU[142492] Acl check with backend Files
INFO[142492] Files acl check with user loraappserver, topic: application/1/node/0004a30b001e0b53/rx, clientid: 65fcb67e-8077-46c3-812c-368a585cde71 and acc: 2
INFO[142492] Files acl check passed.
DEBU[142492] user loraappserver acl authenticated with backend Files
DEBU[142492] setting acl cache (granted = true) for loraappserver
DEBU[142492] Acl is %!s(bool=true) for user loraappserver
DEBU[142492] checking acl cache for CPDET
DEBU[142492] Superuser check with backend Files
DEBU[142492] Superuser check with backend Postgres
DEBU[142492] Checking Postgres for superuser with username CPDET
DEBU[142492] PG get superuser error: pq: invalid byte sequence for encoding "UTF8": 0xee 0xb7 0x30
DEBU[142492] Acl check with backend Files
INFO[142492] Files acl check with user CPDET, topic: application/1/node/0004a30b001e0b53/rx, clientid: mqtt_7c10e46a.fc20ac and acc: 1
WARN[142492] Files acl check failed.
DEBU[142492] Acl check with backend Postgres
DEBU[142492] Checking Postgres for ACL for username CPDET, clientid mqtt_7c10e46a.fc20ac, topic application/1/node/0004a30b001e0b53/rx and access 1
DEBU[142492] PG check acl error: pq: invalid message format
DEBU[142492] setting acl cache (granted = false) for CPDET
DEBU[142492] Acl is %!s(bool=false) for user CPDET
DEBU[142494] checking auth cache for det
I got we can go deep withs logs that you have implemented !!!
Thanks! 
EDIT: Note that the error occurs after sometime or with a service unknow by me yet and it occurs with:
- PG get user error
- PG get superuser error
- PG get acl error (pleasse loot at logs before)
Nice. Would you mind sharing you pg_userquery, pg_superquery and pg_aclquery?
Also, could you share your lora-app-server DB encoding? This command should do the trick (change db name and username to the correct ones, and it’ll prompt for your lora-app-server user password):
psql lora-app-server-db -U -lora-app-server-user -c 'SHOW SERVER_ENCODING'
HI @iegomez! For sure! I guess it is not the written at .conf but how it deal with it after sometime
/etc/mosquitto/conf.d$ sudo cat mosquitto-auth-plug.conf
allow_anonymous false
auth_plugin /usr/bin/go-auth.so
auth_opt_backends files, postgres
auth_opt_log_level debug
#Cache
auth_opt_cache true
auth_opt_cache_reset false
auth_opt_cache_db 3
#Files
auth_opt_password_path /etc/mosquitto/mosquitto-auth-plug/passwords
auth_opt_acl_path /etc/mosquitto/mosquitto-auth-plug/acls
#POSTGRESQL
auth_opt_pg_host localhost
auth_opt_pg_port 5432
auth_opt_pg_dbname loraserver_as
auth_opt_pg_user loraserver_as
auth_opt_pg_password loraserver_as
auth_opt_pg_userquery select password_hash from "user" where username = $1 and is_active = true limit 1
auth_opt_pg_superquery select count(*) from "user" where username = $1 and is_admin = true
auth_opt_pg_aclquery select distinct 'application/' || a.id || '/#' from "user" u inner join organization_user ou on ou.user_id = u.id inner join organization o on o.id = ou.organization_id inner join application a on a.organization_id = o.id where u.username = $1 and $2 = $2
I can receive anything with
sudo psql -h localhost loraserver_as -U loraserver_as -c 'SHOW_SERVER_ENCODING'
perl: warning: Setting locale failed.
perl: warning: Please check that your locale settings:
LANGUAGE = (unset),
LC_ALL = (unset),
LC_PAPER = "pt_BR.UTF-8",
LC_ADDRESS = "pt_BR.UTF-8",
LC_MONETARY = "pt_BR.UTF-8",
LC_NUMERIC = "pt_BR.UTF-8",
LC_TELEPHONE = "pt_BR.UTF-8",
LC_IDENTIFICATION = "pt_BR.UTF-8",
LC_MEASUREMENT = "pt_BR.UTF-8",
LC_CTYPE = "pt_BR.UTF-8",
LC_TIME = "pt_BR.UTF-8",
LC_NAME = "pt_BR.UTF-8",
LANG = "en_US.UTF-8"
are supported and installed on your system.
perl: warning: Falling back to a fallback locale ("en_US.UTF-8").
Password for user loraserver_as:
ERROR: syntax error at or near "SHOW_SERVER_ENCODING"
LINE 1: SHOW_SERVER_ENCODING
Please ditch the -h localhost part, or put it after loraserver_as (the DB name). Alternatively, just log into psql and run this:
SHOW SERVER_ENCODING;
Here it is
loraserver_as=> SHOW SERVER_ENCODING;
server_encoding
-----------------
UTF8
(1 row)
EDIT: i have ran export LC_ALL=“en_US.UTF-8” to target LC_ALL variables at the same variables. So there is not anymore the print these ones:
Regarding the superuser errors like this, the only thing I can think of is something like what’s suggested in this stackoverflow question.
I don’t see anything wrong with your queries, tested them directly on postgres and they run fine. So, I just pushed a change to log the actual queries that are being executed on each check, and also modified the time format of the logger to full timestamp if that’s of any help.
Hello @iegomez,
I was trying to understand how pluging is reading the query. I realise that:
The start of data received:
DEBU[2018-03-01T13:24:43-03:00] found in cache: loragw
DEBU[2018-03-01T13:24:43-03:00] checking acl cache for loraserver
DEBU[2018-03-01T13:24:43-03:00] found in cache: loraserver
DEBU[2018-03-01T13:24:46-03:00] checking acl cache for loragw
DEBU[2018-03-01T13:24:46-03:00] Superuser check with backend Files
DEBU[2018-03-01T13:24:46-03:00] Superuser check with backend Postgres
DEBU[2018-03-01T13:24:46-03:00] Checking Postgres for superuser with username loragw
DEBU[2018-03-01T13:24:46-03:00] sql query to be executed query="select count(*) from \"user\" where username = $1 and is_admin = true" username=loragw
DEBU[2018-03-01T13:24:46-03:00] Acl check with backend Files
INFO[2018-03-01T13:24:46-03:00] Files acl check with user loragw, topic: gateway/7276ff00080801db/rx, clientid: e1fccf2f-4ef8-4dcd-965a-a87a13821ca2 and acc: 2
INFO[2018-03-01T13:24:46-03:00] Files acl check passed.
DEBU[2018-03-01T13:24:46-03:00] user loraserver acl authenticated with backend Files
DEBU[2018-03-01T13:24:46-03:00] setting acl cache (granted = true) for loraserver
DEBU[2018-03-01T13:24:46-03:00] Acl is %!s(bool=true) for user loraserver
DEBU[2018-03-01T13:24:46-03:00] checking acl cache for loraappserver
DEBU[2018-03-01T13:24:46-03:00] Superuser check with backend Files
DEBU[2018-03-01T13:24:46-03:00] Superuser check with backend Postgres
DEBU[2018-03-01T13:24:46-03:00] Checking Postgres for superuser with username loraappserver
DEBU[2018-03-01T13:24:46-03:00] sql query to be executed query="select count(*) from \"user\" where username = $1 and is_admin = true" username=loraappserver
DEBU[2018-03-01T13:24:46-03:00] Acl check with backend Files
INFO[2018-03-01T13:24:46-03:00] Files acl check with user loraappserver, topic: application/1/node/0004a30b001e4c78/rx, clientid: 0f6711b8-5d41-43b0-b31e-2c857d9d0b21 and acc: 2
INFO[2018-03-01T13:24:46-03:00] Files acl check passed.
DEBU[2018-03-01T13:24:46-03:00] user loraappserver acl authenticated with backend Files
DEBU[2018-03-01T13:24:46-03:00] setting acl cache (granted = true) for loraappserver
DEBU[2018-03-01T13:24:46-03:00] Acl is %!s(bool=true) for user loraappserver
DEBU[2018-03-01T13:24:46-03:00] checking acl cache for CPDET
DEBU[2018-03-01T13:24:46-03:00] Superuser check with backend Files
DEBU[2018-03-01T13:24:46-03:00] Superuser check with backend Postgres
DEBU[2018-03-01T13:24:46-03:00] Checking Postgres for superuser with username CPDET
DEBU[2018-03-01T13:24:46-03:00] sql query to be executed query="select count(*) from \"user\" where username = $1 and is_admin = true" username=CPDET
DEBU[2018-03-01T13:24:46-03:00] superuser CPDET acl authenticated with backend Postgres
DEBU[2018-03-01T13:24:46-03:00] setting acl cache (granted = true) for CPDET
DEBU[2018-03-01T13:24:46-03:00] Acl is %!s(bool=true) for user CPDET
DEBU[2018-03-01T13:24:55-03:00] checking acl cache for loragw
DEBU[2018-03-01T13:24:55-03:00] found in cache: loragw
DEBU[2018-03-01T13:24:55-03:00] checking acl cache for loraserver
DEBU[2018-03-01T13:24:55-03:00] found in cache: loraserver
DEBU[2018-03-01T13:25:13-03:00] checking acl cache for loragw
DEBU[2018-03-01T13:25:13-03:00] found in cache: loragw
DEBU[2018-03-01T13:25:13-03:00] checking acl cache for loraserver
DEBU[2018-03-01T13:25:13-03:00] found in cache: loraserver
DEBU[2018-03-01T13:25:25-03:00] checking acl cache for loragw
DEBU[2018-03-01T13:25:25-03:00] found in cache: loragw
DEBU[2018-03-01T13:25:25-03:00] checking acl cache for loraserver
DEBU[2018-03-01T13:25:25-03:00] found in cache: loraserver
DEBU[2018-03-01T13:25:43-03:00] checking acl cache for loragw
DEBU[2018-03-01T13:25:43-03:00] found in cache: loragw
DEBU[2018-03-01T13:25:43-03:00] checking acl cache for loraserver
DEBU[2018-03-01T13:25:43-03:00] found in cache: loraserver
DEBU[2018-03-01T13:25:55-03:00] checking acl cache for loragw
DEBU[2018-03-01T13:25:55-03:00] Superuser check with backend Files
DEBU[2018-03-01T13:25:55-03:00] Superuser check with backend Postgres
DEBU[2018-03-01T13:25:55-03:00] Checking Postgres for superuser with username loragw
DEBU[2018-03-01T13:25:55-03:00] sql query to be executed query="select count(*) from \"user\" where username = $1 and is_admin = true" username=loragw
DEBU[2018-03-01T13:25:55-03:00] Acl check with backend Files
INFO[2018-03-01T13:25:55-03:00] Files acl check with user loragw, topic: gateway/7276ff00080801db/stats, clientid: e1fccf2f-4ef8-4dcd-965a-a87a13821ca2 and acc: 2
These logs is a little confusing at sequence. I can not stablished a sequence.
Other thing. please, why the users from ACL are checked with postgresql backend. Is the ACL checked before, all right? Sou if they have been checked with the ACL backend it could not be passed without postgresql auth?
Detailed look at here, please
DEBU[2018-03-01T13:25:55-03:00] Checking Postgres for superuser with username loragw
DEBU[2018-03-01T13:25:55-03:00] sql query to be executed query="select count(*) from \"user\" where username = $1 and is_admin = true" username=loragw
Why lora gw, loraappserver and loraserver users are checked with acl query at postgres . But it wasnt checked by acl before?
EDIT: Is there in somewhere thas has parse commands because I saw in some error logs the seems message cant be recognized sometimes after some precise clock at 6.25 am. This message i refer is the json phy pyload over the gateway. It seems like also when passed internal at mosquitto over plugin, bytes are dismiss at somewhere.
Hi, Rogerio.
I just changed the log time format and added the actual query that’ll be used in postgres for every check. So, for example, this extract from the logs:
DEBU[2018-03-01T13:24:46-03:00] Checking Postgres for superuser with username loraappserver
DEBU[2018-03-01T13:24:46-03:00] sql query to be executed query="select count(*) from \"user\" where username = $1 and is_admin = true" username=loraappserver
It means that the user (in this case, loraappserver) is going to be checked for superuser against postgres. So, the sql query to be executed will be this, where the placeholder $1 is replaced by the username:
select count(*) from \"user\" where username = 'loraappserver' and is_admin = true
I just added it to see what is really being queried when it starts to fail.
There’s no such thing as an ACL backend, there are ACL checks against different backends. All backends will be checked for any given topic until one authorized the access or none of them do. The order of checking is just the one given in the plugin’s option auth_opt_backends.
I’m not sure what you mean by this, as a phy payload shouldn’t have anything to do with authentication of users or authorization of topics. The missing bytes part is what’s intriguing me, as some things seem to be truncated at that time (e.g., the superuser query), when cron jobs run, (I guess) mosquitto gets restarted and postgres starts to fail on checking. Mind that checks fail, but it doesn’t crash, as the backend is not separate from the plugin so it can’t crash on its own and have the files keep working. If it crashes, everything stops working.
Yes @iegomez,
I have decided to comment the line of superquery. In order to minimize one error per time. So it is more simple. Now i really can understand the logs and it is making mosere sense to me. I study the lines commenting them to open my mind. I guess it works!
I would increase the acl cache time. i guess this is too little yet. How can I change to increase this time. I saw some parameters as aclSec and authSec but to do not error i am asking you where can I input this value, Because the cache is necessary for mos times.
So I will let it running from now until tomorrow, so we could see if that something strange happens
From you mentioned. Yes. After sometime the plugin not chashes. But only postgresql auth fails 
Yes. very intriguing. Maybe the order of reload mosquitto might be after postgresql by cron ?
You can change the default values (defaults are 30 seconds for each) at the configuration options like this. Options are in seconds, so this would would set it to 1 minute each:
auth_opt_auth_cache_seconds 60
auth_opt_acl_cache_seconds 60
I’m sorry to ask, but would you mind keeping the superuser query so that we can see what the query string look likes when it fails tomorrow morning (assuming it will, of course)?
Order shouldn’t matter, the plugin keeps waiting for the postgres connection to be available when it is set as a backend, and keeps stuck at initialization until it does. Also, when mosquitto gets shutdown, the plugin gets cleaned up (closes connections, files, etc.) and “shut down” too (it is just a shared object after all), and then on mosquitto start it will get initialized again, so the whole postgres process I described happens again.
Well, I guess we’ll have to wait till tomorrow to see if the added logging messages give us some more information. Again, it’d be great if you could keep the superuser query, at least until then.
Thanks again, Rogerio, for your infinite patience and good will! 
Hello @iegomez!
Yesterday i have already run the plugin without the superuser and I could not change it. Now i think is a good way keeping the plugin running untill monday because i will have no access on weekend. So if the pluging stops i can not do anything! So Lets will at this strategy and pray that postgres do not find me wrong. 
Thanks you as much to allow being part of this validation. It is beeing a value experience for me! 
EDIT:
EDIT: I will use this certainly on next times. Thank you again!
That’s ok, I hope it goes well during the weekend and we’ll continue this journey on monday. 
Hello @iegomez!
Good m orning/day.
In a soon search about things at journal, I have detected the time of problem. 6.25 am, as we are find the time to something the help us to solve the problem.
So at journalctl I have found the line that ran in crontab. And in crontab I have found exactly this !
sudo cat /etc/crontab
# /etc/crontab: system-wide crontab
# Unlike any other crontab you don't have to run the `crontab'
# command to install the new version when you edit this file
# and files in /etc/cron.d. These files also have username fields,
# that none of the other crontabs do.
SHELL=/bin/sh
PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin
# m h dom mon dow user command
17 * * * * root cd / && run-parts --report /etc/cron.hourly
25 6 * * * root test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily )
47 6 * * 7 root test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.weekly )
52 6 1 * * root test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.monthly )
#
In a google I have found some info that can guide us. Look
http://www.linuxtopia.org/online_books/linux_beginner_books/debian_linux_desktop_survival_guide/CRON_Regular.shtml
Since we do not have anacron at our system, the crontab goes to line
( cd / && run-parts --report /etc/cron. daily)
( cd / && run-parts --report /etc/cron.weekkly )
( cd / && run-parts --report /etc/cron.montly )
I thought you’d already seen that and the idea was to check the plugin’s new log messages. Anyway, that just shows that whatever is at /etc/cron.daily runs each day at 6.25, whatever is at /etc/cron.weekly does once a week, etc. So, if it’s crashing say once a week, the culprit on mosquitto’s restart process should be at /etc/cron.weekly, but what we need is to go deeper and find what exactly is going at mosquitto and the plugin to get to the error.
So, did it crash this time and could you share relevant info from the logs? Hopefully we’ll see when queries get messed up or something.
Hi @iegomez!
I could not find the logs since the script has runned autommatically.
So i verify at postgres logs and the error are always the same listed above.
At the time error it seems it jump the logs. At mosquitto i have a file the ends at 6.18 am and the other start at 6.30 am . It is a clue maybe.
Maybe we could generate a file with the logs mannually please?
sudo mosquitto -c /etc/mosquitto/mosquitto.conf > /home/user/mosq.log
Maybe the cron.daily when restarted, the port 1883 or some other service, e.g., is still opened and when try the connection it could start correcttly?
Yeah, you could try that, but if it’s not crashing daily, we’ll have to wait some time. Also, if started manually it could not get affected by whatever is running on the cron jobs, so I’d suggest you take a look at those jobs to see what they’re doing.
Hi @iegomez! I am takein depper in that case of 6.25 am . Let me please take a doubt. Is that someway to crash the plugin with some tipe of message? because initially i could send a payload from a node and then when i send it again all the plugin just stops! There is a max number of bits ?
related to this:
DEBU[2018-03-05T17:00:16-03:00] checking acl cache for loragw
DEBU[2018-03-05T17:00:16-03:00] Superuser check with backend Files
DEBU[2018-03-05T17:00:16-03:00] Superuser check with backend Postgres
DEBU[2018-03-05T17:00:16-03:00] Acl check with backend Files
INFO[2018-03-05T17:00:16-03:00] Files acl check with user loragw, topic: gateway/7276ff00080801db/rx, clientid: 69e69627-fbf8-4e3e-a032-7cb0a3eb292f and acc: 2
INFO[2018-03-05T17:00:16-03:00] Files acl check passed.
DEBU[2018-03-05T17:00:16-03:00] user loragw acl authenticated with backend Files
DEBU[2018-03-05T17:00:16-03:00] setting acl cache (granted = true) for loragw
DEBU[2018-03-05T17:00:16-03:00] Acl is %!s(bool=true) for user loragw
DEBU[2018-03-05T17:00:16-03:00] checking acl cache for loraserver
DEBU[2018-03-05T17:00:16-03:00] Superuser check with backend Files
DEBU[2018-03-05T17:00:16-03:00] Superuser check with backend Postgres
DEBU[2018-03-05T17:00:16-03:00] Acl check with backend Files
INFO[2018-03-05T17:00:16-03:00] Files acl check with user loraserver, topic: gateway/7276ff00080801db/rx, clientid: 498288f4-59ba-48ca-9b3e-62efb14ad83f and acc: 1
INFO[2018-03-05T17:00:16-03:00] Files acl check passed.
DEBU[2018-03-05T17:00:16-03:00] user loraserver acl authenticated with backend Files
DEBU[2018-03-05T17:00:16-03:00] setting acl cache (granted = true) for loraserver
DEBU[2018-03-05T17:00:16-03:00] Acl is %!s(bool=true) for user loraserver
DEBU[2018-03-05T17:00:17-03:00] checking acl cache for loraappserver
DEBU[2018-03-05T17:00:17-03:00] Superuser check with backend Files
DEBU[2018-03-05T17:00:17-03:00] Superuser check with backend Postgres
DEBU[2018-03-05T17:00:17-03:00] Acl check with backend Files
INFO[2018-03-05T17:00:17-03:00] Files acl check with user loraappserver, topic: application/1/node/0004a30b001abe98/rx, clientid: 68b25e8b-6b88-40ea-83eb-ecff9fb3b97d and acc: 2
INFO[2018-03-05T17:00:17-03:00] Files acl check passed.
DEBU[2018-03-05T17:00:17-03:00] user loraappserver acl authenticated with backend Files
DEBU[2018-03-05T17:00:17-03:00] setting acl cache (granted = true) for loraappserver
DEBU[2018-03-05T17:00:17-03:00] Acl is %!s(bool=true) for user loraappserver
Segmentation fault (core dumped)
Please note that node 0004a30b001abe98 crashes the plugin!
EDIT: I am sending for about 20 bytes
Precisesly, I am sending this datapayload over lorawan protocol 0101220501f20132ff4d
Meanwhile, at the others working nodes I am sending 0b0217a10c0cc9
Please note that in the beggining of the plugin, it was working ok!
Mosquitto does have a configurable max payload size, but according to the conf it’s really big by default and larger messages should just be discarded (taken from here):
message_size_limit limit
This option sets the maximum publish payload size that the broker will allow. Received messages that exceed this size will not be accepted by the broker. The default value is 0, which means that all valid MQTT messages are accepted. MQTT imposes a maximum payload size of 268435455 bytes.
That said, the plugin really doesn’t mind about the payload content, it never gets to see it. When a message is published, mosquitto will pass username, topic, clientid and acc to the plugin, which implements the following function for authorization (as defined in mosquitto) to see if the publisher is allowed to write to that topic, and if any potential connected subscriber is able to read from it:
int mosquitto_auth_acl_check(void *user_data, const char *clientid, const char *username, const char *topic, int access)
So I think the seg fault could be generated at auth-plugin.c and be related to some null param. I’ll add some checkings and debug messages tomorrow to that function to see if there’s something wrong.