0

Spring 統合 (Paho MQTT クライアント 0.4.0 を使用して Tomcat 7 で実行されている 4.0.3.RELEASE) の MQTT サブスクライバーの 1 つで問題が発生しています。

この問題は、頻繁に使用されるトピック (大量のメッセージ) のサブスクライバーにあります。トピックにメッセージを送信するデバイスは、GPRS を介して接続する現場のデバイスです。

Spring 統合とブローカー (Mosquitto) は同じサーバー上で実行されています。

この問題は、サーバーを再起動せずに Tomcat で数回再デプロイした後に発生するようです。問題が発生した場合、Tomcat インスタンスを再起動すると、しばらくの間問題が解決されます。

これが一連のイベントです（mosquittoログから。vdm-dev-liveサブスクライバーは問題のあるものです）：

春の統合を開始すると、すべてのサブスクライバーがさまざまなトピックに接続していることがわかります。

1409645645: New client connected from xxx.xx.xx.xxx as vdm-dev-live (c1, k60).
1409645645: Sending CONNACK to vdm-dev-live (0)
1409645645: Received SUBSCRIBE from vdm-dev-live
1409645645:     vdm/+/+/+/liveData (QoS 1)
1409645645: Sending SUBACK to vdm-dev-live
1409645645: New connection from xxx.xx.xx.xxx on port 1873.
1409645645: New client connected from xxx.xx.xx.xxx as vdm-dev-fmReq (c1, k60).
1409645645: Sending CONNACK to vdm-dev-fmReq (0)
1409645645: Received SUBSCRIBE from vdm-dev-fmReq
1409645645:     vdm/+/+/+/firmware/request (QoS 1)
1409645645: Sending SUBACK to vdm-dev-fmReq
1409645645: New connection from xxx.xx.xx.xxx on port 1873.
1409645645: New client connected from xxx.xx.xx.xxx as vdm-dev-cfgReq (c1, k60).
1409645645: Sending CONNACK to vdm-dev-cfgReq (0)
1409645645: Received SUBSCRIBE from vdm-dev-cfgReq
1409645645:     vdm/+/+/+/config/request (QoS 1)
1409645645: Sending SUBACK to vdm-dev-cfgReq
1409645645: New connection from xxx.xx.xx.xxx on port 1873.
1409645645: New client connected from xxx.xx.xx.xxx as vdm-dev-fmStat (c1, k60).
1409645645: Sending CONNACK to vdm-dev-fmStat (0)
1409645645: Received SUBSCRIBE from vdm-dev-fmStat
1409645645:     vdm/+/+/firmware/status (QoS 1)
1409645645: Sending SUBACK to vdm-dev-fmStat

メッセージが行き来するのを見る

1409645646: Received PUBLISH from 89320292400015932480 (d0, q0, r0, m0, 'vdm/89320292400015932480/WVWZZZ1KZDP005350/4.2/liveData', ... (36 bytes))
1409645646: Sending PUBLISH to vdm-dev-live (d0, q0, r0, m0, 'vdm/89320292400015932480/WVWZZZ1KZDP005350/4.2/liveData', ... (36 bytes))
1409645646: Sending PUBLISH to Yo3zC8ou5y (d0, q0, r0, m0, 'vdm/89320292400015932480/WVWZZZ1KZDP005350/4.2/liveData', ... (36 bytes))
1409645646: Sending PUBLISH to mqttjs_31f1e3f7cd0e0aed (d0, q0, r0, m0, 'vdm/89320292400015932480/WVWZZZ1KZDP005350/4.2/liveData', ... (36 bytes))
1409645648: Received PUBLISH from 89320292400015932480 (d0, q0, r0, m0, 'vdm/89320292400015932480/WVWZZZ1KZDP005350/4.2/liveData', ... (36 bytes))
1409645648: Sending PUBLISH to vdm-dev-live (d0, q0, r0, m0, 'vdm/89320292400015932480/WVWZZZ1KZDP005350/4.2/liveData', ... (36 bytes))
1409645648: Sending PUBLISH to Yo3zC8ou5y (d0, q0, r0, m0, 'vdm/89320292400015932480/WVWZZZ1KZDP005350/4.2/liveData', ... (36 bytes))
1409645648: Sending PUBLISH to mqttjs_31f1e3f7cd0e0aed (d0, q0, r0, m0, 'vdm/89320292400015932480/WVWZZZ1KZDP005350/4.2/liveData', ... (36 bytes))
1409645650: Received PUBLISH from 89320292400015932480 (d0, q0, r0, m0, 'vdm/89320292400015932480/WVWZZZ1KZDP005350/4.2/liveData', ... (36 bytes))
1409645650: Sending PUBLISH to vdm-dev-live (d0, q0, r0, m0, 'vdm/89320292400015932480/WVWZZZ1KZDP005350/4.2/liveData', ... (36 bytes))
1409645650: Sending PUBLISH to Yo3zC8ou5y (d0, q0, r0, m0, 'vdm/89320292400015932480/WVWZZZ1KZDP005350/4.2/liveData', ... (36 bytes))
1409645650: Sending PUBLISH to mqttjs_31f1e3f7cd0e0aed (d0, q0, r0, m0, 'vdm/89320292400015932480/WVWZZZ1KZDP005350/4.2/liveData', ... (36 bytes))

