anarchy.website Toggle Dark Mode

Minor Annoyance in Server Operation

By Trevor J. Hoglund, March 02, 2017

I sent a link to a friend, and it didn’t work. I needed to figure out why.

First thing to do was check the DNS records on my domain (). This is all in IPv6 so I need to check the AAAA records rather than the A. This looks something like this:

Now this is the IP of the server, not the router, because again this is IPv6. I don’t have any dynamic DNS setup so it’s possible it changed.

It didn’t.

This typically only happens when the server restarts which it hasn’t really done much of recently. This is when I needed to check on the server logs. First up was what used to be an Apache server. This thing:

/*
 *  Phene.co Proxy Server
 *  Written by Trevor J Hoglund
 *  2017.02.26
 */

const   client  = require('express')(),
        express = require('express'),
        folders = {
            'notes.phene.co'        : 'notes',
            'scripts.phene.co'      : 'scripts'
        },
        index   = require('serve-index'),
        proxy   = require('http-proxy').createProxyServer({}),
        serve   = require('serve-static'),
        servers = {
            'alpha.gra.phene.co'    : 'http://localhost:3001',
        //   api                    :                  :3002 ,
            'md.phene.co'           : 'http://localhost:3003',
            'trevorjhoglund.com'    : 'http://localhost:3006'
        },
        vhost   = require('vhost');
for(let i in servers)
    client.use(vhost(i,(q,s)=>{
        proxy.web(q,s,{target:servers[i]});
    }));
for(let i in folders){
    var app = express();
    app.use(serve(folders[i],{}));
    app.use('/',index(folders[i],{
        template(locals,next){
            let markup  = `<h2>Index of ${locals.directory}</h2>`;
            for(let i of locals.fileList) if(i.name!=="Thumbs.db")
                markup += `<a href="${i.name}">${i.name}</a><br>`;
            next(null, markup);
        }
    }));
    client.use(vhost(i,app));
}
client.use(serve('public',{}));
client.listen(80,()=>{console.log('Running.')});

Short and sweet, just vhosts and proxies, things that I basically required an Apache server for previously, but nowadays I’m too lazy to install that. This was a bit more convenient. The cmd log for this is a bit of a mess but bear with me here:

cd c:\web\proxy
title proxy
node app
c:\Web\proxy\app.js:10
                        'scripts.phene.co'              : 'scripts'
                        ^^^^^^^^^^^^^^^^^^
SyntaxError: Unexpected string
    at Object.exports.runInThisContext (vm.js:78:16)
    at Module._compile (module.js:545:28)
    at Object.Module._extensions..js (module.js:582:10)
    at Module.load (module.js:490:32)
    at tryModuleLoad (module.js:449:12)
    at Function.Module._load (module.js:441:3)
    at Module.runMain (module.js:607:10)
    at run (bootstrap_node.js:420:7)
    at startup (bootstrap_node.js:139:9)
    at bootstrap_node.js:535:3
node app
Running.
^C
npm i serve-index --save
[email protected] c:\Web\proxy
`-- [email protected]
  `-- [email protected]

npm WARN [email protected] No repository field.
node app
Running.
^C

node app
Running.
^C
node app
Running.
c:\Web\proxy\node_modules\http-proxy\lib\http-proxy\index.js:119
    throw err;
    ^

Error: connect ECONNREFUSED 127.0.0.1:3001
    at Object.exports._errnoException (util.js:1022:11)
    at exports._exceptionWithHostPort (util.js:1045:20)
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1090:14)

The main part here is that final error, not being able to connect ot port 3001. If you look into the object called servers in the proxy code you’ll see that this was an attempt to connect to alpha.gra.phene.co, a test build of my main project: Graphene. The server for that was down, so I ought to check those logs:

cd c:\web\alpha
node app
2017.02.26 09.15.32 Graphene server is now running.
2017.02.26 09.15.32     CDN: 3001
2017.02.26 09.15.32     API: 3002
2017.02.26 09.15.58 Trewbot (58448cd26902df0ec00e4fe9) logged in
(node:3512) DeprecationWarning: Mongoose: mpromise (mongoose's default promise
library) is deprecated, plug in your own promise library instead:
http://mongoosejs.com/docs/promises.html
                                                       events.js:160
      throw er; // Unhandled 'error' event
      ^

TypeError: Cannot read property 'version' of null
    at c:\Web\alpha\controllers\users.js:354:18
    at model.Query.<anonymous> (c:\Web\alpha\node_modules\mongoose\lib\model.js
        :3403:16)
    at c:\Web\alpha\node_modules\kareem\index.js:259:21
    at c:\Web\alpha\node_modules\kareem\index.js:127:16
    at _combinedTickCallback (internal/process/next_tick.js:67:7)
    at process._tickCallback (internal/process/next_tick.js:98:9)

