node.jsmongodbimagemagickgraphicsmagick

Ggraphicsmagick breaks mongoDB. I don't know why


Good day! I have a server, which takes a pictures, create thumbnails at the background and records file names in mongoDB right after starting a process of thumbnails creation.

I have a problem. When I'm uploading 30 pictures, mongo server is breaks (stops). When I'm uploading 2 pictures, It's okay.

Why it happens? Someone explain me please!

UPDATE: Problem appears on dedicated server only. I have not a problem on localhost. UPDATE: Attached mongoBD logs

upload.js

const
  fs = require('fs'),
  {Router} = require("express"),
  router = Router(),
  multer = require('multer'),
  colors = require('colors'),
  path = require('path'),
  cryptoRandomString = require('crypto-random-string');
    
    
const
  thumbnail = require('./thumbnail.js'),
  db_controllers = require('./db_controllers.js'),
  _meta = require('./meta.js');
  helpers = require("../helpers.js"),
  defaults = require("../defaults.js");
        
    
let storage = multer.diskStorage({
    
  destination: function(req, file, cb) {
    let uploads_dir = "public/models/"+req.body.model_id+"/"+req.body.album_id;
    fs.exists("./"+uploads_dir, function(err) {
      fs.mkdir(uploads_dir, {recursive: true}, function(err) {
        cb(null, uploads_dir);
        return;
      });
    });
  },
  filename: function (req, file, cb){
    let random_name = cryptoRandomString({length: 15});
    cb( null, file.originalname.replace(/[а-я-()]/gi, "").split('.').slice(0, -1).join('.') +"_"+ random_name + path.extname(file.originalname) );
  }
});
    
var upload = multer({ storage: storage });
    
router.post('/uploadmultiple', upload.array('myFiles', 200), async function (req, res, next) {
    
  const files = req.files;
  if (!files) {
    const error = new Error('Please choose files')
    error.httpStatusCode = 400
    return next(error)
  }
    
  let data = {
    content: [],
    covers: [],
  };
    
  let meta = _meta.GenerateMetaData(req);
    
  thumb_sizes = { w: defaults.app.thumb_size.w, /*h: defaults.app.thumb_size.h*/ undefined };
    
  for (file of files) {  
    console.log("++ "+file.originalname);
    
    if (file.mimetype == 'image/jpeg' || file.mimetype == 'image/png' || file.mimetype == 'image/webp') {
      extname = path.extname(file.filename);
      filename = file.filename.split('.').slice(0, -1).join('.');
    
      thumbnail.genThumbs(file.destination, file.filename, thumb_sizes);
    
      if ( helpers.findString( filename, ["cover"] ) ) {
        data.covers.push({
          image: filename+"_thumbnail"+extname,
          alt: meta.alt[ helpers.SetRandom( meta.alt.length ) ],
        });
      }
    
      data.content.push({
        original: file.filename,
        thumbnail: filename+"_thumbnail"+extname,
        type: "photo",
        alt: meta.alt[ helpers.SetRandom( meta.alt.length ) ],
      });
    
    }
  }
    
  console.log(data);
    
  data.title = meta.title,
  data.description = meta.description,
  data.album_id = req.body.album_id;
  data.name = req.body.album_name;
  data.model_id = req.body.model_id;
  data.model_name = req.body.model_name;
  data.sise = req.body.sise;
  data.seo_description = req.body.seo_description;
  data.tags = req.body.tags.split(',');
  data.date = new Date(Date.now() + parseInt(req.body.published_after));
  data.category = req.body.category;
  data.author = cryptoRandomString({length: 20, type: 'url-safe'});
      
  db_controllers.CreateAlbum(data, function() {
    res.send(files);
  });
    
});

thumbnail.js

const gm = require('gm').subClass({imageMagick: true});
const path = require('path');
const colors = require('colors');
const ffmpeg = require('fluent-ffmpeg');
const command = ffmpeg();


function genThumbs(origin_path, f_name, thumb_size) {

  f_ext = path.extname(f_name);
  f_name = f_name.split('.').slice(0, -1).join('.');

  gm(origin_path+"/"+f_name+f_ext)
  .resize(thumb_size.w, thumb_size.h)
  .noProfile()
  .write(origin_path+"/"+f_name+"_thumbnail"+f_ext, function(err) {
    if (!err) {
      console.log('thumbnails is generated');

      //return (origin_path+"/"+f_name+"_thumbnail"+f_ext);
    }
    else {
      console.log(err);
      return(undefined);
    }
  });
}

module.exports.genThumbs = genThumbs;

db_controllers.js

const
  colors = require('colors'),
  defaults = require("../defaults.js");

const MongoClient = require("mongodb").MongoClient;
const options = {
  useNewUrlParser: true,
  useUnifiedTopology: true,
  // keepAlive: 1,
  // connectTimeoutMS: 60000,
  // socketTimeoutMS: 60000,
  // auto_reconnect: true,
}
const mongoClient = new MongoClient(defaults.mongo.url, options);

