Use rotating diagnostic file in iOS library

MobileLibrary/iOS/PsiphonTunnel/PsiphonTunnel/PsiphonTunnel.m

@@ -56,6 +56,7 @@
     _Atomic NetworkStatus currentNetworkStatus;
 
     BOOL tunnelWholeDevice;
+    _Atomic BOOL usingRotatingNotices;
 
     // DNS
     NSString *primaryGoogleDNS;
@@ -82,6 +83,7 @@
     self->reachability = [Reachability reachabilityForInternetConnection];
     atomic_init(&self->currentNetworkStatus, NotReachable);
     self->tunnelWholeDevice = FALSE;
+    atomic_init(&self->usingRotatingNotices, FALSE);
 
     // Randomize order of Google DNS servers on start,
     // and consistently return in that fixed order.
@@ -113,8 +115,8 @@
 // See comment in header
 + (PsiphonTunnel * _Nonnull)newPsiphonTunnel:(id<TunneledAppDelegate> _Nonnull)tunneledAppDelegate {
     @synchronized (PsiphonTunnel.self) {
-        // Only one PsiphonTunnel instance may exist at a time, as the underlying
-        // go.psi.Psi and tun2socks implementations each contain global state.
+        // Only one PsiphonTunnel instance may exist at a time, as the
+        // underlying GoPsi implementation contains global state.
         
         static PsiphonTunnel *sharedInstance = nil;
         static dispatch_once_t onceToken = 0;
@@ -155,6 +157,13 @@
 - (BOOL)start {
     @synchronized (PsiphonTunnel.self) {
 
+        // Initialize notice files for writing as early as possible, so all
+        // logMessages will be written, as NoticeUserLogs, to the rotating
+        // file when tunnel-core is managing diagnostics.
+        if ([self initNoticeFiles] == FALSE) {
+            return FALSE;
+        }
+
         [self stop];
 
         [self logMessage:@"Starting Psiphon library"];
@@ -164,7 +173,7 @@
         
         NSString *configStr = [self getConfig];
         if (configStr == nil) {
-            [self logMessage:@"Error getting config from delegate"];
+            [self logMessage:@"Error getting config"];
             return FALSE;
         }
 
@@ -196,48 +205,22 @@
             }
         }
 
-        __block NSString *homepageNoticesPath = @"";
-        if ([self.tunneledAppDelegate respondsToSelector:@selector(getHomepageNoticesPath)]) {
-            dispatch_sync(self->callbackQueue, ^{
-                homepageNoticesPath = [self.tunneledAppDelegate getHomepageNoticesPath];
-                if (homepageNoticesPath == nil) {
-                    homepageNoticesPath = @"";
-                }
-            });
-        }
-
-        __block NSString *rotatingNoticesPath = @"";
-        if ([self.tunneledAppDelegate respondsToSelector:@selector(getRotatingNoticesPath)]) {
-            dispatch_sync(self->callbackQueue, ^{
-                rotatingNoticesPath = [self.tunneledAppDelegate getRotatingNoticesPath];
-                if (rotatingNoticesPath == nil) {
-                    rotatingNoticesPath = @"";
-                }
-            });
-        }
-
         [self changeConnectionStateTo:PsiphonConnectionStateConnecting evenIfSameState:NO];
 
         @try {
             NSError *e = nil;
 
-            BOOL res = GoPsiStart(
-                           configStr,
-                           embeddedServerEntries,
-                           embeddedServerEntriesPath,
-                           homepageNoticesPath,
-                           rotatingNoticesPath,
-                           0, // Use default rotating settings
-                           0, // ...
-                           self,
-                           self->tunnelWholeDevice, // useDeviceBinder
-                           useIPv6Synthesizer,
-                           &e);
-            
-            [self logMessage:[NSString stringWithFormat: @"GoPsiStart: %@", res ? @"TRUE" : @"FALSE"]];
+            GoPsiStart(
+                configStr,
+                embeddedServerEntries,
+                embeddedServerEntriesPath,
+                self,
+                self->tunnelWholeDevice, // useDeviceBinder
+                useIPv6Synthesizer,
+                &e);
             
             if (e != nil) {
-                [self logMessage:[NSString stringWithFormat: @"Psiphon tunnel start failed: %@", e.localizedDescription]];
+                [self logMessage:[NSString stringWithFormat: @"Psiphon library start failed: %@", e.localizedDescription]];
                 [self changeConnectionStateTo:PsiphonConnectionStateDisconnected evenIfSameState:NO];
                 return FALSE;
             }
@@ -250,12 +233,54 @@
 
         [self startInternetReachabilityMonitoring];
 
-        [self logMessage:@"Psiphon tunnel started"];
+        [self logMessage:@"Psiphon library started"];
         
         return TRUE;
     }
 }
 
+- (BOOL)initNoticeFiles {
+
+    __block NSString *homepageNoticesPath = @"";
+    if ([self.tunneledAppDelegate respondsToSelector:@selector(getHomepageNoticesPath)]) {
+        dispatch_sync(self->callbackQueue, ^{
+            homepageNoticesPath = [self.tunneledAppDelegate getHomepageNoticesPath];
+            if (homepageNoticesPath == nil) {
+                homepageNoticesPath = @"";
+            }
+        });
+    }
+
+    __block NSString *rotatingNoticesPath = @"";
+    if ([self.tunneledAppDelegate respondsToSelector:@selector(getRotatingNoticesPath)]) {
+        dispatch_sync(self->callbackQueue, ^{
+            rotatingNoticesPath = [self.tunneledAppDelegate getRotatingNoticesPath];
+            if (rotatingNoticesPath == nil) {
+                rotatingNoticesPath = @"";
+            }
+        });
+    }
+
+    if (rotatingNoticesPath.length > 0) {
+        atomic_store(&self->usingRotatingNotices, TRUE);
+    }
+
+    NSError *e = nil;
+    GoPsiSetNoticeFiles(
+        homepageNoticesPath,
+        rotatingNoticesPath,
+        0, // Use default rotating settings
+        0, // ...
+        &e);
+    if (e != nil) {
+        [self logMessage:[NSString stringWithFormat: @"Psiphon library initialize notices failed: %@", e.localizedDescription]];
+        [self changeConnectionStateTo:PsiphonConnectionStateDisconnected evenIfSameState:NO];
+        return FALSE;
+    }
+
+    return TRUE;
+}
+
 /*!
  Start the tunnel if it's not already started.
  */
@@ -592,7 +617,9 @@
  @param noticeJSON  The notice data, JSON encoded.
  */
 - (void)handlePsiphonNotice:(NSString * _Nonnull)noticeJSON {
+
     BOOL diagnostic = TRUE;
+    BOOL internalError = FALSE;
     
     __block NSDictionary *notice = nil;
     id block = ^(id obj, BOOL *ignored) {
@@ -813,9 +840,25 @@
             });
         }
     }
