diff --git a/ansible/roles/node/tasks/main.yml b/ansible/roles/node/tasks/main.yml index 56c830f2b..049f0d524 100644 --- a/ansible/roles/node/tasks/main.yml +++ b/ansible/roles/node/tasks/main.yml @@ -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: diff --git a/media/js/newsblur/reader/reader.js b/media/js/newsblur/reader/reader.js index bfa9c1ca8..da69ca08b 100644 --- a/media/js/newsblur/reader/reader.js +++ b/media/js/newsblur/reader/reader.js @@ -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(); diff --git a/node/unread_counts.coffee b/node/unread_counts.coffee index 80f1a1d4b..da95c045b 100644 --- a/node/unread_counts.coffee +++ b/node/unread_counts.coffee @@ -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 diff --git a/node/unread_counts.js b/node/unread_counts.js index 79b1e625c..182c047c5 100644 --- a/node/unread_counts.js +++ b/node/unread_counts.js @@ -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; };