github.com/astaguna/popon-core@v0.0.0-20231019235610-96e42d76a5ff/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/astaguna/popon-core/psiphon/common" 35 "github.com/astaguna/popon-core/psiphon/common/buildinfo" 36 "github.com/astaguna/popon-core/psiphon/common/errors" 37 "github.com/astaguna/popon-core/psiphon/common/parameters" 38 "github.com/astaguna/popon-core/psiphon/common/protocol" 39 "github.com/astaguna/popon-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.TLSOSSHSNIServerName != "" { 509 args = append(args, "tlsOSSHSNIServerName", dialParams.TLSOSSHSNIServerName) 510 } 511 512 if dialParams.TLSOSSHTransformedSNIServerName { 513 args = append(args, "tlsOSSHTransformedSNIServerName", dialParams.TLSOSSHTransformedSNIServerName) 514 } 515 516 if dialParams.SelectedUserAgent { 517 args = append(args, "userAgent", dialParams.UserAgent) 518 } 519 520 if dialParams.SelectedTLSProfile { 521 args = append(args, "TLSProfile", dialParams.TLSProfile) 522 args = append(args, "TLSVersion", dialParams.GetTLSVersionForMetrics()) 523 } 524 525 // dialParams.ServerEntry.Region is emitted above. 526 527 if dialParams.ServerEntry.LocalSource != "" { 528 args = append(args, "serverEntrySource", dialParams.ServerEntry.LocalSource) 529 } 530 531 localServerEntryTimestamp := common.TruncateTimestampToHour( 532 dialParams.ServerEntry.LocalTimestamp) 533 if localServerEntryTimestamp != "" { 534 args = append(args, "serverEntryTimestamp", localServerEntryTimestamp) 535 } 536 537 if dialParams.DialPortNumber != "" { 538 args = append(args, "dialPortNumber", dialParams.DialPortNumber) 539 } 540 541 if dialParams.QUICVersion != "" { 542 args = append(args, "QUICVersion", dialParams.QUICVersion) 543 } 544 545 if dialParams.QUICDialSNIAddress != "" { 546 args = append(args, "QUICDialSNIAddress", dialParams.QUICDialSNIAddress) 547 } 548 549 if dialParams.QUICDisablePathMTUDiscovery { 550 args = append(args, "QUICDisableClientPathMTUDiscovery", dialParams.QUICDisablePathMTUDiscovery) 551 } 552 553 if dialParams.DialDuration > 0 { 554 args = append(args, "dialDuration", dialParams.DialDuration) 555 } 556 557 if dialParams.NetworkLatencyMultiplier != 0.0 { 558 args = append(args, "networkLatencyMultiplier", dialParams.NetworkLatencyMultiplier) 559 } 560 561 if dialParams.ConjureTransport != "" { 562 args = append(args, "conjureTransport", dialParams.ConjureTransport) 563 } 564 565 if dialParams.ResolveParameters != nil { 566 567 if dialParams.ResolveParameters.PreresolvedIPAddress != "" { 568 nonredacted := common.EscapeRedactIPAddressString(dialParams.ResolveParameters.PreresolvedIPAddress) 569 args = append(args, "DNSPreresolved", nonredacted) 570 571 } else { 572 573 // See dialParams.ResolveParameters comment in getBaseAPIParameters. 574 575 if dialParams.ResolveParameters.PreferAlternateDNSServer { 576 nonredacted := common.EscapeRedactIPAddressString(dialParams.ResolveParameters.AlternateDNSServer) 577 args = append(args, "DNSPreferred", nonredacted) 578 } 579 580 if dialParams.ResolveParameters.ProtocolTransformName != "" { 581 args = append(args, "DNSTransform", dialParams.ResolveParameters.ProtocolTransformName) 582 } 583 584 if postDial { 585 args = append(args, "DNSAttempt", dialParams.ResolveParameters.GetFirstAttemptWithAnswer()) 586 } 587 } 588 } 589 590 if dialParams.HTTPTransformerParameters != nil { 591 if dialParams.HTTPTransformerParameters.ProtocolTransformSpec != nil { 592 args = append(args, "HTTPTransform", dialParams.HTTPTransformerParameters.ProtocolTransformName) 593 } 594 } 595 596 if dialParams.OSSHObfuscatorSeedTransformerParameters != nil { 597 if dialParams.OSSHObfuscatorSeedTransformerParameters.TransformSpec != nil { 598 args = append(args, "SeedTransform", dialParams.OSSHObfuscatorSeedTransformerParameters.TransformName) 599 } 600 } 601 602 if dialParams.ObfuscatedQUICNonceTransformerParameters != nil { 603 if dialParams.ObfuscatedQUICNonceTransformerParameters.TransformSpec != nil { 604 args = append(args, "SeedTransform", dialParams.ObfuscatedQUICNonceTransformerParameters.TransformName) 605 } 606 } 607 608 if dialParams.OSSHPrefixSpec != nil { 609 if dialParams.OSSHPrefixSpec.Spec != nil { 610 args = append(args, "OSSHPrefix", dialParams.OSSHPrefixSpec.Name) 611 } 612 } 613 614 if dialParams.DialConnMetrics != nil { 615 metrics := dialParams.DialConnMetrics.GetMetrics() 616 for name, value := range metrics { 617 args = append(args, name, value) 618 } 619 } 620 621 if dialParams.DialConnNoticeMetrics != nil { 622 metrics := dialParams.DialConnNoticeMetrics.GetNoticeMetrics() 623 for name, value := range metrics { 624 args = append(args, name, value) 625 } 626 } 627 628 if dialParams.ObfuscatedSSHConnMetrics != nil { 629 metrics := dialParams.ObfuscatedSSHConnMetrics.GetMetrics() 630 for name, value := range metrics { 631 args = append(args, name, value) 632 } 633 } 634 } 635 636 singletonNoticeLogger.outputNotice( 637 noticeType, noticeIsDiagnostic, 638 args...) 639 } 640 641 // NoticeConnectingServer reports parameters and details for a single connection attempt 642 func NoticeConnectingServer(dialParams *DialParameters) { 643 noticeWithDialParameters("ConnectingServer", dialParams, false) 644 } 645 646 // NoticeConnectedServer reports parameters and details for a single successful connection 647 func NoticeConnectedServer(dialParams *DialParameters) { 648 noticeWithDialParameters("ConnectedServer", dialParams, true) 649 } 650 651 // NoticeRequestingTactics reports parameters and details for a tactics request attempt 652 func NoticeRequestingTactics(dialParams *DialParameters) { 653 noticeWithDialParameters("RequestingTactics", dialParams, false) 654 } 655 656 // NoticeRequestedTactics reports parameters and details for a successful tactics request 657 func NoticeRequestedTactics(dialParams *DialParameters) { 658 noticeWithDialParameters("RequestedTactics", dialParams, true) 659 } 660 661 // NoticeActiveTunnel is a successful connection that is used as an active tunnel for port forwarding 662 func NoticeActiveTunnel(diagnosticID, protocol string, isTCS bool) { 663 singletonNoticeLogger.outputNotice( 664 "ActiveTunnel", noticeIsDiagnostic, 665 "diagnosticID", diagnosticID, 666 "protocol", protocol, 667 "isTCS", isTCS) 668 } 669 670 // NoticeSocksProxyPortInUse is a failure to use the configured LocalSocksProxyPort 671 func NoticeSocksProxyPortInUse(port int) { 672 singletonNoticeLogger.outputNotice( 673 "SocksProxyPortInUse", 0, 674 "port", port) 675 } 676 677 // NoticeListeningSocksProxyPort is the selected port for the listening local SOCKS proxy 678 func NoticeListeningSocksProxyPort(port int) { 679 singletonNoticeLogger.outputNotice( 680 "ListeningSocksProxyPort", 0, 681 "port", port) 682 } 683 684 // NoticeHttpProxyPortInUse is a failure to use the configured LocalHttpProxyPort 685 func NoticeHttpProxyPortInUse(port int) { 686 singletonNoticeLogger.outputNotice( 687 "HttpProxyPortInUse", 0, 688 "port", port) 689 } 690 691 // NoticeListeningHttpProxyPort is the selected port for the listening local HTTP proxy 692 func NoticeListeningHttpProxyPort(port int) { 693 singletonNoticeLogger.outputNotice( 694 "ListeningHttpProxyPort", 0, 695 "port", port) 696 } 697 698 // NoticeClientUpgradeAvailable is an available client upgrade, as per the handshake. The 699 // client should download and install an upgrade. 700 func NoticeClientUpgradeAvailable(version string) { 701 singletonNoticeLogger.outputNotice( 702 "ClientUpgradeAvailable", 0, 703 "version", version) 704 } 705 706 // NoticeClientIsLatestVersion reports that an upgrade check was made and the client 707 // is already the latest version. availableVersion is the version available for download, 708 // if known. 709 func NoticeClientIsLatestVersion(availableVersion string) { 710 singletonNoticeLogger.outputNotice( 711 "ClientIsLatestVersion", 0, 712 "availableVersion", availableVersion) 713 } 714 715 // NoticeHomepages emits a series of NoticeHomepage, the sponsor homepages. The client 716 // should display the sponsor's homepages. 717 func NoticeHomepages(urls []string) { 718 for i, url := range urls { 719 noticeFlags := uint32(noticeIsHomepage) 720 if i == 0 { 721 noticeFlags |= noticeClearHomepages 722 } 723 if i == len(urls)-1 { 724 noticeFlags |= noticeSyncHomepages 725 } 726 singletonNoticeLogger.outputNotice( 727 "Homepage", noticeFlags, 728 "url", url) 729 } 730 } 731 732 // NoticeClientRegion is the client's region, as determined by the server and 733 // reported to the client in the handshake. 734 func NoticeClientRegion(region string) { 735 singletonNoticeLogger.outputNotice( 736 "ClientRegion", 0, 737 "region", region) 738 } 739 740 // NoticeClientAddress is the client's public network address, the IP address 741 // and port, as seen by the server and reported to the client in the 742 // handshake. 743 // 744 // Note: "address" should remain private and not included in diagnostics logs. 745 func NoticeClientAddress(address string) { 746 singletonNoticeLogger.outputNotice( 747 "ClientAddress", noticeSkipRedaction, 748 "address", address) 749 } 750 751 // NoticeTunnels is how many active tunnels are available. The client should use this to 752 // determine connecting/unexpected disconnect state transitions. When count is 0, the core is 753 // disconnected; when count > 1, the core is connected. 754 func NoticeTunnels(count int) { 755 singletonNoticeLogger.outputNotice( 756 "Tunnels", 0, 757 "count", count) 758 } 759 760 // NoticeSessionId is the session ID used across all tunnels established by the controller. 761 func NoticeSessionId(sessionId string) { 762 singletonNoticeLogger.outputNotice( 763 "SessionId", noticeIsDiagnostic, 764 "sessionId", sessionId) 765 } 766 767 // NoticeSplitTunnelRegions reports that split tunnel is on for the given country codes. 768 func NoticeSplitTunnelRegions(regions []string) { 769 singletonNoticeLogger.outputNotice( 770 "SplitTunnelRegions", 0, 771 "regions", regions) 772 } 773 774 // NoticeUntunneled indicates than an address has been classified as untunneled and is being 775 // accessed directly. 776 // 777 // Note: "address" should remain private; this notice should only be used for alerting 778 // users, not for diagnostics logs. 779 func NoticeUntunneled(address string) { 780 outputRepetitiveNotice( 781 "Untunneled", address, 0, 782 "Untunneled", noticeSkipRedaction, "address", address) 783 784 } 785 786 // NoticeUpstreamProxyError reports an error when connecting to an upstream proxy. The 787 // user may have input, for example, an incorrect address or incorrect credentials. 788 func NoticeUpstreamProxyError(err error) { 789 message := err.Error() 790 outputRepetitiveNotice( 791 "UpstreamProxyError", message, 0, 792 "UpstreamProxyError", 0, 793 "message", message) 794 } 795 796 // NoticeClientUpgradeDownloadedBytes reports client upgrade download progress. 797 func NoticeClientUpgradeDownloadedBytes(bytes int64) { 798 singletonNoticeLogger.outputNotice( 799 "ClientUpgradeDownloadedBytes", noticeIsDiagnostic, 800 "bytes", bytes) 801 } 802 803 // NoticeClientUpgradeDownloaded indicates that a client upgrade download 804 // is complete and available at the destination specified. 805 func NoticeClientUpgradeDownloaded(filename string) { 806 singletonNoticeLogger.outputNotice( 807 "ClientUpgradeDownloaded", 0, 808 "filename", filename) 809 } 810 811 // NoticeBytesTransferred reports how many tunneled bytes have been 812 // transferred since the last NoticeBytesTransferred. This is not a diagnostic 813 // notice: the user app has requested this notice with EmitBytesTransferred 814 // for functionality such as traffic display; and this frequent notice is not 815 // intended to be included with feedback. 816 func NoticeBytesTransferred(diagnosticID string, sent, received int64) { 817 singletonNoticeLogger.outputNotice( 818 "BytesTransferred", 0, 819 "diagnosticID", diagnosticID, 820 "sent", sent, 821 "received", received) 822 } 823 824 // NoticeTotalBytesTransferred reports how many tunneled bytes have been 825 // transferred in total up to this point. This is a diagnostic notice. 826 func NoticeTotalBytesTransferred(diagnosticID string, sent, received int64) { 827 singletonNoticeLogger.outputNotice( 828 "TotalBytesTransferred", noticeIsDiagnostic, 829 "diagnosticID", diagnosticID, 830 "sent", sent, 831 "received", received) 832 } 833 834 // NoticeLocalProxyError reports a local proxy error message. Repetitive 835 // errors for a given proxy type are suppressed. 836 func NoticeLocalProxyError(proxyType string, err error) { 837 838 // For repeats, only consider the base error message, which is 839 // the root error that repeats (the full error often contains 840 // different specific values, e.g., local port numbers, but 841 // the same repeating root). 842 // Assumes error format of errors.Trace. 843 repetitionMessage := err.Error() 844 index := strings.LastIndex(repetitionMessage, ": ") 845 if index != -1 { 846 repetitionMessage = repetitionMessage[index+2:] 847 } 848 849 outputRepetitiveNotice( 850 "LocalProxyError-"+proxyType, repetitionMessage, 1, 851 "LocalProxyError", noticeIsDiagnostic, 852 "message", err.Error()) 853 } 854 855 // NoticeBuildInfo reports build version info. 856 func NoticeBuildInfo() { 857 singletonNoticeLogger.outputNotice( 858 "BuildInfo", noticeIsDiagnostic, 859 "buildInfo", buildinfo.GetBuildInfo()) 860 } 861 862 // NoticeExiting indicates that tunnel-core is exiting imminently. 863 func NoticeExiting() { 864 singletonNoticeLogger.outputNotice( 865 "Exiting", 0) 866 } 867 868 // NoticeRemoteServerListResourceDownloadedBytes reports remote server list download progress. 869 func NoticeRemoteServerListResourceDownloadedBytes(url string, bytes int64, duration time.Duration) { 870 if !GetEmitNetworkParameters() { 871 url = "[redacted]" 872 } 873 singletonNoticeLogger.outputNotice( 874 "RemoteServerListResourceDownloadedBytes", noticeIsDiagnostic, 875 "url", url, 876 "bytes", bytes, 877 "duration", duration.String()) 878 } 879 880 // NoticeRemoteServerListResourceDownloaded indicates that a remote server list download 881 // completed successfully. 882 func NoticeRemoteServerListResourceDownloaded(url string) { 883 if !GetEmitNetworkParameters() { 884 url = "[redacted]" 885 } 886 singletonNoticeLogger.outputNotice( 887 "RemoteServerListResourceDownloaded", noticeIsDiagnostic, 888 "url", url) 889 } 890 891 // NoticeSLOKSeeded indicates that the SLOK with the specified ID was received from 892 // the Psiphon server. The "duplicate" flags indicates whether the SLOK was previously known. 893 func NoticeSLOKSeeded(slokID string, duplicate bool) { 894 singletonNoticeLogger.outputNotice( 895 "SLOKSeeded", noticeIsDiagnostic, 896 "slokID", slokID, 897 "duplicate", duplicate) 898 } 899 900 // NoticeServerTimestamp reports server side timestamp as seen in the handshake. 901 func NoticeServerTimestamp(diagnosticID string, timestamp string) { 902 singletonNoticeLogger.outputNotice( 903 "ServerTimestamp", 0, 904 "diagnosticID", diagnosticID, 905 "timestamp", timestamp) 906 } 907 908 // NoticeActiveAuthorizationIDs reports the authorizations the server has accepted. 909 // Each ID is a base64-encoded accesscontrol.Authorization.ID value. 910 func NoticeActiveAuthorizationIDs(diagnosticID string, activeAuthorizationIDs []string) { 911 912 // Never emit 'null' instead of empty list 913 if activeAuthorizationIDs == nil { 914 activeAuthorizationIDs = []string{} 915 } 916 917 singletonNoticeLogger.outputNotice( 918 "ActiveAuthorizationIDs", 0, 919 "diagnosticID", diagnosticID, 920 "IDs", activeAuthorizationIDs) 921 } 922 923 // NoticeTrafficRateLimits reports the tunnel traffic rate limits in place for 924 // this client, as reported by the server at the start of the tunnel. Values 925 // of 0 indicate no limit. Values of -1 indicate that the server did not 926 // report rate limits. 927 // 928 // Limitation: any rate limit changes during the lifetime of the tunnel are 929 // not reported. 930 func NoticeTrafficRateLimits( 931 diagnosticID string, upstreamBytesPerSecond, downstreamBytesPerSecond int64) { 932 933 singletonNoticeLogger.outputNotice( 934 "TrafficRateLimits", 0, 935 "diagnosticID", diagnosticID, 936 "upstreamBytesPerSecond", upstreamBytesPerSecond, 937 "downstreamBytesPerSecond", downstreamBytesPerSecond) 938 } 939 940 func NoticeBindToDevice(deviceInfo string) { 941 outputRepetitiveNotice( 942 "BindToDevice", deviceInfo, 0, 943 "BindToDevice", 0, "deviceInfo", deviceInfo) 944 } 945 946 func NoticeNetworkID(networkID string) { 947 outputRepetitiveNotice( 948 "NetworkID", networkID, 0, 949 "NetworkID", 0, "ID", networkID) 950 } 951 952 func NoticeLivenessTest(diagnosticID string, metrics *livenessTestMetrics, success bool) { 953 if GetEmitNetworkParameters() { 954 singletonNoticeLogger.outputNotice( 955 "LivenessTest", noticeIsDiagnostic, 956 "diagnosticID", diagnosticID, 957 "metrics", metrics, 958 "success", success) 959 } 960 } 961 962 func NoticePruneServerEntry(serverEntryTag string) { 963 singletonNoticeLogger.outputNotice( 964 "PruneServerEntry", noticeIsDiagnostic, 965 "serverEntryTag", serverEntryTag) 966 } 967 968 // NoticeEstablishTunnelTimeout reports that the configured EstablishTunnelTimeout 969 // duration was exceeded. 970 func NoticeEstablishTunnelTimeout(timeout time.Duration) { 971 singletonNoticeLogger.outputNotice( 972 "EstablishTunnelTimeout", 0, 973 "timeout", timeout.String()) 974 } 975 976 func NoticeFragmentor(diagnosticID string, message string) { 977 if GetEmitNetworkParameters() { 978 singletonNoticeLogger.outputNotice( 979 "Fragmentor", noticeIsDiagnostic, 980 "diagnosticID", diagnosticID, 981 "message", message) 982 } 983 } 984 985 // NoticeApplicationParameters reports application parameters. 986 func NoticeApplicationParameters(keyValues parameters.KeyValues) { 987 988 // Never emit 'null' instead of empty object 989 if keyValues == nil { 990 keyValues = parameters.KeyValues{} 991 } 992 993 outputRepetitiveNotice( 994 "ApplicationParameters", fmt.Sprintf("%+v", keyValues), 0, 995 "ApplicationParameters", 0, 996 "parameters", keyValues) 997 } 998 999 // NoticeServerAlert reports server alerts. Each distinct server alert is 1000 // reported at most once per session. 1001 func NoticeServerAlert(alert protocol.AlertRequest) { 1002 1003 // Never emit 'null' instead of empty list 1004 actionURLs := alert.ActionURLs 1005 if actionURLs == nil { 1006 actionURLs = []string{} 1007 } 1008 1009 // This key ensures that each distinct server alert will appear, not repeat, 1010 // and not interfere with other alerts appearing. 1011 repetitionKey := fmt.Sprintf("ServerAlert-%+v", alert) 1012 outputRepetitiveNotice( 1013 repetitionKey, "", 0, 1014 "ServerAlert", 0, 1015 "reason", alert.Reason, 1016 "subject", alert.Subject, 1017 "actionURLs", actionURLs) 1018 } 1019 1020 // NoticeBursts reports tunnel data transfer burst metrics. 1021 func NoticeBursts(diagnosticID string, burstMetrics common.LogFields) { 1022 if GetEmitNetworkParameters() { 1023 singletonNoticeLogger.outputNotice( 1024 "Bursts", noticeIsDiagnostic, 1025 append([]interface{}{"diagnosticID", diagnosticID}, listCommonFields(burstMetrics)...)...) 1026 } 1027 } 1028 1029 // NoticeHoldOffTunnel reports tunnel hold-offs. 1030 func NoticeHoldOffTunnel(diagnosticID string, duration time.Duration) { 1031 if GetEmitNetworkParameters() { 1032 singletonNoticeLogger.outputNotice( 1033 "HoldOffTunnel", noticeIsDiagnostic, 1034 "diagnosticID", diagnosticID, 1035 "duration", duration.String()) 1036 } 1037 } 1038 1039 // NoticeSkipServerEntry reports a reason for skipping a server entry when 1040 // preparing dial parameters. To avoid log noise, the server entry 1041 // diagnosticID is not emitted and each reason is reported at most once per 1042 // session. 1043 func NoticeSkipServerEntry(format string, args ...interface{}) { 1044 reason := fmt.Sprintf(format, args...) 1045 repetitionKey := fmt.Sprintf("SkipServerEntryReason-%+v", reason) 1046 outputRepetitiveNotice( 1047 repetitionKey, "", 0, 1048 "SkipServerEntry", 0, "reason", reason) 1049 } 1050 1051 type repetitiveNoticeState struct { 1052 message string 1053 repeats int 1054 } 1055 1056 var repetitiveNoticeMutex sync.Mutex 1057 var repetitiveNoticeStates = make(map[string]*repetitiveNoticeState) 1058 1059 // outputRepetitiveNotice conditionally outputs a notice. Used for noticies which 1060 // often repeat in noisy bursts. For a repeat limit of N, the notice is emitted 1061 // with a "repeats" count on consecutive repeats up to the limit and then suppressed 1062 // until the repetitionMessage differs. 1063 func outputRepetitiveNotice( 1064 repetitionKey, repetitionMessage string, repeatLimit int, 1065 noticeType string, noticeFlags uint32, args ...interface{}) { 1066 1067 repetitiveNoticeMutex.Lock() 1068 defer repetitiveNoticeMutex.Unlock() 1069 1070 state, keyFound := repetitiveNoticeStates[repetitionKey] 1071 if !keyFound { 1072 state = &repetitiveNoticeState{message: repetitionMessage} 1073 repetitiveNoticeStates[repetitionKey] = state 1074 } 1075 1076 emit := true 1077 if keyFound { 1078 if repetitionMessage != state.message { 1079 state.message = repetitionMessage 1080 state.repeats = 0 1081 } else { 1082 state.repeats += 1 1083 if state.repeats > repeatLimit { 1084 emit = false 1085 } 1086 } 1087 } 1088 1089 if emit { 1090 if state.repeats > 0 { 1091 args = append(args, "repeats", state.repeats) 1092 } 1093 singletonNoticeLogger.outputNotice( 1094 noticeType, noticeFlags, 1095 args...) 1096 } 1097 } 1098 1099 // ResetRepetitiveNotices resets the repetitive notice state, so 1100 // the next instance of any notice will not be supressed. 1101 func ResetRepetitiveNotices() { 1102 repetitiveNoticeMutex.Lock() 1103 defer repetitiveNoticeMutex.Unlock() 1104 1105 repetitiveNoticeStates = make(map[string]*repetitiveNoticeState) 1106 } 1107 1108 type noticeObject struct { 1109 NoticeType string `json:"noticeType"` 1110 Data json.RawMessage `json:"data"` 1111 Timestamp string `json:"timestamp"` 1112 } 1113 1114 // GetNotice receives a JSON encoded object and attempts to parse it as a Notice. 1115 // The type is returned as a string and the payload as a generic map. 1116 func GetNotice(notice []byte) ( 1117 noticeType string, payload map[string]interface{}, err error) { 1118 1119 var object noticeObject 1120 err = json.Unmarshal(notice, &object) 1121 if err != nil { 1122 return "", nil, errors.Trace(err) 1123 } 1124 1125 var data interface{} 1126 err = json.Unmarshal(object.Data, &data) 1127 if err != nil { 1128 return "", nil, errors.Trace(err) 1129 } 1130 1131 dataValue, ok := data.(map[string]interface{}) 1132 if !ok { 1133 return "", nil, errors.TraceNew("invalid data value") 1134 } 1135 1136 return object.NoticeType, dataValue, nil 1137 } 1138 1139 // NoticeReceiver consumes a notice input stream and invokes a callback function 1140 // for each discrete JSON notice object byte sequence. 1141 type NoticeReceiver struct { 1142 mutex sync.Mutex 1143 buffer []byte 1144 callback func([]byte) 1145 } 1146 1147 // NewNoticeReceiver initializes a new NoticeReceiver 1148 func NewNoticeReceiver(callback func([]byte)) *NoticeReceiver { 1149 return &NoticeReceiver{callback: callback} 1150 } 1151 1152 // Write implements io.Writer. 1153 func (receiver *NoticeReceiver) Write(p []byte) (n int, err error) { 1154 receiver.mutex.Lock() 1155 defer receiver.mutex.Unlock() 1156 1157 receiver.buffer = append(receiver.buffer, p...) 1158 1159 index := bytes.Index(receiver.buffer, []byte("\n")) 1160 if index == -1 { 1161 return len(p), nil 1162 } 1163 1164 notice := receiver.buffer[:index] 1165 1166 receiver.callback(notice) 1167 1168 if index == len(receiver.buffer)-1 { 1169 receiver.buffer = receiver.buffer[0:0] 1170 } else { 1171 receiver.buffer = receiver.buffer[index+1:] 1172 } 1173 1174 return len(p), nil 1175 } 1176 1177 // NewNoticeConsoleRewriter consumes JSON-format notice input and parses each 1178 // notice and rewrites in a more human-readable format more suitable for 1179 // console output. The data payload field is left as JSON. 1180 func NewNoticeConsoleRewriter(writer io.Writer) *NoticeReceiver { 1181 return NewNoticeReceiver(func(notice []byte) { 1182 var object noticeObject 1183 _ = json.Unmarshal(notice, &object) 1184 fmt.Fprintf( 1185 writer, 1186 "%s %s %s\n", 1187 object.Timestamp, 1188 object.NoticeType, 1189 string(object.Data)) 1190 }) 1191 } 1192 1193 // NoticeWriter implements io.Writer and emits the contents of Write() calls 1194 // as Notices. This is to transform logger messages, if they can be redirected 1195 // to an io.Writer, to notices. 1196 type NoticeWriter struct { 1197 noticeType string 1198 } 1199 1200 // NewNoticeWriter initializes a new NoticeWriter 1201 func NewNoticeWriter(noticeType string) *NoticeWriter { 1202 return &NoticeWriter{noticeType: noticeType} 1203 } 1204 1205 // Write implements io.Writer. 1206 func (writer *NoticeWriter) Write(p []byte) (n int, err error) { 1207 singletonNoticeLogger.outputNotice( 1208 writer.noticeType, noticeIsDiagnostic, 1209 "message", string(p)) 1210 return len(p), nil 1211 } 1212 1213 // NoticeCommonLogger maps the common.Logger interface to the notice facility. 1214 // This is used to make the notice facility available to other packages that 1215 // don't import the "psiphon" package. 1216 func NoticeCommonLogger() common.Logger { 1217 return &commonLogger{} 1218 } 1219 1220 type commonLogger struct { 1221 } 1222 1223 func (logger *commonLogger) WithTrace() common.LogTrace { 1224 return &commonLogTrace{ 1225 trace: stacktrace.GetParentFunctionName(), 1226 } 1227 } 1228 1229 func (logger *commonLogger) WithTraceFields(fields common.LogFields) common.LogTrace { 1230 return &commonLogTrace{ 1231 trace: stacktrace.GetParentFunctionName(), 1232 fields: fields, 1233 } 1234 } 1235 1236 func (logger *commonLogger) LogMetric(metric string, fields common.LogFields) { 1237 singletonNoticeLogger.outputNotice( 1238 metric, noticeIsDiagnostic, 1239 listCommonFields(fields)...) 1240 } 1241 1242 func listCommonFields(fields common.LogFields) []interface{} { 1243 fieldList := make([]interface{}, 0) 1244 for name, value := range fields { 1245 fieldList = append(fieldList, name, value) 1246 } 1247 return fieldList 1248 } 1249 1250 type commonLogTrace struct { 1251 trace string 1252 fields common.LogFields 1253 } 1254 1255 func (log *commonLogTrace) outputNotice( 1256 noticeType string, args ...interface{}) { 1257 1258 singletonNoticeLogger.outputNotice( 1259 noticeType, noticeIsDiagnostic, 1260 append( 1261 []interface{}{ 1262 "message", fmt.Sprint(args...), 1263 "trace", log.trace}, 1264 listCommonFields(log.fields)...)...) 1265 } 1266 1267 func (log *commonLogTrace) Debug(args ...interface{}) { 1268 // Ignored. 1269 } 1270 1271 func (log *commonLogTrace) Info(args ...interface{}) { 1272 log.outputNotice("Info", args...) 1273 } 1274 1275 func (log *commonLogTrace) Warning(args ...interface{}) { 1276 log.outputNotice("Alert", args...) 1277 } 1278 1279 func (log *commonLogTrace) Error(args ...interface{}) { 1280 log.outputNotice("Error", args...) 1281 }