ACL rule: {allow, {ipaddr, "127.0.0.1"}, pubsub, ["$SYS/#", "#"]}. not working in EMQX 5 #10735

rgaufman · 2023-05-17T18:45:19Z

What happened?

I have this rule (in /etc/emqx/acl.conf) that is working in EMQX 4:

{allow, {ipaddr, "127.0.0.1"}, pubsub, ["$SYS/#", "#"]}.

However in EMQX 5 I am getting this error at startup:

May 17 19:39:22 staging1.xancloud.com bash[7815]: {"Kernel pid terminated",application_controller,"{application_start_failure,emqx_machine,{{shutdown,{failed_to_start_child,emqx_machine_boot,{'EXIT',{{failed_to_start_app,emqx_authz,{emqx_authz,{bad_return,{{emqx_authz_app,start,[normal,[]]},{'EXIT',{function_clause,[{emqx_authz_rule,compile,[{allow,{ipaddr,\"127.0.0.1\"},pubsub,[\"$SYS/#\",\"#\"]}],[{file,\"emqx_authz_rule.erl\"},{line,61}]},{emqx_authz_file,'-create/1-lc$^0/1-0-',1,[{file,\"emqx_authz_file.erl\"},{line,47}]},{emqx_authz_file,create,1,[{file,\"emqx_authz_file.erl\"},{line,47}]},{lists,map,2,[{file,\"lists.erl\"},{line,1243}]},{emqx_authz,init,0,[{file,\"emqx_authz.erl\"},{line,106}]},{emqx_authz_app,start,2,[{file,\"emqx_authz_app.erl\"},{line,31}]},{application_master,start_it_old,4,[{file,\"application_master.erl\"},{line,293}]}]}}}}}},[{emqx_machine_boot,start_one_app,1,[{file,\"emqx_machine_boot.erl\"},{line,104}]},{lists,foreach,2,[{file,\"lists.erl\"},{line,1342}]},{emqx_machine_boot,post_boot,0,[{file,\"emqx_machine_boot.erl\"},{line,39}]},{supervisor,do_start_child_i,3,[{file,\"supervisor.erl\"},{line,414}]},{supervisor,do_start_child,2,[{file,\"supervisor.erl\"},{line,400}]},{supervisor,'-start_children/2-fun-0-',3,[{file,\"supervisor.erl\"},{line,384}]},{supervisor,children_map,4,[{file,\"supervisor.erl\"},{line,1250}]},{supervisor,init_children,2,[{file,\"supervisor.erl\"},{line,350}]},{gen_server,init_it,2,[{file,\"gen_server.erl\"},{line,423}]},{gen_server,init_it,6,[{file,\"gen_server.erl\"},{line,390}]},{proc_lib,init_p_do_apply,3,[{file,\"proc_lib.erl\"},{line,226}]}]}}}},{emqx_machine_app,start,[normal,[]]}}}"}
May 17 19:39:22 staging1.xancloud.com bash[7815]: Kernel pid terminated (application_controller) ({application_start_failure,emqx_machine,{{shutdown,{failed_to_start_child,emqx_machine_boot,{'EXIT',{{failed_to_start_app,emqx_authz,{emqx_authz,{bad_return,{{emqx_authz_app,start,[normal,[]]},{'EXIT',{function_clause,[{emqx_authz_rule,compile,[{allow,{ipaddr,"127.0.0.1"},pubsub,["$SYS/#","#"]}],[{file,"emqx_authz_rule.erl"},{line,61}]},{emqx_authz_file,'-create/1-lc$^0/1-0-',1,[{file,"emqx_authz_file.erl"},{line,47}]},{emqx_authz_file,create,1,[{file,"emqx_authz_file.erl"},{line,47}]},{lists,map,2,[{file,"lists.erl"},{line,1243}]},{emqx_authz,init,0,[{file,"emqx_authz.erl"},{line,106}]},{emqx_authz_app,start,2,[{file,"emqx_authz_app.erl"},{line,31}]},{application_master,start_it_old,4,[{file,"application_master.erl"},{line,293}]}]}}}}}},[{emqx_machine_boot,start_one_app,1,[{file,"emqx_machine_boot.erl"},{line,104}]},{lists,foreach,2,[{file,"lists.erl"},{line,1342}]},{emqx_machine_boot,post_boot,0,[{file,"emqx_machine_boot.erl"},{line,39}]},{supervisor,do_start
May 17 19:39:22 staging1.xancloud.com bash[7815]: [1B blob data]
May 17 19:39:23 staging1.xancloud.com bash[7815]: Crash dump is being written to: /var/log/emqx/erl_crash.dump...done

What did you expect to happen?

I expected it to start and work, all my other ACL rules are working as expected as this is what is documented here: https://www.emqx.io/docs/en/v5.0/security/authz/file.html#configuration

How can we reproduce it (as minimally and precisely as possible)?

My full /etc/emqx/acl.conf file is:

{allow, {ipaddr, "127.0.0.1"}, pubsub, ["$SYS/#", "#"]}.
{allow, all, publish, ["tl/#", "connections/tb/%u/#", "$SYS/broker/connection/#"]}.
{allow, all, subscribe, ["tb/%u/#"]}.
{deny, all}.

Removing the first line makes it work, but I need this line :)

Anything else we need to know?

No response

EMQX version

$ sudo emqx_ctl broker
sysdescr  : EMQX
version   : 5.0.25
datetime  : 2023-05-17T19:44:46.433849811+01:00
uptime    : 4 minutes, 16 seconds

OS version

# On Linux:
$ lsb_release -a
No LSB modules are available.
Distributor ID:	Ubuntu
Description:	Ubuntu 18.04.6 LTS
Release:	18.04
Codename:	bionic
You have new mail in /var/mail/deployer
$ uname -a
Linux staging1.xancloud.com 4.15.0-209-generic #220-Ubuntu SMP Tue Mar 21 17:52:18 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

Log files

The text was updated successfully, but these errors were encountered:

zhongwencool · 2023-05-18T02:58:36Z

Sorry, The acl rule v5 is different from v4. the document's example is v4, we will update document!
please use:

{allow, {ipaddr, "127.0.0.1"},all, ["$SYS/#", "#"]}.

fix: emqx/emqx-docs#1885

rgaufman · 2023-05-18T20:55:05Z

Thank you, closing

rgaufman · 2023-05-18T22:30:32Z

Sorry, I spoke too soon, when I try to subscribe from localhost like this:

$ mosquitto_sub -u test -P test -q 2 -t '#' -i subscriber2 -v

I don't see any published messages and I see this in the errors log:

2023-05-18T23:28:23.417394+01:00 [error] crasher: initial call: emqx_connection:init/4, pid: <0.3282.0>, registered_name: [], error: {{badmatch,{error,{bad_type,{emqx_trie,{<<"#">>,1},1}}}},[{emqx_session,subscribe,4,[{file,"emqx_session.erl"},{line,329}]},{emqx_channel,do_subscribe,3,[{file,"emqx_channel.erl"},{line,816}]},{emqx_channel,process_subscribe,4,[{file,"emqx_channel.erl"},{line,787}]},{emqx_channel,handle_in,2,[{file,"emqx_channel.erl"},{line,780}]},{emqx_connection,with_channel,3,[{file,"emqx_connection.erl"},{line,833}]},{emqx_connection,process_msg,2,[{file,"emqx_connection.erl"},{line,485}]},{emqx_connection,process_msg,2,[{file,"emqx_connection.erl"},{line,491}]},{emqx_connection,handle_recv,3,[{file,"emqx_connection.erl"},{line,447}]},{proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,236}]}]}, ancestors: [<0.2336.0>,<0.2335.0>,esockd_sup,<0.1994.0>], message_queue_len: 0, messages: [], links: [<0.2336.0>], dictionary: [{{subscribe,<<"#">>},{allow,1684448903417}},{guid,{1684448903416787,268568599989458,1}},{recv_pkt,2},{'$logger_metadata$',#{clientid => <<"subscriber2">>,peername => "127.0.0.1:46068"}},{outgoing_bytes,4},{authz_keys_q,{[{subscribe,<<"#">>}],[]}},{send_pkt,1},{authz_cache_size,1},{incoming_bytes,53}], trap_exit: false, status: running, heap_size: 2586, stack_size: 29, reductions: 24714; neighbours:
2023-05-18T23:28:23.417838+01:00 [error] supervisor: 'esockd_connection_sup - <0.2336.0>', errorContext: connection_crashed, reason: {{badmatch,{error,{bad_type,{emqx_trie,{<<"#">>,1},1}}}},[{emqx_session,subscribe,4,[{file,"emqx_session.erl"},{line,329}]},{emqx_channel,do_subscribe,3,[{file,"emqx_channel.erl"},{line,816}]},{emqx_channel,process_subscribe,4,[{file,"emqx_channel.erl"},{line,787}]},{emqx_channel,handle_in,2,[{file,"emqx_channel.erl"},{line,780}]},{emqx_connection,with_channel,3,[{file,"emqx_connection.erl"},{line,833}]},{emqx_connection,process_msg,2,[{file,"emqx_connection.erl"},{line,485}]},{emqx_connection,process_msg,2,[{file,"emqx_connection.erl"},{line,491}]},{emqx_connection,handle_recv,3,[{file,"emqx_connection.erl"},{line,447}]},{proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,236}]}]}, offender: [{pid,<0.3282.0>},{name,connection},{mfargs,{emqx_connection,start_link,[#{enable_authn => true,limiter => undefined,listener => {tcp,default},zone => default}]}}]

My acl.conf file is just:

{allow, {ipaddr, "127.0.0.1"}, all, ["$SYS/#", "#"]}.
{deny, all}.

rgaufman · 2023-05-18T22:48:02Z

I captured some more logs:

May 18 23:47:06 preprod.xanview.uk bash[17547]: 2023-05-18T23:47:06.285406+01:00 [info]     msg: authorization_permission_allowed
May 18 23:47:06 preprod.xanview.uk bash[17547]:     mfa: emqx_authz:log_allowed/1
May 18 23:47:06 preprod.xanview.uk bash[17547]:     line: 375
May 18 23:47:06 preprod.xanview.uk bash[17547]:     peername: 127.0.0.1:47768
May 18 23:47:06 preprod.xanview.uk bash[17547]:     clientid: test
May 18 23:47:06 preprod.xanview.uk bash[17547]:     topic: #
May 18 23:47:06 preprod.xanview.uk bash[17547]:     ipaddr: {127,0,0,1}
May 18 23:47:06 preprod.xanview.uk bash[17547]:     source: file
May 18 23:47:06 preprod.xanview.uk bash[17547]:     username: <<"test">>
May 18 23:47:06 preprod.xanview.uk bash[17547]: 2023-05-18T23:47:06.285858+01:00 [info]     msg: terminate
May 18 23:47:06 preprod.xanview.uk bash[17547]:     mfa: emqx_connection:terminate/2
May 18 23:47:06 preprod.xanview.uk bash[17547]:     line: 666
May 18 23:47:06 preprod.xanview.uk bash[17547]:     peername: 127.0.0.1:47768
May 18 23:47:06 preprod.xanview.uk bash[17547]:     clientid: test
May 18 23:47:06 preprod.xanview.uk bash[17547]:     reason: #{context =>
May 18 23:47:06 preprod.xanview.uk bash[17547]:                   {badmatch,{error,{bad_type,{emqx_trie,{<<"#">>,1},1}}}},
May 18 23:47:06 preprod.xanview.uk bash[17547]:               exception => error,
May 18 23:47:06 preprod.xanview.uk bash[17547]:               stacktrace =>
May 18 23:47:06 preprod.xanview.uk bash[17547]:                   [{emqx_session,subscribe,4,
May 18 23:47:06 preprod.xanview.uk bash[17547]:                                  [{file,"emqx_session.erl"},{line,329}]},
May 18 23:47:06 preprod.xanview.uk bash[17547]:                    {emqx_channel,do_subscribe,3,
May 18 23:47:06 preprod.xanview.uk bash[17547]:                                  [{file,"emqx_channel.erl"},{line,816}]},
May 18 23:47:06 preprod.xanview.uk bash[17547]:                    {emqx_channel,process_subscribe,4,
May 18 23:47:06 preprod.xanview.uk bash[17547]:                                  [{file,"emqx_channel.erl"},{line,787}]},
May 18 23:47:06 preprod.xanview.uk bash[17547]:                    {emqx_channel,handle_in,2,
May 18 23:47:06 preprod.xanview.uk bash[17547]:                                  [{file,"emqx_channel.erl"},{line,780}]},
May 18 23:47:06 preprod.xanview.uk bash[17547]:                    {emqx_connection,with_channel,3,
May 18 23:47:06 preprod.xanview.uk bash[17547]:                                     [{file,"emqx_connection.erl"},{line,833}]},
May 18 23:47:06 preprod.xanview.uk bash[17547]:                    {emqx_connection,process_msg,2,
May 18 23:47:06 preprod.xanview.uk bash[17547]:                                     [{file,"emqx_connection.erl"},{line,485}]},
May 18 23:47:06 preprod.xanview.uk bash[17547]:                    {emqx_connection,process_msg,2,
May 18 23:47:06 preprod.xanview.uk bash[17547]:                                     [{file,"emqx_connection.erl"},{line,491}]},
May 18 23:47:06 preprod.xanview.uk bash[17547]:                    {emqx_connection,handle_recv,3,
May 18 23:47:06 preprod.xanview.uk bash[17547]:                                     [{file,"emqx_connection.erl"},{line,447}]},
May 18 23:47:06 preprod.xanview.uk bash[17547]:                    {proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,236}]}]}
May 18 23:47:06 preprod.xanview.uk bash[17547]: 2023-05-18T23:47:06.286007+01:00 [error]   crasher:
May 18 23:47:06 preprod.xanview.uk bash[17547]:     initial call: emqx_connection:init/4
May 18 23:47:06 preprod.xanview.uk bash[17547]:     pid: <0.3692.0>
May 18 23:47:06 preprod.xanview.uk bash[17547]:     registered_name: []
May 18 23:47:06 preprod.xanview.uk bash[17547]:     exception error: no match of right hand side value
May 18 23:47:06 preprod.xanview.uk bash[17547]:                      {error,{bad_type,{emqx_trie,{<<"#">>,1},1}}}
May 18 23:47:06 preprod.xanview.uk bash[17547]:       in function  emqx_session:subscribe/4 (emqx_session.erl, line 329)
May 18 23:47:06 preprod.xanview.uk bash[17547]:       in call from emqx_channel:do_subscribe/3 (emqx_channel.erl, line 816)
May 18 23:47:06 preprod.xanview.uk bash[17547]:       in call from emqx_channel:process_subscribe/4 (emqx_channel.erl, line 787)
May 18 23:47:06 preprod.xanview.uk bash[17547]:       in call from emqx_channel:handle_in/2 (emqx_channel.erl, line 780)
May 18 23:47:06 preprod.xanview.uk bash[17547]:       in call from emqx_connection:with_channel/3 (emqx_connection.erl, line 833)
May 18 23:47:06 preprod.xanview.uk bash[17547]:       in call from emqx_connection:process_msg/2 (emqx_connection.erl, line 485)
May 18 23:47:06 preprod.xanview.uk bash[17547]:       in call from emqx_connection:process_msg/2 (emqx_connection.erl, line 491)
May 18 23:47:06 preprod.xanview.uk bash[17547]:       in call from emqx_connection:handle_recv/3 (emqx_connection.erl, line 447)
May 18 23:47:06 preprod.xanview.uk bash[17547]:     ancestors: [<0.2331.0>,<0.2330.0>,esockd_sup,<0.1991.0>]
May 18 23:47:06 preprod.xanview.uk bash[17547]:     message_queue_len: 0
May 18 23:47:06 preprod.xanview.uk bash[17547]:     messages: []
May 18 23:47:06 preprod.xanview.uk bash[17547]:     links: [<0.2331.0>]
May 18 23:47:06 preprod.xanview.uk bash[17547]:     dictionary: [{{subscribe,<<"#">>},{allow,1684450026285}},
May 18 23:47:06 preprod.xanview.uk bash[17547]:                   {outgoing_bytes,4},
May 18 23:47:06 preprod.xanview.uk bash[17547]:                   {recv_pkt,2},
May 18 23:47:06 preprod.xanview.uk bash[17547]:                   {incoming_bytes,49},
May 18 23:47:06 preprod.xanview.uk bash[17547]:                   {'$logger_metadata$',
May 18 23:47:06 preprod.xanview.uk bash[17547]:                       #{clientid => <<"test">>,
May 18 23:47:06 preprod.xanview.uk bash[17547]:                         peername => "127.0.0.1:47768"}},
May 18 23:47:06 preprod.xanview.uk bash[17547]:                   {authz_keys_q,{[{subscribe,<<"#">>}],[]}},
May 18 23:47:06 preprod.xanview.uk bash[17547]:                   {guid,{1684450026285161,268555715087980,1}},
May 18 23:47:06 preprod.xanview.uk bash[17547]:                   {authz_cache_size,1},
May 18 23:47:06 preprod.xanview.uk bash[17547]:                   {send_pkt,1}]
May 18 23:47:06 preprod.xanview.uk bash[17547]:     trap_exit: false
May 18 23:47:06 preprod.xanview.uk bash[17547]:     status: running
May 18 23:47:06 preprod.xanview.uk bash[17547]:     heap_size: 6772
May 18 23:47:06 preprod.xanview.uk bash[17547]:     stack_size: 29
May 18 23:47:06 preprod.xanview.uk bash[17547]:     reductions: 36246
May 18 23:47:06 preprod.xanview.uk bash[17547]:   neighbours:

zhongwencool · 2023-05-18T23:59:42Z

I can't reproduce this error on my machine(v5.0.25),
I can receive all topic's messages by following you steps, Is there anything else that needs to be noted?

I think this error has nothing with acl.conf, you can delete all rules, and try again to see if the error still occurs?
Could you please run this command to see what happened ?

./bin/emqx eval "mnesia:table_info(emqx_trie)."

rgaufman · 2023-05-19T00:06:50Z

If I remove the lines from the acl file, I just get permission denied. For question 2, I get this:

$ sudo emqx eval "mnesia:table_info(emqx_trie)."
RPC to 'emqx@127.0.0.1' failed: {'EXIT',
                                 {undef,
                                  [{mnesia,table_info,[emqx_trie],[]},
                                   {erl_eval,do_apply,6,
                                    [{file,"erl_eval.erl"},{line,685}]},
                                   {erl_eval,exprs,2,[]}]}}

I'm also on Emqx 5.0.25

This is a clean installation just the acl file and this is in my emqx.conf:

node {
  name = "emqx@127.0.0.1"
  cookie = "emqxsecretcookie"
  data_dir = "/var/lib/emqx"
}

cluster {
  name = emqxcl
  discovery_strategy = manual
}

dashboard {
    listeners.http {
        bind = 18083
    }
}

authorization {
  deny_action = ignore
  no_match = allow
  cache = { enable = true }
}

authentication {enable:true,backend:"built_in_database",mechanism="password_based",user_id_type="username"}
api_key { bootstrap_file = "/etc/emqx/api_key.bootstrap" }

rgaufman · 2023-05-19T00:11:51Z

Oh wait! - I stopped emqx, then rm -Rf /var/lib/emqx and started again, now it works. I think maybe it had stuff left over from EMQX4.

zhongwencool · 2023-05-19T01:51:50Z

Oh wait! - I stopped emqx, then rm -Rf /var/lib/emqx and started again, now it works. I think maybe it had stuff left over from EMQX4.

Yes, the emqx_trie table in v4 builtin database is different from v5, so it's report as {bad_type,{emqx_trie,{<<"#">>,1}

rgaufman added the BUG label May 17, 2023

rgaufman changed the title ~~ACL rul: {allow, {ipaddr, "127.0.0.1"}, pubsub, ["$SYS/#", "#"]}. not working in EMQX 5~~ ACL rule: {allow, {ipaddr, "127.0.0.1"}, pubsub, ["$SYS/#", "#"]}. not working in EMQX 5 May 17, 2023

zhongwencool self-assigned this May 18, 2023

zhongwencool mentioned this issue May 18, 2023

fix: check authz's file source rules in pre_config_update #10742

Merged

8 tasks

rgaufman closed this as completed May 18, 2023

rgaufman reopened this May 18, 2023

zhongwencool closed this as completed May 19, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

ACL rule: {allow, {ipaddr, "127.0.0.1"}, pubsub, ["$SYS/#", "#"]}. not working in EMQX 5 #10735

ACL rule: {allow, {ipaddr, "127.0.0.1"}, pubsub, ["$SYS/#", "#"]}. not working in EMQX 5 #10735

rgaufman commented May 17, 2023 •

edited

zhongwencool commented May 18, 2023 •

edited

rgaufman commented May 18, 2023

rgaufman commented May 18, 2023 •

edited

rgaufman commented May 18, 2023 •

edited

zhongwencool commented May 18, 2023

rgaufman commented May 19, 2023 •

edited

rgaufman commented May 19, 2023 •

edited

zhongwencool commented May 19, 2023

ACL rule: {allow, {ipaddr, "127.0.0.1"}, pubsub, ["$SYS/#", "#"]}. not working in EMQX 5 #10735

ACL rule: {allow, {ipaddr, "127.0.0.1"}, pubsub, ["$SYS/#", "#"]}. not working in EMQX 5 #10735

Comments

rgaufman commented May 17, 2023 • edited

What happened?

What did you expect to happen?

How can we reproduce it (as minimally and precisely as possible)?

Anything else we need to know?

EMQX version

OS version

Log files

zhongwencool commented May 18, 2023 • edited

rgaufman commented May 18, 2023

rgaufman commented May 18, 2023 • edited

rgaufman commented May 18, 2023 • edited

zhongwencool commented May 18, 2023

rgaufman commented May 19, 2023 • edited

rgaufman commented May 19, 2023 • edited

zhongwencool commented May 19, 2023

rgaufman commented May 17, 2023 •

edited

zhongwencool commented May 18, 2023 •

edited

rgaufman commented May 18, 2023 •

edited

rgaufman commented May 18, 2023 •

edited

rgaufman commented May 19, 2023 •

edited

rgaufman commented May 19, 2023 •

edited