search

Eneris / push-receiver

A library to subscribe to GCM/FCM and receive notifications within a node process.
https://medium.com/@MatthieuLemoine/my-journey-to-bring-web-push-support-to-node-and-electron-ce70eea1c0b0
MIT License
16 stars 15 forks source link

IqStanza #9

Closed jd1378 closed 1 year ago

jd1378 commented 1 year ago

I have put the log level to verbose and I see the app getting disconnected and reconnected repeatedly, and I don't get why, is this happening for you as well ?

I thought IQStanzas maybe have a relation to this

so far, I found out that when you receive a IQ Stanzas request, you have to send a response, within a timeout this is what I found so far for creating a response: https://github.com/igniterealtime/tinder/blob/bef99c006ba35f92fef55cca1e781464e363b0ab/src/main/java/org/xmpp/packet/IQ.java#LL375C29-L375C29

Eneris commented 1 year ago

Hi. In what time frame are you getting disconnected? Can you share a log from verbose output?

jd1378 commented 1 year ago

hi sure

[PUSH_RECEIVER_DEBUG] emit ON_CONNECT
[PUSH_RECEIVER_VERBOSE] Got data: 1
[PUSH_RECEIVER_VERBOSE] waitForData state: 0
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Got data: 65
[PUSH_RECEIVER_VERBOSE] waitForData state: 0
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 0
[PUSH_RECEIVER_VERBOSE] VERSION IS 41
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 3
[PUSH_RECEIVER_VERBOSE] Proto size: 63
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] emit ON_READY
[PUSH_RECEIVER_VERBOSE] GCM Handshake complete.
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Got data: 12
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 1
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 7
[PUSH_RECEIVER_VERBOSE] Proto size: 10
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] IqStanza: If anyone knows what is this and how to respond, please let me know! - message:  {"type":"SET","id":"","extension":{"id":12,"data":{"type":"Buffer","data":[]}}}
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_DEBUG] emit ON_DISCONNECT
[PUSH_RECEIVER_VERBOSE] connect
[PUSH_RECEIVER_VERBOSE] checkin
[PUSH_RECEIVER_DEBUG] emit ON_CONNECT
[PUSH_RECEIVER_VERBOSE] Got data: 1
[PUSH_RECEIVER_VERBOSE] waitForData state: 0
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Got data: 65
[PUSH_RECEIVER_VERBOSE] waitForData state: 0
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 0
[PUSH_RECEIVER_VERBOSE] VERSION IS 41
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 3
[PUSH_RECEIVER_VERBOSE] Proto size: 63
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] emit ON_READY
[PUSH_RECEIVER_VERBOSE] GCM Handshake complete.
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Got data: 12
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 1
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 7
[PUSH_RECEIVER_VERBOSE] Proto size: 10
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] IqStanza: If anyone knows what is this and how to respond, please let me know! - message:  {"type":"SET","id":"","extension":{"id":12,"data":{"type":"Buffer","data":[]}}}
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes

it happens like every 15-30 second

jd1378 commented 1 year ago

let me know if you need any extra info

Eneris commented 1 year ago

I get this:

[PUSH_RECEIVER_VERBOSE] Got data: 2
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 1
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 0
[PUSH_RECEIVER_VERBOSE] Proto size: 0
[PUSH_RECEIVER_DEBUG] emit ON_HEARTBEAT
[PUSH_RECEIVER_VERBOSE] HEARTBEAT PING {}
[PUSH_RECEIVER_VERBOSE] Heartbeat send pong { last_stream_id_received: 2 }
[PUSH_RECEIVER_VERBOSE] HEARTBEAT sending PONG { last_stream_id_received: 2 }
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes

.... nothing for 5 minutes ...

[PUSH_RECEIVER_VERBOSE] Heartbeat send pong { last_stream_id_received: 3 }
[PUSH_RECEIVER_VERBOSE] HEARTBEAT sending PING { last_stream_id_received: 3 }
[PUSH_RECEIVER_VERBOSE] Got data: 4
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 1
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 1
[PUSH_RECEIVER_VERBOSE] Proto size: 2
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] emit ON_HEARTBEAT
[PUSH_RECEIVER_VERBOSE] HEARTBEAT PONG { lastStreamIdReceived: 3 }
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes

I'd guess that you're not sending the HEARTBEAT... Which module version are you using? Do you have anything in heartbeatIntervalMs option? (Default is 5minutes)

EDIT: Missing heartbeat would explain why is your websocket getting closed

jd1378 commented 1 year ago

this is my entire code:

import {PushReceiver} from "@eneris/push-receiver";
import fs from "node:fs";

const gcmSenderId = "<somesenderidhere>"; // I put a valid senderid here

let credentials = undefined;

try {
  const credentialsText = fs.readTextFileSync("./credentials.json");
  if (credentialsText) {
    credentials = JSON.parse(credentialsText);
  }
} catch {}

function getPersistentIds() {
  try {
    const idsText = fs.readTextFileSync("./persistentIds.json");
    if (idsText) {
      return JSON.parse(idsText);
    }

    return [];
  } catch {
    return [];
  }
}

/**
 * 
 * @param {Array<string>} ids 
 */
function updatePersistentIds(ids) {
  fs.writeFileSync("./persistentIds.json", JSON.stringify(ids), {
    create: true,
    append: false,
  });
}

let persistentIds = getPersistentIds();

const instance = new PushReceiver({
  credentials,
  // logLevel: "DEBUG",
  logLevel: "VERBOSE",
  senderId: gcmSenderId,
  persistentIds, // Recover stored ids of all previous notifications
});

const stopListeningToCredentials = instance.onCredentialsChanged(
  ({ newCredentials }) => {
    console.log("Client generated new credentials.", newCredentials);
    fs.writeFileSync(
      "./credentials.json",
      JSON.stringify(newCredentials),
      { create: true, append: false },
    );
  },
);

const stopListeningToNotifications = instance.onNotification(
  ({ message, persistentId }) => {
    // Do someting with the notification
    console.log("Notification received", message);
    persistentIds = [...persistentIds, persistentId];
    updatePersistentIds(persistentIds);
  },
);

await instance.connect();

Edit: Part of fs usage is incorrect because I was testing with Deno which didnt work.

jd1378 commented 1 year ago

maybe because heartbeat default is not kicking in ? (I expected it to work by default)

jd1378 commented 1 year ago

I tried setting the heartbeat to 5000 seconds and the results seem to be the same ? (Socket read finished prematurely...)

[PUSH_RECEIVER_DEBUG] emit ON_CONNECT
[PUSH_RECEIVER_VERBOSE] Got data: 1
[PUSH_RECEIVER_VERBOSE] waitForData state: 0
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Got data: 65
[PUSH_RECEIVER_VERBOSE] waitForData state: 0
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 0
[PUSH_RECEIVER_VERBOSE] VERSION IS 41
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 3
[PUSH_RECEIVER_VERBOSE] Proto size: 63
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] emit ON_READY
[PUSH_RECEIVER_VERBOSE] GCM Handshake complete.
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Got data: 12
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 1
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 7
[PUSH_RECEIVER_VERBOSE] Proto size: 10
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] IqStanza: If anyone knows what is this and how to respond, please let me know! - message:  {"type":"SET","id":"","extension":{"id":12,"data":{"type":"Buffer","data":[]}}}
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Heartbeat send pong { last_stream_id_received: 2 }
[PUSH_RECEIVER_VERBOSE] HEARTBEAT sending PING { last_stream_id_received: 2 }
[PUSH_RECEIVER_VERBOSE] Got data: 4
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 1
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 1
[PUSH_RECEIVER_VERBOSE] Proto size: 2
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] emit ON_HEARTBEAT
[PUSH_RECEIVER_VERBOSE] HEARTBEAT PONG { lastStreamIdReceived: 2 }
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Heartbeat send pong { last_stream_id_received: 3 }
[PUSH_RECEIVER_VERBOSE] HEARTBEAT sending PING { last_stream_id_received: 3 }
[PUSH_RECEIVER_VERBOSE] Got data: 4
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 1
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 1
[PUSH_RECEIVER_VERBOSE] Proto size: 2
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] emit ON_HEARTBEAT
[PUSH_RECEIVER_VERBOSE] HEARTBEAT PONG { lastStreamIdReceived: 3 }
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Heartbeat send pong { last_stream_id_received: 4 }
[PUSH_RECEIVER_VERBOSE] HEARTBEAT sending PING { last_stream_id_received: 4 }
[PUSH_RECEIVER_VERBOSE] Got data: 4
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 1
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 1
[PUSH_RECEIVER_VERBOSE] Proto size: 2
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] emit ON_HEARTBEAT
[PUSH_RECEIVER_VERBOSE] HEARTBEAT PONG { lastStreamIdReceived: 4 }
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Heartbeat send pong { last_stream_id_received: 5 }
[PUSH_RECEIVER_VERBOSE] HEARTBEAT sending PING { last_stream_id_received: 5 }
[PUSH_RECEIVER_VERBOSE] Got data: 4
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 1
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 1
[PUSH_RECEIVER_VERBOSE] Proto size: 2
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] emit ON_HEARTBEAT
[PUSH_RECEIVER_VERBOSE] HEARTBEAT PONG { lastStreamIdReceived: 5 }
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Heartbeat send pong { last_stream_id_received: 6 }
[PUSH_RECEIVER_VERBOSE] HEARTBEAT sending PING { last_stream_id_received: 6 }
[PUSH_RECEIVER_VERBOSE] Got data: 4
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 1
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 1
[PUSH_RECEIVER_VERBOSE] Proto size: 2
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] emit ON_HEARTBEAT
[PUSH_RECEIVER_VERBOSE] HEARTBEAT PONG { lastStreamIdReceived: 6 }
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Heartbeat send pong { last_stream_id_received: 7 }
[PUSH_RECEIVER_VERBOSE] HEARTBEAT sending PING { last_stream_id_received: 7 }
[PUSH_RECEIVER_VERBOSE] Got data: 4
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 1
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 1
[PUSH_RECEIVER_VERBOSE] Proto size: 2
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] emit ON_HEARTBEAT
[PUSH_RECEIVER_VERBOSE] HEARTBEAT PONG { lastStreamIdReceived: 7 }
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE]###  Socket read finished prematurely. Waiting for 2 more bytes
jd1378 commented 1 year ago

