Cuttlefish chokes on lines with only whitespace characters in the config file

[puresilk]

Dear cuttlefish maintainers,
I have discovered an issue in cuttlefish as used in VerneMQ:

The original issue is here:
vernemq/vernemq#1208

The problem is that cuttlefish chokes on lines which have only whitespace characters (e.g. tabs) in the config file. This is a particularly difficult issue to debug, as you literally can't see the whitespace. (nano will turn it on if you press Alt + P).

This is what we get currently:

jalpine_morpheus | Error generating config with cuttlefish
jalpine_morpheus |   run `vernemq config generate -l debug` for more information.

and when drilling down with vernemq config generate -l debug:

jalpine_morpheus | escript: exception error: no function clause matching
jalpine_morpheus |                  lists:unzip([[ws,ws],
jalpine_morpheus |                               {["log","console","file"],"./log/console.log"},
jalpine_morpheus |                               {["log","error","file"],"./log/error.log"},
jalpine_morpheus |                               {["log","syslog"],"off"},
jalpine_morpheus |                               {["log","crash"],"on"},
jalpine_morpheus |                               {["log","crash","file"],"./log/crash.log"},
jalpine_morpheus |                               {["log","crash","maximum_message_size"],"64KB"},
jalpine_morpheus |                               {["log","crash","size"],"10MB"},
jalpine_morpheus |                               {["log","crash","rotation"],"$D0"},
jalpine_morpheus |                               {["log","crash","rotation","keep"],"5"},
jalpine_morpheus |                               {["nodename"],"VerneMQ@127.0.0.1"},
jalpine_morpheus |                               {["distributed_cookie"],"vmq"},
jalpine_morpheus |                               {["erlang","async_threads"],"64"},
jalpine_morpheus |                               {["erlang","max_ports"],"262144"},
jalpine_morpheus |                               {["leveldb","maximum_memory","percent"],"70"},
(snip)
jalpine_morpheus |                               {["log","console"],"console"},
jalpine_morpheus |                               {["erlang","distribution","port_range",
jalpine_morpheus |                                 "minimum"],
jalpine_morpheus |                                "9100"},
jalpine_morpheus |                               {["erlang","distribution","port_range",
jalpine_morpheus |                                 "maximum"],
jalpine_morpheus |                                "9109"}],
jalpine_morpheus |                              [["log","console","level"],
jalpine_morpheus |                               ["log","console"],
jalpine_morpheus |                               ["vmq_diversity","auth_redis","enabled"],
jalpine_morpheus |                               ["vmq_diversity","mongodb","database"],
jalpine_morpheus |                               ["vmq_diversity","mongodb","password"],
jalpine_morpheus |                               ["vmq_diversity","mongodb","login"],
jalpine_morpheus |                               ["vmq_diversity","mongodb","port"],
jalpine_morpheus |                               ["vmq_diversity","mongodb","host"],
jalpine_morpheus |                               ["vmq_diversity","auth_mongodb","enabled"],
jalpine_morpheus |                               ["vmq_diversity","mysql","password_hash_method"],
jalpine_morpheus |                               ["vmq_diversity","auth_mysql","enabled"],
jalpine_morpheus |                               ["vmq_diversity","auth_postgres","enabled"],
jalpine_morpheus |                               ["vmq_diversity","script_dir"],
jalpine_morpheus |                               ["vmq_passwd","password_reload_interval"],
jalpine_morpheus |                               ["vmq_passwd","password_file"],
jalpine_morpheus |                               ["vmq_acl","acl_reload_interval"],
jalpine_morpheus |                               ["vmq_acl","acl_file"],
jalpine_morpheus |                               ["metadata_plugin"],
jalpine_morpheus |                               ["plugins","vmq_bridge"],
jalpine_morpheus |                               ["plugins","vmq_webhooks"],
jalpine_morpheus |                               ["plugins","vmq_diversity"],
jalpine_morpheus |                               ["plugins","vmq_acl"],
jalpine_morpheus |                               ["plugins","vmq_passwd"],
jalpine_morpheus |                               ["shared_subscription_policy"],
jalpine_morpheus |                               ["graphite_interval"],
jalpine_morpheus |                               ["graphite_port"],
jalpine_morpheus |                               ["graphite_host"],
jalpine_morpheus |                               ["graphite_enabled"],
jalpine_morpheus |                               ["systree_interval"],
jalpine_morpheus |                               ["systree_enabled"],
jalpine_morpheus |                               ["listener","ws","piclient","mountpoint"],
jalpine_morpheus |                               ["listener","ws","jsclient","mountpoint"],
jalpine_morpheus |                               ["listener","ws","piclient"],
jalpine_morpheus |                               ["listener","ws","jsclient"],
jalpine_morpheus |                               ["listener","nr_of_acceptors"],
jalpine_morpheus |                               ["listener","max_connections"],
jalpine_morpheus |                               ["upgrade_outgoing_qos"],
jalpine_morpheus |                               ["max_message_size"],
jalpine_morpheus |                               ["max_offline_messages"],
jalpine_morpheus |                               ["max_online_messages"],
jalpine_morpheus |                               ["max_inflight_messages"],
jalpine_morpheus |                               ["allow_multiple_sessions"],
jalpine_morpheus |                               ["allow_unsubscribe_during_netsplit"],
jalpine_morpheus |                               ["allow_subscribe_during_netsplit"],
jalpine_morpheus |                               ["allow_publish_during_netsplit"],
jalpine_morpheus |                               [[...]],
jalpine_morpheus |                               [...]],
jalpine_morpheus |                               [...]|...]) (lists.erl, line 402)
jalpine_morpheus |   in function  cuttlefish_conf:file/1 (/vernemq-build/_build/default/lib/cuttlefish/src/cuttlefish_conf.erl, line 74)
jalpine_morpheus |   in call from cuttlefish_conf:'-files/1-fun-1-'/2 (/vernemq-build/_build/default/lib/cuttlefish/src/cuttlefish_conf.erl, line 45)
jalpine_morpheus |   in call from lists:foldl/3 (lists.erl, line 1263)
jalpine_morpheus |   in call from cuttlefish_conf:files/1 (/vernemq-build/_build/default/lib/cuttlefish/src/cuttlefish_conf.erl, line 43)
jalpine_morpheus |   in call from cuttlefish_escript:load_conf/1 (/vernemq-build/_build/default/lib/cuttlefish/src/cuttlefish_escript.erl, line 307)
jalpine_morpheus |   in call from cuttlefish_escript:engage_cuttlefish/1 (/vernemq-build/_build/default/lib/cuttlefish/src/cuttlefish_escript.erl, line 361)
jalpine_morpheus |   in call from cuttlefish_escript:generate/1 (/vernemq-build/_build/default/lib/cuttlefish/src/cuttlefish_escript.erl, line 255)

