public-mirrors/NewsBlur
1
0
Fork 0
mirror of https://github.com/samuelclay/NewsBlur.git synced 2025-09-18 21:50:56 +00:00
Code Issues Projects Releases Packages Wiki Activity Actions

Adding a lot more socket.io logging.

Browse source
This commit is contained in:
Samuel Clay 2025-02-27 23:57:28 -08:00
parent b469f0dd67
commit c56262e466
4 changed files with 169 additions and 39 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

16
ansible/roles/node/tasks/main.yml
View file

@ -1,12 +1,12 @@
---
- name: Ensure 'nb' user owns /srv/ recursively
become: yes
file:
path: /srv
owner: nb
group: nb
recurse: yes
state: directory
# - name: Ensure 'nb' user owns /srv/ recursively
# become: yes
# file:
# path: /srv
# owner: nb
# group: nb
# recurse: yes
# state: directory
- name: Copy node secrets
copy:

79
media/js/newsblur/reader/reader.js
View file

@ -5263,6 +5263,7 @@
if (!force && NEWSBLUR.Globals.is_anonymous) return;
// if (!force && !NEWSBLUR.Globals.is_premium) return;
if (this.socket && !this.socket.connected) {
NEWSBLUR.log(["Reconnecting to existing socket..."]);
this.socket.connect();
} else if (force || !this.socket || !this.socket.connected) {
var server = window.location.protocol + '//' + window.location.hostname;
@ -5274,6 +5275,9 @@
if (local) {
port = https ? 8889 : 8888;
}
NEWSBLUR.log(["Creating new socket connection to", server + ":" + port]);
this.socket = this.socket || io.connect(server + ":" + port, {
path: "/v3/socket.io",
reconnectionDelay: 2000,
@ -5284,10 +5288,47 @@
upgrade: false
});
// Debug socket connection events
this.socket.on('connect_error', _.bind(function (error) {
NEWSBLUR.log(["Socket connect_error:", error.message]);
}, this));
this.socket.on('connect_timeout', _.bind(function () {
NEWSBLUR.log(["Socket connect_timeout"]);
}, this));
this.socket.on('reconnect', _.bind(function (attemptNumber) {
NEWSBLUR.log(["Socket reconnected after", attemptNumber, "attempts"]);
}, this));
this.socket.on('reconnect_attempt', _.bind(function (attemptNumber) {
NEWSBLUR.log(["Socket reconnect attempt #", attemptNumber]);
}, this));
this.socket.on('reconnect_error', _.bind(function (error) {
NEWSBLUR.log(["Socket reconnect_error:", error.message]);
}, this));
this.socket.on('reconnect_failed', _.bind(function () {
NEWSBLUR.log(["Socket reconnect_failed"]);
}, this));
this.socket.on('error', _.bind(function (error) {
NEWSBLUR.log(["Socket error:", error]);
}, this));
this.socket.on('ping', _.bind(function () {
NEWSBLUR.log(["Socket ping sent at", new Date().toISOString()]);
}, this));
this.socket.on('pong', _.bind(function (latency) {
NEWSBLUR.log(["Socket pong received, latency:", latency, "ms"]);
}, this));
// this.socket.refresh_feeds = _.debounce(_.bind(this.force_feeds_refresh, this), 1000*10);
this.socket.on('connect', _.bind(function () {
var active_feeds = this.send_socket_active_feeds();
NEWSBLUR.log(["Connected to real-time pubsub with " + active_feeds.length + " feeds."]);
NEWSBLUR.log(["Connected to real-time pubsub with " + active_feeds.length + " feeds at", new Date().toISOString()]);
this.flags.feed_refreshing_in_realtime = true;
this.setup_feed_refresh();
NEWSBLUR.assets.stories.retry_failed_marked_read_stories();
@ -5316,16 +5357,17 @@
this.socket.on('user:update', _.bind(this.handle_realtime_update, this));
this.socket.on('disconnect', _.bind(function () {
NEWSBLUR.log(["Lost connection to real-time pubsub. Falling back to polling."]);
this.socket.on('disconnect', _.bind(function (reason) {
NEWSBLUR.log(["Lost connection to real-time pubsub due to:", reason, "at", new Date().toISOString(), "Falling back to polling."]);
this.flags.feed_refreshing_in_realtime = false;
this.setup_feed_refresh();
// $('.NB-module-content-account-realtime-subtitle').html($.make('b', 'Updating every 60 sec'));
$('.NB-module-content-account-realtime').attr('title', 'Updating sites every ' + this.flags.refresh_interval + ' seconds...').addClass('NB-error').removeClass('NB-active');
this.apply_tipsy_titles();
}, this));
this.socket.on('error', _.bind(function () {
NEWSBLUR.log(["Can't connect to real-time pubsub."]);
this.socket.on('error', _.bind(function (error) {
NEWSBLUR.log(["Can't connect to real-time pubsub:", error]);
this.flags.feed_refreshing_in_realtime = false;
this.setup_feed_refresh();
// $('.NB-module-content-account-realtime-subtitle').html($.make('b', 'Updating every 60 sec'));
@ -5333,15 +5375,24 @@
this.apply_tipsy_titles();
_.delay(_.bind(this.setup_socket_realtime_unread_counts, this), Math.random() * 60 * 1000);
}, this));
this.socket.on('reconnect_failed', _.bind(function () {
console.log(["Socket.io reconnect failed"]);
}, this));
this.socket.on('reconnect', _.bind(function () {
console.log(["Socket.io reconnected successfully!"]);
}, this));
this.socket.on('reconnecting', _.bind(function () {
console.log(["Socket.io reconnecting..."]);
}, this));
// Add a heartbeat check to detect stalled connections
this.socket_heartbeat_interval = setInterval(_.bind(function () {
if (this.socket && this.socket.connected) {
var now = Date.now();
if (!this.last_heartbeat_time) {
this.last_heartbeat_time = now;
} else if (now - this.last_heartbeat_time > 70000) { // 70 seconds (longer than pingInterval)
NEWSBLUR.log(["Socket heartbeat missed, reconnecting...",
"Last heartbeat:", new Date(this.last_heartbeat_time).toISOString(),
"Current time:", new Date(now).toISOString(),
"Difference:", now - this.last_heartbeat_time, "ms"]);
this.socket.disconnect();
this.socket.connect();
}
this.last_heartbeat_time = now;
}
}, this), 30000); // Check every 30 seconds
}
// this.watch_navigator_online();

55
node/unread_counts.coffee
View file

@ -87,13 +87,34 @@ unread_counts = (server) =>
return client
# Track active connections by username for debugging
active_connections = {}
# Log engine events for debugging
io.engine.on 'connection', (socket) ->
log.debug "Engine connection established: #{socket.id}"
io.engine.on 'close', (socket) ->
log.debug "Engine connection closed: #{socket.id}"
io.on 'connection', (socket) ->
ip = socket.handshake.headers['X-Forwarded-For'] || socket.handshake.address
socket_id = socket.id
log.debug "Socket connected: #{socket_id} from #{ip}"
socket.conn.on 'error', (err) ->
log.debug "Socket #{socket_id} - connection error: #{err}"
socket.conn.on 'close', (reason) ->
log.debug "Socket #{socket_id} - connection closed: #{reason}"
socket.on 'subscribe:feeds', (@feeds, @username) =>
log.info @username, "Connecting (#{@feeds.length} feeds, #{ip})," +
" (#{io.engine.clientsCount} connected) " +
" #{if SECURE then "(SSL)" else ""}"
log.info @username, "Connecting (#{@feeds.length} feeds, #{ip}), (#{io.engine.clientsCount} connected) #{if SECURE then "(SSL)" else ""}"
# Track connections by username for debugging
active_connections[@username] = active_connections[@username] || []
active_connections[@username].push(socket_id)
log.debug "#{@username} now has #{active_connections[@username].length} active connections"
if not @username
return
@ -105,9 +126,7 @@ unread_counts = (server) =>
socket.subscribe = setup_redis_client(socket, @username)
socket.subscribe.on "connect", =>
log.info @username, "Connected (#{@feeds.length} feeds, #{ip})," +
" (#{io.engine.clientsCount} connected) " +
" #{if SECURE then "(SSL)" else "(non-SSL)"}"
log.info @username, "Connected (#{@feeds.length} feeds, #{ip}), (#{io.engine.clientsCount} connected) #{if SECURE then "(SSL)" else "(non-SSL)"}"
socket.subscribe.subscribe @feeds
feeds_story = @feeds.map (f) -> "#{f}:story"
socket.subscribe.subscribe feeds_story
@ -122,17 +141,33 @@ unread_counts = (server) =>
log.info @username, "Update on #{channel}: #{event_name} - #{message}"
socket.emit event_name, channel, message
socket.on 'disconnect', () =>
socket.on 'disconnect', (reason) =>
log.debug "Socket #{socket_id} disconnected: #{reason}"
# Update connection tracking
if @username and active_connections[@username]
idx = active_connections[@username].indexOf(socket_id)
if idx > -1
active_connections[@username].splice(idx, 1)
log.debug "#{@username} now has #{active_connections[@username].length} active connections"
if active_connections[@username].length == 0
delete active_connections[@username]
socket.subscribe?.quit()
log.info @username, "Disconnect (#{@feeds?.length} feeds, #{ip})," +
" there are now #{io.engine.clientsCount} users. " +
" #{if SECURE then "(SSL)" else "(non-SSL)"}"
log.info @username, "Disconnect (#{@feeds?.length} feeds, #{ip}), there are now #{io.engine.clientsCount} users. #{if SECURE then "(SSL)" else "(non-SSL)"}"
io.engine.on 'connection_error', (err) ->
log.debug "Connection Error: #{err.code} - #{err.message}"
io.sockets.on 'error', (err) ->
log.debug "Error (sockets): #{err}"
# Periodically log connection stats
setInterval ->
total_users = Object.keys(active_connections).length
total_connections = io.engine.clientsCount
log.debug "Connection stats: #{total_users} users with #{total_connections} total connections"
, 60000
return io

58
node/unread_counts.js
View file

@ -9,7 +9,7 @@
log = require('./log.js');
unread_counts = (server) => {
var ENV_DEV, ENV_DOCKER, ENV_PROD, REDIS_PORT, REDIS_SERVER, SECURE, io, pub_client, redis_opts, setup_redis_client, sub_client;
var ENV_DEV, ENV_DOCKER, ENV_PROD, REDIS_PORT, REDIS_SERVER, SECURE, active_connections, io, pub_client, redis_opts, setup_redis_client, sub_client;
ENV_DEV = process.env.NODE_ENV === 'development' || process.env.NODE_ENV === 'debug';
ENV_PROD = process.env.NODE_ENV === 'production';
ENV_DOCKER = process.env.NODE_ENV === 'docker';
@ -92,14 +92,37 @@
});
return client;
};
// Track active connections by username for debugging
active_connections = {};
// Log engine events for debugging
io.engine.on('connection', function(socket) {
return log.debug(`Engine connection established: ${socket.id}`);
});
io.engine.on('close', function(socket) {
return log.debug(`Engine connection closed: ${socket.id}`);
});
io.on('connection', function(socket) {
var ip;
var ip, socket_id;
ip = socket.handshake.headers['X-Forwarded-For'] || socket.handshake.address;
socket_id = socket.id;
log.debug(`Socket connected: ${socket_id} from ${ip}`);
socket.conn.on('error', function(err) {
return log.debug(`Socket ${socket_id} - connection error: ${err}`);
});
socket.conn.on('close', function(reason) {
return log.debug(`Socket ${socket_id} - connection closed: ${reason}`);
});
socket.on('subscribe:feeds', (feeds, username1) => {
var ref;
this.feeds = feeds;
this.username = username1;
log.info(this.username, `Connecting (${this.feeds.length} feeds, ${ip}),` + ` (${io.engine.clientsCount} connected) ` + ` ${SECURE ? "(SSL)" : ""}`);
log.info(this.username, `Connecting (${this.feeds.length} feeds, ${ip}), (${io.engine.clientsCount} connected) ${SECURE ? "(SSL)" : ""}`);
// Track connections by username for debugging
active_connections[this.username] = active_connections[this.username] || [];
active_connections[this.username].push(socket_id);
log.debug(`${this.username} now has ${active_connections[this.username].length} active connections`);
if (!this.username) {
return;
}
@ -112,7 +135,7 @@
socket.subscribe = setup_redis_client(socket, this.username);
socket.subscribe.on("connect", () => {
var feeds_story;
log.info(this.username, `Connected (${this.feeds.length} feeds, ${ip}),` + ` (${io.engine.clientsCount} connected) ` + ` ${SECURE ? "(SSL)" : "(non-SSL)"}`);
log.info(this.username, `Connected (${this.feeds.length} feeds, ${ip}), (${io.engine.clientsCount} connected) ${SECURE ? "(SSL)" : "(non-SSL)"}`);
socket.subscribe.subscribe(this.feeds);
feeds_story = this.feeds.map(function(f) {
return `${f}:story`;
@ -132,12 +155,25 @@
return socket.emit(event_name, channel, message);
});
});
return socket.on('disconnect', () => {
var ref, ref1;
return socket.on('disconnect', (reason) => {
var idx, ref, ref1;
log.debug(`Socket ${socket_id} disconnected: ${reason}`);
// Update connection tracking
if (this.username && active_connections[this.username]) {
idx = active_connections[this.username].indexOf(socket_id);
if (idx > -1) {
active_connections[this.username].splice(idx, 1);
log.debug(`${this.username} now has ${active_connections[this.username].length} active connections`);
}
if (active_connections[this.username].length === 0) {
delete active_connections[this.username];
}
}
if ((ref = socket.subscribe) != null) {
ref.quit();
}
return log.info(this.username, `Disconnect (${(ref1 = this.feeds) != null ? ref1.length : void 0} feeds, ${ip}),` + ` there are now ${io.engine.clientsCount} users. ` + ` ${SECURE ? "(SSL)" : "(non-SSL)"}`);
return log.info(this.username, `Disconnect (${(ref1 = this.feeds) != null ? ref1.length : void 0} feeds, ${ip}), there are now ${io.engine.clientsCount} users. ${SECURE ? "(SSL)" : "(non-SSL)"}`);
});
});
io.engine.on('connection_error', function(err) {
@ -146,6 +182,14 @@
io.sockets.on('error', function(err) {
return log.debug(`Error (sockets): ${err}`);
});
// Periodically log connection stats
setInterval(function() {
var total_connections, total_users;
total_users = Object.keys(active_connections).length;
total_connections = io.engine.clientsCount;
return log.debug(`Connection stats: ${total_users} users with ${total_connections} total connections`);
}, 60000);
return io;
};