ably-java icon indicating copy to clipboard operation
ably-java copied to clipboard
verified publisher icon ably

java.lang.NullPointerException when publishing to channel following re-auth

Open mattheworiordan opened this issue 9 years ago • 3 comments

Client lib version: 0.8.8

Customer has reported that during the following sequence, they fail to publish a message, and inspecting the logs, there is a NullPointerException.

  • Connect to ably with capability to publish to channel "private:chat:29453".
  • Publish something on the channel
  • Re-authorize with additional capability to publish to channel "private:chat:11111".
  • Publish something on both channels, NullPointerException when publishing to "private:chat:11111"

Log below:

12-26 17:20:26.429 26180 26180 I FA      : To enable debug logging run: adb shell setprop log.tag.FA VERBOSE
12-26 17:20:27.561 26180 26296 I System.out: (VERBOSE): io.ably.lib.transport.ConnectionManager: requestState(): requesting connecting; id = null
12-26 17:20:27.572 26180 26297 I System.out: (VERBOSE): io.ably.lib.transport.ConnectionManager: notifyState(): notifying connecting; id = null
12-26 17:20:27.572 26180 26297 I System.out: (VERBOSE): io.ably.lib.transport.ConnectionManager: setState(): setting connecting
12-26 17:20:34.364 26180 26357 I System.out: (VERBOSE): io.ably.lib.transport.ConnectionManager: onMessage(): {"action":4,"connectionDetails":{"clientId":"21571","connectionKey":"REDUCTED","maxFrameSize":262144,"maxIdleInterval":15000,"maxInboundRate":15,"maxMessageSize":16384,"serverId":"frontend.32a0.1.ap-southeast-1-A.i-5ee70edf"},"connectionId":"wRXvNpJ9LX","connectionKey":"REDUCTED","connectionSerial":-1,"count":0,"flags":0,"timestamp":0}
12-26 17:20:34.366 26180 26357 I System.out: (VERBOSE): io.ably.lib.transport.ConnectionManager: notifyState(): notifying connected; id = a2d3QLn3QA21D4!wRXvNpJ9LX3fMqHZ-e196a2d3QLn3QA21D4
12-26 17:20:34.366 26180 26357 I System.out: (VERBOSE): io.ably.lib.transport.WebSocketTransport: checkActivity: ok
12-26 17:20:34.366 26180 26297 I System.out: (VERBOSE): io.ably.lib.transport.ConnectionManager: setState(): setting connected
12-26 17:20:34.366 26180 26297 D companyx.AblyTest: connected to ably
12-26 17:20:34.367 26180 26297 D companyx.AblyTest: testing ... 0 + 0 => 0
12-26 17:20:34.378 26180 26297 I System.out: (VERBOSE): io.ably.lib.realtime.Channel: RealtimeChannel(); channel = private:chat:29453
12-26 17:20:34.385 26180 26297 D companyx.AblyTest: chat message => [#1] @ private:chat:29453 : hello from b4b16f6037a1192c @ Mon Dec 26 17:20:34 GMT+05:30 2016
12-26 17:20:34.387 26180 26297 I System.out: (VERBOSE): io.ably.lib.realtime.Channel: publish(String, Object); channel = private:chat:29453; event = chat_message
12-26 17:20:34.392 26180 26297 I System.out: (VERBOSE): io.ably.lib.realtime.Channel: publish(Message[]); channel = private:chat:29453
12-26 17:20:34.393 26180 26297 I System.out: (VERBOSE): io.ably.lib.realtime.Channel: attach(); channel = private:chat:29453
12-26 17:20:34.393 26180 26297 I System.out: (VERBOSE): io.ably.lib.realtime.Channel: setState(): channel = private:chat:29453; setting attaching
12-26 17:20:34.394 26180 26297 I System.out: (VERBOSE): io.ably.lib.transport.WebSocketTransport: send(): {"action":10,"channel":"private:chat:29453","count":0,"flags":0,"timestamp":0}
12-26 17:20:34.674 26180 26357 I System.out: (VERBOSE): io.ably.lib.transport.ConnectionManager: onMessage(): {"action":11,"channel":"private:chat:29453","channelSerial":"a2dxowR3wA23SW28169890:1","count":0,"flags":0,"timestamp":0}
12-26 17:20:34.674 26180 26357 I System.out: (VERBOSE): io.ably.lib.realtime.Channel: setAttached(); channel = private:chat:29453
12-26 17:20:34.674 26180 26357 I System.out: (VERBOSE): io.ably.lib.realtime.Channel: setState(): channel = private:chat:29453; setting attached
12-26 17:20:34.674 26180 26357 I System.out: (VERBOSE): io.ably.lib.realtime.Channel: sendQueuedMessages()
12-26 17:20:34.674 26180 26357 I System.out: (VERBOSE): io.ably.lib.transport.WebSocketTransport: send(): {"action":15,"channel":"private:chat:29453","count":0,"flags":0,"messages":[{"data":"[#1] @ private:chat:29453 : hello from b4b16f6037a1192c @ Mon Dec 26 17:20:34 GMT+05:30 2016","name":"chat_message"}],"msgSerial":0,"timestamp":0}
12-26 17:20:34.678 26180 26357 I System.out: (VERBOSE): io.ably.lib.realtime.Channel: sendQueuedMessages()
12-26 17:20:35.035 26180 26357 I System.out: (VERBOSE): io.ably.lib.transport.ConnectionManager: onMessage(): {"action":15,"channel":"private:chat:29453","channelSerial":"a2dxowR3wA23SW28169890:2","connectionId":"wRXvNpJ9LX","connectionSerial":0,"count":104,"flags":0,"id":"wRXvNpJ9LX:0","messages":[{"data":"[#1] @ private:chat:29453 : hello from b4b16f6037a1192c @ Mon Dec 26 17:20:34 GMT+05:30 2016","clientId":"21571","name":"chat_message"}],"timestamp":1482753034823}
12-26 17:20:35.035 26180 26357 I System.out: (VERBOSE): io.ably.lib.realtime.Channel: onMessage(); channel = private:chat:29453
12-26 17:20:35.036 26180 26357 I System.out: (VERBOSE): io.ably.lib.transport.ConnectionManager: onMessage(): {"action":1,"count":1,"flags":0,"msgSerial":0,"timestamp":0}
12-26 17:20:35.037 26180 26357 D companyx.AblyTest: [onSuccess] Message 1 sent on channel private:chat:29453
12-26 17:20:35.037 26180 26357 D companyx.AblyTest: force re-authorizing ...
12-26 17:20:38.715 26180 26357 I System.out: (VERBOSE): io.ably.lib.transport.ConnectionManager: onAuthUpdated: closing transport
12-26 17:20:38.723 26180 26357 D companyx.AblyTest: channel private:chat:29453  => attached
12-26 17:20:38.723 26180 26357 D companyx.AblyTest: capability after re-auth : {"private:chat:11111":["*"],"private:chat:29453":["*"]}
12-26 17:20:38.724 26180 26357 D companyx.AblyTest: time taken for sync re-auth : 3685 ms
12-26 17:20:38.724 26180 26357 D companyx.AblyTest: testing ... 1 + 0 => 1
12-26 17:20:38.724 26180 26357 D companyx.AblyTest: channel private:chat:29453  => attached
12-26 17:20:38.872 26180 26357 I System.out: (VERBOSE): io.ably.lib.realtime.Channel: RealtimeChannel(); channel = private:chat:11111
12-26 17:20:38.872 26180 26357 D companyx.AblyTest: chat message => [#2] @ private:chat:29453 : hello from b4b16f6037a1192c @ Mon Dec 26 17:20:38 GMT+05:30 2016
12-26 17:20:38.872 26180 26357 I System.out: (VERBOSE): io.ably.lib.realtime.Channel: publish(String, Object); channel = private:chat:29453; event = chat_message
12-26 17:20:38.873 26180 26357 I System.out: (VERBOSE): io.ably.lib.realtime.Channel: publish(Message[]); channel = private:chat:29453
12-26 17:20:38.873 26180 26357 I System.out: (VERBOSE): io.ably.lib.transport.WebSocketTransport: send(): {"action":15,"channel":"private:chat:29453","count":0,"flags":0,"messages":[{"data":"[#2] @ private:chat:29453 : hello from b4b16f6037a1192c @ Mon Dec 26 17:20:38 GMT+05:30 2016","name":"chat_message"}],"msgSerial":1,"timestamp":0}
12-26 17:20:38.873 26180 26357 D companyx.AblyTest: channel private:chat:29453  => attached
12-26 17:20:38.873 26180 26357 D companyx.AblyTest: channel private:chat:11111  => initialized
12-26 17:20:38.873 26180 26357 W System.err: io.ably.lib.types.AblyException: java.lang.NullPointerException: Attempt to invoke virtual method 'void io.ably.lib.transport.WebSocketTransport$WsClient.send(byte[])' on a null object reference
12-26 17:20:38.874 26180 26357 W System.err:  at io.ably.lib.transport.WebSocketTransport.send(WebSocketTransport.java:127)
12-26 17:20:38.874 26180 26357 W System.err:  at io.ably.lib.transport.ConnectionManager.sendImpl(ConnectionManager.java:796)
12-26 17:20:38.874 26180 26357 W System.err:  at io.ably.lib.transport.ConnectionManager.send(ConnectionManager.java:762)
12-26 17:20:38.874 26180 26357 W System.err:  at io.ably.lib.realtime.Channel.publish(Channel.java:536)
12-26 17:20:38.874 26180 26357 W System.err:  at io.ably.lib.realtime.Channel.publish(Channel.java:496)
12-26 17:20:38.874 26180 26357 W System.err:  at in.companyx.util.AblyTest.test(AblyTest.kt:299)
12-26 17:20:38.874 26180 26357 W System.err:  at in.companyx.util.AblyTest.reauthorizeAndTest(AblyTest.kt:229)
12-26 17:20:38.874 26180 26357 W System.err:  at in.companyx.util.AblyTest$test$1.onSuccess(AblyTest.kt:303)
12-26 17:20:38.874 26180 26357 W System.err:  at io.ably.lib.transport.ConnectionManager$PendingMessageQueue.ack(ConnectionManager.java:889)
12-26 17:20:38.874 26180 26357 W System.err:  at io.ably.lib.transport.ConnectionManager.onAck(ConnectionManager.java:427)
12-26 17:20:38.874 26180 26357 W System.err:  at io.ably.lib.transport.ConnectionManager.onMessage(ConnectionManager.java:344)
12-26 17:20:38.874 26180 26357 W System.err:  at io.ably.lib.transport.WebSocketTransport$WsClient.onMessage(WebSocketTransport.java:158)
12-26 17:20:38.874 26180 26357 W System.err:  at org.java_websocket.client.WebSocketClient.onWebsocketMessage(WebSocketClient.java:253)
12-26 17:20:38.874 26180 26357 W System.err:  at org.java_websocket.WebSocketImpl.decodeFrames(WebSocketImpl.java:381)
12-26 17:20:38.874 26180 26357 W System.err:  at org.java_websocket.WebSocketImpl.decode(WebSocketImpl.java:158)
12-26 17:20:38.874 26180 26357 W System.err:  at org.java_websocket.client.WebSocketClient.run(WebSocketClient.java:185)
12-26 17:20:38.874 26180 26357 W System.err:  at java.lang.Thread.run(Thread.java:818)
12-26 17:20:38.874 26180 26357 W System.err: Caused by: java.lang.NullPointerException: Attempt to invoke virtual method 'void io.ably.lib.transport.WebSocketTransport$WsClient.send(byte[])' on a null object reference
12-26 17:20:38.874 26180 26357 W System.err:  at io.ably.lib.transport.WebSocketTransport.send(WebSocketTransport.java:123)
12-26 17:20:38.874 26180 26357 W System.err:  ... 16 more
12-26 17:20:38.874 26180 26357 D companyx.AblyTest: [EXCEPTION] Message 2 *COULD NOT* be sent on channel private:chat:29453; err_msg => java.lang.NullPointerException: Attempt to invoke virtual method 'void io.ably.lib.transport.WebSocketTransport$WsClient.send(byte[])' on a null object reference
12-26 17:20:38.875 26180 26357 D companyx.AblyTest: chat message => [#3] @ private:chat:11111 : hello from b4b16f6037a1192c @ Mon Dec 26 17:20:38 GMT+05:30 2016
12-26 17:20:38.875 26180 26357 I System.out: (VERBOSE): io.ably.lib.realtime.Channel: publish(String, Object); channel = private:chat:11111; event = chat_message
12-26 17:20:38.875 26180 26357 I System.out: (VERBOSE): io.ably.lib.realtime.Channel: publish(Message[]); channel = private:chat:11111
12-26 17:20:38.875 26180 26357 I System.out: (VERBOSE): io.ably.lib.realtime.Channel: attach(); channel = private:chat:11111
12-26 17:20:38.875 26180 26357 I System.out: (VERBOSE): io.ably.lib.realtime.Channel: setState(): channel = private:chat:11111; setting attaching
12-26 17:20:38.875 26180 26357 I System.out: (VERBOSE): io.ably.lib.transport.WebSocketTransport: send(): {"action":10,"channel":"private:chat:11111","count":0,"flags":0,"timestamp":0}
12-26 17:20:38.875 26180 26357 D companyx.AblyTest: channel private:chat:29453  => attached
12-26 17:20:38.875 26180 26357 D companyx.AblyTest: channel private:chat:11111  => attaching
12-26 17:20:38.875 26180 26357 W System.err: io.ably.lib.types.AblyException: java.lang.NullPointerException: Attempt to invoke virtual method 'void io.ably.lib.transport.WebSocketTransport$WsClient.send(byte[])' on a null object reference
12-26 17:20:38.875 26180 26357 W System.err:  at io.ably.lib.transport.WebSocketTransport.send(WebSocketTransport.java:127)
12-26 17:20:38.875 26180 26357 W System.err:  at io.ably.lib.transport.ConnectionManager.sendImpl(ConnectionManager.java:796)
12-26 17:20:38.875 26180 26357 W System.err:  at io.ably.lib.transport.ConnectionManager.send(ConnectionManager.java:762)
12-26 17:20:38.875 26180 26357 W System.err:  at io.ably.lib.realtime.Channel.attach(Channel.java:136)
12-26 17:20:38.875 26180 26357 W System.err:  at io.ably.lib.realtime.Channel.attach(Channel.java:92)
12-26 17:20:38.875 26180 26357 W System.err:  at io.ably.lib.realtime.Channel.publish(Channel.java:525)
12-26 17:20:38.875 26180 26357 W System.err:  at io.ably.lib.realtime.Channel.publish(Channel.java:496)
12-26 17:20:38.875 26180 26357 W System.err:  at in.companyx.util.AblyTest.test(AblyTest.kt:299)
12-26 17:20:38.876 26180 26357 W System.err:  at in.companyx.util.AblyTest.reauthorizeAndTest(AblyTest.kt:229)
12-26 17:20:38.876 26180 26357 W System.err:  at in.companyx.util.AblyTest$test$1.onSuccess(AblyTest.kt:303)
12-26 17:20:38.876 26180 26357 W System.err:  at io.ably.lib.transport.ConnectionManager$PendingMessageQueue.ack(ConnectionManager.java:889)
12-26 17:20:38.876 26180 26357 W System.err:  at io.ably.lib.transport.ConnectionManager.onAck(ConnectionManager.java:427)
12-26 17:20:38.876 26180 26357 W System.err:  at io.ably.lib.transport.ConnectionManager.onMessage(ConnectionManager.java:344)
12-26 17:20:38.876 26180 26357 W System.err:  at io.ably.lib.transport.WebSocketTransport$WsClient.onMessage(WebSocketTransport.java:158)
12-26 17:20:38.876 26180 26357 W System.err:  at org.java_websocket.client.WebSocketClient.onWebsocketMessage(WebSocketClient.java:253)
12-26 17:20:38.876 26180 26357 W System.err:  at org.java_websocket.WebSocketImpl.decodeFrames(WebSocketImpl.java:381)
12-26 17:20:38.876 26180 26357 W System.err:  at org.java_websocket.WebSocketImpl.decode(WebSocketImpl.java:158)
12-26 17:20:38.876 26180 26357 W System.err:  at org.java_websocket.client.WebSocketClient.run(WebSocketClient.java:185)
12-26 17:20:38.876 26180 26357 W System.err:  at java.lang.Thread.run(Thread.java:818)
12-26 17:20:38.876 26180 26357 W System.err: Caused by: java.lang.NullPointerException: Attempt to invoke virtual method 'void io.ably.lib.transport.WebSocketTransport$WsClient.send(byte[])' on a null object reference
12-26 17:20:38.876 26180 26357 W System.err:  at io.ably.lib.transport.WebSocketTransport.send(WebSocketTransport.java:123)
12-26 17:20:38.876 26180 26357 W System.err:  ... 18 more
12-26 17:20:38.876 26180 26357 D companyx.AblyTest: [EXCEPTION] Message 3 *COULD NOT* be sent on channel private:chat:11111; err_msg => java.lang.NullPointerException: Attempt to invoke virtual method 'void io.ably.lib.transport.WebSocketTransport$WsClient.send(byte[])' on a null object reference
12-26 17:20:38.990 26180 26357 I System.out: (VERBOSE): io.ably.lib.transport.ConnectionManager: notifyState(): notifying disconnected; id = a2d3QLn3QA21D4!wRXvNpJ9LX3fMqHZ-e196a2d3QLn3QA21D4
12-26 17:20:38.991 26180 26297 I System.out: (VERBOSE): io.ably.lib.transport.ConnectionManager: requestState(): requesting connecting; id = a2d3QLn3QA21D4!wRXvNpJ9LX3fMqHZ-e196a2d3QLn3QA21D4
12-26 17:20:38.991 26180 26297 I System.out: (VERBOSE): io.ably.lib.transport.ConnectionManager: setState(): setting disconnected
12-26 17:20:38.991 26180 26297 D companyx.AblyTest: disconnected from ably
12-26 17:20:38.992 26180 26297 I System.out: (VERBOSE): io.ably.lib.transport.ConnectionManager: notifyState(): notifying connecting; id = a2d3QLn3QA21D4!wRXvNpJ9LX3fMqHZ-e196a2d3QLn3QA21D4
12-26 17:20:38.992 26180 26297 I System.out: (VERBOSE): io.ably.lib.transport.ConnectionManager: setState(): setting connecting
12-26 17:20:38.992 26180 26297 I System.out: (VERBOSE): io.ably.lib.transport.ConnectionManager: notifyState: wrong transport
12-26 17:20:40.201 26180 26368 I System.out: (VERBOSE): io.ably.lib.transport.WebSocketTransport: checkActivity: ok
12-26 17:20:40.204 26180 26368 I System.out: (VERBOSE): io.ably.lib.transport.ConnectionManager: onMessage(): {"action":4,"connectionDetails":{"clientId":"21571","connectionKey":"REDUCTED","maxFrameSize":262144,"maxIdleInterval":15000,"maxInboundRate":15,"maxMessageSize":16384,"serverId":"frontend.32a0.1.ap-southeast-1-A.i-5ee70edf"},"connectionId":"wRXvNpJ9LX","connectionKey":"REDUCTED","connectionSerial":0,"count":0,"flags":0,"timestamp":0}
12-26 17:20:40.204 26180 26368 I System.out: (VERBOSE): io.ably.lib.transport.ConnectionManager: notifyState(): notifying connected; id = a2d3QLn3QA21D4!wRXvNpJ9LX3fMqHZ-e197a2d3QLn3QA21D4
12-26 17:20:40.204 26180 26297 I System.out: (VERBOSE): io.ably.lib.transport.ConnectionManager: setState(): setting connected
12-26 17:20:40.205 26180 26297 D companyx.AblyTest: connected to ably
12-26 17:20:40.206 26180 26297 D companyx.AblyTest: channel private:chat:29453  => attached
12-26 17:20:40.207 26180 26297 D companyx.AblyTest: channel private:chat:11111  => attaching
12-26 17:20:40.207 26180 26297 D companyx.AblyTest: testing ... 1 + 2 => 3
12-26 17:20:40.208 26180 26297 D companyx.AblyTest: channel private:chat:29453  => attached
12-26 17:20:40.209 26180 26297 D companyx.AblyTest: channel private:chat:11111  => attaching
12-26 17:20:40.209 26180 26297 D companyx.AblyTest: closing connection to ably

My initial thoughts:

  • It does look like the library, following reauth, is failing when the publish is called. This looks like a lib issue as opposed to a user issue, however I am not sure.
  • We should be logging the websocket URL we are connecting to at this log level, we should fix that at the same time

┆Issue is synchronized with this Jira Task by Unito

mattheworiordan avatar Dec 27 '16 11:12 mattheworiordan

FYI, if you want to see their source code, see support ticket 1455

mattheworiordan avatar Dec 27 '16 11:12 mattheworiordan

This looks like https://github.com/ably/ably-java/issues/180

paddybyers avatar Dec 27 '16 16:12 paddybyers

Yes, shame the issue wasn't resolved at the time then instead of adding a delay :(

mattheworiordan avatar Dec 27 '16 16:12 mattheworiordan