I feel that lines with whitespace should be accepted and ignored.

I ran into this issue while debugging with VerneMQ for a different issue, and having edited the config file with nano.

See also
https://pi3g.com/2019/06/04/debugging-vernemq-connection-authentication-problems-for-dual-authentication-with-webhooks-and-vmq_diversity/ (Bonus section)

[lukebakken]

Hello, thanks for the report. To expedite a fix, please do the following:

• Attach a configuration file and schema that reproduces the issue
• Provide the exact cuttlefish command to run to reproduce it

Without the above, this project's maintainers (who do so on their free time) will have to spend time going through your report and vernemq/vernemq#1208 to piece together a means to reproduce this issue. If you provide it here, I'm sure I can fix it this week.

[puresilk]

Hello,

As requested, to support you with the debugging:

Please note: unfortunately I am not able to test with the newest cuttlefish (2.2.0) (to be shipped in vernemq 1.8.1), as my knowledge of Erlang / packages is extremely limited. I am testing with the version shipped with vernemq 1.8.0. (which is based on the kyorai repository).

I'm attaching a .tgz file (inside a zip file, as Github does not allow tgz files) which contains a "good" and a "broken" file (manually edited with two tabs to break, I have indicated the break location in the inline comments in the file).

The directory is built up as follows:

vernemq_broken.conf is an edited version of vernemq_ok.conf - so you have both to compare.

The command I use to run it:

/vernemq/erts-10.3.5/bin/escript /vernemq/erts-10.3.5/bin/cuttlefish -e /tmp/cf-test/etc -s /tmp/cf-test/schema -d /tmp/cf-test/output -c /tmp/cf-test/etc/vernemq_broken.conf generate -l debug

