github.com/psiphon-labs/psiphon-tunnel-core@v2.0.28+incompatible/psiphon/notice.go (about) 1 /* 2 * Copyright (c) 2015, Psiphon Inc. 3 * All rights reserved. 4 * 5 * This program is free software: you can redistribute it and/or modify 6 * it under the terms of the GNU General Public License as published by 7 * the Free Software Foundation, either version 3 of the License, or 8 * (at your option) any later version. 9 * 10 * This program is distributed in the hope that it will be useful, 11 * but WITHOUT ANY WARRANTY; without even the implied warranty of 12 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the 13 * GNU General Public License for more details. 14 * 15 * You should have received a copy of the GNU General Public License 16 * along with this program. If not, see <http://www.gnu.org/licenses/>. 17 * 18 */ 19 20 package psiphon 21 22 import ( 23 "bytes" 24 "encoding/json" 25 "fmt" 26 "io" 27 "os" 28 "sort" 29 "strings" 30 "sync" 31 "sync/atomic" 32 "time" 33 34 "github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common" 35 "github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common/buildinfo" 36 "github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common/errors" 37 "github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common/parameters" 38 "github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common/protocol" 39 "github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common/stacktrace" 40 ) 41 42 type noticeLogger struct { 43 emitDiagnostics int32 44 emitNetworkParameters int32 45 mutex sync.Mutex 46 writer io.Writer 47 homepageFilename string 48 homepageFile *os.File 49 rotatingFilename string 50 rotatingOlderFilename string 51 rotatingFile *os.File 52 rotatingFileSize int64 53 rotatingCurrentFileSize int64 54 rotatingSyncFrequency int 55 rotatingCurrentNoticeCount int 56 } 57 58 var singletonNoticeLogger = noticeLogger{ 59 writer: os.Stderr, 60 } 61 62 // SetEmitDiagnosticNotices toggles whether diagnostic notices are emitted; 63 // and whether to include circumvention network parameters in diagnostics. 64 // 65 // Diagnostic notices contain potentially sensitive user information; and 66 // sensitive circumvention network parameters, when enabled. Only enable this 67 // in environments where notices are handled securely (for example, don't 68 // include these notices in log files which users could post to public 69 // forums). 70 func SetEmitDiagnosticNotices( 71 emitDiagnostics bool, emitNetworkParameters bool) { 72 73 if emitDiagnostics { 74 atomic.StoreInt32(&singletonNoticeLogger.emitDiagnostics, 1) 75 } else { 76 atomic.StoreInt32(&singletonNoticeLogger.emitDiagnostics, 0) 77 } 78 79 if emitNetworkParameters { 80 atomic.StoreInt32(&singletonNoticeLogger.emitNetworkParameters, 1) 81 } else { 82 atomic.StoreInt32(&singletonNoticeLogger.emitNetworkParameters, 0) 83 } 84 } 85 86 // GetEmitDiagnosticNotices returns the current state 87 // of emitting diagnostic notices. 88 func GetEmitDiagnosticNotices() bool { 89 return atomic.LoadInt32(&singletonNoticeLogger.emitDiagnostics) == 1 90 } 91 92 // GetEmitNetworkParameters returns the current state 93 // of emitting network parameters. 94 func GetEmitNetworkParameters() bool { 95 return atomic.LoadInt32(&singletonNoticeLogger.emitNetworkParameters) == 1 96 } 97 98 // SetNoticeWriter sets a target writer to receive notices. By default, 99 // notices are written to stderr. Notices are newline delimited. 100 // 101 // writer specifies an alternate io.Writer where notices are to be written. 102 // 103 // Notices are encoded in JSON. Here's an example: 104 // 105 // {"data":{"message":"shutdown operate tunnel"},"noticeType":"Info","timestamp":"2006-01-02T15:04:05.999999999Z07:00"} 106 // 107 // All notices have the following fields: 108 // - "noticeType": the type of notice, which indicates the meaning of the notice along with what's in the data payload. 109 // - "data": additional structured data payload. For example, the "ListeningSocksProxyPort" notice type has a "port" integer 110 // data in its payload. 111 // - "timestamp": UTC timezone, RFC3339Milli format timestamp for notice event 112 // 113 // See the Notice* functions for details on each notice meaning and payload. 114 func SetNoticeWriter(writer io.Writer) { 115 116 singletonNoticeLogger.mutex.Lock() 117 defer singletonNoticeLogger.mutex.Unlock() 118 119 singletonNoticeLogger.writer = writer 120 } 121 122 // setNoticeFiles configures files for notice writing. 123 // 124 // - When homepageFilename is not "", homepages are written to the specified file 125 // and omitted from the writer. The file may be read after the Tunnels notice 126 // with count of 1. The file should be opened read-only for reading. 127 // 128 // - When rotatingFilename is not "", all notices are are written to the specified 129 // file. Diagnostic notices are omitted from the writer. The file is rotated 130 // when its size exceeds rotatingFileSize. One rotated older file, 131 // <rotatingFilename>.1, is retained. The files may be read at any time; and 132 // should be opened read-only for reading. rotatingSyncFrequency specifies how 133 // many notices are written before syncing the file. 134 // If either rotatingFileSize or rotatingSyncFrequency are <= 0, default values 135 // are used. 136 // 137 // - If an error occurs when writing to a file, an InternalError notice is emitted to 138 // the writer. 139 // 140 // setNoticeFiles closes open homepage or rotating files before applying the new 141 // configuration. 142 func setNoticeFiles( 143 homepageFilename string, 144 rotatingFilename string, 145 rotatingFileSize int, 146 rotatingSyncFrequency int) error { 147 148 singletonNoticeLogger.mutex.Lock() 149 defer singletonNoticeLogger.mutex.Unlock() 150 151 if homepageFilename != "" { 152 var err error 153 if singletonNoticeLogger.homepageFile != nil { 154 singletonNoticeLogger.homepageFile.Close() 155 } 156 singletonNoticeLogger.homepageFile, err = os.OpenFile( 157 homepageFilename, os.O_CREATE|os.O_TRUNC|os.O_WRONLY, 0600) 158 if err != nil { 159 return errors.Trace(err) 160 } 161 singletonNoticeLogger.homepageFilename = homepageFilename 162 } 163 164 if rotatingFilename != "" { 165 var err error 166 if singletonNoticeLogger.rotatingFile != nil { 167 singletonNoticeLogger.rotatingFile.Close() 168 } 169 singletonNoticeLogger.rotatingFile, err = os.OpenFile( 170 rotatingFilename, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0600) 171 if err != nil { 172 return errors.Trace(err) 173 } 174 175 fileInfo, err := singletonNoticeLogger.rotatingFile.Stat() 176 if err != nil { 177 return errors.Trace(err) 178 } 179 180 if rotatingFileSize <= 0 { 181 rotatingFileSize = 1 << 20 182 } 183 184 if rotatingSyncFrequency <= 0 { 185 rotatingSyncFrequency = 100 186 } 187 188 singletonNoticeLogger.rotatingFilename = rotatingFilename 189 singletonNoticeLogger.rotatingOlderFilename = rotatingFilename + ".1" 190 singletonNoticeLogger.rotatingFileSize = int64(rotatingFileSize) 191 singletonNoticeLogger.rotatingCurrentFileSize = fileInfo.Size() 192 singletonNoticeLogger.rotatingSyncFrequency = rotatingSyncFrequency 193 singletonNoticeLogger.rotatingCurrentNoticeCount = 0 194 } 195 196 return nil 197 } 198 199 const ( 200 noticeIsDiagnostic = 1 201 noticeIsHomepage = 2 202 noticeClearHomepages = 4 203 noticeSyncHomepages = 8 204 noticeSkipRedaction = 16 205 ) 206 207 // outputNotice encodes a notice in JSON and writes it to the output writer. 208 func (nl *noticeLogger) outputNotice(noticeType string, noticeFlags uint32, args ...interface{}) { 209 210 if (noticeFlags¬iceIsDiagnostic != 0) && !GetEmitDiagnosticNotices() { 211 return 212 } 213 214 obj := make(map[string]interface{}) 215 noticeData := make(map[string]interface{}) 216 obj["noticeType"] = noticeType 217 obj["data"] = noticeData 218 obj["timestamp"] = time.Now().UTC().Format(common.RFC3339Milli) 219 for i := 0; i < len(args)-1; i += 2 { 220 name, ok := args[i].(string) 221 value := args[i+1] 222 if ok { 223 noticeData[name] = value 224 } 225 } 226 encodedJson, err := json.Marshal(obj) 227 var output []byte 228 if err == nil { 229 output = append(encodedJson, byte('\n')) 230 231 } else { 232 // Try to emit a properly formatted notice that the outer client can report. 233 // One scenario where this is useful is if the preceding Marshal fails due to 234 // bad data in the args. This has happened for a json.RawMessage field. 235 output = makeNoticeInternalError( 236 fmt.Sprintf("marshal notice failed: %s", errors.Trace(err))) 237 } 238 239 // Skip redaction when we need to display browsing activity network addresses 240 // to users; for example, in the case of the Untunneled notice. Never log 241 // skipRedaction notices to diagnostics files (outputNoticeToRotatingFile, 242 // below). The notice writer may still be invoked for a skipRedaction notice; 243 // the writer must keep all known skipRedaction notices out of any upstream 244 // diagnostics logs. 245 246 skipRedaction := (noticeFlags¬iceSkipRedaction != 0) 247 248 if !skipRedaction { 249 // Ensure direct server IPs are not exposed in notices. The "net" package, 250 // and possibly other 3rd party packages, will include destination addresses 251 // in I/O error messages. 252 output = common.RedactIPAddresses(output) 253 } 254 255 // Don't call RedactFilePaths here, as the file path redaction can 256 // potentially match many non-path strings. Instead, RedactFilePaths should 257 // be applied in specific cases. 258 259 nl.mutex.Lock() 260 defer nl.mutex.Unlock() 261 262 skipWriter := false 263 264 if nl.homepageFile != nil && 265 (noticeFlags¬iceIsHomepage != 0) { 266 267 skipWriter = true 268 269 err := nl.outputNoticeToHomepageFile(noticeFlags, output) 270 271 if err != nil { 272 output := makeNoticeInternalError( 273 fmt.Sprintf("write homepage file failed: %s", err)) 274 nl.writer.Write(output) 275 } 276 } 277 278 if nl.rotatingFile != nil { 279 280 if !skipWriter { 281 skipWriter = (noticeFlags¬iceIsDiagnostic != 0) 282 } 283 284 if !skipRedaction { 285 286 err := nl.outputNoticeToRotatingFile(output) 287 288 if err != nil { 289 output := makeNoticeInternalError( 290 fmt.Sprintf("write rotating file failed: %s", err)) 291 nl.writer.Write(output) 292 } 293 } 294 } 295 296 if !skipWriter { 297 _, _ = nl.writer.Write(output) 298 } 299 } 300 301 // NoticeInteralError is an error formatting or writing notices. 302 // A NoticeInteralError handler must not call a Notice function. 303 func makeNoticeInternalError(errorMessage string) []byte { 304 // Format an Alert Notice (_without_ using json.Marshal, since that can fail) 305 alertNoticeFormat := "{\"noticeType\":\"InternalError\",\"timestamp\":\"%s\",\"data\":{\"message\":\"%s\"}}\n" 306 return []byte(fmt.Sprintf(alertNoticeFormat, time.Now().UTC().Format(common.RFC3339Milli), errorMessage)) 307 } 308 309 func (nl *noticeLogger) outputNoticeToHomepageFile(noticeFlags uint32, output []byte) error { 310 311 if (noticeFlags & noticeClearHomepages) != 0 { 312 err := nl.homepageFile.Truncate(0) 313 if err != nil { 314 return errors.Trace(err) 315 } 316 _, err = nl.homepageFile.Seek(0, 0) 317 if err != nil { 318 return errors.Trace(err) 319 } 320 } 321 322 _, err := nl.homepageFile.Write(output) 323 if err != nil { 324 return errors.Trace(err) 325 } 326 327 if (noticeFlags & noticeSyncHomepages) != 0 { 328 err = nl.homepageFile.Sync() 329 if err != nil { 330 return errors.Trace(err) 331 } 332 } 333 334 return nil 335 } 336 337 func (nl *noticeLogger) outputNoticeToRotatingFile(output []byte) error { 338 339 nl.rotatingCurrentFileSize += int64(len(output) + 1) 340 if nl.rotatingCurrentFileSize >= nl.rotatingFileSize { 341 342 // Note: all errors are fatal in order to preserve the 343 // rotatingFileSize limit; e.g., no attempt is made to 344 // continue writing to the file if it can't be rotated. 345 346 err := nl.rotatingFile.Sync() 347 if err != nil { 348 return errors.Trace(err) 349 } 350 351 err = nl.rotatingFile.Close() 352 if err != nil { 353 return errors.Trace(err) 354 } 355 356 err = os.Rename(nl.rotatingFilename, nl.rotatingOlderFilename) 357 if err != nil { 358 return errors.Trace(err) 359 } 360 361 nl.rotatingFile, err = os.OpenFile( 362 nl.rotatingFilename, os.O_CREATE|os.O_TRUNC|os.O_WRONLY, 0600) 363 if err != nil { 364 return errors.Trace(err) 365 } 366 367 nl.rotatingCurrentFileSize = 0 368 } 369 370 _, err := nl.rotatingFile.Write(output) 371 if err != nil { 372 return errors.Trace(err) 373 } 374 375 nl.rotatingCurrentNoticeCount += 1 376 if nl.rotatingCurrentNoticeCount >= nl.rotatingSyncFrequency { 377 nl.rotatingCurrentNoticeCount = 0 378 err = nl.rotatingFile.Sync() 379 if err != nil { 380 return errors.Trace(err) 381 } 382 } 383 384 return nil 385 } 386 387 // NoticeInfo is an informational message 388 func NoticeInfo(format string, args ...interface{}) { 389 singletonNoticeLogger.outputNotice( 390 "Info", noticeIsDiagnostic, 391 "message", fmt.Sprintf(format, args...)) 392 } 393 394 // NoticeWarning is a warning message; typically a recoverable error condition 395 func NoticeWarning(format string, args ...interface{}) { 396 singletonNoticeLogger.outputNotice( 397 "Warning", noticeIsDiagnostic, 398 "message", fmt.Sprintf(format, args...)) 399 } 400 401 // NoticeError is an error message; typically an unrecoverable error condition 402 func NoticeError(format string, args ...interface{}) { 403 singletonNoticeLogger.outputNotice( 404 "Error", noticeIsDiagnostic, 405 "message", fmt.Sprintf(format, args...)) 406 } 407 408 // NoticeUserLog is a log message from the outer client user of tunnel-core 409 func NoticeUserLog(message string) { 410 singletonNoticeLogger.outputNotice( 411 "UserLog", noticeIsDiagnostic, 412 "message", message) 413 } 414 415 // NoticeCandidateServers is how many possible servers are available for the selected region and protocols 416 func NoticeCandidateServers( 417 region string, 418 constraints *protocolSelectionConstraints, 419 initialCount int, 420 count int, 421 duration time.Duration) { 422 423 singletonNoticeLogger.outputNotice( 424 "CandidateServers", noticeIsDiagnostic, 425 "region", region, 426 "initialLimitTunnelProtocols", constraints.initialLimitTunnelProtocols, 427 "initialLimitTunnelProtocolsCandidateCount", constraints.initialLimitTunnelProtocolsCandidateCount, 428 "limitTunnelProtocols", constraints.limitTunnelProtocols, 429 "limitTunnelDialPortNumbers", constraints.limitTunnelDialPortNumbers, 430 "replayCandidateCount", constraints.replayCandidateCount, 431 "initialCount", initialCount, 432 "count", count, 433 "duration", duration.String()) 434 } 435 436 // NoticeAvailableEgressRegions is what regions are available for egress from. 437 // Consecutive reports of the same list of regions are suppressed. 438 func NoticeAvailableEgressRegions(regions []string) { 439 sortedRegions := append([]string{}, regions...) 440 sort.Strings(sortedRegions) 441 repetitionMessage := strings.Join(sortedRegions, "") 442 outputRepetitiveNotice( 443 "AvailableEgressRegions", repetitionMessage, 0, 444 "AvailableEgressRegions", 0, "regions", sortedRegions) 445 } 446 447 func noticeWithDialParameters(noticeType string, dialParams *DialParameters, postDial bool) { 448 449 args := []interface{}{ 450 "diagnosticID", dialParams.ServerEntry.GetDiagnosticID(), 451 "region", dialParams.ServerEntry.Region, 452 "protocol", dialParams.TunnelProtocol, 453 "isReplay", dialParams.IsReplay, 454 "candidateNumber", dialParams.CandidateNumber, 455 "establishedTunnelsCount", dialParams.EstablishedTunnelsCount, 456 "networkType", dialParams.GetNetworkType(), 457 } 458 459 if GetEmitNetworkParameters() { 460 461 // Omit appliedTacticsTag as that is emitted in another notice. 462 463 if dialParams.BPFProgramName != "" { 464 args = append(args, "clientBPF", dialParams.BPFProgramName) 465 } 466 467 if dialParams.SelectedSSHClientVersion { 468 args = append(args, "SSHClientVersion", dialParams.SSHClientVersion) 469 } 470 471 if dialParams.UpstreamProxyType != "" { 472 args = append(args, "upstreamProxyType", dialParams.UpstreamProxyType) 473 } 474 475 if dialParams.UpstreamProxyCustomHeaderNames != nil { 476 args = append(args, "upstreamProxyCustomHeaderNames", strings.Join(dialParams.UpstreamProxyCustomHeaderNames, ",")) 477 } 478 479 if dialParams.FrontingProviderID != "" { 480 args = append(args, "frontingProviderID", dialParams.FrontingProviderID) 481 } 482 483 if dialParams.MeekDialAddress != "" { 484 args = append(args, "meekDialAddress", dialParams.MeekDialAddress) 485 } 486 487 if protocol.TunnelProtocolUsesFrontedMeek(dialParams.TunnelProtocol) { 488 meekResolvedIPAddress := dialParams.MeekResolvedIPAddress.Load().(string) 489 if meekResolvedIPAddress != "" { 490 nonredacted := common.EscapeRedactIPAddressString(meekResolvedIPAddress) 491 args = append(args, "meekResolvedIPAddress", nonredacted) 492 } 493 } 494 495 if dialParams.MeekSNIServerName != "" { 496 args = append(args, "meekSNIServerName", dialParams.MeekSNIServerName) 497 } 498 499 if dialParams.MeekHostHeader != "" { 500 args = append(args, "meekHostHeader", dialParams.MeekHostHeader) 501 } 502 503 // MeekTransformedHostName is meaningful when meek is used, which is when MeekDialAddress != "" 504 if dialParams.MeekDialAddress != "" { 505 args = append(args, "meekTransformedHostName", dialParams.MeekTransformedHostName) 506 } 507 508 if dialParams.SelectedUserAgent { 509 args = append(args, "userAgent", dialParams.UserAgent) 510 } 511 512 if dialParams.SelectedTLSProfile { 513 args = append(args, "TLSProfile", dialParams.TLSProfile) 514 args = append(args, "TLSVersion", dialParams.GetTLSVersionForMetrics()) 515 } 516 517 // dialParams.ServerEntry.Region is emitted above. 518 519 if dialParams.ServerEntry.LocalSource != "" { 520 args = append(args, "serverEntrySource", dialParams.ServerEntry.LocalSource) 521 } 522 523 localServerEntryTimestamp := common.TruncateTimestampToHour( 524 dialParams.ServerEntry.LocalTimestamp) 525 if localServerEntryTimestamp != "" { 526 args = append(args, "serverEntryTimestamp", localServerEntryTimestamp) 527 } 528 529 if dialParams.DialPortNumber != "" { 530 args = append(args, "dialPortNumber", dialParams.DialPortNumber) 531 } 532 533 if dialParams.QUICVersion != "" { 534 args = append(args, "QUICVersion", dialParams.QUICVersion) 535 } 536 537 if dialParams.QUICDialSNIAddress != "" { 538 args = append(args, "QUICDialSNIAddress", dialParams.QUICDialSNIAddress) 539 } 540 541 if dialParams.QUICDisablePathMTUDiscovery { 542 args = append(args, "QUICDisableClientPathMTUDiscovery", dialParams.QUICDisablePathMTUDiscovery) 543 } 544 545 if dialParams.DialDuration > 0 { 546 args = append(args, "dialDuration", dialParams.DialDuration) 547 } 548 549 if dialParams.NetworkLatencyMultiplier != 0.0 { 550 args = append(args, "networkLatencyMultiplier", dialParams.NetworkLatencyMultiplier) 551 } 552 553 if dialParams.ConjureTransport != "" { 554 args = append(args, "conjureTransport", dialParams.ConjureTransport) 555 } 556 557 if dialParams.ResolveParameters != nil { 558 559 if dialParams.ResolveParameters.PreresolvedIPAddress != "" { 560 nonredacted := common.EscapeRedactIPAddressString(dialParams.ResolveParameters.PreresolvedIPAddress) 561 args = append(args, "DNSPreresolved", nonredacted) 562 563 } else { 564 565 // See dialParams.ResolveParameters comment in getBaseAPIParameters. 566 567 if dialParams.ResolveParameters.PreferAlternateDNSServer { 568 nonredacted := common.EscapeRedactIPAddressString(dialParams.ResolveParameters.AlternateDNSServer) 569 args = append(args, "DNSPreferred", nonredacted) 570 } 571 572 if dialParams.ResolveParameters.ProtocolTransformName != "" { 573 args = append(args, "DNSTransform", dialParams.ResolveParameters.ProtocolTransformName) 574 } 575 576 if postDial { 577 args = append(args, "DNSAttempt", dialParams.ResolveParameters.GetFirstAttemptWithAnswer()) 578 } 579 } 580 } 581 582 if dialParams.DialConnMetrics != nil { 583 metrics := dialParams.DialConnMetrics.GetMetrics() 584 for name, value := range metrics { 585 args = append(args, name, value) 586 } 587 } 588 589 if dialParams.DialConnNoticeMetrics != nil { 590 metrics := dialParams.DialConnNoticeMetrics.GetNoticeMetrics() 591 for name, value := range metrics { 592 args = append(args, name, value) 593 } 594 } 595 596 if dialParams.ObfuscatedSSHConnMetrics != nil { 597 metrics := dialParams.ObfuscatedSSHConnMetrics.GetMetrics() 598 for name, value := range metrics { 599 args = append(args, name, value) 600 } 601 } 602 } 603 604 singletonNoticeLogger.outputNotice( 605 noticeType, noticeIsDiagnostic, 606 args...) 607 } 608 609 // NoticeConnectingServer reports parameters and details for a single connection attempt 610 func NoticeConnectingServer(dialParams *DialParameters) { 611 noticeWithDialParameters("ConnectingServer", dialParams, false) 612 } 613 614 // NoticeConnectedServer reports parameters and details for a single successful connection 615 func NoticeConnectedServer(dialParams *DialParameters) { 616 noticeWithDialParameters("ConnectedServer", dialParams, true) 617 } 618 619 // NoticeRequestingTactics reports parameters and details for a tactics request attempt 620 func NoticeRequestingTactics(dialParams *DialParameters) { 621 noticeWithDialParameters("RequestingTactics", dialParams, false) 622 } 623 624 // NoticeRequestedTactics reports parameters and details for a successful tactics request 625 func NoticeRequestedTactics(dialParams *DialParameters) { 626 noticeWithDialParameters("RequestedTactics", dialParams, true) 627 } 628 629 // NoticeActiveTunnel is a successful connection that is used as an active tunnel for port forwarding 630 func NoticeActiveTunnel(diagnosticID, protocol string, isTCS bool) { 631 singletonNoticeLogger.outputNotice( 632 "ActiveTunnel", noticeIsDiagnostic, 633 "diagnosticID", diagnosticID, 634 "protocol", protocol, 635 "isTCS", isTCS) 636 } 637 638 // NoticeSocksProxyPortInUse is a failure to use the configured LocalSocksProxyPort 639 func NoticeSocksProxyPortInUse(port int) { 640 singletonNoticeLogger.outputNotice( 641 "SocksProxyPortInUse", 0, 642 "port", port) 643 } 644 645 // NoticeListeningSocksProxyPort is the selected port for the listening local SOCKS proxy 646 func NoticeListeningSocksProxyPort(port int) { 647 singletonNoticeLogger.outputNotice( 648 "ListeningSocksProxyPort", 0, 649 "port", port) 650 } 651 652 // NoticeHttpProxyPortInUse is a failure to use the configured LocalHttpProxyPort 653 func NoticeHttpProxyPortInUse(port int) { 654 singletonNoticeLogger.outputNotice( 655 "HttpProxyPortInUse", 0, 656 "port", port) 657 } 658 659 // NoticeListeningHttpProxyPort is the selected port for the listening local HTTP proxy 660 func NoticeListeningHttpProxyPort(port int) { 661 singletonNoticeLogger.outputNotice( 662 "ListeningHttpProxyPort", 0, 663 "port", port) 664 } 665 666 // NoticeClientUpgradeAvailable is an available client upgrade, as per the handshake. The 667 // client should download and install an upgrade. 668 func NoticeClientUpgradeAvailable(version string) { 669 singletonNoticeLogger.outputNotice( 670 "ClientUpgradeAvailable", 0, 671 "version", version) 672 } 673 674 // NoticeClientIsLatestVersion reports that an upgrade check was made and the client 675 // is already the latest version. availableVersion is the version available for download, 676 // if known. 677 func NoticeClientIsLatestVersion(availableVersion string) { 678 singletonNoticeLogger.outputNotice( 679 "ClientIsLatestVersion", 0, 680 "availableVersion", availableVersion) 681 } 682 683 // NoticeHomepages emits a series of NoticeHomepage, the sponsor homepages. The client 684 // should display the sponsor's homepages. 685 func NoticeHomepages(urls []string) { 686 for i, url := range urls { 687 noticeFlags := uint32(noticeIsHomepage) 688 if i == 0 { 689 noticeFlags |= noticeClearHomepages 690 } 691 if i == len(urls)-1 { 692 noticeFlags |= noticeSyncHomepages 693 } 694 singletonNoticeLogger.outputNotice( 695 "Homepage", noticeFlags, 696 "url", url) 697 } 698 } 699 700 // NoticeClientRegion is the client's region, as determined by the server and 701 // reported to the client in the handshake. 702 func NoticeClientRegion(region string) { 703 singletonNoticeLogger.outputNotice( 704 "ClientRegion", 0, 705 "region", region) 706 } 707 708 // NoticeClientAddress is the client's public network address, the IP address 709 // and port, as seen by the server and reported to the client in the 710 // handshake. 711 // 712 // Note: "address" should remain private and not included in diagnostics logs. 713 func NoticeClientAddress(address string) { 714 singletonNoticeLogger.outputNotice( 715 "ClientAddress", noticeSkipRedaction, 716 "address", address) 717 } 718 719 // NoticeTunnels is how many active tunnels are available. The client should use this to 720 // determine connecting/unexpected disconnect state transitions. When count is 0, the core is 721 // disconnected; when count > 1, the core is connected. 722 func NoticeTunnels(count int) { 723 singletonNoticeLogger.outputNotice( 724 "Tunnels", 0, 725 "count", count) 726 } 727 728 // NoticeSessionId is the session ID used across all tunnels established by the controller. 729 func NoticeSessionId(sessionId string) { 730 singletonNoticeLogger.outputNotice( 731 "SessionId", noticeIsDiagnostic, 732 "sessionId", sessionId) 733 } 734 735 // NoticeSplitTunnelRegions reports that split tunnel is on for the given country codes. 736 func NoticeSplitTunnelRegions(regions []string) { 737 singletonNoticeLogger.outputNotice( 738 "SplitTunnelRegions", 0, 739 "regions", regions) 740 } 741 742 // NoticeUntunneled indicates than an address has been classified as untunneled and is being 743 // accessed directly. 744 // 745 // Note: "address" should remain private; this notice should only be used for alerting 746 // users, not for diagnostics logs. 747 func NoticeUntunneled(address string) { 748 outputRepetitiveNotice( 749 "Untunneled", address, 0, 750 "Untunneled", noticeSkipRedaction, "address", address) 751 752 } 753 754 // NoticeUpstreamProxyError reports an error when connecting to an upstream proxy. The 755 // user may have input, for example, an incorrect address or incorrect credentials. 756 func NoticeUpstreamProxyError(err error) { 757 message := err.Error() 758 outputRepetitiveNotice( 759 "UpstreamProxyError", message, 0, 760 "UpstreamProxyError", 0, 761 "message", message) 762 } 763 764 // NoticeClientUpgradeDownloadedBytes reports client upgrade download progress. 765 func NoticeClientUpgradeDownloadedBytes(bytes int64) { 766 singletonNoticeLogger.outputNotice( 767 "ClientUpgradeDownloadedBytes", noticeIsDiagnostic, 768 "bytes", bytes) 769 } 770 771 // NoticeClientUpgradeDownloaded indicates that a client upgrade download 772 // is complete and available at the destination specified. 773 func NoticeClientUpgradeDownloaded(filename string) { 774 singletonNoticeLogger.outputNotice( 775 "ClientUpgradeDownloaded", 0, 776 "filename", filename) 777 } 778 779 // NoticeBytesTransferred reports how many tunneled bytes have been 780 // transferred since the last NoticeBytesTransferred. This is not a diagnostic 781 // notice: the user app has requested this notice with EmitBytesTransferred 782 // for functionality such as traffic display; and this frequent notice is not 783 // intended to be included with feedback. 784 func NoticeBytesTransferred(diagnosticID string, sent, received int64) { 785 singletonNoticeLogger.outputNotice( 786 "BytesTransferred", 0, 787 "diagnosticID", diagnosticID, 788 "sent", sent, 789 "received", received) 790 } 791 792 // NoticeTotalBytesTransferred reports how many tunneled bytes have been 793 // transferred in total up to this point. This is a diagnostic notice. 794 func NoticeTotalBytesTransferred(diagnosticID string, sent, received int64) { 795 singletonNoticeLogger.outputNotice( 796 "TotalBytesTransferred", noticeIsDiagnostic, 797 "diagnosticID", diagnosticID, 798 "sent", sent, 799 "received", received) 800 } 801 802 // NoticeLocalProxyError reports a local proxy error message. Repetitive 803 // errors for a given proxy type are suppressed. 804 func NoticeLocalProxyError(proxyType string, err error) { 805 806 // For repeats, only consider the base error message, which is 807 // the root error that repeats (the full error often contains 808 // different specific values, e.g., local port numbers, but 809 // the same repeating root). 810 // Assumes error format of errors.Trace. 811 repetitionMessage := err.Error() 812 index := strings.LastIndex(repetitionMessage, ": ") 813 if index != -1 { 814 repetitionMessage = repetitionMessage[index+2:] 815 } 816 817 outputRepetitiveNotice( 818 "LocalProxyError-"+proxyType, repetitionMessage, 1, 819 "LocalProxyError", noticeIsDiagnostic, 820 "message", err.Error()) 821 } 822 823 // NoticeBuildInfo reports build version info. 824 func NoticeBuildInfo() { 825 singletonNoticeLogger.outputNotice( 826 "BuildInfo", noticeIsDiagnostic, 827 "buildInfo", buildinfo.GetBuildInfo()) 828 } 829 830 // NoticeExiting indicates that tunnel-core is exiting imminently. 831 func NoticeExiting() { 832 singletonNoticeLogger.outputNotice( 833 "Exiting", 0) 834 } 835 836 // NoticeRemoteServerListResourceDownloadedBytes reports remote server list download progress. 837 func NoticeRemoteServerListResourceDownloadedBytes(url string, bytes int64, duration time.Duration) { 838 if !GetEmitNetworkParameters() { 839 url = "[redacted]" 840 } 841 singletonNoticeLogger.outputNotice( 842 "RemoteServerListResourceDownloadedBytes", noticeIsDiagnostic, 843 "url", url, 844 "bytes", bytes, 845 "duration", duration.String()) 846 } 847 848 // NoticeRemoteServerListResourceDownloaded indicates that a remote server list download 849 // completed successfully. 850 func NoticeRemoteServerListResourceDownloaded(url string) { 851 if !GetEmitNetworkParameters() { 852 url = "[redacted]" 853 } 854 singletonNoticeLogger.outputNotice( 855 "RemoteServerListResourceDownloaded", noticeIsDiagnostic, 856 "url", url) 857 } 858 859 // NoticeSLOKSeeded indicates that the SLOK with the specified ID was received from 860 // the Psiphon server. The "duplicate" flags indicates whether the SLOK was previously known. 861 func NoticeSLOKSeeded(slokID string, duplicate bool) { 862 singletonNoticeLogger.outputNotice( 863 "SLOKSeeded", noticeIsDiagnostic, 864 "slokID", slokID, 865 "duplicate", duplicate) 866 } 867 868 // NoticeServerTimestamp reports server side timestamp as seen in the handshake. 869 func NoticeServerTimestamp(diagnosticID string, timestamp string) { 870 singletonNoticeLogger.outputNotice( 871 "ServerTimestamp", 0, 872 "diagnosticID", diagnosticID, 873 "timestamp", timestamp) 874 } 875 876 // NoticeActiveAuthorizationIDs reports the authorizations the server has accepted. 877 // Each ID is a base64-encoded accesscontrol.Authorization.ID value. 878 func NoticeActiveAuthorizationIDs(diagnosticID string, activeAuthorizationIDs []string) { 879 880 // Never emit 'null' instead of empty list 881 if activeAuthorizationIDs == nil { 882 activeAuthorizationIDs = []string{} 883 } 884 885 singletonNoticeLogger.outputNotice( 886 "ActiveAuthorizationIDs", 0, 887 "diagnosticID", diagnosticID, 888 "IDs", activeAuthorizationIDs) 889 } 890 891 // NoticeTrafficRateLimits reports the tunnel traffic rate limits in place for 892 // this client, as reported by the server at the start of the tunnel. Values 893 // of 0 indicate no limit. Values of -1 indicate that the server did not 894 // report rate limits. 895 // 896 // Limitation: any rate limit changes during the lifetime of the tunnel are 897 // not reported. 898 func NoticeTrafficRateLimits( 899 diagnosticID string, upstreamBytesPerSecond, downstreamBytesPerSecond int64) { 900 901 singletonNoticeLogger.outputNotice( 902 "TrafficRateLimits", 0, 903 "diagnosticID", diagnosticID, 904 "upstreamBytesPerSecond", upstreamBytesPerSecond, 905 "downstreamBytesPerSecond", downstreamBytesPerSecond) 906 } 907 908 func NoticeBindToDevice(deviceInfo string) { 909 outputRepetitiveNotice( 910 "BindToDevice", deviceInfo, 0, 911 "BindToDevice", 0, "deviceInfo", deviceInfo) 912 } 913 914 func NoticeNetworkID(networkID string) { 915 outputRepetitiveNotice( 916 "NetworkID", networkID, 0, 917 "NetworkID", 0, "ID", networkID) 918 } 919 920 func NoticeLivenessTest(diagnosticID string, metrics *livenessTestMetrics, success bool) { 921 if GetEmitNetworkParameters() { 922 singletonNoticeLogger.outputNotice( 923 "LivenessTest", noticeIsDiagnostic, 924 "diagnosticID", diagnosticID, 925 "metrics", metrics, 926 "success", success) 927 } 928 } 929 930 func NoticePruneServerEntry(serverEntryTag string) { 931 singletonNoticeLogger.outputNotice( 932 "PruneServerEntry", noticeIsDiagnostic, 933 "serverEntryTag", serverEntryTag) 934 } 935 936 // NoticeEstablishTunnelTimeout reports that the configured EstablishTunnelTimeout 937 // duration was exceeded. 938 func NoticeEstablishTunnelTimeout(timeout time.Duration) { 939 singletonNoticeLogger.outputNotice( 940 "EstablishTunnelTimeout", 0, 941 "timeout", timeout.String()) 942 } 943 944 func NoticeFragmentor(diagnosticID string, message string) { 945 if GetEmitNetworkParameters() { 946 singletonNoticeLogger.outputNotice( 947 "Fragmentor", noticeIsDiagnostic, 948 "diagnosticID", diagnosticID, 949 "message", message) 950 } 951 } 952 953 // NoticeApplicationParameters reports application parameters. 954 func NoticeApplicationParameters(keyValues parameters.KeyValues) { 955 956 // Never emit 'null' instead of empty object 957 if keyValues == nil { 958 keyValues = parameters.KeyValues{} 959 } 960 961 outputRepetitiveNotice( 962 "ApplicationParameters", fmt.Sprintf("%+v", keyValues), 0, 963 "ApplicationParameters", 0, 964 "parameters", keyValues) 965 } 966 967 // NoticeServerAlert reports server alerts. Each distinct server alert is 968 // reported at most once per session. 969 func NoticeServerAlert(alert protocol.AlertRequest) { 970 971 // Never emit 'null' instead of empty list 972 actionURLs := alert.ActionURLs 973 if actionURLs == nil { 974 actionURLs = []string{} 975 } 976 977 // This key ensures that each distinct server alert will appear, not repeat, 978 // and not interfere with other alerts appearing. 979 repetitionKey := fmt.Sprintf("ServerAlert-%+v", alert) 980 outputRepetitiveNotice( 981 repetitionKey, "", 0, 982 "ServerAlert", 0, 983 "reason", alert.Reason, 984 "subject", alert.Subject, 985 "actionURLs", actionURLs) 986 } 987 988 // NoticeBursts reports tunnel data transfer burst metrics. 989 func NoticeBursts(diagnosticID string, burstMetrics common.LogFields) { 990 if GetEmitNetworkParameters() { 991 singletonNoticeLogger.outputNotice( 992 "Bursts", noticeIsDiagnostic, 993 append([]interface{}{"diagnosticID", diagnosticID}, listCommonFields(burstMetrics)...)...) 994 } 995 } 996 997 // NoticeHoldOffTunnel reports tunnel hold-offs. 998 func NoticeHoldOffTunnel(diagnosticID string, duration time.Duration) { 999 if GetEmitNetworkParameters() { 1000 singletonNoticeLogger.outputNotice( 1001 "HoldOffTunnel", noticeIsDiagnostic, 1002 "diagnosticID", diagnosticID, 1003 "duration", duration.String()) 1004 } 1005 } 1006 1007 // NoticeSkipServerEntry reports a reason for skipping a server entry when 1008 // preparing dial parameters. To avoid log noise, the server entry 1009 // diagnosticID is not emitted and each reason is reported at most once per 1010 // session. 1011 func NoticeSkipServerEntry(format string, args ...interface{}) { 1012 reason := fmt.Sprintf(format, args...) 1013 repetitionKey := fmt.Sprintf("SkipServerEntryReason-%+v", reason) 1014 outputRepetitiveNotice( 1015 repetitionKey, "", 0, 1016 "SkipServerEntry", 0, "reason", reason) 1017 } 1018 1019 type repetitiveNoticeState struct { 1020 message string 1021 repeats int 1022 } 1023 1024 var repetitiveNoticeMutex sync.Mutex 1025 var repetitiveNoticeStates = make(map[string]*repetitiveNoticeState) 1026 1027 // outputRepetitiveNotice conditionally outputs a notice. Used for noticies which 1028 // often repeat in noisy bursts. For a repeat limit of N, the notice is emitted 1029 // with a "repeats" count on consecutive repeats up to the limit and then suppressed 1030 // until the repetitionMessage differs. 1031 func outputRepetitiveNotice( 1032 repetitionKey, repetitionMessage string, repeatLimit int, 1033 noticeType string, noticeFlags uint32, args ...interface{}) { 1034 1035 repetitiveNoticeMutex.Lock() 1036 defer repetitiveNoticeMutex.Unlock() 1037 1038 state, keyFound := repetitiveNoticeStates[repetitionKey] 1039 if !keyFound { 1040 state = &repetitiveNoticeState{message: repetitionMessage} 1041 repetitiveNoticeStates[repetitionKey] = state 1042 } 1043 1044 emit := true 1045 if keyFound { 1046 if repetitionMessage != state.message { 1047 state.message = repetitionMessage 1048 state.repeats = 0 1049 } else { 1050 state.repeats += 1 1051 if state.repeats > repeatLimit { 1052 emit = false 1053 } 1054 } 1055 } 1056 1057 if emit { 1058 if state.repeats > 0 { 1059 args = append(args, "repeats", state.repeats) 1060 } 1061 singletonNoticeLogger.outputNotice( 1062 noticeType, noticeFlags, 1063 args...) 1064 } 1065 } 1066 1067 // ResetRepetitiveNotices resets the repetitive notice state, so 1068 // the next instance of any notice will not be supressed. 1069 func ResetRepetitiveNotices() { 1070 repetitiveNoticeMutex.Lock() 1071 defer repetitiveNoticeMutex.Unlock() 1072 1073 repetitiveNoticeStates = make(map[string]*repetitiveNoticeState) 1074 } 1075 1076 type noticeObject struct { 1077 NoticeType string `json:"noticeType"` 1078 Data json.RawMessage `json:"data"` 1079 Timestamp string `json:"timestamp"` 1080 } 1081 1082 // GetNotice receives a JSON encoded object and attempts to parse it as a Notice. 1083 // The type is returned as a string and the payload as a generic map. 1084 func GetNotice(notice []byte) ( 1085 noticeType string, payload map[string]interface{}, err error) { 1086 1087 var object noticeObject 1088 err = json.Unmarshal(notice, &object) 1089 if err != nil { 1090 return "", nil, errors.Trace(err) 1091 } 1092 1093 var data interface{} 1094 err = json.Unmarshal(object.Data, &data) 1095 if err != nil { 1096 return "", nil, errors.Trace(err) 1097 } 1098 1099 dataValue, ok := data.(map[string]interface{}) 1100 if !ok { 1101 return "", nil, errors.TraceNew("invalid data value") 1102 } 1103 1104 return object.NoticeType, dataValue, nil 1105 } 1106 1107 // NoticeReceiver consumes a notice input stream and invokes a callback function 1108 // for each discrete JSON notice object byte sequence. 1109 type NoticeReceiver struct { 1110 mutex sync.Mutex 1111 buffer []byte 1112 callback func([]byte) 1113 } 1114 1115 // NewNoticeReceiver initializes a new NoticeReceiver 1116 func NewNoticeReceiver(callback func([]byte)) *NoticeReceiver { 1117 return &NoticeReceiver{callback: callback} 1118 } 1119 1120 // Write implements io.Writer. 1121 func (receiver *NoticeReceiver) Write(p []byte) (n int, err error) { 1122 receiver.mutex.Lock() 1123 defer receiver.mutex.Unlock() 1124 1125 receiver.buffer = append(receiver.buffer, p...) 1126 1127 index := bytes.Index(receiver.buffer, []byte("\n")) 1128 if index == -1 { 1129 return len(p), nil 1130 } 1131 1132 notice := receiver.buffer[:index] 1133 1134 receiver.callback(notice) 1135 1136 if index == len(receiver.buffer)-1 { 1137 receiver.buffer = receiver.buffer[0:0] 1138 } else { 1139 receiver.buffer = receiver.buffer[index+1:] 1140 } 1141 1142 return len(p), nil 1143 } 1144 1145 // NewNoticeConsoleRewriter consumes JSON-format notice input and parses each 1146 // notice and rewrites in a more human-readable format more suitable for 1147 // console output. The data payload field is left as JSON. 1148 func NewNoticeConsoleRewriter(writer io.Writer) *NoticeReceiver { 1149 return NewNoticeReceiver(func(notice []byte) { 1150 var object noticeObject 1151 _ = json.Unmarshal(notice, &object) 1152 fmt.Fprintf( 1153 writer, 1154 "%s %s %s\n", 1155 object.Timestamp, 1156 object.NoticeType, 1157 string(object.Data)) 1158 }) 1159 } 1160 1161 // NoticeWriter implements io.Writer and emits the contents of Write() calls 1162 // as Notices. This is to transform logger messages, if they can be redirected 1163 // to an io.Writer, to notices. 1164 type NoticeWriter struct { 1165 noticeType string 1166 } 1167 1168 // NewNoticeWriter initializes a new NoticeWriter 1169 func NewNoticeWriter(noticeType string) *NoticeWriter { 1170 return &NoticeWriter{noticeType: noticeType} 1171 } 1172 1173 // Write implements io.Writer. 1174 func (writer *NoticeWriter) Write(p []byte) (n int, err error) { 1175 singletonNoticeLogger.outputNotice( 1176 writer.noticeType, noticeIsDiagnostic, 1177 "message", string(p)) 1178 return len(p), nil 1179 } 1180 1181 // NoticeCommonLogger maps the common.Logger interface to the notice facility. 1182 // This is used to make the notice facility available to other packages that 1183 // don't import the "psiphon" package. 1184 func NoticeCommonLogger() common.Logger { 1185 return &commonLogger{} 1186 } 1187 1188 type commonLogger struct { 1189 } 1190 1191 func (logger *commonLogger) WithTrace() common.LogTrace { 1192 return &commonLogTrace{ 1193 trace: stacktrace.GetParentFunctionName(), 1194 } 1195 } 1196 1197 func (logger *commonLogger) WithTraceFields(fields common.LogFields) common.LogTrace { 1198 return &commonLogTrace{ 1199 trace: stacktrace.GetParentFunctionName(), 1200 fields: fields, 1201 } 1202 } 1203 1204 func (logger *commonLogger) LogMetric(metric string, fields common.LogFields) { 1205 singletonNoticeLogger.outputNotice( 1206 metric, noticeIsDiagnostic, 1207 listCommonFields(fields)...) 1208 } 1209 1210 func listCommonFields(fields common.LogFields) []interface{} { 1211 fieldList := make([]interface{}, 0) 1212 for name, value := range fields { 1213 fieldList = append(fieldList, name, value) 1214 } 1215 return fieldList 1216 } 1217 1218 type commonLogTrace struct { 1219 trace string 1220 fields common.LogFields 1221 } 1222 1223 func (log *commonLogTrace) outputNotice( 1224 noticeType string, args ...interface{}) { 1225 1226 singletonNoticeLogger.outputNotice( 1227 noticeType, noticeIsDiagnostic, 1228 append( 1229 []interface{}{ 1230 "message", fmt.Sprint(args...), 1231 "trace", log.trace}, 1232 listCommonFields(log.fields)...)...) 1233 } 1234 1235 func (log *commonLogTrace) Debug(args ...interface{}) { 1236 // Ignored. 1237 } 1238 1239 func (log *commonLogTrace) Info(args ...interface{}) { 1240 log.outputNotice("Info", args...) 1241 } 1242 1243 func (log *commonLogTrace) Warning(args ...interface{}) { 1244 log.outputNotice("Alert", args...) 1245 } 1246 1247 func (log *commonLogTrace) Error(args ...interface{}) { 1248 log.outputNotice("Error", args...) 1249 }