Add log file for important notifications

Add a new log file for important notifications that require an action from the node operator. Using a separate log file makes it easier than grepping specific messages from the standard logs, and lets us use a different style of messaging, where we provide more information about what steps to take to resolve the issue.
ACINQ · Oct 1, 2021 · 25b0a2d · 25b0a2d
1 parent fd56504
commit 25b0a2d
Show file tree

Hide file tree

Showing 11 changed files with 87 additions and 15 deletions.
diff --git a/docs/release-notes/eclair-vnext.md b/docs/release-notes/eclair-vnext.md
@@ -116,6 +116,11 @@ We still support receiving non-segwit remote scripts, but will force-close if th
 
 See the [spec discussions](https://github.com/lightningnetwork/lightning-rfc/pull/894) for more details.
 
+### Separate log for important notifications
+
+Eclair added a new log file (`notifications.log`) for important notifications that require an action from the node operator.
+Node operators should watch this file very regularly.
+
 ### Sample GUI removed
 
 We previously included code for a sample GUI: `eclair-node-gui`.

diff --git a/eclair-core/src/main/scala/fr/acinq/eclair/Logs.scala b/eclair-core/src/main/scala/fr/acinq/eclair/Logs.scala
@@ -28,11 +28,15 @@ import fr.acinq.eclair.io.{Peer, PeerConnection}
 import fr.acinq.eclair.router.Router._
 import fr.acinq.eclair.router._
 import fr.acinq.eclair.wire.protocol._
+import grizzled.slf4j.Logger
 
 import java.util.UUID
 
 object Logs {
 
+  /** This logger should be used to log important notifications for the node operator. */
+  val notifications = Logger("notifications")
+
   /**
    * @param parentPaymentId_opt depending on the context, this may be:
    *                            - for a send : the parent payment id
@@ -77,7 +81,6 @@ object Logs {
     }
   }
 
-  // @formatter: off
   sealed trait LogCategory {
     def category: String
   }
@@ -138,7 +141,6 @@ object Logs {
     }
   }
 
-  // @formatter: on
 }
 
 // we use a dedicated class so that the logging can be independently adjusted

diff --git a/eclair-core/src/main/scala/fr/acinq/eclair/Setup.scala b/eclair-core/src/main/scala/fr/acinq/eclair/Setup.scala
@@ -79,6 +79,7 @@ class Setup(val datadir: File,
   implicit val ec = ExecutionContext.Implicits.global
   implicit val sttpBackend = OkHttpFutureBackend()
 
+  Logs.notifications.info(s"eclair is starting (version=${Kit.getVersion} commit=${Kit.getCommit})")
   logger.info(s"hello!")
   logger.info(s"version=${Kit.getVersion} commit=${Kit.getCommit}")
   logger.info(s"datadir=${datadir.getCanonicalPath}")

diff --git a/eclair-core/src/main/scala/fr/acinq/eclair/balance/BalanceActor.scala b/eclair-core/src/main/scala/fr/acinq/eclair/balance/BalanceActor.scala
@@ -2,7 +2,8 @@ package fr.acinq.eclair.balance
 
 import akka.actor.typed.scaladsl.{ActorContext, Behaviors}
 import akka.actor.typed.{ActorRef, Behavior}
-import fr.acinq.bitcoin.ByteVector32
+import fr.acinq.bitcoin.{ByteVector32, MilliBtcDouble}
+import fr.acinq.eclair.Logs
 import fr.acinq.eclair.balance.BalanceActor._
 import fr.acinq.eclair.balance.CheckBalance.GlobalBalance
 import fr.acinq.eclair.balance.Monitoring.{Metrics, Tags}
@@ -83,6 +84,9 @@ private class BalanceActor(context: ActorContext[Command],
         case Success(result) =>
           log.info("current balance: total={} onchain.confirmed={} onchain.unconfirmed={} offchain={}", result.total.toDouble, result.onChain.confirmed.toDouble, result.onChain.unconfirmed.toDouble, result.offChain.total.toDouble)
           log.debug("current balance details : {}", result)
+          if (result.onChain.confirmed < 1.millibtc) {
+            Logs.notifications.warn(s"on-chain confirmed balance is low (${result.onChain.confirmed.toMilliBtc}), eclair may not be able to guarantee funds safety in case channels force-close: you should add some utxos to your bitcoin wallet")
+          }
           Metrics.GlobalBalance.withoutTags().update(result.total.toMilliBtc.toDouble)
           Metrics.GlobalBalanceDetailed.withTag(Tags.BalanceType, Tags.BalanceTypes.OnchainConfirmed).update(result.onChain.confirmed.toMilliBtc.toDouble)
           Metrics.GlobalBalanceDetailed.withTag(Tags.BalanceType, Tags.BalanceTypes.OnchainUnconfirmed).update(result.onChain.unconfirmed.toMilliBtc.toDouble)

diff --git a/eclair-core/src/main/scala/fr/acinq/eclair/channel/Channel.scala b/eclair-core/src/main/scala/fr/acinq/eclair/channel/Channel.scala
@@ -2485,6 +2485,7 @@ class Channel(val nodeParams: NodeParams, val wallet: OnChainChannelFunder, remo
       case None =>
         // the published tx was neither their current commitment nor a revoked one
         log.error(s"couldn't identify txid=${tx.txid}, something very bad is going on!!!")
+        Logs.notifications.error(s"funding tx ${d.commitments.commitInput.outPoint.txid} of channel ${d.channelId} was spent by an unknown transaction, indicating that your DB has lost data or your node has been breached: please contact the dev team.")
         goto(ERR_INFORMATION_LEAK)
     }
   }
@@ -2508,7 +2509,8 @@ class Channel(val nodeParams: NodeParams, val wallet: OnChainChannelFunder, remo
 
   private def handleInformationLeak(tx: Transaction, d: HasCommitments) = {
     // this is never supposed to happen !!
-    log.error(s"our funding tx ${d.commitments.commitInput.outPoint.txid} was spent by txid=${tx.txid} !!")
+    log.error(s"our funding tx ${d.commitments.commitInput.outPoint.txid} was spent by txid=${tx.txid}!!")
+    Logs.notifications.error(s"funding tx ${d.commitments.commitInput.outPoint.txid} of channel ${d.channelId} was spent by an unknown transaction, indicating that your DB has lost data or your node has been breached: please contact the dev team.")
     val exc = FundingTxSpent(d.channelId, tx)
     val error = Error(d.channelId, exc.getMessage)
 
@@ -2604,6 +2606,7 @@ class Channel(val nodeParams: NodeParams, val wallet: OnChainChannelFunder, remo
       } catch {
         case t: SQLException =>
           log.error(t, "fatal database error\n")
+          Logs.notifications.error("eclair is shutting down because of a fatal database error", t)
           sys.exit(-2)
         case t: Throwable => handleLocalError(t, event.stateData, None)
       }

diff --git a/eclair-core/src/main/scala/fr/acinq/eclair/io/Peer.scala b/eclair-core/src/main/scala/fr/acinq/eclair/io/Peer.scala
@@ -114,6 +114,7 @@ class Peer(val nodeParams: NodeParams, remoteNodeId: PublicKey, wallet: OnChainA
 
       case Event(err@Error(channelId, reason, _), d: ConnectedData) if channelId == CHANNELID_ZERO =>
         log.error(s"connection-level error, failing all channels! reason=${new String(reason.toArray)}")
+        Logs.notifications.info(s"$remoteNodeId sent us a connection-level error, closing all channels (reason=${new String(reason.toArray)})")
         d.channels.values.toSet[ActorRef].foreach(_ forward err) // we deduplicate with toSet because there might be two entries per channel (tmp id and final id)
         d.peerConnection ! PeerConnection.Kill(KillReason.AllChannelsFail)
         stay()

diff --git a/eclair-core/src/test/resources/logback-test.xml b/eclair-core/src/test/resources/logback-test.xml
@@ -24,29 +24,40 @@
         </encoder>
     </appender>
 
+    <appender name="CONSOLE_NOTIFICATIONS" class="ch.qos.logback.core.ConsoleAppender">
+        <target>System.out</target>
+        <encoder>
+            <pattern>%d %highlight(%-5level)- %msg%ex{12}%n</pattern>
+        </encoder>
+    </appender>
+
     <!--
     Logging from tests are silenced by this appender. When there is a test failure
     the captured logging events are flushed to the appenders defined for the
     akka.actor.testkit.typed.internal.CapturingAppenderDelegate logger.
     -->
-    <appender name="CapturingAppender" class="akka.actor.testkit.typed.internal.CapturingAppender" />
+    <appender name="CapturingAppender" class="akka.actor.testkit.typed.internal.CapturingAppender"/>
 
     <!--
     The appenders defined for this CapturingAppenderDelegate logger are used
     when there is a test failure and all logging events from the test are
     flushed to these appenders.
     -->
-    <logger name="akka.actor.testkit.typed.internal.CapturingAppenderDelegate" >
+    <logger name="akka.actor.testkit.typed.internal.CapturingAppenderDelegate">
         <appender-ref ref="CONSOLE"/>
     </logger>
 
-    <!--logger name="fr.acinq.eclair.channel" level="DEBUG"/-->
+    <logger level="INFO" name="notifications">
+        <!--<appender-ref ref="CONSOLE_NOTIFICATIONS"/>-->
+    </logger>
+
     <logger name="fr.acinq.eclair.router" level="WARN"/>
     <logger name="fr.acinq.eclair.channel" level="WARN"/>
     <logger name="fr.acinq.eclair.Diagnostics" level="OFF"/>
     <logger name="fr.acinq.eclair.blockchain.bitcoind.ZmqWatcher" level="OFF"/>
     <logger name="fr.acinq.eclair.db.FileBackupHandler" level="OFF"/>
-    <logger name="fr.acinq.eclair.payment.relay" level="DEBUG" />
+    <!--<logger name="fr.acinq.eclair.payment.relay" level="DEBUG" />-->
+    <!--<logger name="fr.acinq.eclair.channel" level="DEBUG" />-->
 
     <root level="INFO">
         <appender-ref ref="CapturingAppender"/>

diff --git a/eclair-front/src/main/resources/logback.xml b/eclair-front/src/main/resources/logback.xml
@@ -39,6 +39,20 @@
         </encoder>
     </appender>
 
+    <appender name="ROLLING_NOTIFICATIONS">
+        <file>${eclair.datadir:-${user.home}/.eclair}/notifications.log</file>
+        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
+            <!-- daily rollover -->
+            <fileNamePattern>${eclair.datadir:-${user.home}/.eclair}/notifications.%d{yyyy-MM-dd}.log</fileNamePattern>
+            <!-- keep 30 days' worth of history capped at 1 GB total size -->
+            <maxHistory>30</maxHistory>
+            <totalSizeCap>1GB</totalSizeCap>
+        </rollingPolicy>
+        <encoder>
+            <pattern>%d %highlight(%-5level)- %msg%ex{24}%n</pattern>
+        </encoder>
+    </appender>
+
     <if condition='isDefined("eclair.printToConsole")'>
         <then>
             <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
@@ -52,6 +66,11 @@
         </then>
     </if>
 
+    <!-- This logger contains important notifications for node operators. -->
+    <logger level="INFO" name="notifications">
+        <appender-ref ref="ROLLING_NOTIFICATIONS"/>
+    </logger>
+
     <root level="INFO">
         <appender-ref ref="ROLLING"/>
     </root>

diff --git a/eclair-node/src/main/resources/logback.xml b/eclair-node/src/main/resources/logback.xml
@@ -39,6 +39,20 @@
         </encoder>
     </appender>
 
+    <appender name="ROLLING_NOTIFICATIONS">
+        <file>${eclair.datadir:-${user.home}/.eclair}/notifications.log</file>
+        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
+            <!-- daily rollover -->
+            <fileNamePattern>${eclair.datadir:-${user.home}/.eclair}/notifications.%d{yyyy-MM-dd}.log</fileNamePattern>
+            <!-- keep 30 days' worth of history capped at 1 GB total size -->
+            <maxHistory>30</maxHistory>
+            <totalSizeCap>1GB</totalSizeCap>
+        </rollingPolicy>
+        <encoder>
+            <pattern>%d %highlight(%-5level)- %msg%ex{24}%n</pattern>
+        </encoder>
+    </appender>
+
     <if condition='isDefined("eclair.printToConsole")'>
         <then>
             <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
@@ -52,6 +66,11 @@
         </then>
     </if>
 
+    <!-- This logger contains important notifications for node operators. -->
+    <logger level="INFO" name="notifications">
+        <appender-ref ref="ROLLING_NOTIFICATIONS"/>
+    </logger>
+
     <root level="INFO">
         <appender-ref ref="ROLLING"/>
     </root>

diff --git a/eclair-node/src/main/scala/fr/acinq/eclair/Boot.scala b/eclair-node/src/main/scala/fr/acinq/eclair/Boot.scala
@@ -16,15 +16,14 @@
 
 package fr.acinq.eclair
 
-import java.io.File
-
 import akka.actor.ActorSystem
 import akka.http.scaladsl.Http
 import akka.stream.BindFailedException
 import fr.acinq.eclair.api.Service
 import grizzled.slf4j.Logging
 import kamon.Kamon
 
+import java.io.File
 import scala.concurrent.ExecutionContext
 import scala.util.{Failure, Success}
 
@@ -61,10 +60,6 @@ object Boot extends App with Logging {
 
   /**
    * Starts the http APIs service if enabled in the configuration
-   *
-   * @param kit
-   * @param system
-   * @param ec
    */
   def startApiServiceIfEnabled(kit: Kit, providers: Seq[RouteProvider] = Nil)(implicit system: ActorSystem, ec: ExecutionContext) = {
     val config = system.settings.config.getConfig("eclair")
@@ -91,6 +86,7 @@ object Boot extends App with Logging {
     val errorMsg = if (t.getMessage != null) t.getMessage else t.getClass.getSimpleName
     System.err.println(s"fatal error: $errorMsg")
     logger.error(s"fatal error: $errorMsg", t)
+    Logs.notifications.error("could not start eclair:", t)
     System.exit(1)
   }
 }
diff --git a/eclair-node/src/test/resources/logback-test.xml b/eclair-node/src/test/resources/logback-test.xml
@@ -24,8 +24,19 @@
         </encoder>
     </appender>
 
+    <appender name="CONSOLE_NOTIFICATIONS" class="ch.qos.logback.core.ConsoleAppender">
+        <target>System.out</target>
+        <encoder>
+            <pattern>%d %highlight(%-5level)- %msg%ex{12}%n</pattern>
+        </encoder>
+    </appender>
+
+    <logger level="INFO" name="notifications">
+        <!--<appender-ref ref="CONSOLE_NOTIFICATIONS"/>-->
+    </logger>
+
     <root level="INFO">
-        <!--appender-ref ref="CONSOLE"/-->
+        <!--<appender-ref ref="CONSOLE"/>-->
     </root>
 
 </configuration>