I expect that the initial bits "/vernemq/erts-10.3.5/bin/escript /vernemq/erts-10.3.5/bin/cuttlefish" could be replaced by just cuttlefish, if the system is set up accordingly.

This command will show the problem:

16:54:13.532 [debug] Lager installed handler error_logger_lager_h into error_logger
16:54:13.868 [debug] Cuttlefish set to debug level logging
16:54:13.873 [info] Checking /tmp/cf-test/etc/app.config exists... false
16:54:13.873 [info] Checking /tmp/cf-test/etc/vm.args exists... true
16:54:13.873 [info] /tmp/cf-test/etc/vm.args exists, generating app.config
16:54:13.874 [debug] Generating config in: "/tmp/cf-test/output/app.2019.08.01.16.54.13.config"
16:54:13.874 [debug] SchemaFiles: ["/tmp/cf-test/schema/10-vmq_server.schema","/tmp/cf-test/schema/12-vmq_plugin.schema","/tmp/cf-test/schema/13-vmq_acl.schema","/tmp/cf-test/schema/14-vmq_passwd.schema","/tmp/cf-test/schema/15-vmq_diversity.schema","/tmp/cf-test/schema/16-vmq_bcrypt.schema","/tmp/cf-test/schema/17-vmq_webhooks.schema","/tmp/cf-test/schema/18-vmq_bridge.schema","/tmp/cf-test/schema/19-vmq_swc.schema","/tmp/cf-test/schema/20-vmq_pulse.schema","/tmp/cf-test/schema/30-vmq.schema","/tmp/cf-test/schema/31-erlang_vm.schema","/tmp/cf-test/schema/32-riak_sysmon.schema","/tmp/cf-test/schema/33-eleveldb.schema"]
16:54:13.992 [debug] ConfFiles: ["/tmp/cf-test/etc/vernemq_broken.conf"]
escript: exception error: no function clause matching
lists:unzip([[ws,ws],
{["allow_register_during_netsplit"],"off"},
{["allow_publish_during_netsplit"],"off"}],
[["allow_anonymous"]],
["off"]) (lists.erl, line 402)
in function cuttlefish_conf:file/1 (/vernemq-build/_build/default/lib/cuttlefish/src/cuttlefish_conf.erl, line 74)
in call from cuttlefish_conf:'-files/1-fun-1-'/2 (/vernemq-build/_build/default/lib/cuttlefish/src/cuttlefish_conf.erl, line 45)
in call from lists:foldl/3 (lists.erl, line 1263)
in call from cuttlefish_conf:files/1 (/vernemq-build/_build/default/lib/cuttlefish/src/cuttlefish_conf.erl, line 43)
in call from cuttlefish_escript:load_conf/1 (/vernemq-build/_build/default/lib/cuttlefish/src/cuttlefish_escript.erl, line 307)
in call from cuttlefish_escript:engage_cuttlefish/1 (/vernemq-build/_build/default/lib/cuttlefish/src/cuttlefish_escript.erl, line 361)
in call from cuttlefish_escript:generate/1 (/vernemq-build/_build/default/lib/cuttlefish/src/cuttlefish_escript.erl, line 255)

This error is caused by the two tabs I have inserted in the vernemq_broken.conf file.

As a comparison, for the file without errors:

/vernemq/erts-10.3.5/bin/escript /vernemq/erts-10.3.5/bin/cuttlefish -e /tmp/cf-test/etc -s /tmp/cf-test/schema -d /tmp/cf-test/output -c /tmp/cf-test/etc/vernemq_ok.conf generate -l debug