+    else if ([noticeType isEqualToString:@"InternalError"]) {
+        internalError = TRUE;
+    }
     
-    // Pass diagnostic messages to onDiagnosticMessage.
-    if (diagnostic) {
+    // When tunnel-core is managing diagnostics, onDiagnosticMessage is
+    // typically not called: the user app will get callbacks for specific
+    // events such as onConnected, and for all other notices tunnel-core
+    // is recording them and the overhead of posting to the user app is
+    // redundant and unnecessary.
+    //
+    // The only exception is NoticeInternalError, where tunnel-core has
+    // failed to log a notice. In this case, the user app receives
+    // onDiagnosticMessage and a chance to report the error.
+    //
+    // Otherwise, when tunnel-core is not managing diagnosrics, pass
+    // diagnostic messages to onDiagnosticMessage.
+    if (diagnostic &&
+        (atomic_load(&self->usingRotatingNotices) == FALSE || internalError == TRUE)) {
+
         NSDictionary *data = notice[@"data"];
         if (data == nil) {
             return;
@@ -825,10 +868,32 @@
         NSString *timestampStr = notice[@"timestamp"];
 
         NSString *diagnosticMessage = [NSString stringWithFormat:@"%@: %@", noticeType, dataStr];
-        [self logMessage:diagnosticMessage withTimestamp:timestampStr];
+        [self postDiagnosticMessage:diagnosticMessage withTimestamp:timestampStr];
     }
 }
 
+- (void)logMessage:(NSString *)message {
+
+    // When tunnel-core is configured to manage diagnostics,
+    // library logMessages are sent to tunnel-core.
+    // Otherwise, they are posted to onDiagnosticMessage for
+    // the user app to manage.
+
+    if (atomic_load(&self->usingRotatingNotices) == TRUE) {
+        GoPsiNoticeUserLog(message);
+    } else {
+        NSString *timestamp = [rfc3339Formatter stringFromDate:[NSDate date]];
+        [self postDiagnosticMessage:message withTimestamp:timestamp];
+    }
+}
+
+- (void)postDiagnosticMessage:(NSString *)message withTimestamp:(NSString * _Nonnull)timestamp {
+    if ([self.tunneledAppDelegate respondsToSelector:@selector(onDiagnosticMessage:withTimestamp:)]) {
+        dispatch_sync(self->callbackQueue, ^{
+            [self.tunneledAppDelegate onDiagnosticMessage:message withTimestamp:timestamp];
+        });
+    }
+}
 
 #pragma mark - GoPsiPsiphonProvider protocol implementation (private)
 
@@ -1020,19 +1085,6 @@
     return serverList;
 }
 
