pubnub/objective-c

Subscription failed by timeout

Closed this issue · 9 comments

Hello,

We are writing iOS chat application. All was working great before we add APN support.
Here is my workflow:

  1. App opened
  2. Update channels ids from server
  3. Subscribe on channels if I have device token I also enabled APN for channels

Also I send request for enabling APN right after I got device token if I've already got channels id from server. So I can got token before or after I got channels ids.

I always receive subscription by timeout. I've tried to removed code for push notification but problem is still here. Here is my log:

2013-08-23 06:53:50.956 ProfileCode[5085:907] My token is: <30ac2427 f57f53ee 5a79c4d1 505cca7b b708ae18 a9f48bd2 ca58b189 e8968f41>
2013-08-23 06:53:50:985 ProfileCode[5085:2311] call enablePushNotificationsOnChannels: at ChatEngine
2013-08-23 06:53:55.889 ProfileCode[5085:907] PNConfiguration (0x1c58aa70)
{WARN} Before running in production, please contact support@pubnub.com for your custom origin.
Please set the origin from ios.pubnub.com to IUNDERSTAND.pubnub.com to remove this warning.
2013-08-23 06:53:55.891 ProfileCode[5085:907] PNReachability (0x1c577aa0) STOP REACHABILITY OBSERVATION
2013-08-23 06:53:55.899 ProfileCode[5085:907] PNReachability (0x1c577aa0) START REACHABILITY OBSERVATION
2013-08-23 06:53:56.151 ProfileCode[5085:907] PNReachability (0x1c577aa0) PubNub services reachability changed [CONNECTED? YES]
2013-08-23 06:53:56.153 ProfileCode[5085:907] PubNub (0x1d05b720) IS CONNECTED? YES (STATE: 1)
2013-08-23 06:53:56.156 ProfileCode[5085:907] PNConnection (0x1c59e070) {INFO} "<PNConnection: 0x1c59e070>" configuration
2013-08-23 06:53:56.159 ProfileCode[5085:907] PNConnection (0x1c59e070) {INFO} "PNMessagingConnectionIdentifier" connecting
2013-08-23 06:53:56.161 ProfileCode[5085:907] PNConnection (0x1c59e070) {INFO} "PNMessagingConnectionIdentifier" opened read stream
2013-08-23 06:53:56.162 ProfileCode[5085:907] PNConnection (0x1c59e070) {INFO} "PNMessagingConnectionIdentifier" opened write stream
2013-08-23 06:53:56.164 ProfileCode[5085:907] PNConnection (0x1c58fc90) {INFO} "<PNConnection: 0x1c58fc90>" configuration
2013-08-23 06:53:56.166 ProfileCode[5085:907] PNConnection (0x1c58fc90) {INFO} "PNServiceConnectionIdentifier" connecting
2013-08-23 06:53:56.168 ProfileCode[5085:907] PNConnection (0x1c58fc90) {INFO} "PNServiceConnectionIdentifier" opened read stream
2013-08-23 06:53:56.169 ProfileCode[5085:907] PNConnection (0x1c58fc90) {INFO} "PNServiceConnectionIdentifier" opened write stream
2013-08-23 06:53:56.279 ProfileCode[5085:907] PNConnection (0x1c59e070) {INFO}[CONNECTION::PNMessagingConnectionIdentifier::READ] STREAM OPENED (STREAM IS OPENED)
2013-08-23 06:53:56.281 ProfileCode[5085:907] PNConnection (0x1c59e070) {INFO}[CONNECTION::PNMessagingConnectionIdentifier::WRITE] STREAM OPENED (STREAM IS OPENED)
2013-08-23 06:53:56.289 ProfileCode[5085:907] PNConnection (0x1c58fc90) {INFO}[CONNECTION::PNServiceConnectionIdentifier::READ] STREAM OPENED (STREAM IS OPENED)
2013-08-23 06:53:56.290 ProfileCode[5085:907] PNConnection (0x1c58fc90) {INFO}[CONNECTION::PNServiceConnectionIdentifier::WRITE] STREAM OPENED (STREAM IS OPENED)
2013-08-23 06:53:56:297 ProfileCode[5085:2311] PubNub Connection Success: ios.pubnub.com
2013-08-23 06:53:56:304 ProfileCode[5085:2311] call attachChannels: at ChatEngine
2013-08-23 06:53:56:308 ProfileCode[5085:2311] starting attachChannels: (
yYd010XTJk,
phFZ8cGuoe
)
2013-08-23 06:53:56.910 ProfileCode[5085:907] PNConnection (0x1c59e070) {INFO}[CONNECTION::PNMessagingConnectionIdentifier::WRITE] READY TO SEND (STREAM IS OPENED)
2013-08-23 06:53:56.912 ProfileCode[5085:907] PNMessagingChannel (0x1c5731b0) {INFO} WILL START REQUEST PROCESSING: <PNTimeTokenRequest: 0x1c59cbe0> [BODY: /time/t_40d05]
2013-08-23 06:53:56.914 ProfileCode[5085:907] PNMessagingChannel (0x1c5731b0) {INFO} DID SEND REQUEST: <PNTimeTokenRequest: 0x1c59cbe0> [BODY: /time/t_40d05][WAITING FOR COMPLETION? NO]
2013-08-23 06:53:56.917 ProfileCode[5085:907] PNMessagingChannel (0x1c5731b0) {INFO} WILL START REQUEST PROCESSING: <PNSubscribeRequest: 0x1c595250> [BODY: /subscribe/sub-c-bbe1d18a-80ab-11e2-b64e-12313f022c90/phFZ8cGuoe,yYd010XTJk/s_29e12/0?uuid=1cf38361-88c7-4b1e-b3cf-0169a98e6b56]
2013-08-23 06:53:56.919 ProfileCode[5085:907] PNMessagingChannel (0x1c5731b0) {INFO} DID SEND REQUEST: <PNSubscribeRequest: 0x1c595250> [BODY: /subscribe/sub-c-bbe1d18a-80ab-11e2-b64e-12313f022c90/phFZ8cGuoe,yYd010XTJk/s_29e12/0?uuid=1cf38361-88c7-4b1e-b3cf-0169a98e6b56][WAITING FOR COMPLETION? YES]
2013-08-23 06:53:56.922 ProfileCode[5085:907] PNConnection (0x1c59e070) {INFO}[CONNECTION::PNMessagingConnectionIdentifier::WRITE] READY TO SEND (STREAM IS OPENED)
2013-08-23 06:53:56.976 ProfileCode[5085:907] Warning: A long-running Parse operation is being executed on the main thread.
Break on warnParseOperationOnMainThread() to debug.
2013-08-23 06:53:57.333 ProfileCode[5085:907] PNConnection (0x1c59e070) {INFO}[CONNECTION::PNMessagingConnectionIdentifier::READ] HAS DATA FOR READ OUT (STREAM IS OPENED)
2013-08-23 06:53:57.335 ProfileCode[5085:907] PNResponseDeserialize (0x1c55eb70) {INFO} RAW DATA: t_40d05([13772372383118602])
2013-08-23 06:53:57.339 ProfileCode[5085:907] PNConnection (0x1c58fc90) {INFO}[CONNECTION::PNServiceConnectionIdentifier::WRITE] READY TO SEND (STREAM IS OPENED)
2013-08-23 06:53:57.340 ProfileCode[5085:907] PNServiceChannel (0x1c5ab9c0) {INFO} WILL START REQUEST PROCESSING: <PNTimeTokenRequest: 0x1c5b1250> [BODY: /time/t_164f2]
2013-08-23 06:53:57.343 ProfileCode[5085:907] PNServiceChannel (0x1c5ab9c0) {INFO} DID SEND REQUEST: <PNTimeTokenRequest: 0x1c5b1250> [BODY: /time/t_164f2]
2013-08-23 06:53:57.344 ProfileCode[5085:907] PNConnection (0x1c58fc90) {INFO}[CONNECTION::PNServiceConnectionIdentifier::WRITE] READY TO SEND (STREAM IS OPENED)
2013-08-23 06:53:57.401 ProfileCode[5085:907] Warning: A long-running Parse operation is being executed on the main thread.
Break on warnParseOperationOnMainThread() to debug.
2013-08-23 06:53:57.837 ProfileCode[5085:907] PNConnection (0x1c58fc90) {INFO}[CONNECTION::PNServiceConnectionIdentifier::READ] HAS DATA FOR READ OUT (STREAM IS OPENED)
2013-08-23 06:53:57.839 ProfileCode[5085:907] PNResponseDeserialize (0x1c556d80) {INFO} RAW DATA: t_164f2([13772372387419212])
2013-08-23 06:53:57.841 ProfileCode[5085:907] PNServiceChannel (0x1c5ab9c0) {INFO} RECIEVED RESPONSE:
HTTP STATUS CODE: 200
RESPONSE SIZE: 28
RESPONSE CONTENT SIZE: 268
IS JSONP: YES
CALLBACK METHOD: t
REQUEST IDENTIFIER: 164f2
RESPONSE: (
13772372387419212
)
2013-08-23 06:53:57.844 ProfileCode[5085:907] PNServiceChannel (0x1c5ab9c0) {INFO} PARSED DATA: PNTimeTokenResponseParser (0x1c540e20): <time token: 13772372387419212>
2013-08-23 06:53:57.845 ProfileCode[5085:907] PNServiceChannel (0x1c5ab9c0) {INFO} OBSERVED REQUEST COMPLETED: (null)
2013-08-23 06:54:06.921 ProfileCode[5085:907] error.associatedObject: (
phFZ8cGuoe,
yYd010XTJk
)
2013-08-23 06:54:06.923 ProfileCode[5085:907] we can't subscribe on channel error: Domain=com.pubnub.pubnub; Code=106; Description="Subscription failed by timeout"; Reason="Looks like there is some packets lost because of which request failed by timeout"; Fix suggestion="Try send request again later."; Associated object=(
"PNChannel(0x1c5b3530) phFZ8cGuoe",
"PNChannel(0x1c5b2160) yYd010XTJk"
)
2013-08-23 06:54:06:928 ProfileCode[5085:2311] performSelector:@selector(attachChannels:) after delay at message center
2013-08-23 06:54:06.930 ProfileCode[5085:907] subscribeOnChannels : Domain=com.pubnub.pubnub; Code=106; Description="Subscription failed by timeout"; Reason="Looks like there is some packets lost because of which request failed by timeout"; Fix suggestion="Try send request again later."; Associated object=(
"PNChannel(0x1c5b3530) phFZ8cGuoe",
"PNChannel(0x1c5b2160) yYd010XTJk"
)
2013-08-23 06:54:06:936 ProfileCode[5085:2311] performSelector:@selector(attachChannels:) after delay recursivly
2013-08-23 06:54:09:935 ProfileCode[5085:2311] starting attachChannels: (
phFZ8cGuoe,
yYd010XTJk
)
2013-08-23 06:54:09.938 ProfileCode[5085:907] PNMessagingChannel (0x1c5731b0) {INFO} WILL START REQUEST PROCESSING: <PNSubscribeRequest: 0x1d070fd0> [BODY: /subscribe/sub-c-bbe1d18a-80ab-11e2-b64e-12313f022c90/phFZ8cGuoe,yYd010XTJk/s_b41a9/0?uuid=1cf38361-88c7-4b1e-b3cf-0169a98e6b56]
2013-08-23 06:54:09.941 ProfileCode[5085:907] PNMessagingChannel (0x1c5731b0) {INFO} DID SEND REQUEST: <PNSubscribeRequest: 0x1d070fd0> [BODY: /subscribe/sub-c-bbe1d18a-80ab-11e2-b64e-12313f022c90/phFZ8cGuoe,yYd010XTJk/s_b41a9/0?uuid=1cf38361-88c7-4b1e-b3cf-0169a98e6b56][WAITING FOR COMPLETION? YES]
2013-08-23 06:54:09.943 ProfileCode[5085:907] PNConnection (0x1c59e070) {INFO}[CONNECTION::PNMessagingConnectionIdentifier::WRITE] READY TO SEND (STREAM IS OPENED)
2013-08-23 06:54:09:947 ProfileCode[5085:2311] starting attachChannels: (
"PNChannel(0x1c5b3530) phFZ8cGuoe",
"PNChannel(0x1c5b2160) yYd010XTJk"
)
2013-08-23 06:54:10.073 ProfileCode[5085:907] PNConnection (0x1c59e070) {INFO}[CONNECTION::PNMessagingConnectionIdentifier::READ] HAS DATA FOR READ OUT (STREAM IS OPENED)
2013-08-23 06:54:10.076 ProfileCode[5085:907] PNResponseDeserialize (0x1c55eb70) {INFO} RAW DATA: t_40d05([13772372383118602])
2013-08-23 06:54:19.942 ProfileCode[5085:907] error.associatedObject: (
phFZ8cGuoe,
yYd010XTJk
)
2013-08-23 06:54:19.944 ProfileCode[5085:907] we can't subscribe on channel error: Domain=com.pubnub.pubnub; Code=106; Description="Subscription failed by timeout"; Reason="Looks like there is some packets lost because of which request failed by timeout"; Fix suggestion="Try send request again later."; Associated object=(
"PNChannel(0x1c5b3530) phFZ8cGuoe",
"PNChannel(0x1c5b2160) yYd010XTJk"
)

