Tigase Forge
Dashboards
Projects
Pull Requests
Issues
Builds
Packages
Code Search
tigase-mix
Code
Pull Requests
Issues
List
Boards
Iterations
Builds
Statistics
Child Projects
OneDev 10.9.4
Documentation Support & Bug Report RESTful API Incompatibilities License Agreement Check Update
Projects tigase _server tigase-mix Issues #15
NPE in MAMItemHandler (#15)
Closed
wojciech.kapcia@tigase.net opened 4 years ago 
java.lang.NullPointerException
	at tigase.mix.modules.mam.MAMItemHandler.itemFound(MAMItemHandler.java:36)
	at tigase.pubsub.repository.PubSubDAOJDBC.queryItems(PubSubDAOJDBC.java:962)
	at tigase.pubsub.repository.PubSubDAOJDBC.queryItems(PubSubDAOJDBC.java:46)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.$$YJP$$invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at tigase.stats.StatisticsInvocationHandler.invoke(StatisticsInvocationHandler.java:75)
	at com.sun.proxy.$Proxy52.queryItems(Unknown Source)
	at tigase.pubsub.repository.PubSubDAOPool.queryItems(PubSubDAOPool.java:403)
	at tigase.pubsub.repository.cached.CachedPubSubRepository.queryItems(CachedPubSubRepository.java:506)
	at tigase.pubsub.repository.cached.CachedPubSubRepository.queryItems(CachedPubSubRepository.java:66)
	at tigase.xmpp.mam.modules.QueryModule.process(QueryModule.java:80)
	at tigase.component.modules.StanzaProcessor.process(StanzaProcessor.java:164)
	at tigase.component.modules.StanzaProcessor.processPacket(StanzaProcessor.java:85)
	at tigase.component.AbstractKernelBasedComponent.processPacket(AbstractKernelBasedComponent.java:81)
	at tigase.pubsub.PubSubComponent.processPacket(PubSubComponent.java:191)
	at tigase.pubsub.cluster.PubSubComponentClustered.processPacket(SourceFile:183)
	at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1405)
wojciech.kapcia@tigase.net commented 4 years ago

Packet:

<iq from="wojtek@xmpp.cloud/565860449-tigase-596" to="xmpp-mix@mix.xmpp.cloud" xmlns="jabber:client" type="set"
    id="55F40E5B-32AF-40C7-BFDC-42B4630F0E3D">
    <query xmlns="urn:xmpp:mam:2" node="urn:xmpp:mix:nodes:messages" queryid="4F1FB39C-3BD1-443C-A56E-913E3C91517E">
        <x xmlns="jabber:x:data" type="submit">
            <field var="FORM_TYPE" type="hidden">
                <value>CData size: 14</value>
            </field>
        </x>
        <set xmlns="http://jabber.org/protocol/rsm">
            <max>CData size: 3</max>
        </set>
    </query>
</iq>

Complete log:

[2020-08-28 17:02:48:480] [SEVERE  ] [              in_2-mix ] StanzaProcessor.processPacket()  : null when processing from=sess-man@ip-10-0-32-126.us-west-2.compute.internal, to=null, DATA=[iq from="wojtek@xmpp.cloud/565860449-tigase-596" to="xmpp-mix@mix.xmpp.cloud" xmlns="jabber:client" type="set" id="55F40E5B-32AF-40C7-BFDC-42B4630F0E3D"][query xmlns="urn:xmpp:mam:2" node="urn:xmpp:mix:nodes:messages" queryid="4F1FB39C-3BD1-443C-A56E-913E3C91517E"][x xmlns="jabber:x:data" type="submit"][field var="FORM_TYPE" type="hidden"][value]CData size: 14[/value][/field][/x][set xmlns="http://jabber.org/protocol/rsm"][max]CData size: 3[/max][/set][/query][/iq], SIZE=460, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=set, STABLE_ID=null
java.lang.NullPointerException
	at tigase.mix.modules.mam.MAMItemHandler.itemFound(MAMItemHandler.java:36)
	at tigase.pubsub.repository.PubSubDAOJDBC.queryItems(PubSubDAOJDBC.java:962)
	at tigase.pubsub.repository.PubSubDAOJDBC.queryItems(PubSubDAOJDBC.java:46)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.$$YJP$$invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at tigase.stats.StatisticsInvocationHandler.invoke(StatisticsInvocationHandler.java:75)
	at com.sun.proxy.$Proxy52.queryItems(Unknown Source)
	at tigase.pubsub.repository.PubSubDAOPool.queryItems(PubSubDAOPool.java:403)
	at tigase.pubsub.repository.cached.CachedPubSubRepository.queryItems(CachedPubSubRepository.java:506)
	at tigase.pubsub.repository.cached.CachedPubSubRepository.queryItems(CachedPubSubRepository.java:66)
	at tigase.xmpp.mam.modules.QueryModule.process(QueryModule.java:80)
	at tigase.component.modules.StanzaProcessor.process(StanzaProcessor.java:164)
	at tigase.component.modules.StanzaProcessor.processPacket(StanzaProcessor.java:85)
	at tigase.component.AbstractKernelBasedComponent.processPacket(AbstractKernelBasedComponent.java:81)
	at tigase.pubsub.PubSubComponent.processPacket(PubSubComponent.java:191)
	at tigase.pubsub.cluster.PubSubComponentClustered.processPacket(SourceFile:183)
	at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1405)
Andrzej Wójcik (Tigase) commented 4 years ago

The issue looks like not properly initialized MIX component. Moreover in the logs file, I've found following entries:

[2020-08-27 21:19:41:677] [WARNING ] [        out_13-cl-comp ] ClusterController.handleClusterPacket(): Missing CommandListener for cluster method: pubsub-request-caps-sync
[2020-08-27 21:19:41:684] [WARNING ] [         out_5-cl-comp ] ClusterController.handleClusterPacket(): Missing CommandListener for cluster method: muc-request-occupants-sync
[2020-08-27 21:19:41:955] [WARNING ] [         out_5-cl-comp ] ClusterController.handleClusterPacket(): Missing CommandListener for cluster method: muc-request-occupants-sync
[2020-08-27 21:19:41:960] [WARNING ] [        out_13-cl-comp ] ClusterController.handleClusterPacket(): Missing CommandListener for cluster method: pubsub-request-caps-sync
[2020-08-27 21:19:42:760] [WARNING ] [       pool-1-thread-4 ] BoshConnectionClustered.lambda$start$0(): Starting listening on ports of component: bosh
[2020-08-27 21:19:42:767] [WARNING ] [       pool-1-thread-2 ] WebSocketClientConnectionClustered.lambda$start$0(): Starting listening on ports of component: ws2s
[2020-08-27 21:19:42:768] [WARNING ] [       pool-1-thread-8 ] ClientConnectionClustered.lambda$start$0(): Starting listening on ports of component: c2s
[2020-08-27 21:19:42:786] [WARNING ] [         out_5-cl-comp ] ClusterController.handleClusterPacket(): Missing CommandListener for cluster method: muc-request-occupants-sync
[2020-08-27 21:19:42:795] [WARNING ] [        out_13-cl-comp ] ClusterController.handleClusterPacket(): Missing CommandListener for cluster method: pubsub-request-caps-sync

which means that there is something wrong with this installation. (looks like clustering is not properly initialized...)
Andrzej Wójcik (Tigase) commented 4 years ago

Is it possible that there is a version with an issue? ie. tigase.org (updated today) is working just fine...
wojciech.kapcia@tigase.net commented 4 years ago

I dug a bit into the issue and it's a bit weird. Missing CommandListener - those commands are there: (form config-dump.properties) 'request-caps-sync' (class: tigase.pubsub.cluster.commands.RequestCapsSyncCommand) {}. I tried to reproduce the issue and wasn't able to - no issue/warning/error happened. What's more - no other "Missing CommandListener" entry could be found in logs. Considering that, from the log you shared, they happened during startup (vide "Starting listening on ports") maybe there is a problem with initialisation? We do have this delay mechanism so user's won't be able to connect to the instance before it's fully initialised (including clustering) so maybe Kernel somehow instantiated them incorrectly?