さまざまなサブスクライバーからの ping 要求が表示されます

1409645705: Received PINGREQ from vdm-dev-update
1409645705: Sending PINGRESP to vdm-dev-update
1409645705: Received PINGREQ from vdm-dev-live
1409645705: Sending PINGRESP to vdm-dev-live
1409645705: Received PINGREQ from vdm-dev-fmReq
1409645705: Sending PINGRESP to vdm-dev-fmReq
1409645705: Received PINGREQ from vdm-dev-cfgReq
1409645705: Sending PINGRESP to vdm-dev-cfgReq
1409645705: Received PINGREQ from vdm-dev-fmStat
1409645705: Sending PINGRESP to vdm-dev-fmStat

しかし、突然、次のことがわかります。

1409645776: Socket error on client vdm-dev-live, disconnecting.

そしてその時点で、サブスクライバーは死んでいます。ping リクエストは見られず、そのトピックからのメッセージは処理されていません。ブローカー レベルでは、(NodeJS を使用して) debug-log サブスクライバーがあり、これらのサブスクライバーがまだそのトピックからのメッセージを正常に処理していることがわかります (したがって、問題はサブスクライバー レベルにあります)。

Tomcat のログには、次のようにも表示されます。

Sep 02, 2014 10:16:05 AM org.eclipse.paho.client.mqttv3.internal.ClientState checkForActivity
SEVERE: vdm-dev-live: Timed out as no activity, keepAlive=60,000 lastOutboundActivity=1,409,645,705,714 lastInboundActivity=1,409,645,755,075

しかし、Paho はこのサブスクライバーのクリーンアップや再始動を行いません。

Tomcat ログにもこれが表示されます。

SEVERE: The web application [/vdmapp] appears to have started a thread named [MQTT Snd: vdm-dev-live] but has failed to stop it. This is very likely to create a memory leak.

また、シャットダウン中にスタックしているサブスクライバーのスレッドが多数あることにも気付きました。

"MQTT Snd: vdm-dev-live" daemon prio=10 tid=0x00007f1b44781800 nid=0x3061 in Object.wait() [0x00007f1aa7bfa000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.lang.Thread.join(Thread.java:1258)
    - locked <0x00000007ab13e218> (a java.lang.Thread)
    at java.lang.Thread.join(Thread.java:1332)
    at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.stop(CommsReceiver.java:77)
    - locked <0x00000007ab552730> (a java.lang.Object)
    at org.eclipse.paho.client.mqttv3.internal.ClientComms.shutdownConnection(ClientComms.java:294)
    at org.eclipse.paho.client.mqttv3.internal.CommsSender.handleRunException(CommsSender.java:154)
    at org.eclipse.paho.client.mqttv3.internal.CommsSender.run(CommsSender.java:131)
    at java.lang.Thread.run(Thread.java:722)

これを引き起こしている原因と、これを防ぐ方法はありますか?

4

2 に答える 2

2

@Artemの回答での私のコメントのフォローアップ...

Paho クライアントでデッドロックが発生しているようです。Gist の 573 行目を参照してください。スレッドは、スレッドが終了Sndするのを待っていRecます。行 586 で、Rec受信キューがいっぱい (10) であるため、スレッドがブロックされます。このように見えるすべてのケースについて、Callスレッドはありません。そのため、キューがいっぱいになった状態がクリアされることはありません。227 行目で、3 つのスレッドが正常に動作していることに注意してください (おそらく、再デプロイ後の再接続ですか?)。

死んだスレッドでは、Callスレッドはありません。

問題はPahoクライアントにあると思います-CommsCallback.run()メソッドには、接続を閉じるキャッチがThrowableありますが、キューがいっぱいであるため、Recスレッドには通知されません(したがって、クリーンアップされません)。したがって、メッセージ配信が例外をスローしているようで、キューがいっぱいの場合、このデッドロックが発生します。

Paho クライアントには修正が必要ですが、それまでの間、例外が何であるかを突き止めることができます。

例外が受信ゲートウェイの下流にある場合は、ログが表示されます...

        logger.error("Unhandled exception for " + message.toString(), e);

このログは で生成されるため、このMqttCallback.messageArrived()ようなエラーが表示されない場合は、Paho クライアント自体に問題がある可能性があります。

の例外処理はCommsCallback次のようになります...

        } catch (Throwable ex) {
            // Users code could throw an Error or Exception e.g. in the case
            // of class NoClassDefFoundError
            // @TRACE 714=callback threw exception
            log.fine(className, methodName, "714", null, ex);
            running = false;
            clientComms.shutdownConnection(null, new MqttException(ex));
        }

(それは、(死んでいる)スレッドspaceAvailable.notifyAll()をウェイクアップするために呼び出す必要がある場所です)。Rec

そのため、Paho クライアントの FINE ロギングを有効にすると、例外の場所と内容がわかります。

于 2014-09-02T19:39:35.763 に答える