[Australia, farmbot_os 6.4.9] AMQP connection restarts intermittently . . ? net.congestion?

jsimmonds · August 20, 2018, 10:39am

Logger records (UTC stamps)

10:16:49.916 [debug] Starting HTTP requests.


10:16:53.780 [debug] HTTP requests took: 3902460us.


10:16:53.900 [info]  Synced


10:16:53.916 [info]  [supervisor: {#PID<0.14013.0>, :amqp_connection_sup}, started: [pid: #PID<0.14014.0>, name: :connection_type_sup, mfargs: {:amqp_connection_type_sup, :start_link, []}, restart_type: :transient, shutdown: :infinity, child_type: :supervisor]]

10:16:53.918 [error] GenServer #PID<0.12151.0> terminating
** (stop) 'stopping because dependent process <0.12148.0> died: shutdown'
Last message: {:EXIT, #PID<0.12148.0>, :shutdown}
State: {:state, :amqp_network_connection, {:state, #Port<0.937>, "client 10.0.1.111:49771 -> 54.224.11.35:5672", 10, #PID<0.12154.0>, 131072, #PID<0.12150.0>, :undefined, false}, #PID<0.12153.0>, {:amqp_params_network, "device_3505", "eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJib3QiLCJzdWIiOjM1MDksImlhdCI6MTUzNDc1ODQxNSwianRpIjoiN2I2ZmU2ZjAtNjAwMy00MTEwLWFlZmEtNzBiMTFhMzY3NWU4IiwiaXNzIjoiLy9teS5mYXJtYm90LmlvOjQ0MyIsImV4cCI6MTUzODIxNDQxNSwibXF0dCI6ImJyaXNrLWJlYXIucm1xLmNsb3VkYW1xcC5jb20iLCJib3QiOiJkZXZpY2VfMzUwNSIsInZob3N0IjoidmJ6Y3hzcXIiLCJtcXR0X3dzIjoid3NzOi8vYnJpc2stYmVhci5ybXEuY2xvdWRhbXFwLmNvbTo0NDMvd3MvbXF0dCIsIm9zX3VwZGF0ZV9zZXJ2ZXIiOiJodHRwczovL2FwaS5naXRodWIuY29tL3JlcG9zL2Zhcm1ib3QvZmFybWJvdF9vcy9yZWxlYXNlcy9sYXRlc3QiLCJmd191cGRhdGVfc2VydmVyIjoiREVQUkVDQVRFRCIsImludGVyaW1fZW1haWwiOiJqb2huLmguc2ltbW9uZHNAb3V0bG9vay5jb20iLCJiZXRhX29zX3VwZGF0ZV9zZXJ2ZXIiOiJodHRwczovL2FwaS5naXRodWIuY29tL3JlcG9zL0Zhcm1Cb3QvZmFybWJvdF9vcy9yZWxlYXNlcy8xMjQ0NjEyOSJ9.ll5_EDFj414M5c6OYexuoGN9mbY1QYfNY-Zqpxm_ewOMpsEl0xI_a2VmRMHqs2VIfO3u7kyNdps1p6LS4tfipBLnUOPaMgCXWUZfhr992xYH8f22k6h3qdnZFmHx7ns_CM8BFoS0uejNEjc6hF2UvUNEaVkcTlAuaj1c5dmqLbmx2KBo2OP35eUOPLJF2I-mfvjl4iapHIpNPhD4QpNiqixqH0J3V_HThi6LKND_2oGZLrIaBUgK1rwAvglU86oN-OzcZmTCDRcHGYycJ5ZyRhJ4oINSRv_j1xNDb2KTZGGklisaXE16L5jtwGh2ip9LtgJKtSi69P0xNJwmjxUbQQ", "vbzcxsqr", 'brisk-bear.rmq.cloudamqp.com', 5672, 0, 0, 10, 60000, :none, [&:amqp_auth_mechanisms.plain/3, &:amqp_auth_mechanisms.amqplain/3], [], []}, 0, [{"capabilities", :table, [{"publisher_confirms", :bool, true}, {"exchange_exchange_bindings", :bool, true}, {"basic.nack", :bool, true}, {"consumer_cancel_notify", :bool, true}, {"connection.blocked", :bool, true}, {"consumer_priorities", :bool, true}, {"authentication_failure_close", :bool, true}, {"per_consumer_qos", :bool, true}, {"direct_reply_to", :bool, true}]}, {"cluster_name", :longstr, "brisk-bear"}, {"copyright", :longstr, "Copyright (C) 2007-2017 Pivotal Software, Inc."}, {"information", :longstr, "Licensed under the MPL.  See http://www.rabbitmq.com/"}, {"platform", :longstr, "Erlang/OTP 19.3"}, {"product", :longstr, "RabbitMQ"}, {"version", :longstr, "3.6.12"}], :none, false}

10:16:53.922 [error] Process #PID<0.12151.0> terminating
** (exit) 'stopping because dependent process <0.12148.0> died: shutdown'
    (stdlib) gen_server.erl:751: :gen_server.handle_common_reply/8
    (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Initial Call: :amqp_gen_connection.init/1
Ancestors: [#PID<0.12149.0>, :amqp_sup, #PID<0.579.0>]
Message Queue Length: 0
Messages: []
Links: [#PID<0.12149.0>, #Port<0.937>]
Dictionary: [process_name: {:amqp_gen_connection, "client 10.0.1.111:49771 -> 54.224.11.35:5672"}, gen_server_call_timeout: 60000]
Trapping Exits: true
Status: :running
Heap Size: 987
Stack Size: 27
Reductions: 32146

10:16:53.923 [info]  [supervisor: {#PID<0.14013.0>, :amqp_connection_sup}, started: [pid: #PID<0.14015.0>, name: :connection, mfargs: {:amqp_gen_connection, :start_link, [#PID<0.14014.0>, {:amqp_params_network, "device_3505", "eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJib3QiLCJzdWIiOjM1MDksImlhdCI6MTUzNDc2MDIwOSwianRpIjoiOGI4ZjQxMWYtZWY4Yi00YjA4LTk1MDUtNmZkNzRmYzY1NDRkIiwiaXNzIjoiLy9teS5mYXJtYm90LmlvOjQ0MyIsImV4cCI6MTUzODIxNjIwOSwibXF0dCI6ImJyaXNrLWJlYXIucm1xLmNsb3VkYW1xcC5jb20iLCJib3QiOiJkZXZpY2VfMzUwNSIsInZob3N0IjoidmJ6Y3hzcXIiLCJtcXR0X3dzIjoid3NzOi8vYnJpc2stYmVhci5ybXEuY2xvdWRhbXFwLmNvbTo0NDMvd3MvbXF0dCIsIm9zX3VwZGF0ZV9zZXJ2ZXIiOiJodHRwczovL2FwaS5naXRodWIuY29tL3JlcG9zL2Zhcm1ib3QvZmFybWJvdF9vcy9yZWxlYXNlcy9sYXRlc3QiLCJmd191cGRhdGVfc2VydmVyIjoiREVQUkVDQVRFRCIsImludGVyaW1fZW1haWwiOiJqb2huLmguc2ltbW9uZHNAb3V0bG9vay5jb20iLCJiZXRhX29zX3VwZGF0ZV9zZXJ2ZXIiOiJodHRwczovL2FwaS5naXRodWIuY29tL3JlcG9zL0Zhcm1Cb3QvZmFybWJvdF9vcy9yZWxlYXNlcy8xMjQ0NjEyOSJ9.PbPVyYlcn5VCBA5brtTNj4155ylQfn693J4FBpXdRg0L3tX-k6DK2KKvFmvehtnpSyyHhB0Sejwa0xNhpw0t2PXq0Qjf_kIG6PwfYh_meZaWARpxy3q33VhW5RngaMAdCzkehRmoiocYokQevIZSCtKVMx33rLOU4EcHJjbrYKG0fZzVNqFFyWgmgjor6bsV1MnIl9G7U06bNmtrC4dYC2PLmJ00R7FSNh41BbNgk-21tZJo0RbFXQm33aoJ4WtwYwceyRWCJyFxJtTrT7oJ9dmMhmDPlql3kz0uH03cTUJ3Exu6QdUULJyDUOGwAourqTlC-TqDFPPafbLuoIeUeQ", "vbzcxsqr", 'brisk-bear.rmq.cloudamqp.com', 5672, 0, 0, 10, 60000, :none, [&:amqp_auth_mechanisms.plain/3, &:amqp_auth_mechanisms.amqplain/3], [], []}]}, restart_type: :intrinsic, shutdown: :brutal_kill, child_type: :worker]]

10:16:53.936 [error] Failure while translating Erlang's logger event
** (FunctionClauseError) no function clause matching in Logger.Translator.child_info/2
    (logger) lib/logger/translator.ex:320: Logger.Translator.child_info(:debug, [name: :connection, mfargs: {:amqp_gen_connection, :start_link, [#PID<0.12150.0>, {:amqp_params_network, "device_3505", "eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJib3QiLCJzdWIiOjM1MDksImlhdCI6MTUzNDc1ODQxNSwianRpIjoiN2I2ZmU2ZjAtNjAwMy00MTEwLWFlZmEtNzBiMTFhMzY3NWU4IiwiaXNzIjoiLy9teS5mYXJtYm90LmlvOjQ0MyIsImV4cCI6MTUzODIxNDQxNSwibXF0dCI6ImJyaXNrLWJlYXIucm1xLmNsb3VkYW1xcC5jb20iLCJib3QiOiJkZXZpY2VfMzUwNSIsInZob3N0IjoidmJ6Y3hzcXIiLCJtcXR0X3dzIjoid3NzOi8vYnJpc2stYmVhci5ybXEuY2xvdWRhbXFwLmNvbTo0NDMvd3MvbXF0dCIsIm9zX3VwZGF0ZV9zZXJ2ZXIiOiJodHRwczovL2FwaS5naXRodWIuY29tL3JlcG9zL2Zhcm1ib3QvZmFybWJvdF9vcy9yZWxlYXNlcy9sYXRlc3QiLCJmd191cGRhdGVfc2VydmVyIjoiREVQUkVDQVRFRCIsImludGVyaW1fZW1haWwiOiJqb2huLmguc2ltbW9uZHNAb3V0bG9vay5jb20iLCJiZXRhX29zX3VwZGF0ZV9zZXJ2ZXIiOiJodHRwczovL2FwaS5naXRodWIuY29tL3JlcG9zL0Zhcm1Cb3QvZmFybWJvdF9vcy9yZWxlYXNlcy8xMjQ0NjEyOSJ9.ll5_EDFj414M5c6OYexuoGN9mbY1QYfNY-Zqpxm_ewOMpsEl0xI_a2VmRMHqs2VIfO3u7kyNdps1p6LS4tfipBLnUOPaMgCXWUZfhr992xYH8f22k6h3qdnZFmHx7ns_CM8BFoS0uejNEjc6hF2UvUNEaVkcTlAuaj1c5dmqLbmx2KBo2OP35eUOPLJF2I-mfvjl4iapHIpNPhD4QpNiqixqH0J3V_HThi6LKND_2oGZLrIaBUgK1rwAvglU86oN-OzcZmTCDRcHGYycJ5ZyRhJ4oINSRv_j1xNDb2KTZGGklisaXE16L5jtwGh2ip9LtgJKtSi69P0xNJwmjxUbQQ", "vbzcxsqr", 'brisk-bear.rmq.cloudamqp.com', 5672, 0, 0, 10, 60000, :none, [&:amqp_auth_mechanisms.plain/3, &:amqp_auth_mechanisms.amqplain/3], [], []}]}, restart_type: :intrinsic, shutdown: :brutal_kill, child_type: :worker])
    (logger) lib/logger/translator.ex:294: Logger.Translator.report_supervisor/2
    (logger) lib/logger/erlang_handler.ex:104: Logger.ErlangHandler.translate/6
    (logger) lib/logger/erlang_handler.ex:97: Logger.ErlangHandler.translate/5
    (logger) lib/logger/erlang_handler.ex:27: anonymous fn/3 in Logger.ErlangHandler.log/2
    (logger) lib/logger.ex:764: Logger.normalize_message/2
    (logger) lib/logger.ex:625: Logger.bare_log/3
    (kernel) logger_backend.erl:51: :logger_backend.call_handlers/3


10:16:53.949 [error] Failure while translating Erlang's logger event
** (FunctionClauseError) no function clause matching in Logger.Translator.child_info/2
    (logger) lib/logger/translator.ex:320: Logger.Translator.child_info(:debug, [name: :connection, mfargs: {:amqp_gen_connection, :start_link, [#PID<0.12150.0>, {:amqp_params_network, "device_3505", "eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJib3QiLCJzdWIiOjM1MDksImlhdCI6MTUzNDc1ODQxNSwianRpIjoiN2I2ZmU2ZjAtNjAwMy00MTEwLWFlZmEtNzBiMTFhMzY3NWU4IiwiaXNzIjoiLy9teS5mYXJtYm90LmlvOjQ0MyIsImV4cCI6MTUzODIxNDQxNSwibXF0dCI6ImJyaXNrLWJlYXIucm1xLmNsb3VkYW1xcC5jb20iLCJib3QiOiJkZXZpY2VfMzUwNSIsInZob3N0IjoidmJ6Y3hzcXIiLCJtcXR0X3dzIjoid3NzOi8vYnJpc2stYmVhci5ybXEuY2xvdWRhbXFwLmNvbTo0NDMvd3MvbXF0dCIsIm9zX3VwZGF0ZV9zZXJ2ZXIiOiJodHRwczovL2FwaS5naXRodWIuY29tL3JlcG9zL2Zhcm1ib3QvZmFybWJvdF9vcy9yZWxlYXNlcy9sYXRlc3QiLCJmd191cGRhdGVfc2VydmVyIjoiREVQUkVDQVRFRCIsImludGVyaW1fZW1haWwiOiJqb2huLmguc2ltbW9uZHNAb3V0bG9vay5jb20iLCJiZXRhX29zX3VwZGF0ZV9zZXJ2ZXIiOiJodHRwczovL2FwaS5naXRodWIuY29tL3JlcG9zL0Zhcm1Cb3QvZmFybWJvdF9vcy9yZWxlYXNlcy8xMjQ0NjEyOSJ9.ll5_EDFj414M5c6OYexuoGN9mbY1QYfNY-Zqpxm_ewOMpsEl0xI_a2VmRMHqs2VIfO3u7kyNdps1p6LS4tfipBLnUOPaMgCXWUZfhr992xYH8f22k6h3qdnZFmHx7ns_CM8BFoS0uejNEjc6hF2UvUNEaVkcTlAuaj1c5dmqLbmx2KBo2OP35eUOPLJF2I-mfvjl4iapHIpNPhD4QpNiqixqH0J3V_HThi6LKND_2oGZLrIaBUgK1rwAvglU86oN-OzcZmTCDRcHGYycJ5ZyRhJ4oINSRv_j1xNDb2KTZGGklisaXE16L5jtwGh2ip9LtgJKtSi69P0xNJwmjxUbQQ", "vbzcxsqr", 'brisk-bear.rmq.cloudamqp.com', 5672, 0, 0, 10, 60000, :none, [&:amqp_auth_mechanisms.plain/3, &:amqp_auth_mechanisms.amqplain/3], [], []}]}, restart_type: :intrinsic, shutdown: :brutal_kill, child_type: :worker])
    (logger) lib/logger/translator.ex:294: Logger.Translator.report_supervisor/2
    (logger) lib/logger/erlang_handler.ex:104: Logger.ErlangHandler.translate/6
    (logger) lib/logger/erlang_handler.ex:97: Logger.ErlangHandler.translate/5
    (logger) lib/logger/erlang_handler.ex:27: anonymous fn/3 in Logger.ErlangHandler.log/2
    (logger) lib/logger.ex:764: Logger.normalize_message/2
    (logger) lib/logger.ex:625: Logger.bare_log/3
    (kernel) logger_backend.erl:51: :logger_backend.call_handlers/3


10:16:54.513 [info]  [supervisor: {#PID<0.14014.0>, :amqp_connection_type_sup}, started: [pid: #PID<0.14017.0>, name: :channel_sup_sup, mfargs: {:amqp_channel_sup_sup, :start_link, [:network, #PID<0.14015.0>, "client 10.0.1.111:42879 -> 54.224.11.35:5672"]}, restart_type: :intrinsic, shutdown: :infinity, child_type: :supervisor]]

10:16:54.515 [info]  [supervisor: {#PID<0.14014.0>, :amqp_connection_type_sup}, started: [pid: #PID<0.14018.0>, name: :channels_manager, mfargs: {:amqp_channels_manager, :start_link, [#PID<0.14015.0>, "client 10.0.1.111:42879 -> 54.224.11.35:5672", #PID<0.14017.0>]}, restart_type: :transient, shutdown: 30000, child_type: :worker]]

connor · August 20, 2018, 2:58pm

Be careful posting logs from the console. Some of them will have your device’s JWT embedded in it.
(this post does not)

FarmBot restarts AMQP every so often when a JWT is fetched. JWT’s are set to expire at a certain time, so FarmBot needs to get a new one and reconnect to the broker whenever this happens.

The excessive console logging is an unfortunate side effect.

jsimmonds · August 21, 2018, 1:46am

Thanks Connor for that warning and your explanation makes sense as the ‘died:’ reason is shutdown for that AMQP process . . but the following

Failure while translating Erlang's logger event

could be fixed I imagine (?)

jsimmonds · August 21, 2018, 9:02am

I could have a crack at a fix for that collateral error bug . . you (@Connor) seem to be a very busy person at the moment . . but I’m quite the newbie in Elixir development, so may take a while I’ll have a go and send in a PR (observing the usual pre-requisites)

connor · August 21, 2018, 11:50am

It’s actually a bug in Elixirs Logger translating an Erlang Logger message. I have an issue open o n the GitHub repository for the AMQP client, but they don’t seem to care to fix this kind of thing a lot of times since it doesn’t hurt functionality. I’d love a fix/work around if you can figure one out tho.

jsimmonds · August 21, 2018, 11:59am

Thanks for that “head start” I’m heading over to sleuth around.

jsimmonds · August 24, 2018, 2:01am

[error] Failure while translating Erlang's logger event

might be corrected already in Elixir 1.7.2 by the PR 7892 merge.

Will test this as soon I’m able to build farmbot_os (version 6.4.10) with that Elixir version.
Currently fails right toward the end of the process with

==> Release failed, during .boot generation:
    Undefined applications: [elixir_make,dialyzer]

[I’m using Ubuntu 18.04.1 LTS + Erlang/OTP 21 + Elixir 1.7.2 and clean clones of farmbot_os (staging) and Arduino code]

connor · August 24, 2018, 3:26pm

i checked asked around yesterday: https://github.com/elixir-lang/elixir/issues/8126

It’s actually been fixed in Elixir 1.7. Unfortunately there is a bug in Mix that breaks release creation.

FWIW if you want to compile FarmbotOS, you should check out ASDF. Currently OTP-21.04, and Elixir 1.6.6 are used.

jsimmonds · August 26, 2018, 12:31am

Haven’t bothered, yet, with ASDF. Just grabbed the pre-compiled binaries for Elixir 1.7.3 (which has that Mix fix).

Got a build Ok, but suddenly a couple of the .so built for Linux have ELFCLASS64 so FarmBot_OS crashes.

Think I’ll step back and wait for the ‘official’ release which supports Elixir 1.7+ … ( love being a bleeding-edger, though

connor · August 26, 2018, 12:56am

Yeah that sounds like a bug with either Elixir make or Nerves. With Elixirconf coming up the core team of Nerves, (including myself) are only supporting 1.6.6. Probably during or after Elixir Conf, we will get 1.7.3 support.

connor · August 28, 2018, 5:05pm

I’ve started drafting up an update here.

For what it’s worth not much needed to be changed on FBOS. I had to update the custom linux system dependency and just bump version numbers and it magically worked.

jsimmonds · August 29, 2018, 5:39am

End OP : the FarmBot OS log is quieter now

My Rpi3B+ is now running like the ‘proverbial train’ on FBOS 6.4.10 with Elixir 1.7.3 ! Thanks Connor.

Relax and enjoy ElixirConf to the max.

( and now I need to find out how to config the WiFi regulatory_domain to “AU” (-: )
( oh, and SSH works nicely, too . . )