I took a look at the stacktrace, and NPE seems possible. It happens on the line:

if (roomPresenceRepository.isParticipant(query.getComponentJID().getBareJID(), query.getQuestionerJID())) {

And repository is marked as allowing nulls:

@Inject(nullAllowed = true)
private RoomPresenceRepository roomPresenceRepository;

Now the question is - why do we allow null repository? What would be the use case? Can we ignore that that fact?

At any rate, if we allow and (somewhat) expect that repository may be null, shouldn't we check if it's null before referencing it?
wojciech.kapcia@tigase.net commented 4 years ago

Actually I did manage to somehow reproduce - it seems that the repository is not initialised? No other errors are happening.
Andrzej Wójcik (Tigase) commented 4 years ago

That repository SHOULD NOT be null after kernel injects all dependencies! The null is there just to deal with circular dependency which was there (something need to be initiated as a first item) and for nothing else so under no circumstances under normal condition there should be a null!
Andrzej Wójcik (Tigase) commented 4 years ago

@wojtek How did you reproduced the issue? That are condition causing this issue? as this is an error on the Kernel level, if bean is registered and there is field annotated then instance of that bean should be injected!
wojciech.kapcia@tigase.net commented 4 years ago

That repository SHOULD NOT be null after kernel injects all dependencies! The null is there just to deal with circular dependency which was there (something need to be initiated as a first item) and for nothing else so under no circumstances under normal condition there should be a null!

@andrzej.wojcik shouldn't we somehow try to avoid those circular dependencies? Or at least add mechanism that would allow null only during Kernel initialisation and afterwards would check if everything was correctly initialised? (just an idea)

How did you reproduced the issue? That are condition causing this issue? as this is an error on the Kernel level, if bean is registered and there is field annotated then instance of that bean should be injected!

I just tried leaving and entering the MIX channel again, which probably triggered MAM retrieval. As discussed in the chat: RoomPresenceRepository can't be found in config dump, in the same dump MAMItemHandler doesn't have any sub-beans (for example RoomPresenceRepository) but RoomPresenceRepository has parent configured as RoomPresenceModule, which in config dump is marked as inactive: roomPresenceModule (class: tigase.mix.modules.RoomPresenceModule, active: false) {} - maybe because it's parent is inactive, repository instance wasn't created and thus was not injected?
Andrzej Wójcik (Tigase) commented 4 years ago

@wojtek We could try to add "allow null only during initialization by kernel" but that would complicate kernel even more and I'm not sure that we want to do that.

Actually, the issue was caused by my mistake. It occurs that RoomPresenceRepository is not only null during initialization, but also when roomPresenceModule is not enabled (it is disabled by default). This module registers repository and is responsible for MUC<->MIX compatibility layer, so actually we should properly handle cases when this field is null.

I've already made proper changes.
wojciech.kapcia@tigase.net commented 4 years ago

We could try to add "allow null only during initialization by kernel" but that would complicate kernel even more and I'm not sure that we want to do that.

OK, let's leave it for now.

Actually, the issue was caused by my mistake. It occurs that RoomPresenceRepository is not only null during initialization, but also when roomPresenceModule is not enabled (it is disabled by default). This module registers repository and is responsible for MUC<->MIX compatibility layer, so actually we should properly handle cases when this field is null.

OK, thank you for explanation. As per our conversation, I additionally activated this module by default as MIX-MUC compatibility seems essential (at least in the "transition period").
issue 1 of 1
Type
Bug
Priority
Normal
Assignee
wojciech.kapcia@tigase.net
Version
tigase-server-8.2.0
Spent time
2h 15m
Issue Votes (0)
Login to vote
Watchers (0)
Reference
tigase/_server/tigase-mix#15
Please wait...
Page is in error, reload to recover