The problem occurred only for last sdk version. I moved back to previous version and all works good

Hi @danilNil can you tell me which commit fails, and which commit is working? We were testing this last week and it seemed operational...

when I say tested last week, I meant against on our newest release candidate branch refinement-connection (https://github.com/pubnub/objective-c/tree/refinement-connection/iOS/3.4/pubnub/libs/PubNub)

Feel free to test on this branch -- otherwise, I'll be verifying your issue on master, then testing for the fix on this branch as a next step.

geremy

Hi @geremyCohen
I've got zip file with latest SDK yesterday.
I think I can't tell which commit it is but I can send you files.

here is changed files:
ProfileCode/Classes/External/PubNub/Core/PubNub.m
ProfileCode/Classes/External/PubNub/Data/PNResponse.h
ProfileCode/Classes/External/PubNub/Data/PNResponse.m
ProfileCode/Classes/External/PubNub/Data/Parsers/PNResponseDeserialize.m
ProfileCode/Classes/External/PubNub/Misc/Categories/NSData+PNAdditions.h
ProfileCode/Classes/External/PubNub/Misc/Categories/NSData+PNAdditions.m
ProfileCode/Classes/External/PubNub/Misc/PNConstants.h
ProfileCode/Classes/External/PubNub/Misc/PNMacro.h
ProfileCode/Classes/External/PubNub/Network/PNMessagingChannel.m
ProfileCode/Classes/External/PubNub/Network/Transport/PNConnection.h
ProfileCode/Classes/External/PubNub/Network/Transport/PNConnection.m
ProfileCode/Classes/External/PubNub/Network/Transport/PNConnectionChannel.h
ProfileCode/Classes/External/PubNub/Network/Transport/PNConnectionChannel.m

Here is copies of sdk: https://www.dropbox.com/sh/32273xqlb65d19x/c7NYr5HISC

@danilNil please confirm the branch ?

@geremyCohen sorry I'm busy now. I will do it a bit later.

@danilNil I'm going to close this issue on Github, but I've opened a new ticket on our helpdesk system for you on it. We'll continue from there. Thanks,
geremy

Was this issue resolved? I'm experiencing this problem as well.

@tristanhimmelman Yes, it should be fixed.

please be sure you are on current master, the log's preamble should state that you are on version 3.5.0.

If you still experience issues on 3.5.0, please contact us at support@pubnub.com, and we'll be sure to get to the bottom of your issue!