db_name = defaults.mongo.db;
albums_coll = defaults.mongo.albums_coll;

function CreateAlbum (data, callback) {

  console.log("/upload/db_conttrollers.js CreateAlbum() – is working");

  // ERROR HAPPENS HERE

  mongoClient.connect(function(err, dbClient) {
    if(err) throw err;
    console.log("----- posts.js: CreateAlbumRecord(): client is created -----");

    let collection = dbClient.db(db_name).collection(albums_coll);
    data.views = 0;

    collection.insertOne(data, function(err, res) {
      if (err) throw err;
      console.log("-- posts.js: CreateAlbumRecord(): album_object is inserted --");
      callback();
    });
  });
}

module.exports.CreateAlbum = CreateAlbum;

Error text

MongoServerSelectionError: connect ECONNREFUSED 127.0.0.1:27017
    at Timeout.<anonymous> (/root/node_modules/mongodb/lib/core/sdam/server_selection.js:307:9)
    at listOnTimeout (internal/timers.js:549:17)
    at processTimers (internal/timers.js:492:7) {
  name: 'MongoServerSelectionError',
  reason: TopologyDescription {
    type: 'Single',
    setName: null,
    maxSetVersion: null,
    maxElectionId: null,
    servers: Map { 'localhost:27017' => [ServerDescription] },
    stale: false,
    compatible: true,
    compatibilityError: null,
    logicalSessionTimeoutMinutes: null,
    heartbeatFrequencyMS: 10000,
    localThresholdMS: 15,
    commonWireVersion: null
  },
  [Symbol(mongoErrorContextSymbol)]: {}
}

MongoDB log