Now, I’ve never had this issue before, most properties named version are part of the changelog, which is an object in the database that keeps track of the development of the whole project and lets the client know when to update their browsers to keep up to date. The code it’s pointing to is in here (lines 339 - 361 of users.js):

app.get('/session', function(req,res){
    if(req.session.user)
        Graphene.getUserInfo(req.session.user,false,function(u){
            res.send(u);
        },req,res);
    else
        Change.findOne({},{},{sort:{_id:-1}},function(e,c){if(e) return res.send(e);
            res.send(JSON.stringify({
                rank        : 0,
                user        : 0,
                advanced    : [{
                    emailNotes  : true,
                    hoverColors : false,
                    eventStream : true
                }],
                version     : c.version,
                sVersion    : Graphene.v,
                accent      : "#444444",
                colorAvatar : true,
                avatarColor : "#444444"
            }));
        });
});

This just gives the basic info needed to un a session of Graphene. You could argue maybe there was an instance of Change, c, that did not have the version property, but for the sake of argument let’s assume they all conformed to the schema:

/*
 *  Graphene >> Changelog Model
 *  Written by Trewbot
 *  Jan 04, 2015
 */

var mongoose = require('mongoose'),
    changeSchema = new mongoose.Schema({
        version     : String,
        date        : String,
        description : String
    }),
    Change = mongoose.model('Change', changeSchema, 'webClientChanges');
module.exports = Change;

which requires a String object for version. So it came down to it, check the server logs and see the error there:

cd c:\web\bin\mongo
mongod --dbpath c:\web\bin\data
2017-02-26T09:14:07.713-0600 I CONTROL  [initandlisten] MongoDB starting : pid=416 port=27017 dbpath=c:\web\bin\data 64-bit host=DESKTOP-INLTJ1V
2017-02-26T09:14:07.716-0600 I CONTROL  [initandlisten] targetMinOS: Windows 7/Windows Server 2008 R2
2017-02-26T09:14:07.717-0600 I CONTROL  [initandlisten] db version v3.2.11
2017-02-26T09:14:07.718-0600 I CONTROL  [initandlisten] git version: 009580ad490190ba33d1c6253ebd8d91808923e4
2017-02-26T09:14:07.718-0600 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.1t-fips  3 May 2016
2017-02-26T09:14:07.718-0600 I CONTROL  [initandlisten] allocator: tcmalloc
2017-02-26T09:14:07.718-0600 I CONTROL  [initandlisten] modules: none
2017-02-26T09:14:07.718-0600 I CONTROL  [initandlisten] build environment:
2017-02-26T09:14:07.718-0600 I CONTROL  [initandlisten]     distmod: 2008plus-ssl
2017-02-26T09:14:07.718-0600 I CONTROL  [initandlisten]     distarch: x86_64
2017-02-26T09:14:07.718-0600 I CONTROL  [initandlisten]     target_arch: x86_64
2017-02-26T09:14:07.719-0600 I CONTROL  [initandlisten] options: { storage: { dbPath: "c:\web\bin\data" } }
2017-02-26T09:14:07.732-0600 I -        [initandlisten] Detected data files in c:\web\bin\data created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2017-02-26T09:14:07.734-0600 W -        [initandlisten] Detected unclean shutdown - c:\web\bin\data\mongod.lock is not empty.
2017-02-26T09:14:07.746-0600 W STORAGE  [initandlisten] Recovering data from the last clean checkpoint.
2017-02-26T09:14:07.747-0600 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=1G,session_max=20000,eviction=(threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
2017-02-26T09:14:10.953-0600 I NETWORK  [HostnameCanonicalizationWorker] Starting hostname canonicalization worker
2017-02-26T09:14:10.953-0600 I FTDC     [initandlisten] Initializing full-time diagnostic data capture with directory 'c:/web/bin/data/diagnostic.data'
2017-02-26T09:14:11.017-0600 I NETWORK  [initandlisten] waiting for connections on port 27017
2017-02-26T09:15:32.156-0600 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:51377 #1 (1 connection now open)
2017-02-26T09:15:32.307-0600 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:51378 #2 (2 connections now open)
2017-02-26T09:15:32.323-0600 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:51379 #3 (3 connections now open)
2017-02-26T09:15:32.333-0600 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:51380 #4 (4 connections now open)
2017-02-26T09:15:59.536-0600 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:51419 #5 (5 connections now open)
2017-02-26T09:16:00.216-0600 I WRITE    [conn4] update alphaphene.sessions query: { _id: "4NaliKOQQN7T8tX0EFc1zNkoLFnbFLDC" } update: { $set: { expires: new Date(1519658160023) } } keysExamined:1 docsExamined:1 nMatched:1 nModified:1 keyUpdates:1 writeConflicts:1 numYields:1 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { w: 2 } } } 180ms
2017-02-26T09:16:00.270-0600 I COMMAND  [conn4] command alphaphene.$cmd command: update { update: "sessions", updates: [ { q: { _id: "4NaliKOQQN7T8tX0EFc1zNkoLFnbFLDC" }, u: { $set: { expires: new Date(1519658160023) } }, upsert: false, multi: false } ], ordered: true, writeConcern: { w: 1 } } keyUpdates:0 writeConflicts:0 numYields:0 reslen:55 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { w: 2 } } } protocol:op_query 234ms
2017-02-26T15:41:53.810-0600 I NETWORK  [initandlisten] connection accepted from 89.248.172.16:44691 #6 (6 connections now open)
2017-02-26T15:41:54.982-0600 I COMMAND  [conn6] command admin.$cmd command: listDatabases { listDatabases: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:236 locks:{ Global: { acquireCount: { r: 6 } }, Database: { acquireCount: { r: 3 } } } protocol:op_query 651ms
2017-02-26T15:41:59.541-0600 I NETWORK  [conn6] end connection 89.248.172.16:44691 (5 connections now open)
2017-02-26T22:23:43.056-0600 I NETWORK  [initandlisten] connection accepted from 74.82.47.3:63738 #7 (6 connections now open)
2017-02-26T22:23:43.186-0600 I NETWORK  [conn7] end connection 74.82.47.3:63738 (5 connections now open)
2017-02-26T22:23:56.285-0600 I NETWORK  [initandlisten] connection accepted from 74.82.47.3:9572 #8 (6 connections now open)
2017-02-26T22:23:56.374-0600 I NETWORK  [conn8] end connection 74.82.47.3:9572 (5 connections now open)
2017-02-27T22:56:41.524-0600 I NETWORK  [initandlisten] connection accepted from 184.105.247.196:11780 #9 (6 connections now open)
2017-02-27T22:56:41.792-0600 I NETWORK  [conn9] end connection 184.105.247.196:11780 (5 connections now open)
2017-02-27T22:56:53.968-0600 I NETWORK  [initandlisten] connection accepted from 184.105.247.196:32676 #10 (6 connections now open)
2017-02-27T22:56:54.108-0600 I NETWORK  [conn10] end connection 184.105.247.196:32676 (5 connections now open)
2017-02-28T14:48:48.420-0600 I NETWORK  [initandlisten] connection accepted from 207.154.223.77:37372 #11 (6 connections now open)
2017-02-28T14:48:49.951-0600 I NETWORK  [conn11] end connection 207.154.223.77:37372 (5 connections now open)
2017-02-28T14:48:50.050-0600 I NETWORK  [initandlisten] connection accepted from 207.154.223.77:37968 #12 (6 connections now open)
2017-02-28T14:48:51.554-0600 I NETWORK  [conn12] end connection 207.154.223.77:37968 (5 connections now open)
2017-02-28T14:48:51.696-0600 I NETWORK  [initandlisten] connection accepted from 207.154.223.77:38276 #13 (6 connections now open)
2017-02-28T14:48:51.857-0600 I NETWORK  [conn13] AssertionException handling request, closing client connection: 17132 SSL handshake received but server is started without SSL support
2017-02-28T14:48:52.139-0600 I NETWORK  [initandlisten] connection accepted from 207.154.223.77:38368 #14 (6 connections now open)
2017-02-28T14:48:52.352-0600 I NETWORK  [conn14] end connection 207.154.223.77:38368 (5 connections now open)
2017-02-28T22:26:01.778-0600 I NETWORK  [initandlisten] connection accepted from 184.105.247.194:23852 #15 (6 connections now open)
2017-02-28T22:26:01.929-0600 I NETWORK  [conn15] end connection 184.105.247.194:23852 (5 connections now open)
2017-02-28T22:26:14.186-0600 I NETWORK  [initandlisten] connection accepted from 184.105.247.194:26444 #16 (6 connections now open)
2017-02-28T22:26:14.376-0600 I NETWORK  [conn16] end connection 184.105.247.194:26444 (5 connections now open)
2017-03-01T17:47:25.745-0600 I NETWORK  [initandlisten] connection accepted from 95.139.218.255:53405 #17 (6 connections now open)
2017-03-01T17:47:26.586-0600 I NETWORK  [initandlisten] connection accepted from 95.139.218.255:43801 #18 (7 connections now open)
2017-03-01T17:47:27.406-0600 I COMMAND  [conn18] dropDatabase alphaphene starting
2017-03-01T17:47:29.787-0600 I COMMAND  [conn18] dropDatabase alphaphene finished
2017-03-01T17:47:29.796-0600 I COMMAND  [conn18] command alphaphene command: dropDatabase { dropDatabase: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:61 locks:{ Global: { acquireCount: { r: 2, w: 1, W: 1 } }, Database: { acquireCount: { W: 1 } } } protocol:op_query 2426ms
2017-03-01T17:47:30.165-0600 I COMMAND  [conn18] dropDatabase graphene starting
2017-03-01T17:47:30.419-0600 I COMMAND  [conn18] dropDatabase graphene finished
2017-03-01T17:47:30.430-0600 I COMMAND  [conn18] command graphene command: dropDatabase { dropDatabase: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:59 locks:{ Global: { acquireCount: { r: 2, w: 1, W: 1 } }, Database: { acquireCount: { W: 1 } } } protocol:op_query 264ms
2017-03-01T17:47:30.701-0600 I COMMAND  [conn18] dropDatabase local starting
2017-03-01T17:47:30.984-0600 I COMMAND  [conn18] dropDatabase local finished
2017-03-01T17:47:31.016-0600 I COMMAND  [conn18] command local command: dropDatabase { dropDatabase: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:56 locks:{ Global: { acquireCount: { r: 2, w: 1, W: 1 } }, Database: { acquireCount: { W: 1 } } } protocol:op_query 315ms
2017-03-01T17:47:31.557-0600 I COMMAND  [conn18] command DB_H4CK3D.URG3NT_W4RN1NG command: insert { insert: "URG3NT_W4RN1NG", ordered: true, documents: [ { BitCoin Address: "156JqyC1m71WNG8Hq6yGnAxvxRHgzpGWZW", _id: ObjectId('58b75db4d6ca3f0b0f974d13'), eMail Address: "[email protected]", There Is Always A Solution: "Your DataBase is downloaded and backed up on our secured servers. To recover your lost data : Send 0.5 BTC to our BitCoin Address and Contact us by eM..." } ] } ninserted:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:40 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 1, W: 1 } }, Collection: { acquireCount: { W: 1 } } } protocol:op_query 259ms
2017-03-01T17:47:31.928-0600 I NETWORK  [conn18] end connection 95.139.218.255:43801 (6 connections now open)
2017-03-01T17:47:31.931-0600 I NETWORK  [conn17] end connection 95.139.218.255:53405 (6 connections now open)
2017-03-01T22:26:13.568-0600 I NETWORK  [initandlisten] connection accepted from 216.218.206.68:58612 #19 (6 connections now open)
2017-03-01T22:26:13.754-0600 I NETWORK  [conn19] end connection 216.218.206.68:58612 (5 connections now open)
2017-03-01T22:26:28.548-0600 I NETWORK  [initandlisten] connection accepted from 216.218.206.68:14236 #20 (6 connections now open)
2017-03-01T22:26:28.714-0600 I COMMAND  [conn20] command admin.$cmd command: listDatabases { listDatabases: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:128 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } } } protocol:op_query 109ms
2017-03-01T22:26:28.876-0600 I NETWORK  [conn20] end connection 216.218.206.68:14236 (5 connections now open)
2017-03-02T07:49:19.788-0600 I NETWORK  [conn1] end connection 127.0.0.1:51377 (4 connections now open)
2017-03-02T07:49:19.788-0600 I NETWORK  [conn2] end connection 127.0.0.1:51378 (4 connections now open)
2017-03-02T07:49:19.789-0600 I NETWORK  [conn4] end connection 127.0.0.1:51380 (4 connections now open)
2017-03-02T07:49:19.789-0600 I NETWORK  [conn3] end connection 127.0.0.1:51379 (4 connections now open)
2017-03-02T07:49:19.792-0600 I NETWORK  [conn5] end connection 127.0.0.1:51419 (4 connections now open)

This makes it evident that at 2017-02-26T15:41:53.810-0600 somebody jumped in to the MongoDB server and started fucking about. They expect me to pay for my data. That’s not happening. But what went wrong? How did this happen?

I fucked up, previously I had multiple servers in my room. They were on their own router connected by LAN to the main router in my apartment, As such, it was easiest to do the super unsafe thing of opening a DMZ on the main router to the sub-network. Any ports forwarded on the sub would be open on the main. This is fine-ish because the sub has its own security. But when I removed that router, the single server solution wasn’t secured. The DMZ allowed me to test new servers, but I don’t actually need it. Because I had it only when I didn’t have my proxies, which I have now. But it opened up my Mongo server to the internet. Which is bad. Mainly because my credentials are default. Because it’s not supposed to be open like that.

Solution: kill the DMZ, crack open a backup, and restart the server.