it will yield:
16:56:52.523 [debug] Lager installed handler error_logger_lager_h into error_logger
16:56:52.858 [debug] Cuttlefish set to debug level logging
16:56:52.863 [info] Checking /tmp/cf-test/etc/app.config exists... false
16:56:52.864 [info] Checking /tmp/cf-test/etc/vm.args exists... true
16:56:52.864 [info] /tmp/cf-test/etc/vm.args exists, generating app.config
16:56:52.864 [debug] Generating config in: "/tmp/cf-test/output/app.2019.08.01.16.56.52.config"
16:56:52.864 [debug] SchemaFiles: ["/tmp/cf-test/schema/10-vmq_server.schema","/tmp/cf-test/schema/12-vmq_plugin.schema","/tmp/cf-test/schema/13-vmq_acl.schema","/tmp/cf-test/schema/14-vmq_passwd.schema","/tmp/cf-test/schema/15-vmq_diversity.schema","/tmp/cf-test/schema/16-vmq_bcrypt.schema","/tmp/cf-test/schema/17-vmq_webhooks.schema","/tmp/cf-test/schema/18-vmq_bridge.schema","/tmp/cf-test/schema/19-vmq_swc.schema","/tmp/cf-test/schema/20-vmq_pulse.schema","/tmp/cf-test/schema/30-vmq.schema","/tmp/cf-test/schema/31-erlang_vm.schema","/tmp/cf-test/schema/32-riak_sysmon.schema","/tmp/cf-test/schema/33-eleveldb.schema"]
16:56:52.980 [debug] ConfFiles: ["/tmp/cf-test/etc/vernemq_ok.conf"]
16:56:52.992 [debug] Adding Defaults
16:56:52.993 [debug] Right Hand Side Substitutions
16:56:52.993 [debug] Applying Datatypes
16:56:53.012 [debug] Lager installed handler lager_backend_throttle into lager_event
16:56:53.025 [debug] Validation
16:56:53.034 [debug] Applied 1:1 Mappings
16:56:53.034 [debug] Running translation for vmq_server.allow_multiple_sessions
16:56:53.034 [debug] Running translation for vmq_server.queue_deliver_mode
16:56:53.034 [debug] Running translation for vmq_server.queue_type
16:56:53.034 [debug] Running translation for vmq_server.reg_views
16:56:53.034 [debug] Running translation for vmq_server.persistent_client_expiration
16:56:53.034 [debug] Running translation for vmq_server.max_last_will_delay
16:56:53.037 [debug] Running translation for vmq_server.message_size_limit
16:56:53.038 [debug] Running translation for vmq_server.http_modules
16:56:53.038 [debug] Running translation for vmq_server.listeners
16:56:53.053 [debug] Running translation for vmq_server.tcp_listen_options
16:56:53.053 [debug] Running translation for vmq_server.user_plugins
16:56:53.054 [debug] Running translation for vmq_plugin.default_schema_dir
16:56:53.054 [debug] "vmq_diversity.user_scripts" in Translations to drop...
16:56:53.054 [debug] Running translation for bcrypt.pool_size
16:56:53.054 [debug] Running translation for vmq_webhooks.user_webhooks
16:56:53.054 [debug] Running translation for vmq_bridge.registry_mfa
16:56:53.055 [debug] Running translation for vmq_bridge.config
16:56:53.106 [debug] Running translation for lager.handlers
16:56:53.106 [debug] Running translation for lager.crash_log
16:56:53.106 [debug] Running translation for lager.crash_log_count
16:56:53.106 [debug] "vm_args.+S" in Translations to drop...
16:56:53.106 [debug] "vm_args.+a" in Translations to drop...
16:56:53.107 [debug] "vm_args.+zdbbl" in Translations to drop...
16:56:53.107 [debug] Running translation for riak_sysmon.gc_ms_limit
16:56:53.107 [debug] Running translation for riak_sysmon.schedule_ms_limit
16:56:53.107 [debug] Running translation for riak_sysmon.heap_word_limit
16:56:53.107 [debug] Running translation for eleveldb.delete_threshold
16:56:53.107 [debug] Running translation for eleveldb.tiered_slow_level
16:56:53.107 [debug] Applied Translations
-config /tmp/cf-test/output/app.2019.08.01.16.56.52.config -args_file /tmp/cf-test/etc/vm.args -vm_args /tmp/cf-test/etc/vm.args

and now two files will be located in the output directory:

cf-test.zip

Could you please try to see if the error occurs with the newest cuttlefish, or point me to instructions how to run cuttlefish (fetching it from hex.pm) in a Docker container? I will be happy to try with the newest, then. At the moment I simply do not know how to go about it (I am a user of VerneMQ and know how to develop, but not in Erlang ) :-)

[lukebakken]

Thank you so much for this. Using cuttlefish built from develop, I can reproduce the error and also the success case (with some small edits to the schema/10-vmq_server.schema file to replace the vmq_schema_util calls with calls into filelib). I'm currently working on erlang-lager/lager#509 but will address this issue next.

[puresilk]

Happy to have helped :-)