2020-04-09T03:01:33.204+0000 I  CONTROL  [main] ***** SERVER RESTARTED *****
2020-04-09T03:01:33.218+0000 I  CONTROL  [main] Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'
2020-04-09T03:01:33.311+0000 W  ASIO     [main] No TransportLayer configured during NetworkInterface startup
2020-04-09T03:01:33.313+0000 I  CONTROL  [initandlisten] MongoDB starting : pid=13500 port=27017 dbpath=/var/lib/mongodb 64-bit host=ubuntu-s-1vcpu-1gb-fra1-01
2020-04-09T03:01:33.313+0000 I  CONTROL  [initandlisten] db version v4.2.5
2020-04-09T03:01:33.313+0000 I  CONTROL  [initandlisten] git version: 2261279b51ea13df08ae708ff278f0679c59dc32
2020-04-09T03:01:33.313+0000 I  CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.1.1  11 Sep 2018
2020-04-09T03:01:33.313+0000 I  CONTROL  [initandlisten] allocator: tcmalloc
2020-04-09T03:01:33.313+0000 I  CONTROL  [initandlisten] modules: none
2020-04-09T03:01:33.313+0000 I  CONTROL  [initandlisten] build environment:
2020-04-09T03:01:33.313+0000 I  CONTROL  [initandlisten]     distmod: ubuntu1804
2020-04-09T03:01:33.313+0000 I  CONTROL  [initandlisten]     distarch: x86_64
2020-04-09T03:01:33.313+0000 I  CONTROL  [initandlisten]     target_arch: x86_64
2020-04-09T03:01:33.313+0000 I  CONTROL  [initandlisten] options: { config: "/etc/mongod.conf", net: { bindIp: "127.0.0.1", port: 27017 }, processManagement: { timeZoneInfo: "/usr/share/zoneinfo" }, storage: { dbPath: "/var/lib/mongodb", journal: { enabled: true } }, systemLog: { destination: "file", logAppend: true, path: "/var/log/mongodb/mongod.log" } }
2020-04-09T03:01:33.318+0000 W  STORAGE  [initandlisten] Detected unclean shutdown - /var/lib/mongodb/mongod.lock is not empty.
2020-04-09T03:01:33.318+0000 I  STORAGE  [initandlisten] Detected data files in /var/lib/mongodb created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2020-04-09T03:01:33.318+0000 W  STORAGE  [initandlisten] Recovering data from the last clean checkpoint.
2020-04-09T03:01:33.318+0000 I  STORAGE  [initandlisten] 
2020-04-09T03:01:33.318+0000 I  STORAGE  [initandlisten] ** WARNING: Using the XFS filesystem is strongly recommended with the WiredTiger storage engine
2020-04-09T03:01:33.318+0000 I  STORAGE  [initandlisten] **          See http://dochub.mongodb.org/core/prodnotes-filesystem
2020-04-09T03:01:33.318+0000 I  STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=256M,cache_overflow=(file_max=0M),session_max=33000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000,close_scan_interval=10,close_handle_minimum=250),statistics_log=(wait=0),verbose=[recovery_progress,checkpoint_progress],
2020-04-09T03:01:33.908+0000 I  STORAGE  [initandlisten] WiredTiger message [1586401293:908591][13500:0x7fbed1005b00], txn-recover: Recovering log 19 through 20
2020-04-09T03:01:33.987+0000 I  STORAGE  [initandlisten] WiredTiger message [1586401293:987910][13500:0x7fbed1005b00], txn-recover: Recovering log 20 through 20
2020-04-09T03:01:34.063+0000 I  STORAGE  [initandlisten] WiredTiger message [1586401294:63623][13500:0x7fbed1005b00], txn-recover: Main recovery loop: starting at 19/10112 to 20/256
2020-04-09T03:01:34.064+0000 I  STORAGE  [initandlisten] WiredTiger message [1586401294:64932][13500:0x7fbed1005b00], txn-recover: Recovering log 19 through 20
2020-04-09T03:01:34.125+0000 I  STORAGE  [initandlisten] WiredTiger message [1586401294:125783][13500:0x7fbed1005b00], txn-recover: Recovering log 20 through 20
2020-04-09T03:01:34.176+0000 I  STORAGE  [initandlisten] WiredTiger message [1586401294:176256][13500:0x7fbed1005b00], txn-recover: Set global recovery timestamp: (0, 0)
2020-04-09T03:01:34.228+0000 I  RECOVERY [initandlisten] WiredTiger recoveryTimestamp. Ts: Timestamp(0, 0)
2020-04-09T03:01:34.243+0000 I  STORAGE  [initandlisten] Timestamp monitor starting
2020-04-09T03:01:34.255+0000 I  CONTROL  [initandlisten] 
2020-04-09T03:01:34.255+0000 I  CONTROL  [initandlisten] ** WARNING: Access control is not enabled for the database.
2020-04-09T03:01:34.255+0000 I  CONTROL  [initandlisten] **          Read and write access to data and configuration is unrestricted.
2020-04-09T03:01:34.255+0000 I  CONTROL  [initandlisten] 
2020-04-09T03:01:34.273+0000 I  SHARDING [initandlisten] Marking collection local.system.replset as collection version: <unsharded>
2020-04-09T03:01:34.282+0000 I  STORAGE  [initandlisten] Flow Control is enabled on this deployment.
2020-04-09T03:01:34.284+0000 I  SHARDING [initandlisten] Marking collection admin.system.roles as collection version: <unsharded>
2020-04-09T03:01:34.285+0000 I  SHARDING [initandlisten] Marking collection admin.system.version as collection version: <unsharded>
2020-04-09T03:01:34.291+0000 I  SHARDING [initandlisten] Marking collection local.startup_log as collection version: <unsharded>
2020-04-09T03:01:34.291+0000 I  FTDC     [initandlisten] Initializing full-time diagnostic data capture with directory '/var/lib/mongodb/diagnostic.data'
2020-04-09T03:01:34.295+0000 I  SHARDING [LogicalSessionCacheRefresh] Marking collection config.system.sessions as collection version: <unsharded>
2020-04-09T03:01:34.296+0000 I  SHARDING [LogicalSessionCacheReap] Marking collection config.transactions as collection version: <unsharded>
2020-04-09T03:01:34.296+0000 I  NETWORK  [listener] Listening on /tmp/mongodb-27017.sock
2020-04-09T03:01:34.296+0000 I  NETWORK  [listener] Listening on 127.0.0.1
2020-04-09T03:01:34.296+0000 I  NETWORK  [listener] waiting for connections on port 27017
2020-04-09T03:01:35.005+0000 I  FTDC     [ftdc] Unclean full-time diagnostic data capture shutdown detected, found interim file, some metrics may have been lost. OK
2020-04-09T03:01:35.013+0000 I  SHARDING [ftdc] Marking collection local.oplog.rs as collection version: <unsharded>

Solution

  • App runs on the simplest DigitalOcean Droplet. It has 1 Gb RAM. Graphicsmagick / ImageMagick use all RAM and breaks mongo. To avoid it I will run Thumbnail Generator with delay. Now it works fine.

    function genThumbs(origin_path, f_name, thumb_size, delay) {
    
      f_ext = path.extname(f_name);
      f_name = f_name.split('.').slice(0, -1).join('.');
    
      setTimeout(function() {
        gm(origin_path+"/"+f_name+f_ext)
        .resize(thumb_size.w, thumb_size.h)
        .noProfile()
        .write(origin_path+"/"+f_name+"_thumbnail"+f_ext, function(err) {
          if (!err) {
            console.log('thumbnails is generated');
    
            //return (origin_path+"/"+f_name+"_thumbnail"+f_ext);
          }
          else {
            console.log(err);
            return(undefined);
          }
        });
      }, delay);
    }