Uploaded image for project: 'StreamPipes'
  1. StreamPipes
  2. STREAMPIPES-574

MQTT Adapter Suddently Unable to Connect due to Authorization Issue

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Fixed
    • None
    • None
    • Connect
    • None

    Description

      Issue

      One of our MQTT Adapters we use as a data source for one of our production pipelines stopped delivering data. After checking the logs (see below) it was found that the MQTT client was unable to connect to the broker on account of an authorization problem.

      After double-checking that the credentials did not change (via an MQTT command line client), the pipeline was stopped and the adapter restarted. This did not solve the issue. Checking the logs verified that the same error occurred.

      Extra Info

      We have had a couple of Kubernetes Node problems lately which might have randomly deleted / rescheduled Pods onto other Nodes.

      Connect Worker Logs:

      ❯ ks2 logs connect-worker-7c9569d477-kv4qp
      14:52:35,928 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
      14:52:35,929 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
      14:52:35,929 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [jar:file:/streampipes-connect
      -adapters.jar!/BOOT-INF/lib/streampipes-commons-0.68.0.jar!/logback.xml]
      14:52:35,932 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs multiple times on the classpath.
      14:52:35,932 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [jar:file:/streampipes-connec
      t-adapters.jar!/BOOT-INF/lib/streampipes-commons-0.68.0.jar!/logback.xml]
      14:52:35,932 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [jar:file:/streampipes-connec
      t-adapters.jar!/BOOT-INF/lib/plc4j-driver-s7-0.8.0.jar!/logback.xml]
      14:52:35,959 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@612d8c37 - URL [jar:file:/streampipes-connect-adapters.ja
      r!/BOOT-INF/lib/streampipes-commons-0.68.0.jar!/logback.xml] is not of type file
      14:52:36,012 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
      14:52:36,016 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.C
      onsoleAppender]
      14:52:36,024 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
      14:52:36,076 |-WARN in ch.qos.logback.core.ConsoleAppender[STDOUT] - This appender no longer admits a layout as a sub-component, set
      an encoder instead.
      14:52:36,077 |-WARN in ch.qos.logback.core.ConsoleAppender[STDOUT] - To ensure compatibility, wrapping your layout in LayoutWrappingE
      ncoder.
      14:52:36,077 |-WARN in ch.qos.logback.core.ConsoleAppender[STDOUT] - See also http://logback.qos.ch/codes.html#layoutInsteadOfEncoder
       for details
      14:52:36,078 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.streampipes] to INFO
      14:52:36,078 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.lightcouch] to ERROR
      14:52:36,078 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.kafka] to ERROR
      14:52:36,078 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
      14:52:36,078 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
      14:52:36,078 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
      14:52:36,080 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@895f9399 - Registering current configuration as safe fallback p
      oint14:52:36.157 SP [main] INFO  o.a.s.config.consul.ConsulSpConfig - Trying to connect to Consul to register config items
      14:52:36.167 SP [main] INFO  o.a.s.config.consul.ConsulSpConfig - Successfully connected to Consul
      14:52:37.315 SP [main] INFO  o.a.s.c.c.w.i.AdapterWorkerContainer - Started StreamPipes Connect Resource in WORKER mode
       _______ __                              ______ __
      |     __|  |_.----.-----.---.-.--------.|   __ \__|.-----.-----.-----.
      |__     |   _|   _|  -__|  _  |        ||    __/  ||  _  |  -__|__ --|
      |_______|____|__| |_____|___._|__|__|__||___|  |__||   __|_____|_____|
                                                         |__|
      ** StreamPipes Connect Worker **log4j:WARN No appenders could be found for logger (org.jboss.logging).
      log4j:WARN Please initialize the log4j system properly.
      log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.
      14:52:38.132 SP [main] INFO  o.a.s.connect.ConnectAdapterInit - Starting ConnectAdapterInit v0.68.0 using Java 1.8.0_292 on connect-w
      orker-7c9569d477-kv4qp with PID 1 (/streampipes-connect-adapters.jar started by root in /)
      14:52:38.137 SP [main] INFO  o.a.s.connect.ConnectAdapterInit - No active profile set, falling back to default profiles: default
      14:52:39.667 SP [main] INFO  o.s.b.w.s.c.ServletWebServerApplicationContext - Root WebApplicationContext: initialization completed in
       1452 ms
      14:52:40.307 SP [main] INFO  o.s.b.w.e.undertow.UndertowWebServer - Undertow started on port(s) 8098 (http)
      14:52:40.319 SP [main] INFO  o.a.s.connect.ConnectAdapterInit - Started ConnectAdapterInit in 2.834 seconds (JVM running for 4.912)
      14:52:40.322 SP [main] INFO  o.a.s.c.c.w.i.AdapterWorkerContainer - Trying to connect to master: http://backend:8030/streampipes-back
      end
      14:52:42.426 SP [XNIO-1 task-1] INFO  o.a.s.config.consul.ConsulSpConfig - Trying to connect to Consul to register config items
      14:52:42.428 SP [XNIO-1 task-1] INFO  o.a.s.config.consul.ConsulSpConfig - Successfully connected to Consul
      14:52:42.488 SP [XNIO-1 task-1] INFO  o.a.s.m.kafka.SpKafkaProducer - Kafka producer: Connecting to org.apache.streampipes.connect.73
      653e0e-b5d5-4af0-b071-65897410604a
      14:52:43.004 SP [XNIO-1 task-1] ERROR o.a.s.m.kafka.SpKafkaProducer - Could not create topic: org.apache.streampipes.connect.73653e0e
      -b5d5-4af0-b071-65897410604a on broker null:0
      14:52:43.084 SP [XNIO-1 task-1] INFO  o.a.s.c.c.worker.rest.WorkerResource - Stream adapter with id http://backend:8030/streampipes-b
      ackend/api/v2/connect/sysops@edi.gmbh/master/sources/9030f401-a579-4b9a-bb8b-44bb3d3d0ae5 successfully started
      14:52:43.239 SP [XNIO-1 task-1] INFO  o.a.s.m.kafka.SpKafkaProducer - Kafka producer: Connecting to org.apache.streampipes.connect.eb
      1b01e3-38c7-4e03-a738-f36a49a21436
      14:52:43.255 SP [XNIO-1 task-1] ERROR o.a.s.m.kafka.SpKafkaProducer - Could not create topic: org.apache.streampipes.connect.eb1b01e3
      -38c7-4e03-a738-f36a49a21436 on broker null:0
      14:52:43.262 SP [XNIO-1 task-1] INFO  o.a.s.c.c.worker.rest.WorkerResource - Stream adapter with id http://backend:8030/streampipes-b
      ackend/api/v2/connect/sysops@edi.gmbh/master/sources/86488fd5-8ff5-42b3-b23d-9e3229c6c7ab successfully started
      14:52:43.369 SP [main] INFO  o.a.s.c.c.w.i.AdapterWorkerContainer - Successfully connected to master: http://backend:8030/streampipes
      -backend Worker is now running.
      14:52:48.456 SP [XNIO-1 task-1] INFO  o.a.s.m.kafka.SpKafkaProducer - Kafka producer: Connecting to org.apache.streampipes.connect.73
      653e0e-b5d5-4af0-b071-65897410604a
      14:52:48.478 SP [XNIO-1 task-1] ERROR o.a.s.m.kafka.SpKafkaProducer - Could not create topic: org.apache.streampipes.connect.73653e0e
      -b5d5-4af0-b071-65897410604a on broker null:0
      14:52:48.487 SP [XNIO-1 task-1] INFO  o.a.s.c.c.worker.rest.WorkerResource - Stream adapter with id http://backend:8030/streampipes-b
      ackend/api/v2/connect/sysops@edi.gmbh/master/sources/9030f401-a579-4b9a-bb8b-44bb3d3d0ae5 successfully started
      14:53:07.013 SP [XNIO-1 task-1] INFO  o.a.s.c.c.worker.rest.WorkerResource - Stream adapter with id http://backend:8030/streampipes-b
      ackend/api/v2/connect/sysops@edi.gmbh/master/sources/9030f401-a579-4b9a-bb8b-44bb3d3d0ae5 successfully stopped
      14:53:08.402 SP [XNIO-1 task-1] INFO  o.a.s.c.c.worker.rest.WorkerResource - Stream adapter with id http://backend:8030/streampipes-b
      ackend/api/v2/connect/sysops@edi.gmbh/master/sources/86488fd5-8ff5-42b3-b23d-9e3229c6c7ab successfully stopped
      14:53:14.544 SP [XNIO-1 task-5] INFO  o.a.s.m.kafka.SpKafkaProducer - Kafka producer: Connecting to org.apache.streampipes.connect.73
      653e0e-b5d5-4af0-b071-65897410604a
      14:53:14.572 SP [XNIO-1 task-5] ERROR o.a.s.m.kafka.SpKafkaProducer - Could not create topic: org.apache.streampipes.connect.73653e0e
      -b5d5-4af0-b071-65897410604a on broker null:0
      14:53:14.585 SP [XNIO-1 task-5] INFO  o.a.s.c.c.worker.rest.WorkerResource - Stream adapter with id http://backend:8030/streampipes-b
      ackend/api/v2/connect/sysops@edi.gmbh/master/sources/9030f401-a579-4b9a-bb8b-44bb3d3d0ae5 successfully started
      14:53:15.971 SP [XNIO-1 task-5] INFO  o.a.s.m.kafka.SpKafkaProducer - Kafka producer: Connecting to org.apache.streampipes.connect.eb
      1b01e3-38c7-4e03-a738-f36a49a21436
      14:53:16.025 SP [XNIO-1 task-5] ERROR o.a.s.m.kafka.SpKafkaProducer - Could not create topic: org.apache.streampipes.connect.eb1b01e3
      -38c7-4e03-a738-f36a49a21436 on broker null:0
      14:53:16.034 SP [XNIO-1 task-5] INFO  o.a.s.c.c.worker.rest.WorkerResource - Stream adapter with id http://backend:8030/streampipes-b
      ackend/api/v2/connect/sysops@edi.gmbh/master/sources/86488fd5-8ff5-42b3-b23d-9e3229c6c7ab successfully started
      org.fusesource.mqtt.client.MQTTException: Could not connect: CONNECTION_REFUSED_NOT_AUTHORIZED
              at org.fusesource.mqtt.client.CallbackConnection$LoginHandler$1.onTransportCommand(CallbackConnection.java:362)
              at org.fusesource.hawtdispatch.transport.TcpTransport.drainInbound(TcpTransport.java:713)
              at org.fusesource.hawtdispatch.transport.TcpTransport$6.run(TcpTransport.java:592)
              at org.fusesource.hawtdispatch.internal.NioDispatchSource$3.run(NioDispatchSource.java:209)
              at org.fusesource.hawtdispatch.internal.SerialDispatchQueue.run(SerialDispatchQueue.java:100)
              at org.fusesource.hawtdispatch.internal.pool.SimpleThread.run(SimpleThread.java:77)
      09:47:47.921 SP [XNIO-1 task-4] INFO  o.a.s.c.c.worker.rest.WorkerResource - Stream adapter with id http://backend:8030/streampipes-b
      ackend/api/v2/connect/sysops@edi.gmbh/master/sources/86488fd5-8ff5-42b3-b23d-9e3229c6c7ab successfully stopped
      09:47:49.882 SP [XNIO-1 task-4] INFO  o.a.s.m.kafka.SpKafkaProducer - Kafka producer: Connecting to org.apache.streampipes.connect.eb
      1b01e3-38c7-4e03-a738-f36a49a21436
      09:47:49.904 SP [XNIO-1 task-4] ERROR o.a.s.m.kafka.SpKafkaProducer - Could not create topic: org.apache.streampipes.connect.eb1b01e3
      -38c7-4e03-a738-f36a49a21436 on broker null:0
      09:47:49.912 SP [XNIO-1 task-4] INFO  o.a.s.c.c.worker.rest.WorkerResource - Stream adapter with id http://backend:8030/streampipes-b
      ackend/api/v2/connect/sysops@edi.gmbh/master/sources/86488fd5-8ff5-42b3-b23d-9e3229c6c7ab successfully started
      org.fusesource.mqtt.client.MQTTException: Could not connect: CONNECTION_REFUSED_NOT_AUTHORIZED
              at org.fusesource.mqtt.client.CallbackConnection$LoginHandler$1.onTransportCommand(CallbackConnection.java:362)
              at org.fusesource.hawtdispatch.transport.TcpTransport.drainInbound(TcpTransport.java:713)
              at org.fusesource.hawtdispatch.transport.TcpTransport$6.run(TcpTransport.java:592)
              at org.fusesource.hawtdispatch.internal.NioDispatchSource$3.run(NioDispatchSource.java:209)
              at org.fusesource.hawtdispatch.internal.SerialDispatchQueue.run(SerialDispatchQueue.java:100)
              at org.fusesource.hawtdispatch.internal.pool.SimpleThread.run(SimpleThread.java:77)
      09:16:55.959 SP [XNIO-1 task-1] INFO  o.a.s.c.c.worker.rest.WorkerResource - Stream adapter with id http://backend:8030/streampipes-b
      ackend/api/v2/connect/sysops@edi.gmbh/master/sources/86488fd5-8ff5-42b3-b23d-9e3229c6c7ab successfully stopped
      09:17:29.645 SP [XNIO-1 task-1] INFO  o.a.s.m.kafka.SpKafkaProducer - Kafka producer: Connecting to org.apache.streampipes.connect.eb
      1b01e3-38c7-4e03-a738-f36a49a21436
      09:17:29.668 SP [XNIO-1 task-1] ERROR o.a.s.m.kafka.SpKafkaProducer - Could not create topic: org.apache.streampipes.connect.eb1b01e3
      -38c7-4e03-a738-f36a49a21436 on broker null:0
      09:17:29.675 SP [XNIO-1 task-1] INFO  o.a.s.c.c.worker.rest.WorkerResource - Stream adapter with id http://backend:8030/streampipes-b
      ackend/api/v2/connect/sysops@edi.gmbh/master/sources/86488fd5-8ff5-42b3-b23d-9e3229c6c7ab successfully started
      org.fusesource.mqtt.client.MQTTException: Could not connect: CONNECTION_REFUSED_NOT_AUTHORIZED
              at org.fusesource.mqtt.client.CallbackConnection$LoginHandler$1.onTransportCommand(CallbackConnection.java:362)
              at org.fusesource.hawtdispatch.transport.TcpTransport.drainInbound(TcpTransport.java:713)
              at org.fusesource.hawtdispatch.transport.TcpTransport$6.run(TcpTransport.java:592)
              at org.fusesource.hawtdispatch.internal.NioDispatchSource$3.run(NioDispatchSource.java:209)
              at org.fusesource.hawtdispatch.internal.SerialDispatchQueue.run(SerialDispatchQueue.java:100)
              at org.fusesource.hawtdispatch.internal.pool.SimpleThread.run(SimpleThread.java:77)
      09:17:31.744 SP [XNIO-1 task-1] INFO  o.a.s.c.c.worker.rest.WorkerResource - Stream adapter with id http://backend:8030/streampipes-b
      ackend/api/v2/connect/sysops@edi.gmbh/master/sources/86488fd5-8ff5-42b3-b23d-9e3229c6c7ab successfully stopped
      09:18:00.892 SP [XNIO-1 task-2] INFO  o.a.s.m.kafka.SpKafkaProducer - Kafka producer: Connecting to org.apache.streampipes.connect.eb
      1b01e3-38c7-4e03-a738-f36a49a21436
      09:18:00.916 SP [XNIO-1 task-2] ERROR o.a.s.m.kafka.SpKafkaProducer - Could not create topic: org.apache.streampipes.connect.eb1b01e3
      -38c7-4e03-a738-f36a49a21436 on broker null:0
      09:18:00.924 SP [XNIO-1 task-2] INFO  o.a.s.c.c.worker.rest.WorkerResource - Stream adapter with id http://backend:8030/streampipes-b
      ackend/api/v2/connect/sysops@edi.gmbh/master/sources/86488fd5-8ff5-42b3-b23d-9e3229c6c7ab successfully started
      org.fusesource.mqtt.client.MQTTException: Could not connect: CONNECTION_REFUSED_NOT_AUTHORIZED
              at org.fusesource.mqtt.client.CallbackConnection$LoginHandler$1.onTransportCommand(CallbackConnection.java:362)
              at org.fusesource.hawtdispatch.transport.TcpTransport.drainInbound(TcpTransport.java:713)
              at org.fusesource.hawtdispatch.transport.TcpTransport$6.run(TcpTransport.java:592)
              at org.fusesource.hawtdispatch.internal.NioDispatchSource$3.run(NioDispatchSource.java:209)
              at org.fusesource.hawtdispatch.internal.SerialDispatchQueue.run(SerialDispatchQueue.java:100)
              at org.fusesource.hawtdispatch.internal.pool.SimpleThread.run(SimpleThread.java:77)
      

      Attachments

        Activity

          People

            Unassigned Unassigned
            doemski Dominick Madden
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: