Feature: Better Error-management, logging for the APP and Macos builds improvements (#1405)

* tiny changes

* more documentation

* added upload-instructions

* better traceability of startup

* logs for signing results

* bugfix for sign_results

* winston logging

* error-management and check for specterd-exit

* adding locale

* distinguish logging properly

* don't throw that error unfortunately

* fix accidental change

* increase memory + cpu for cirrus

* increase to 8CPUs but only for cirrus

* decrease resources again

.cirrus.yml

@@ -65,6 +65,8 @@ test_task:
 cypress_test_task:
   container:
     image: registry.gitlab.com/cryptoadvance/specter-desktop/cypress-python:latest
+    cpu: 6
+    memory: 6G
   pre_prep_script: 
     - apt-get update && apt-get install -y --no-install-recommends python3-dev python3-pip python3-virtualenv bc
     # The stupid old debian-package is not installing a proper binary but just the python-package

pyinstaller/build-osx.sh

@@ -1,4 +1,34 @@
 #!/usr/bin/env bash
+set -exo
+# possible prerequisites
+# brew install gmp # to prevent module 'embit.util' has no attribute 'ctypes_secp256k1'
+# npm install --global create-dmg
+
+# Download into torbrowser:
+# wget -P torbrowser https://archive.torproject.org/tor-package-archive/torbrowser/10.0.15/TorBrowser-10.0.15-osx64_en-US.dmg
+
+# Currently, only MacOS Catalina is supported to build the dmg-file
+# Therefore we expect xcode 12.1 (according to google)
+# After installation of xcode: sudo xcode-select -s /Applications/Xcode.app/Contents/Developer
+# otherwise you get xcrun: error: unable to find utility "altool", not a developer tool or in PATH
+
+# Fill the keychain with your password like this
+# xcrun altool --store-password-in-keychain-item AC_PASSWORD -u '<your apple id>' -p apassword
+
+# You need to participate in the Apple-Developer Program (Eur 99,- yearly fee)
+# https://developer.apple.com/programs/enroll/ 
+
+# Then you need to create a cert which you need to store in the keychain
+# https://developer.apple.com/account/resources/certificates/list
+
+# If you have the common issue "errSecInternalComponent" while signing the code:
+# https://medium.com/@ceyhunkeklik/how-to-fix-ios-application-code-signing-error-4818bd331327
+
+# create-dmg issue? Note that there are 2 create-dmg scripts out there. We use:
+# https://github.com/sindresorhus/create-dmg
+
+# Example-call:
+# ./build-osx.sh v1.6.1-pre1 "Kim Neunert (FWV59JHV83)" "kneunert@gmail.com" "make-hash"
 
 echo $1 > version.txt
 pip3 install -r requirements.txt --require-hashes
@@ -7,7 +37,7 @@ cd ..
 python3 setup.py install
 cd pyinstaller
 rm -rf build/ dist/ release/ electron/release/ electron/dist
-rm *.dmg
+rm *.dmg || true
 pyinstaller specterd.spec
 cd electron
 npm ci
@@ -30,8 +60,14 @@ if [[ "$2" != '' ]]
 then
     echo 'Attempting to code sign...'
     ditto -c -k --keepParent "dist/mac/Specter.app" dist/Specter.zip
-    xcrun altool --notarize-app -t osx -f dist/Specter.zip --primary-bundle-id "solutions.specter.desktop" -u "$3" --password "@keychain:AC_PASSWORD"
+    output_json=$(xcrun altool --notarize-app -t osx -f dist/Specter.zip --primary-bundle-id "solutions.specter.desktop" -u "$3" --password "@keychain:AC_PASSWORD" --output-format json)
+    echo "JSON-Output:"
+    requestuuid=$(echo $output_json | jq -r '."notarization-upload".RequestUUID')
     sleep 180
+    sign_result_json=$(xcrun altool --notarization-info $requestuuid -u "$3" --password "@keychain:AC_PASSWORD" --output-format json)
+    mkdir -p signing_logs
+    timestamp=$(date +"%Y%m%d-%H%M")
+    echo $sign_result_json | jq . > ./signing_logs/${timestamp}_${requestuuid}.log
     xcrun stapler staple "dist/mac/Specter.app"
 fi
 
@@ -48,3 +84,10 @@ cd ..
 
 sha256sum ./release/specterd-$1-osx.zip
 sha256sum ./release/SpecterDesktop-$1.dmg
+
+# "In order to upload these artifacts to github, do:"
+# export CI_PROJECT_ROOT_NAMESPACE=cryptoadvance
+# export CI_COMMIT_TAG=$1
+# export GH_BIN_UPLOAD_PW=YourSecretHere
+# python ./utils/github.py upload ./release/specterd-$1-osx.zip
+# python ./utils/github.py upload ./release/SpecterDesktop-$1.dmg

pyinstaller/electron/error_logs.html

@@ -0,0 +1,22 @@
+<html>
+    <link rel="stylesheet" type="text/css" href="./styles.css">
+    <body style="overflow: auto; height: 100%;">
+	<div class="card" style="width:90%; max-width: 1000px;">
+		This window show you the Logs of specter. It might give you hints on why specter is not coming up properly.
+		<pre><code id="specterapp-logs"></code></pre>
+		<br>
+	
+	</div>
+    <script>
+        const fs = require('fs')
+        const path = require('path')
+        const helpers = require('./helpers')
+        const specterAppLogs = helpers.getSpecterAppLogs
+        document.getElementById('specterapp-logs').innerText = specterAppLogs()
+
+
+        
+
+    </script>
+    </body>
+</html>

pyinstaller/electron/helpers.js

@@ -14,6 +14,7 @@ try {
 }
 const appSettingsPath = path.resolve(require('os').homedir(), '.specter/app_settings.json')
 const specterdDirPath = path.resolve(require('os').homedir(), '.specter/specterd-binaries')
+const specterAppLogPath = path.resolve(require('os').homedir(), '.specter/specterApp.log')
 
 function getFileHash(filename, callback) {
   let shasum = crypto.createHash('sha256')
@@ -59,11 +60,17 @@ function getAppSettings() {
     }
   
     return appSettings
-  }
+}
+
+function getSpecterAppLogs() {
+  return fs.readFileSync(specterAppLogPath, 'utf8')  
+}
 
 module.exports = {
     getFileHash: getFileHash,
     appSettingsPath: appSettingsPath,
     getAppSettings: getAppSettings,
-    specterdDirPath: specterdDirPath
+    specterdDirPath: specterdDirPath,
+    getSpecterAppLogs: getSpecterAppLogs,
+    specterAppLogPath: specterAppLogPath
 }

pyinstaller/electron/main.js

@@ -1,5 +1,6 @@
 // Modules to control application life and create native browser window
 const { app, BrowserWindow, Menu, Tray, screen, shell, dialog, ipcMain } = require('electron')
+
 const path = require('path')
 const fs = require('fs')
 const request = require('request')
@@ -11,11 +12,37 @@ const getFileHash = helpers.getFileHash
 const getAppSettings = helpers.getAppSettings
 const appSettingsPath = helpers.appSettingsPath
 const specterdDirPath = helpers.specterdDirPath
+
+// Logging
+const {transports, format, createLogger } = require('winston')
+const combinedLog = new transports.File({ filename: helpers.specterAppLogPath });
+const winstonOptions = {
+    exitOnError: false,
+    format: format.combine(
+      format.timestamp(),
+      // format.timestamp({format:'MM/DD/YYYY hh:mm:ss.SSS'}),
+      format.json(),
+      format.printf(info => {
+        return `${info.timestamp} [${info.level}] : ${info.message}`;
+      })
+    ),
+    transports: [
+      new transports.Console({json:false}),
+      combinedLog
+    ],
+    exceptionHandlers: [
+      combinedLog
+    ]
+}
+const logger = createLogger(winstonOptions)
+
+
 let appSettings = getAppSettings()
 
 let dimensions = { widIth: 1500, height: 1000 };
 
 const contextMenu = require('electron-context-menu');
+const { options } = require('request')
 
 contextMenu({
 	menu: (actions) => [
@@ -40,8 +67,8 @@ contextMenu({
 
 const download = (uri, filename, callback) => {
     request.head(uri, (err, res, body) => {
-        console.log('content-type:', res.headers['content-type'])
-        console.log('content-length:', res.headers['content-length'])
+        logger.info('content-type:', res.headers['content-type'])
+        logger.info('content-length:', res.headers['content-length'])
         if (res.statusCode != 404) {
           request(uri).pipe(fs.createWriteStream(filename)).on('close', callback)
         } else {
@@ -102,6 +129,7 @@ function createWindow (specterURL) {
 // Some APIs can only be used after this event occurs.
 app.whenReady().then(() => {
   // Start the tray icon
+  logger.info("Framework Ready! Starting tray Icon ...");
   tray = new Tray(path.join(__dirname, 'assets/icon.png'))
   trayMenu = [
     { label: 'Launching Specter...', enabled: false },
@@ -115,6 +143,7 @@ app.whenReady().then(() => {
   dimensions = screen.getPrimaryDisplay().size;
 
   // create a new `splash`-Window 
+  logger.info("Framework Ready! Initializing Main-Window, popultaing Menu ...");
   initMainWindow()
 
   setMainMenu();
@@ -122,11 +151,13 @@ app.whenReady().then(() => {
   mainWindow.loadURL(`file://${__dirname}/splash.html`);
 
   if (!fs.existsSync(specterdDirPath)){
-      fs.mkdirSync(specterdDirPath, { recursive: true });
+    logger.info("Creating specterd-binaries folder");
+    fs.mkdirSync(specterdDirPath, { recursive: true });
   }
 
   let versionData = require('./version-data.json')
   if (!appSettings.versionInitialized || appSettings.versionInitialized != versionData.version) {
+    logger.info(`Updating ${appSettingsPath} : ${JSON.stringify(appSettings)}`);
     appSettings.specterdVersion = versionData.version
     appSettings.specterdHash = versionData.sha256
     appSettings.versionInitialized = versionData.version
@@ -136,6 +167,7 @@ app.whenReady().then(() => {
   if (fs.existsSync(specterdPath + (platformName == 'win64' ? '.exe' : ''))) {
     getFileHash(specterdPath + (platformName == 'win64' ? '.exe' : ''), function (specterdHash) {
       if (appSettings.specterdHash.toLowerCase() == specterdHash || appSettings.specterdHash == "") {
+        
         startSpecterd(specterdPath)
       } else if (appSettings.specterdVersion != "") {
         updatingLoaderMsg('Specterd version could not be validated.<br>Retrying fetching specterd...<br>This might take a minute...')
@@ -187,8 +219,8 @@ function initMainWindow(specterURL) {
 function downloadSpecterd(specterdPath) {
   updatingLoaderMsg('Fetching the Specter binary...<br>This might take a minute...')
   updateSpecterdStatus('Fetching Specter binary...')
-  console.log("Using version ", appSettings.specterdVersion);
-  console.log(`https://github.com/cryptoadvance/specter-desktop/releases/download/${appSettings.specterdVersion}/specterd-${appSettings.specterdVersion}-${platformName}.zip`);
+  logger.info("Using version ", appSettings.specterdVersion);
+  logger.info(`https://github.com/cryptoadvance/specter-desktop/releases/download/${appSettings.specterdVersion}/specterd-${appSettings.specterdVersion}-${platformName}.zip`);
   download(`https://github.com/cryptoadvance/specter-desktop/releases/download/${appSettings.specterdVersion}/specterd-${appSettings.specterdVersion}-${platformName}.zip`, specterdPath + '.zip', function(errored) {
     if (errored == true) {
       updatingLoaderMsg('Fetching specter binary from the server failed, could not reach the server or the file could not have been found.')
@@ -249,6 +281,11 @@ function updatingLoaderMsg(msg) {
   } 
 }
 
+function hasSuccessfullyStarted(logs) {
+  return logs.toString().includes('  * Running on http')
+  //return logs.toString().includes('Serving Flask app "cryptoadvance.specter.server"')
+}
+
 function startSpecterd(specterdPath) {
   if (platformName == 'win64') {
     specterdPath += '.exe'
@@ -257,7 +294,9 @@ function startSpecterd(specterdPath) {
   let hwiBridgeMode = appSettings.mode == 'hwibridge'
   updatingLoaderMsg('Launching Specter Desktop...')
   updateSpecterdStatus('Launching Specter...')
-  let specterdArgs = hwiBridgeMode ? ['--hwibridge'] : null
+  let specterdArgs = ["server"]
+  specterdArgs.push("--no-filelog")
+  if (hwiBridgeMode) specterdArgs.push('--hwibridge')
   if (appSettings.specterdCLIArgs != '') {
     if (specterdArgs == null) {
       specterdArgs = []
@@ -268,17 +307,47 @@ function startSpecterd(specterdPath) {
     
     specterdArgs = specterdArgs.concat(specterdExtraArgs)
   }
-  specterdProcess = spawn(specterdPath, specterdArgs);
+
+
+  logger.info(`Starting specterd ${specterdPath} ${specterdArgs}`);
+  // locale fix (copying from nodejs-env + adding locales)
+  const options = {
+    env: { ...process.env}
+  }
+  options.env['LC_ALL']='en_US.utf-8'
+  options.env['LANG'] = 'en_US.utf-8'
+  options.env['SPECTER_LOGFORMAT'] = 'SPECTERD: %(levelname)s in %(module)s: %(message)s'
+  specterdProcess = spawn(specterdPath, specterdArgs, options);
+  var procStdout = ""
+  var procStderr = ""
   specterdProcess.stdout.on('data', (data) => {
-    if(data.toString().includes('Serving Flask app "cryptoadvance.specter.server"')) {
+    procStdout += data
+    logger.info("stdout-"+data.toString())
+    if(hasSuccessfullyStarted(data)) {
+      logger.info(`App seem to to run ...`);
       if (mainWindow) {
+        logger.info(`... creating window ...`);
         createWindow(appSettings.specterURL)
+        
       }
     }
   });
-  specterdProcess.stderr.on('data', function(_) {
-    // https://stackoverflow.com/questions/20792427/why-is-my-node-child-process-that-i-created-via-spawn-hanging
-    // needed so specterd won't get stuck
+  specterdProcess.stderr.on('data', (data) => {
+    procStderr += data
+    logger.info("stderr-"+data.toString())
+    if(hasSuccessfullyStarted(data)) {
+      logger.info(`App seem to to run ...`);
+      if (mainWindow) {
+        logger.info(`... creating window ...`);
+        createWindow(appSettings.specterURL)
+        
+      }
+    }
+  });
+
+  specterdProcess.on('exit', (code) => {
+    logger.error(`specterd exited with code ${code}`);
+    showError(`specterd exited with code ${code}. Check the logs in the menu!`)
   });
 
   app.on('activate', function () {
@@ -289,7 +358,7 @@ function startSpecterd(specterdPath) {
   // since these are streams, you can pipe them elsewhere
   specterdProcess.on('close', (code) => {
     updateSpecterdStatus('Specter stopped...')
-    console.log(`child process exited with code ${code}`);
+    logger.info(`child process exited with code ${code}`);
   });
 }
 
@@ -322,7 +391,7 @@ ipcMain.on('request-mainprocess-action', (event, arg) => {
         prefWindow.webContents.executeJavaScript(`savePreferences()`);
       } else {
         specterdProcess.on('close', (code) => {
-          console.log(`child process exited with code ${code}`);
+          logger.info(`child process exited with code ${code}`);
           prefWindow.webContents.executeJavaScript(`savePreferences()`);
         });
         quitSpecterd()
@@ -345,7 +414,7 @@ function quitSpecterd() {
       }
       specterdProcess.kill('SIGINT')
     } catch (e) {
-      console.log('Specterd quit warning: ' + e)
+      logger.info('Specterd quit warning: ' + e)
     }
   }
 }
@@ -362,14 +431,28 @@ function setMainMenu() {
         accelerator: "CmdOrCtrl+,"
       }
     );
+    menu[0].submenu.splice(1, 0,
+      {
+        label: 'Specter Logs',
+        click: openErrorLog,
+        accelerator: "CmdOrCtrl+,"
+      }
+    );
   } else {
     menu.unshift({
         label: 'Specter',
-        submenu: [{
+        submenu: [
+        {
           label: 'Preferences',
           click: openPreferences,
           accelerator: "CmdOrCtrl+,"
-        }]
+        },
+        {
+          label: 'Specter Logs',
+          click: openErrorLog,
+          accelerator: "CmdOrCtrl+,"
+        }
+        ]
       } 
     );
   }
@@ -377,32 +460,50 @@ function setMainMenu() {
   Menu.setApplicationMenu(Menu.buildFromTemplate(menu));
 }
 
-function openPreferences() {
+
+function openNewWindow(htmlContentFile) {
   prefWindow = new BrowserWindow({
     width: 700,
     height: 750,
+    autoHideMenuBar: true,
     webPreferences: {
       nodeIntegration: true,
-      enableRemoteModule: true
+      enableRemoteModule: true,
+      
     }
   })
   prefWindow.webContents.on('new-window', function(e, url) {
     e.preventDefault();
     shell.openExternal(url);
   });
-  prefWindow.loadURL(`file://${__dirname}/settings.html`)
+  prefWindow.loadURL(`file://${__dirname}/${htmlContentFile}`)
   prefWindow.show()
 }
 
+
+function openPreferences() {
+  openNewWindow("settings.html")
+}
+
+function openErrorLog() {
+  openNewWindow("error_logs.html")
+}
+
 function showError(error) {
-  console.error('Specter Desktop encounter an error', error.toString())
   updatingLoaderMsg('Specter Desktop encounter an error:<br>' + error.toString())
 }
 
 process.on('unhandledRejection', error => {
   showError(error)
+  logger.error(error.toString(), error.name)
 })
 
 process.on("uncaughtException", error => {
   showError(error)
+  // I would love to rethrow the error here as this would create a stacktrace in the logs
+  // but this will terminate the whole process even though i've set
+  // exitOnError: false in the wistonOptions above.
+  // Unacceptable for the folks which can't use a commandline, clicking an icon
+  //throw(error)
+  logger.error(error.toString())
 })

pyinstaller/electron/package.json

@@ -1,6 +1,5 @@
 {
   "name": "specter-desktop",
-  "version": "v1.6.0",
   "description": "Specter Desktop Electron application",
   "main": "main.js",
   "scripts": {
@@ -46,6 +45,7 @@
     "electron-context-menu": "^2.3.0",
     "electron-default-menu": "^1.0.2",
     "extract-zip": "^2.0.1",
-    "request": "^2.88.2"
+    "request": "^2.88.2",
+    "winston": "^3.3.3"
   }
 }

pyinstaller/specterd.py

@@ -1,27 +1,4 @@
-from logging.config import dictConfig
-from cryptoadvance.specter.cli import server
-import sys
-import logging
+from cryptoadvance.specter.cli import entry_point
 
 if __name__ == "__main__":
-    # central and early configuring of logging see
-    # https://flask.palletsprojects.com/en/1.1.x/logging/#basic-configuration
-
-    ch = logging.StreamHandler()
-    ch.setLevel(logging.INFO)
-    formatter = logging.Formatter(
-        "[%(asctime)s] %(levelname)s in %(module)s: %(message)s"
-    )
-    ch.setFormatter(formatter)
-    logging.getLogger().addHandler(ch)
-    # However initially, we'll set the root-logger to INFO:
-    logging.getLogger().setLevel(logging.INFO)
-    logging.getLogger(__name__).info("Logging configured")
-    if "--daemon" in sys.argv:
-        print("Daemon mode is not supported in binaries yet")
-        sys.exit(1)
-    if "--debug" in sys.argv:
-        print("Debug mode is useless in binary mode, don't use it")
-        sys.exit(1)
-    print("Starting Specter server. It may take a while, please be patient")
-    server()
+    entry_point()

src/cryptoadvance/specter/cli/__init__.py

@@ -1,5 +1,6 @@
 import logging
 import click
+import os
 from .cli_server import server
 from .cli_noded import bitcoind, elementsd
 
@@ -17,14 +18,17 @@ logger = logging.getLogger(__name__)
 def entry_point(config_home, debug=False, tracerpc=False):
     ch = logging.StreamHandler()
     ch.setLevel(logging.DEBUG)
-
     if debug:
         # No need for timestamps while developing
         formatter = logging.Formatter("[%(levelname)7s] in %(module)15s: %(message)s")
         logging.getLogger("cryptoadvance").setLevel(logging.DEBUG)
     else:
         formatter = logging.Formatter(
-            "[%(asctime)s] %(levelname)s in %(module)s: %(message)s"
+            # Too early to format that via the flask-config, so let's copy it from there:
+            os.getenv(
+                "SPECTER_LOGFORMAT",
+                "[%(asctime)s] %(levelname)s in %(module)s: %(message)s",
+            )
         )
         logging.getLogger("cryptoadvance").setLevel(logging.INFO)
     ch.setFormatter(formatter)