-- (void)logMessage:(NSString *)message {
-    NSString *timestamp = [rfc3339Formatter stringFromDate:[NSDate date]];
-    [self logMessage:message withTimestamp:timestamp];
-}
-
-- (void)logMessage:(NSString *)message withTimestamp:(NSString * _Nonnull)timestamp {
-    if ([self.tunneledAppDelegate respondsToSelector:@selector(onDiagnosticMessage:withTimestamp:)]) {
-        dispatch_sync(self->callbackQueue, ^{
-            [self.tunneledAppDelegate onDiagnosticMessage:message withTimestamp:timestamp];
-        });
-    }
-}
-
 - (void)changeConnectionStateTo:(PsiphonConnectionState)newState evenIfSameState:(BOOL)forceNotification {
     // Store the new state and get the old state.
     PsiphonConnectionState oldState = atomic_exchange(&self->connectionState, newState);

MobileLibrary/psi/psi.go

@@ -45,6 +45,23 @@ type PsiphonProvider interface {
 	GetSecondaryDnsServer() string
 }
 
+func SetNoticeFiles(
+	homepageFilename,
+	rotatingFilename string,
+	rotatingFileSize,
+	rotatingSyncFrequency int) error {
+
+	return psiphon.SetNoticeFiles(
+		homepageFilename,
+		rotatingFilename,
+		rotatingFileSize,
+		rotatingSyncFrequency)
+}
+
+func NoticeUserLog(message string) {
+	psiphon.NoticeUserLog(message)
+}
+
 var controllerMutex sync.Mutex
 var controller *psiphon.Controller
 var shutdownBroadcast chan struct{}
@@ -53,11 +70,7 @@ var controllerWaitGroup *sync.WaitGroup
 func Start(
 	configJson,
 	embeddedServerEntryList,
-	embeddedServerEntryListFilename,
-	homepageFilename,
-	rotatingFilename string,
-	rotatingFileSize int,
-	rotatingSyncFrequency int,
+	embeddedServerEntryListFilename string,
 	provider PsiphonProvider,
 	useDeviceBinder,
 	useIPv6Synthesizer bool) error {
@@ -92,22 +105,13 @@ func Start(
 		config.IPv6Synthesizer = provider
 	}
 
-	err = psiphon.SetNoticeOutput(psiphon.NewNoticeReceiver(
+	psiphon.SetNoticeWriter(psiphon.NewNoticeReceiver(
 		func(notice []byte) {
 			provider.Notice(string(notice))
-		}),
-		homepageFilename,
-		rotatingFilename,
-		rotatingFileSize,
-		rotatingSyncFrequency)
-	if err != nil {
-		return fmt.Errorf("error initializing notice output: %s\n", err)
-	}
+		}))
 
 	psiphon.NoticeBuildInfo()
 
-	// TODO: should following errors be Notices?
-
 	err = psiphon.InitDataStore(config)
 	if err != nil {
 		return fmt.Errorf("error initializing datastore: %s", err)

psiphon/controller.go

@@ -756,6 +756,7 @@ func (controller *Controller) TerminateNextActiveTunnel() {
 	tunnel := controller.getNextActiveTunnel()
 	if tunnel != nil {
 		controller.SignalTunnelFailure(tunnel)
+		NoticeInfo("terminated tunnel: %s", tunnel.serverEntry.IpAddress)
 	}
 }
 

psiphon/controller_test.go

@@ -546,7 +546,7 @@ func controllerRun(t *testing.T, runConfig *controllerRunConfig) {
 		classification map[string]int
 	}{classification: make(map[string]int)}
 
-	SetNoticeOutput(NewNoticeReceiver(
+	SetNoticeWriter(NewNoticeReceiver(
 		func(notice []byte) {
 			// TODO: log notices without logging server IPs:
 			// fmt.Fprintf(os.Stderr, "%s\n", string(notice))
@@ -662,8 +662,7 @@ func controllerRun(t *testing.T, runConfig *controllerRunConfig) {
 				}
 
 			}
-		}),
-		"", "", 0, 0)
+		}))
 
 	// Run controller, which establishes tunnels
 