my node version is v18.14.2

Eneris commented 1 year ago

I tried setting the heartbeat to 5000 seconds and the results seem to be the same ? (Socket read finished prematurely...)

[PUSH_RECEIVER_DEBUG] emit ON_CONNECT
[PUSH_RECEIVER_VERBOSE] Got data: 1
[PUSH_RECEIVER_VERBOSE] waitForData state: 0
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Got data: 65
[PUSH_RECEIVER_VERBOSE] waitForData state: 0
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 0
[PUSH_RECEIVER_VERBOSE] VERSION IS 41
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 3
[PUSH_RECEIVER_VERBOSE] Proto size: 63
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] emit ON_READY
[PUSH_RECEIVER_VERBOSE] GCM Handshake complete.
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Got data: 12
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 1
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 7
[PUSH_RECEIVER_VERBOSE] Proto size: 10
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] IqStanza: If anyone knows what is this and how to respond, please let me know! - message:  {"type":"SET","id":"","extension":{"id":12,"data":{"type":"Buffer","data":[]}}}
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Heartbeat send pong { last_stream_id_received: 2 }
[PUSH_RECEIVER_VERBOSE] HEARTBEAT sending PING { last_stream_id_received: 2 }
[PUSH_RECEIVER_VERBOSE] Got data: 4
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 1
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 1
[PUSH_RECEIVER_VERBOSE] Proto size: 2
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] emit ON_HEARTBEAT
[PUSH_RECEIVER_VERBOSE] HEARTBEAT PONG { lastStreamIdReceived: 2 }
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Heartbeat send pong { last_stream_id_received: 3 }
[PUSH_RECEIVER_VERBOSE] HEARTBEAT sending PING { last_stream_id_received: 3 }
[PUSH_RECEIVER_VERBOSE] Got data: 4
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 1
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 1
[PUSH_RECEIVER_VERBOSE] Proto size: 2
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] emit ON_HEARTBEAT
[PUSH_RECEIVER_VERBOSE] HEARTBEAT PONG { lastStreamIdReceived: 3 }
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Heartbeat send pong { last_stream_id_received: 4 }
[PUSH_RECEIVER_VERBOSE] HEARTBEAT sending PING { last_stream_id_received: 4 }
[PUSH_RECEIVER_VERBOSE] Got data: 4
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 1
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 1
[PUSH_RECEIVER_VERBOSE] Proto size: 2
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] emit ON_HEARTBEAT
[PUSH_RECEIVER_VERBOSE] HEARTBEAT PONG { lastStreamIdReceived: 4 }
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Heartbeat send pong { last_stream_id_received: 5 }
[PUSH_RECEIVER_VERBOSE] HEARTBEAT sending PING { last_stream_id_received: 5 }
[PUSH_RECEIVER_VERBOSE] Got data: 4
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 1
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 1
[PUSH_RECEIVER_VERBOSE] Proto size: 2
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] emit ON_HEARTBEAT
[PUSH_RECEIVER_VERBOSE] HEARTBEAT PONG { lastStreamIdReceived: 5 }
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Heartbeat send pong { last_stream_id_received: 6 }
[PUSH_RECEIVER_VERBOSE] HEARTBEAT sending PING { last_stream_id_received: 6 }
[PUSH_RECEIVER_VERBOSE] Got data: 4
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 1
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 1
[PUSH_RECEIVER_VERBOSE] Proto size: 2
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] emit ON_HEARTBEAT
[PUSH_RECEIVER_VERBOSE] HEARTBEAT PONG { lastStreamIdReceived: 6 }
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Heartbeat send pong { last_stream_id_received: 7 }
[PUSH_RECEIVER_VERBOSE] HEARTBEAT sending PING { last_stream_id_received: 7 }
[PUSH_RECEIVER_VERBOSE] Got data: 4
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 1
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 1
[PUSH_RECEIVER_VERBOSE] Proto size: 2
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] emit ON_HEARTBEAT
[PUSH_RECEIVER_VERBOSE] HEARTBEAT PONG { lastStreamIdReceived: 7 }
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE]###  Socket read finished prematurely. Waiting for 2 more bytes

