Changes to sshClient.stop() logging

- Rename log to "server_tunnel"
- Use LogRawFieldsWithTimestamp for ELK compatibility
- Include all base handshake API params in log message

psiphon/server/api.go

@@ -135,10 +135,8 @@ func handshakeAPIRequestHandler(
 
 	// Note: ignoring errors as params are validated
 	sessionID, _ := getStringRequestParam(params, "client_session_id")
-	propagationChannelID, _ := getStringRequestParam(params, "propagation_channel_id")
 	sponsorID, _ := getStringRequestParam(params, "sponsor_id")
-	clientVersionStr, _ := getStringRequestParam(params, "client_version")
-	clientVersion, _ := strconv.Atoi(clientVersionStr)
+	clientVersion, _ := getStringRequestParam(params, "client_version")
 	clientPlatform, _ := getStringRequestParam(params, "client_platform")
 	isMobile := isMobileClientPlatform(clientPlatform)
 	normalizedPlatform := normalizeClientPlatform(clientPlatform)
@@ -152,11 +150,8 @@ func handshakeAPIRequestHandler(
 	err = support.TunnelServer.SetClientHandshakeState(
 		sessionID,
 		handshakeState{
-			completed:            true,
-			propagationChannelID: propagationChannelID,
-			sponsorID:            sponsorID,
-			clientVersion:        clientVersion,
-			clientPlatform:       clientPlatform,
+			completed: true,
+			apiParams: copyBaseRequestParams(params),
 		})
 	if err != nil {
 		return nil, common.ContextError(err)
@@ -166,7 +161,7 @@ func handshakeAPIRequestHandler(
 	db := support.PsinetDatabase
 	handshakeResponse := common.HandshakeResponse{
 		Homepages:            db.GetHomepages(sponsorID, geoIPData.Country, isMobile),
-		UpgradeClientVersion: db.GetUpgradeClientVersion(clientVersionStr, normalizedPlatform),
+		UpgradeClientVersion: db.GetUpgradeClientVersion(clientVersion, normalizedPlatform),
 		HttpsRequestRegexes:  db.GetHttpsRequestRegexes(sponsorID),
 		EncodedServerList:    db.DiscoverServers(geoIPData.DiscoveryValue),
 		ClientRegion:         geoIPData.Country,
@@ -448,7 +443,7 @@ var baseRequestParams = []requestParamSpec{
 	requestParamSpec{"client_session_id", isHexDigits, requestParamOptional | requestParamNotLogged},
 	requestParamSpec{"propagation_channel_id", isHexDigits, 0},
 	requestParamSpec{"sponsor_id", isHexDigits, 0},
-	requestParamSpec{"client_version", isInt, 0},
+	requestParamSpec{"client_version", isIntString, 0},
 	requestParamSpec{"client_platform", isClientPlatform, 0},
 	requestParamSpec{"relay_protocol", isRelayProtocol, 0},
 	requestParamSpec{"tunnel_whole_device", isBooleanFlag, requestParamOptional},
@@ -493,6 +488,26 @@ func validateRequestParams(
 	return nil
 }
 
+// copyBaseRequestParams makes a copy of the params which
+// includes only the baseRequestParams.
+func copyBaseRequestParams(params requestJSONObject) requestJSONObject {
+
+	// Note: not a deep copy; assumes baseRequestParams values
+	// are all scalar types (int, string, etc.)
+
+	paramsCopy := make(requestJSONObject)
+	for _, baseParam := range baseRequestParams {
+		value := params[baseParam.name]
+		if value == nil {
+			continue
+		}
+
+		paramsCopy[baseParam.name] = value
+	}
+
+	return paramsCopy
+}
+
 func validateStringRequestParam(
 	support *SupportServices,
 	expectedParam requestParamSpec,
@@ -551,6 +566,10 @@ func getRequestLogFields(
 	logFields["client_city"] = strings.Replace(geoIPData.City, " ", "_", -1)
 	logFields["client_isp"] = strings.Replace(geoIPData.ISP, " ", "_", -1)
 
+	if params == nil {
+		return logFields
+	}
+
 	for _, expectedParam := range expectedParams {
 
 		if expectedParam.flags&requestParamNotLogged != 0 {
@@ -732,7 +751,7 @@ func isDigits(_ *SupportServices, value string) bool {
 	})
 }
 
-func isInt(_ *SupportServices, value string) bool {
+func isIntString(_ *SupportServices, value string) bool {
 	_, err := strconv.Atoi(value)
 	return err == nil
 }

psiphon/server/tunnelServer.go

@@ -631,11 +631,8 @@ type trafficState struct {
 }
 
 type handshakeState struct {
-	completed            bool
-	propagationChannelID string
-	sponsorID            string
-	clientVersion        int
-	clientPlatform       string
+	completed bool
+	apiParams requestJSONObject
 }
 
 func newSshClient(
@@ -759,33 +756,31 @@ func (sshClient *sshClient) stop() {
 	// it did the client may not have the opportunity to send a final
 	// request with an EOF flag set.)
 
+	sshClient.Lock()
+
+	logFields := getRequestLogFields(
+		sshClient.sshServer.support,
+		"server_tunnel",
+		sshClient.geoIPData,
+		sshClient.handshakeState.apiParams,
+		baseRequestParams)
+
 	// TODO: match legacy log field naming convention?
-	// TODO: log all handshake common inputs?
+	logFields["HandshakeCompleted"] = sshClient.handshakeState.completed
+	logFields["startTime"] = sshClient.activityConn.GetStartTime()
+	logFields["Duration"] = sshClient.activityConn.GetActiveDuration()
+	logFields["BytesUpTCP"] = sshClient.tcpTrafficState.bytesUp
+	logFields["BytesDownTCP"] = sshClient.tcpTrafficState.bytesDown
+	logFields["PeakConcurrentPortForwardCountTCP"] = sshClient.tcpTrafficState.peakConcurrentPortForwardCount
+	logFields["TotalPortForwardCountTCP"] = sshClient.tcpTrafficState.totalPortForwardCount
+	logFields["BytesUpUDP"] = sshClient.udpTrafficState.bytesUp
+	logFields["BytesDownUDP"] = sshClient.udpTrafficState.bytesDown
+	logFields["PeakConcurrentPortForwardCountUDP"] = sshClient.udpTrafficState.peakConcurrentPortForwardCount
+	logFields["TotalPortForwardCountUDP"] = sshClient.udpTrafficState.totalPortForwardCount
 
-	sshClient.Lock()
-	log.WithContextFields(
-		LogFields{
-			"handshakeCompleted":                sshClient.handshakeState.completed,
-			"propagationChannelID":              sshClient.handshakeState.propagationChannelID,
-			"sponsorID":                         sshClient.handshakeState.sponsorID,
-			"clientVersion":                     sshClient.handshakeState.clientVersion,
-			"clientPlatform":                    sshClient.handshakeState.clientPlatform,
-			"startTime":                         sshClient.activityConn.GetStartTime(),
-			"duration":                          sshClient.activityConn.GetActiveDuration(),
-			"sessionID":                         sshClient.sessionID,
-			"country":                           sshClient.geoIPData.Country,
-			"city":                              sshClient.geoIPData.City,
-			"ISP":                               sshClient.geoIPData.ISP,
-			"bytesUpTCP":                        sshClient.tcpTrafficState.bytesUp,
-			"bytesDownTCP":                      sshClient.tcpTrafficState.bytesDown,
-			"peakConcurrentPortForwardCountTCP": sshClient.tcpTrafficState.peakConcurrentPortForwardCount,
-			"totalPortForwardCountTCP":          sshClient.tcpTrafficState.totalPortForwardCount,
-			"bytesUpUDP":                        sshClient.udpTrafficState.bytesUp,
-			"bytesDownUDP":                      sshClient.udpTrafficState.bytesDown,
-			"peakConcurrentPortForwardCountUDP": sshClient.udpTrafficState.peakConcurrentPortForwardCount,
-			"totalPortForwardCountUDP":          sshClient.udpTrafficState.totalPortForwardCount,
-		}).Info("tunnel closed")
 	sshClient.Unlock()
+
+	log.LogRawFieldsWithTimestamp(logFields)
 }
 
 // runClient handles/dispatches new channel and new requests from the client.