psiphon/memory_test/memory_test.go

@@ -133,7 +133,7 @@ func runMemoryTest(t *testing.T, testMode int) {
 	reconnectTunnel := make(chan bool, 1)
 	tunnelsEstablished := int32(0)
 
-	psiphon.SetNoticeOutput(psiphon.NewNoticeReceiver(
+	psiphon.SetNoticeWriter(psiphon.NewNoticeReceiver(
 		func(notice []byte) {
 			noticeType, payload, err := psiphon.GetNotice(notice)
 			if err != nil {
@@ -171,8 +171,7 @@ func runMemoryTest(t *testing.T, testMode int) {
 					fmt.Printf("%s\n", message)
 				}
 			}
-		}),
-		"", "", 0, 0)
+		}))
 
 	startController := func() {
 		controller, err = psiphon.NewController(config)

psiphon/notice.go

@@ -72,10 +72,35 @@ func GetEmitDiagnoticNotices() bool {
 	return atomic.LoadInt32(&singletonNoticeLogger.logDiagnostics) == 1
 }
 
-// SetNoticeOutput sets a target writer to receive notices. By default,
+// SetNoticeWriter sets a target writer to receive notices. By default,
 // notices are written to stderr. Notices are newline delimited.
 //
-// - writer specifies an alternate io.Writer where notices are to be written.
+// writer specifies an alternate io.Writer where notices are to be written.
+//
+// Notices are encoded in JSON. Here's an example:
+//
+// {"data":{"message":"shutdown operate tunnel"},"noticeType":"Info","showUser":false,"timestamp":"2006-01-02T15:04:05.999999999Z07:00"}
+//
+// All notices have the following fields:
+// - "noticeType": the type of notice, which indicates the meaning of the notice along with what's in the data payload.
+// - "data": additional structured data payload. For example, the "ListeningSocksProxyPort" notice type has a "port" integer
+// data in its payload.
+// - "showUser": whether the information should be displayed to the user. For example, this flag is set for "SocksProxyPortInUse"
+// as the user should be informed that their configured choice of listening port could not be used. Core clients should
+// anticipate that the core will add additional "showUser"=true notices in the future and emit at least the raw notice.
+// - "timestamp": UTC timezone, RFC3339Milli format timestamp for notice event
+//
+// See the Notice* functions for details on each notice meaning and payload.
+//
+func SetNoticeWriter(writer io.Writer) {
+
+	singletonNoticeLogger.mutex.Lock()
+	defer singletonNoticeLogger.mutex.Unlock()
+
+	singletonNoticeLogger.writer = writer
+}
+
+// SetNoticeFiles configures files for notice writing.
 //
 // - When homepageFilename is not "", homepages are written to the specified file
 //   and omitted from the writer. The file may be read after the Tunnels notice
@@ -90,26 +115,13 @@ func GetEmitDiagnoticNotices() bool {
 //   If either rotatingFileSize or rotatingSyncFrequency are <= 0, default values
 //   are used.
 //
-// - If an error occurs when writing to a file, an Alert notice is emitted to
+// - If an error occurs when writing to a file, an InternalError notice is emitted to
 //   the writer.
 //
-// Notices are encoded in JSON. Here's an example:
-//
-// {"data":{"message":"shutdown operate tunnel"},"noticeType":"Info","showUser":false,"timestamp":"2006-01-02T15:04:05.999999999Z07:00"}
+// SetNoticeFiles closes open homepage or rotating files before applying the new
+// configuration.
 //
-// All notices have the following fields:
-// - "noticeType": the type of notice, which indicates the meaning of the notice along with what's in the data payload.
-// - "data": additional structured data payload. For example, the "ListeningSocksProxyPort" notice type has a "port" integer
-// data in its payload.
-// - "showUser": whether the information should be displayed to the user. For example, this flag is set for "SocksProxyPortInUse"
-// as the user should be informed that their configured choice of listening port could not be used. Core clients should
-// anticipate that the core will add additional "showUser"=true notices in the future and emit at least the raw notice.
-// - "timestamp": UTC timezone, RFC3339Milli format timestamp for notice event
-//
-// See the Notice* functions for details on each notice meaning and payload.
-//
-func SetNoticeOutput(
-	writer io.Writer,
+func SetNoticeFiles(
 	homepageFilename string,
 	rotatingFilename string,
 	rotatingFileSize int,
@@ -118,8 +130,6 @@ func SetNoticeOutput(
 	singletonNoticeLogger.mutex.Lock()
 	defer singletonNoticeLogger.mutex.Unlock()
 
-	singletonNoticeLogger.writer = writer
-
 	if homepageFilename != "" {
 		var err error
 		if singletonNoticeLogger.homepageFile != nil {
@@ -201,11 +211,10 @@ func (nl *noticeLogger) outputNotice(noticeType string, noticeFlags uint32, args
 		output = append(encodedJson, byte('\n'))
 
 	} else {
-		// Try to emit a properly formatted Alert notice that the outer client can
-		// report. One scenario where this is useful is if the preceding Marshal
-		// fails due to bad data in the args. This has happened for a json.RawMessage
-		// field.
-		output = makeOutputNoticeError(
+		// Try to emit a properly formatted notice that the outer client can report.
+		// One scenario where this is useful is if the preceding Marshal fails due to
+		// bad data in the args. This has happened for a json.RawMessage field.
+		output = makeNoticeInternalError(
 			fmt.Sprintf("marshal notice failed: %s", common.ContextError(err)))
 	}
 
@@ -222,7 +231,7 @@ func (nl *noticeLogger) outputNotice(noticeType string, noticeFlags uint32, args
 		err := nl.outputNoticeToHomepageFile(noticeFlags, output)
 
 		if err != nil {
-			output := makeOutputNoticeError(
+			output := makeNoticeInternalError(
 				fmt.Sprintf("write homepage file failed: %s", err))
 			nl.writer.Write(output)
 		}
@@ -237,7 +246,7 @@ func (nl *noticeLogger) outputNotice(noticeType string, noticeFlags uint32, args
 		err := nl.outputNoticeToRotatingFile(output)
 
 		if err != nil {
-			output := makeOutputNoticeError(
+			output := makeNoticeInternalError(
 				fmt.Sprintf("write rotating file failed: %s", err))
 			nl.writer.Write(output)
 		}
@@ -248,9 +257,11 @@ func (nl *noticeLogger) outputNotice(noticeType string, noticeFlags uint32, args
 	}
 }
 
-func makeOutputNoticeError(errorMessage string) []byte {
+// NoticeInteralError is an error formatting or writing notices.
+// A NoticeInteralError handler must not call a Notice function.
+func makeNoticeInternalError(errorMessage string) []byte {
 	// Format an Alert Notice (_without_ using json.Marshal, since that can fail)
-	alertNoticeFormat := "{\"noticeType\":\"Alert\",\"showUser\":false,\"timestamp\":\"%s\",\"data\":{\"message\":\"%s\"}}\n"
+	alertNoticeFormat := "{\"noticeType\":\"InternalError\",\"showUser\":false,\"timestamp\":\"%s\",\"data\":{\"message\":\"%s\"}}\n"
 	return []byte(fmt.Sprintf(alertNoticeFormat, time.Now().UTC().Format(common.RFC3339Milli), errorMessage))
 
 }
@@ -354,6 +365,13 @@ func NoticeError(format string, args ...interface{}) {
 		"message", fmt.Sprintf(format, args...))
 }
 
+// NoticeUserLog is a log message from the outer client user of tunnel-core
+func NoticeUserLog(message string) {
+	singletonNoticeLogger.outputNotice(
+		"UserLog", noticeIsDiagnostic,
+		"message", message)
+}
+
 // NoticeCandidateServers is how many possible servers are available for the selected region and protocol
 func NoticeCandidateServers(region, protocol string, count int) {
 	singletonNoticeLogger.outputNotice(

psiphon/remoteServerList_test.go

@@ -362,7 +362,7 @@ func TestObfuscatedRemoteServerLists(t *testing.T) {
 
 	tunnelEstablished := make(chan struct{}, 1)
 
-	SetNoticeOutput(NewNoticeReceiver(
+	SetNoticeWriter(NewNoticeReceiver(
 		func(notice []byte) {
 
 			noticeType, payload, err := GetNotice(notice)
@@ -391,8 +391,7 @@ func TestObfuscatedRemoteServerLists(t *testing.T) {
 			if printNotice {
 				fmt.Printf("%s\n", string(notice))
 			}
-		}),
-		"", "", 0, 0)
+		}))
 
 	go func() {
 		controller.Run(make(chan struct{}))

psiphon/server/server_test.go

@@ -464,7 +464,7 @@ func runServer(t *testing.T, runConfig *runServerConfig) {
 	verificationRequired := make(chan struct{}, 1)
 	verificationCompleted := make(chan struct{}, 1)
 
-	psiphon.SetNoticeOutput(psiphon.NewNoticeReceiver(
+	psiphon.SetNoticeWriter(psiphon.NewNoticeReceiver(
 		func(notice []byte) {
 
 			//fmt.Printf("%s\n", string(notice))
@@ -498,8 +498,7 @@ func runServer(t *testing.T, runConfig *runServerConfig) {
 			case "NoticeClientVerificationRequestCompleted":
 				sendNotificationReceived(verificationCompleted)
 			}
-		}),
-		"", "", 0, 0)
+		}))
 
 	controllerShutdownBroadcast := make(chan struct{})
 	controllerWaitGroup := new(sync.WaitGroup)

psiphon/userAgent_test.go

@@ -214,7 +214,7 @@ func attemptConnectionsWithUserAgent(
 		t.Fatalf("error initializing client datastore: %s", err)
 	}
 
-	SetNoticeOutput(NewNoticeReceiver(
+	SetNoticeWriter(NewNoticeReceiver(
 		func(notice []byte) {
 			noticeType, payload, err := GetNotice(notice)
 			if err != nil {
@@ -226,8 +226,7 @@ func attemptConnectionsWithUserAgent(
 					countNoticeUserAgent(userAgent.(string))
 				}
 			}
-		}),
-		"", "", 0, 0)
+		}))
 
 	controller, err := NewController(clientConfig)
 	if err != nil {