Yea that finished prematurely is just pore choice of wording. I can see that you're not getting disconnected anymore.

Eneris commented 1 year ago

Only thing that i can see different from my config is that you're not sending current chrome version which gets old from time to time in the default configuration. Mine is 110.0.5481.177

Eneris commented 1 year ago

Or it could mean that protobuff which parses that exact message is not accurrate. But it gets the job done fine for now

jd1378 commented 1 year ago

hmm I set chromeVersion: "110.0.5481.177" and it still disconnected without short interval heartbeat

Eneris commented 1 year ago

hmm I set chromeVersion: "110.0.5481.177" and it still disconnected without short interval heartbeat

You identify as disconnected by message [PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes or [PUSH_RECEIVER_DEBUG] emit ON_DISCONNECT ?

Because the first one does not mean that you're disconnected

Eneris commented 1 year ago

so far, I found out that when you receive a IQ Stanzas request, you have to send a response, within a timeout this is what I found so far for creating a response: https://github.com/igniterealtime/tinder/blob/bef99c006ba35f92fef55cca1e781464e363b0ab/src/main/java/org/xmpp/packet/IQ.java#LL375C29-L375C29

Thanks btw for the link to stanza code. I'll check it out and see if I can construct response for it

jd1378 commented 1 year ago

hmm I set chromeVersion: "110.0.5481.177" and it still disconnected without short interval heartbeat

You identify as disconnected by message [PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes or [PUSH_RECEIVER_DEBUG] emit ON_DISCONNECT ?

Because the first one does not mean that you're disconnected

First I thought its the first one, but when you said it's poor wording I understood that it's the second one

So yeah with short heartbeat I don't get disconnected anymore

Eneris commented 1 year ago

Be careful with the heartbeat timer. The idea is not to get noticed as abnormal clients. Chromium has minimum of 180000(3 minutes)

jd1378 commented 1 year ago

the problem is it gets disconnected ([PUSH_RECEIVER_DEBUG] emit ON_DISCONNECT) in less than 15 seconds (I have tested it to make sure, in my case it took ~13 seconds) so what's wrong here ?

Eneris commented 1 year ago

the problem is it gets disconnected ([PUSH_RECEIVER_DEBUG] emit ON_DISCONNECT) in less than 15 seconds (I have tested it to make sure, in my case it took ~13 seconds) so what's wrong here?

Ok so I have run the exact copy of your code and it looks like it works. It does one re-connect right after start but runs fine since then including the 5mins heartbeat.

My guess is that you may have done something to get G-servers suspicious. I'd suggest to try different IP/senderId or wait few (12+) hours and try again. It happened to me during development of this module but with registrations (it was just killing connections with no reason given)

Sorry that I cannot be of any more help right now. Please let me know if it changes.

[PUSH_RECEIVER_DEBUG] emit ON_CONNECT
[PUSH_RECEIVER_VERBOSE] Got data: 1
[PUSH_RECEIVER_VERBOSE] waitForData state: 0
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Got data: 59
[PUSH_RECEIVER_VERBOSE] waitForData state: 0
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 0
[PUSH_RECEIVER_VERBOSE] VERSION IS 41
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 3
[PUSH_RECEIVER_VERBOSE] Proto size: 57
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] emit ON_READY
[PUSH_RECEIVER_VERBOSE] GCM Handshake complete.
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Got data: 2
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 1
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 4
[PUSH_RECEIVER_VERBOSE] Proto size: 0
[PUSH_RECEIVER_VERBOSE] Close: Server requested close! message:  {}
[PUSH_RECEIVER_DEBUG] emit ON_DISCONNECT
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] connect
[PUSH_RECEIVER_VERBOSE] checkin
[PUSH_RECEIVER_DEBUG] emit ON_CONNECT
[PUSH_RECEIVER_VERBOSE] Got data: 1
[PUSH_RECEIVER_VERBOSE] waitForData state: 0
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Got data: 65
[PUSH_RECEIVER_VERBOSE] waitForData state: 0
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 0
[PUSH_RECEIVER_VERBOSE] VERSION IS 41
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 3
[PUSH_RECEIVER_VERBOSE] Proto size: 63
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] emit ON_READY
[PUSH_RECEIVER_VERBOSE] GCM Handshake complete.
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Got data: 12
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 1
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 7
[PUSH_RECEIVER_VERBOSE] Proto size: 10
[PUSH_RECEIVER_VERBOSE] waitForData state: 3
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 3
[PUSH_RECEIVER_DEBUG] IqStanza: If anyone knows what is this and how to respond, please let me know! - message:  {"type":"SET","id":"","extension":{"id":12,"data":{"type":"Buffer","data":[]}}}
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
[PUSH_RECEIVER_VERBOSE] Got data: 2
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Processing MCS data: state == 1
[PUSH_RECEIVER_VERBOSE] RECEIVED PROTO OF TYPE 0
[PUSH_RECEIVER_VERBOSE] Proto size: 0
[PUSH_RECEIVER_DEBUG] emit ON_HEARTBEAT
[PUSH_RECEIVER_VERBOSE] HEARTBEAT PING {}
[PUSH_RECEIVER_VERBOSE] Heartbeat send pong { last_stream_id_received: 4 }
[PUSH_RECEIVER_VERBOSE] HEARTBEAT sending PONG { last_stream_id_received: 4 }
[PUSH_RECEIVER_VERBOSE] waitForData state: 1
[PUSH_RECEIVER_VERBOSE] Socket read finished prematurely. Waiting for 2 more bytes
jd1378 commented 1 year ago

My guess is that you may have done something to get G-servers suspicious. I'd suggest to try different IP/senderId or wait few (12+) hours and try again. It happened to me during development of this module but with registrations (it was just killing connections with no reason given)

oh okay, that's good to know ! thank you I think it would be helpful to include this information in the readme

Eneris commented 1 year ago

Well. That would be a bit hard to explain. But I could write something like: Server sometimes refuses to talk when you don't act as a normal device would

btw: In your code, I am not familiar with fs.readTextFileSync. Had to replace for fs.readFileSync in my env for that code to load/save the credentials properly`

jd1378 commented 1 year ago

Something along the lines of When G-servers become suspicious of your client activity, they may drop your connections more frequently or refuse to connect. I'd suggest to try different IP/SenderId or wait a few (12+) hours and try again. It happened to me during development of this module but with registrations (it was just killing connections with no reason given) would be fine imo. no need to be serious about it. just knowing something like that helps troubleshooting

btw: In your code, I am not familiar with fs.readTextFileSync. Had to replace for fs.readFileSync in my env for that code to load/save the credentials properly`

yeah sorry about that, were testing stuff with deno, so I forgot to change them to node stuff properly, and I don't have project setup so it doesn't throw any error in editor so I didn't see.