notice.go 32 KB

1234567891011121314151617181920212223242526272829303132333435363738394041424344454647484950515253545556575859606162636465666768697071727374757677787980818283848586878889909192939495969798991001011021031041051061071081091101111121131141151161171181191201211221231241251261271281291301311321331341351361371381391401411421431441451461471481491501511521531541551561571581591601611621631641651661671681691701711721731741751761771781791801811821831841851861871881891901911921931941951961971981992002012022032042052062072082092102112122132142152162172182192202212222232242252262272282292302312322332342352362372382392402412422432442452462472482492502512522532542552562572582592602612622632642652662672682692702712722732742752762772782792802812822832842852862872882892902912922932942952962972982993003013023033043053063073083093103113123133143153163173183193203213223233243253263273283293303313323333343353363373383393403413423433443453463473483493503513523533543553563573583593603613623633643653663673683693703713723733743753763773783793803813823833843853863873883893903913923933943953963973983994004014024034044054064074084094104114124134144154164174184194204214224234244254264274284294304314324334344354364374384394404414424434444454464474484494504514524534544554564574584594604614624634644654664674684694704714724734744754764774784794804814824834844854864874884894904914924934944954964974984995005015025035045055065075085095105115125135145155165175185195205215225235245255265275285295305315325335345355365375385395405415425435445455465475485495505515525535545555565575585595605615625635645655665675685695705715725735745755765775785795805815825835845855865875885895905915925935945955965975985996006016026036046056066076086096106116126136146156166176186196206216226236246256266276286296306316326336346356366376386396406416426436446456466476486496506516526536546556566576586596606616626636646656666676686696706716726736746756766776786796806816826836846856866876886896906916926936946956966976986997007017027037047057067077087097107117127137147157167177187197207217227237247257267277287297307317327337347357367377387397407417427437447457467477487497507517527537547557567577587597607617627637647657667677687697707717727737747757767777787797807817827837847857867877887897907917927937947957967977987998008018028038048058068078088098108118128138148158168178188198208218228238248258268278288298308318328338348358368378388398408418428438448458468478488498508518528538548558568578588598608618628638648658668678688698708718728738748758768778788798808818828838848858868878888898908918928938948958968978988999009019029039049059069079089099109119129139149159169179189199209219229239249259269279289299309319329339349359369379389399409419429439449459469479489499509519529539549559569579589599609619629639649659669679689699709719729739749759769779789799809819829839849859869879889899909919929939949959969979989991000100110021003100410051006100710081009101010111012101310141015101610171018101910201021102210231024102510261027102810291030103110321033103410351036103710381039104010411042104310441045104610471048104910501051105210531054105510561057
  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. package psiphon
  20. import (
  21. "bytes"
  22. "encoding/json"
  23. "fmt"
  24. "io"
  25. "os"
  26. "sort"
  27. "strings"
  28. "sync"
  29. "sync/atomic"
  30. "time"
  31. "github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common"
  32. "github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common/buildinfo"
  33. )
  34. type noticeLogger struct {
  35. emitDiagnostics int32
  36. emitNetworkParameters int32
  37. mutex sync.Mutex
  38. writer io.Writer
  39. homepageFilename string
  40. homepageFile *os.File
  41. rotatingFilename string
  42. rotatingOlderFilename string
  43. rotatingFile *os.File
  44. rotatingFileSize int64
  45. rotatingCurrentFileSize int64
  46. rotatingSyncFrequency int
  47. rotatingCurrentNoticeCount int
  48. }
  49. var singletonNoticeLogger = noticeLogger{
  50. writer: os.Stderr,
  51. }
  52. // SetEmitDiagnosticNotices toggles whether diagnostic notices are emitted;
  53. // and whether to include circumvention network parameters in diagnostics.
  54. //
  55. // Diagnostic notices contain potentially sensitive user information; and
  56. // sensitive circumvention network parameters, when enabled. Only enable this
  57. // in environments where notices are handled securely (for example, don't
  58. // include these notices in log files which users could post to public
  59. // forums).
  60. func SetEmitDiagnosticNotices(
  61. emitDiagnostics bool, emitNetworkParameters bool) {
  62. if emitDiagnostics {
  63. atomic.StoreInt32(&singletonNoticeLogger.emitDiagnostics, 1)
  64. } else {
  65. atomic.StoreInt32(&singletonNoticeLogger.emitDiagnostics, 0)
  66. }
  67. if emitNetworkParameters {
  68. atomic.StoreInt32(&singletonNoticeLogger.emitNetworkParameters, 1)
  69. } else {
  70. atomic.StoreInt32(&singletonNoticeLogger.emitNetworkParameters, 0)
  71. }
  72. }
  73. // GetEmitDiagnosticNotices returns the current state
  74. // of emitting diagnostic notices.
  75. func GetEmitDiagnosticNotices() bool {
  76. return atomic.LoadInt32(&singletonNoticeLogger.emitDiagnostics) == 1
  77. }
  78. // GetEmitNetworkParameters returns the current state
  79. // of emitting network parameters.
  80. func GetEmitNetworkParameters() bool {
  81. return atomic.LoadInt32(&singletonNoticeLogger.emitNetworkParameters) == 1
  82. }
  83. // SetNoticeWriter sets a target writer to receive notices. By default,
  84. // notices are written to stderr. Notices are newline delimited.
  85. //
  86. // writer specifies an alternate io.Writer where notices are to be written.
  87. //
  88. // Notices are encoded in JSON. Here's an example:
  89. //
  90. // {"data":{"message":"shutdown operate tunnel"},"noticeType":"Info","showUser":false,"timestamp":"2006-01-02T15:04:05.999999999Z07:00"}
  91. //
  92. // All notices have the following fields:
  93. // - "noticeType": the type of notice, which indicates the meaning of the notice along with what's in the data payload.
  94. // - "data": additional structured data payload. For example, the "ListeningSocksProxyPort" notice type has a "port" integer
  95. // data in its payload.
  96. // - "showUser": whether the information should be displayed to the user. For example, this flag is set for "SocksProxyPortInUse"
  97. // as the user should be informed that their configured choice of listening port could not be used. Core clients should
  98. // anticipate that the core will add additional "showUser"=true notices in the future and emit at least the raw notice.
  99. // - "timestamp": UTC timezone, RFC3339Milli format timestamp for notice event
  100. //
  101. // See the Notice* functions for details on each notice meaning and payload.
  102. //
  103. func SetNoticeWriter(writer io.Writer) {
  104. singletonNoticeLogger.mutex.Lock()
  105. defer singletonNoticeLogger.mutex.Unlock()
  106. singletonNoticeLogger.writer = writer
  107. }
  108. // SetNoticeFiles configures files for notice writing.
  109. //
  110. // - When homepageFilename is not "", homepages are written to the specified file
  111. // and omitted from the writer. The file may be read after the Tunnels notice
  112. // with count of 1. The file should be opened read-only for reading.
  113. //
  114. // - When rotatingFilename is not "", all notices are are written to the specified
  115. // file. Diagnostic notices are omitted from the writer. The file is rotated
  116. // when its size exceeds rotatingFileSize. One rotated older file,
  117. // <rotatingFilename>.1, is retained. The files may be read at any time; and
  118. // should be opened read-only for reading. rotatingSyncFrequency specifies how
  119. // many notices are written before syncing the file.
  120. // If either rotatingFileSize or rotatingSyncFrequency are <= 0, default values
  121. // are used.
  122. //
  123. // - If an error occurs when writing to a file, an InternalError notice is emitted to
  124. // the writer.
  125. //
  126. // SetNoticeFiles closes open homepage or rotating files before applying the new
  127. // configuration.
  128. //
  129. func SetNoticeFiles(
  130. homepageFilename string,
  131. rotatingFilename string,
  132. rotatingFileSize int,
  133. rotatingSyncFrequency int) error {
  134. singletonNoticeLogger.mutex.Lock()
  135. defer singletonNoticeLogger.mutex.Unlock()
  136. if homepageFilename != "" {
  137. var err error
  138. if singletonNoticeLogger.homepageFile != nil {
  139. singletonNoticeLogger.homepageFile.Close()
  140. }
  141. singletonNoticeLogger.homepageFile, err = os.OpenFile(
  142. homepageFilename, os.O_CREATE|os.O_TRUNC|os.O_WRONLY, 0600)
  143. if err != nil {
  144. return common.ContextError(err)
  145. }
  146. }
  147. if rotatingFilename != "" {
  148. var err error
  149. if singletonNoticeLogger.rotatingFile != nil {
  150. singletonNoticeLogger.rotatingFile.Close()
  151. }
  152. singletonNoticeLogger.rotatingFile, err = os.OpenFile(
  153. rotatingFilename, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0600)
  154. if err != nil {
  155. return common.ContextError(err)
  156. }
  157. fileInfo, err := singletonNoticeLogger.rotatingFile.Stat()
  158. if err != nil {
  159. return common.ContextError(err)
  160. }
  161. if rotatingFileSize <= 0 {
  162. rotatingFileSize = 1 << 20
  163. }
  164. if rotatingSyncFrequency <= 0 {
  165. rotatingSyncFrequency = 100
  166. }
  167. singletonNoticeLogger.rotatingFilename = rotatingFilename
  168. singletonNoticeLogger.rotatingOlderFilename = rotatingFilename + ".1"
  169. singletonNoticeLogger.rotatingFileSize = int64(rotatingFileSize)
  170. singletonNoticeLogger.rotatingCurrentFileSize = fileInfo.Size()
  171. singletonNoticeLogger.rotatingSyncFrequency = rotatingSyncFrequency
  172. singletonNoticeLogger.rotatingCurrentNoticeCount = 0
  173. }
  174. return nil
  175. }
  176. const (
  177. noticeShowUser = 1
  178. noticeIsDiagnostic = 2
  179. noticeIsHomepage = 4
  180. noticeClearHomepages = 8
  181. noticeSyncHomepages = 16
  182. )
  183. // outputNotice encodes a notice in JSON and writes it to the output writer.
  184. func (nl *noticeLogger) outputNotice(noticeType string, noticeFlags uint32, args ...interface{}) {
  185. if (noticeFlags&noticeIsDiagnostic != 0) && !GetEmitDiagnosticNotices() {
  186. return
  187. }
  188. obj := make(map[string]interface{})
  189. noticeData := make(map[string]interface{})
  190. obj["noticeType"] = noticeType
  191. obj["showUser"] = (noticeFlags&noticeShowUser != 0)
  192. obj["data"] = noticeData
  193. obj["timestamp"] = time.Now().UTC().Format(common.RFC3339Milli)
  194. for i := 0; i < len(args)-1; i += 2 {
  195. name, ok := args[i].(string)
  196. value := args[i+1]
  197. if ok {
  198. noticeData[name] = value
  199. }
  200. }
  201. encodedJson, err := json.Marshal(obj)
  202. var output []byte
  203. if err == nil {
  204. output = append(encodedJson, byte('\n'))
  205. } else {
  206. // Try to emit a properly formatted notice that the outer client can report.
  207. // One scenario where this is useful is if the preceding Marshal fails due to
  208. // bad data in the args. This has happened for a json.RawMessage field.
  209. output = makeNoticeInternalError(
  210. fmt.Sprintf("marshal notice failed: %s", common.ContextError(err)))
  211. }
  212. // Ensure direct server IPs are not exposed in notices. The "net" package,
  213. // and possibly other 3rd party packages, will include destination addresses
  214. // in I/O error messages.
  215. output = StripIPAddresses(output)
  216. nl.mutex.Lock()
  217. defer nl.mutex.Unlock()
  218. skipWriter := false
  219. if nl.homepageFile != nil &&
  220. (noticeFlags&noticeIsHomepage != 0) {
  221. skipWriter = true
  222. err := nl.outputNoticeToHomepageFile(noticeFlags, output)
  223. if err != nil {
  224. output := makeNoticeInternalError(
  225. fmt.Sprintf("write homepage file failed: %s", err))
  226. nl.writer.Write(output)
  227. }
  228. }
  229. if nl.rotatingFile != nil {
  230. if !skipWriter {
  231. skipWriter = (noticeFlags&noticeIsDiagnostic != 0)
  232. }
  233. err := nl.outputNoticeToRotatingFile(output)
  234. if err != nil {
  235. output := makeNoticeInternalError(
  236. fmt.Sprintf("write rotating file failed: %s", err))
  237. nl.writer.Write(output)
  238. }
  239. }
  240. if !skipWriter {
  241. _, _ = nl.writer.Write(output)
  242. }
  243. }
  244. // NoticeInteralError is an error formatting or writing notices.
  245. // A NoticeInteralError handler must not call a Notice function.
  246. func makeNoticeInternalError(errorMessage string) []byte {
  247. // Format an Alert Notice (_without_ using json.Marshal, since that can fail)
  248. alertNoticeFormat := "{\"noticeType\":\"InternalError\",\"showUser\":false,\"timestamp\":\"%s\",\"data\":{\"message\":\"%s\"}}\n"
  249. return []byte(fmt.Sprintf(alertNoticeFormat, time.Now().UTC().Format(common.RFC3339Milli), errorMessage))
  250. }
  251. func (nl *noticeLogger) outputNoticeToHomepageFile(noticeFlags uint32, output []byte) error {
  252. if (noticeFlags & noticeClearHomepages) != 0 {
  253. err := nl.homepageFile.Truncate(0)
  254. if err != nil {
  255. return common.ContextError(err)
  256. }
  257. _, err = nl.homepageFile.Seek(0, 0)
  258. if err != nil {
  259. return common.ContextError(err)
  260. }
  261. }
  262. _, err := nl.homepageFile.Write(output)
  263. if err != nil {
  264. return common.ContextError(err)
  265. }
  266. if (noticeFlags & noticeSyncHomepages) != 0 {
  267. err = nl.homepageFile.Sync()
  268. if err != nil {
  269. return common.ContextError(err)
  270. }
  271. }
  272. return nil
  273. }
  274. func (nl *noticeLogger) outputNoticeToRotatingFile(output []byte) error {
  275. nl.rotatingCurrentFileSize += int64(len(output) + 1)
  276. if nl.rotatingCurrentFileSize >= nl.rotatingFileSize {
  277. // Note: all errors are fatal in order to preserve the
  278. // rotatingFileSize limit; e.g., no attempt is made to
  279. // continue writing to the file if it can't be rotated.
  280. err := nl.rotatingFile.Sync()
  281. if err != nil {
  282. return common.ContextError(err)
  283. }
  284. err = nl.rotatingFile.Close()
  285. if err != nil {
  286. return common.ContextError(err)
  287. }
  288. err = os.Rename(nl.rotatingFilename, nl.rotatingOlderFilename)
  289. if err != nil {
  290. return common.ContextError(err)
  291. }
  292. nl.rotatingFile, err = os.OpenFile(
  293. nl.rotatingFilename, os.O_CREATE|os.O_TRUNC|os.O_WRONLY, 0600)
  294. if err != nil {
  295. return common.ContextError(err)
  296. }
  297. nl.rotatingCurrentFileSize = 0
  298. }
  299. _, err := nl.rotatingFile.Write(output)
  300. if err != nil {
  301. return common.ContextError(err)
  302. }
  303. nl.rotatingCurrentNoticeCount += 1
  304. if nl.rotatingCurrentNoticeCount >= nl.rotatingSyncFrequency {
  305. nl.rotatingCurrentNoticeCount = 0
  306. err = nl.rotatingFile.Sync()
  307. if err != nil {
  308. return common.ContextError(err)
  309. }
  310. }
  311. return nil
  312. }
  313. // NoticeInfo is an informational message
  314. func NoticeInfo(format string, args ...interface{}) {
  315. singletonNoticeLogger.outputNotice(
  316. "Info", noticeIsDiagnostic,
  317. "message", fmt.Sprintf(format, args...))
  318. }
  319. // NoticeAlert is an alert message; typically a recoverable error condition
  320. func NoticeAlert(format string, args ...interface{}) {
  321. singletonNoticeLogger.outputNotice(
  322. "Alert", noticeIsDiagnostic,
  323. "message", fmt.Sprintf(format, args...))
  324. }
  325. // NoticeError is an error message; typically an unrecoverable error condition
  326. func NoticeError(format string, args ...interface{}) {
  327. singletonNoticeLogger.outputNotice(
  328. "Error", noticeIsDiagnostic,
  329. "message", fmt.Sprintf(format, args...))
  330. }
  331. // NoticeUserLog is a log message from the outer client user of tunnel-core
  332. func NoticeUserLog(message string) {
  333. singletonNoticeLogger.outputNotice(
  334. "UserLog", noticeIsDiagnostic,
  335. "message", message)
  336. }
  337. // NoticeCandidateServers is how many possible servers are available for the selected region and protocols
  338. func NoticeCandidateServers(
  339. region string,
  340. constraints *protocolSelectionConstraints,
  341. initialCount int,
  342. count int) {
  343. singletonNoticeLogger.outputNotice(
  344. "CandidateServers", noticeIsDiagnostic,
  345. "region", region,
  346. "initialLimitTunnelProtocols", constraints.initialLimitProtocols,
  347. "initialLimitTunnelProtocolsCandidateCount", constraints.initialLimitProtocolsCandidateCount,
  348. "limitTunnelProtocols", constraints.limitProtocols,
  349. "replayCandidateCount", constraints.replayCandidateCount,
  350. "initialCount", initialCount,
  351. "count", count)
  352. }
  353. // NoticeAvailableEgressRegions is what regions are available for egress from.
  354. // Consecutive reports of the same list of regions are suppressed.
  355. func NoticeAvailableEgressRegions(regions []string) {
  356. sortedRegions := append([]string(nil), regions...)
  357. sort.Strings(sortedRegions)
  358. repetitionMessage := strings.Join(sortedRegions, "")
  359. outputRepetitiveNotice(
  360. "AvailableEgressRegions", repetitionMessage, 0,
  361. "AvailableEgressRegions", 0, "regions", sortedRegions)
  362. }
  363. func noticeWithDialParameters(noticeType string, dialParams *DialParameters) {
  364. args := []interface{}{
  365. "diagnosticID", dialParams.ServerEntry.GetDiagnosticID(),
  366. "region", dialParams.ServerEntry.Region,
  367. "protocol", dialParams.TunnelProtocol,
  368. "isReplay", dialParams.IsReplay,
  369. "candidateNumber", dialParams.CandidateNumber,
  370. }
  371. if GetEmitNetworkParameters() {
  372. if dialParams.SelectedSSHClientVersion {
  373. args = append(args, "SSHClientVersion", dialParams.SSHClientVersion)
  374. }
  375. if dialParams.UpstreamProxyType != "" {
  376. args = append(args, "upstreamProxyType", dialParams.UpstreamProxyType)
  377. }
  378. if dialParams.UpstreamProxyCustomHeaderNames != nil {
  379. args = append(args, "upstreamProxyCustomHeaderNames", strings.Join(dialParams.UpstreamProxyCustomHeaderNames, ","))
  380. }
  381. if dialParams.MeekDialAddress != "" {
  382. args = append(args, "meekDialAddress", dialParams.MeekDialAddress)
  383. }
  384. meekResolvedIPAddress := dialParams.MeekResolvedIPAddress.Load().(string)
  385. if meekResolvedIPAddress != "" {
  386. args = append(args, "meekResolvedIPAddress", meekResolvedIPAddress)
  387. }
  388. if dialParams.MeekSNIServerName != "" {
  389. args = append(args, "meekSNIServerName", dialParams.MeekSNIServerName)
  390. }
  391. if dialParams.MeekHostHeader != "" {
  392. args = append(args, "meekHostHeader", dialParams.MeekHostHeader)
  393. }
  394. // MeekTransformedHostName is meaningful when meek is used, which is when MeekDialAddress != ""
  395. if dialParams.MeekDialAddress != "" {
  396. args = append(args, "meekTransformedHostName", dialParams.MeekTransformedHostName)
  397. }
  398. if dialParams.SelectedUserAgent {
  399. args = append(args, "userAgent", dialParams.UserAgent)
  400. }
  401. if dialParams.SelectedTLSProfile {
  402. args = append(args, "TLSProfile", dialParams.TLSProfile)
  403. args = append(args, "TLSVersion", dialParams.GetTLSVersionForMetrics())
  404. }
  405. if dialParams.DialPortNumber != "" {
  406. args = append(args, "dialPortNumber", dialParams.DialPortNumber)
  407. }
  408. if dialParams.QUICVersion != "" {
  409. args = append(args, "QUICVersion", dialParams.QUICVersion)
  410. }
  411. if dialParams.QUICDialSNIAddress != "" {
  412. args = append(args, "QUICDialSNIAddress", dialParams.QUICDialSNIAddress)
  413. }
  414. if dialParams.DialDuration > 0 {
  415. args = append(args, "dialDuration", dialParams.DialDuration)
  416. }
  417. if dialParams.NetworkLatencyMultiplier != 0.0 {
  418. args = append(args, "networkLatencyMultiplier", dialParams.NetworkLatencyMultiplier)
  419. }
  420. if dialParams.DialConnMetrics != nil {
  421. metrics := dialParams.DialConnMetrics.GetMetrics()
  422. for name, value := range metrics {
  423. args = append(args, name, value)
  424. }
  425. }
  426. if dialParams.ObfuscatedSSHConnMetrics != nil {
  427. metrics := dialParams.ObfuscatedSSHConnMetrics.GetMetrics()
  428. for name, value := range metrics {
  429. args = append(args, name, value)
  430. }
  431. }
  432. }
  433. singletonNoticeLogger.outputNotice(
  434. noticeType, noticeIsDiagnostic,
  435. args...)
  436. }
  437. // NoticeConnectingServer reports parameters and details for a single connection attempt
  438. func NoticeConnectingServer(dialParams *DialParameters) {
  439. noticeWithDialParameters("ConnectingServer", dialParams)
  440. }
  441. // NoticeConnectedServer reports parameters and details for a single successful connection
  442. func NoticeConnectedServer(dialParams *DialParameters) {
  443. noticeWithDialParameters("ConnectedServer", dialParams)
  444. }
  445. // NoticeRequestingTactics reports parameters and details for a tactics request attempt
  446. func NoticeRequestingTactics(dialParams *DialParameters) {
  447. noticeWithDialParameters("RequestingTactics", dialParams)
  448. }
  449. // NoticeRequestedTactics reports parameters and details for a successful tactics request
  450. func NoticeRequestedTactics(dialParams *DialParameters) {
  451. noticeWithDialParameters("RequestedTactics", dialParams)
  452. }
  453. // NoticeActiveTunnel is a successful connection that is used as an active tunnel for port forwarding
  454. func NoticeActiveTunnel(diagnosticID, protocol string, isTCS bool) {
  455. singletonNoticeLogger.outputNotice(
  456. "ActiveTunnel", noticeIsDiagnostic,
  457. "diagnosticID", diagnosticID,
  458. "protocol", protocol,
  459. "isTCS", isTCS)
  460. }
  461. // NoticeSocksProxyPortInUse is a failure to use the configured LocalSocksProxyPort
  462. func NoticeSocksProxyPortInUse(port int) {
  463. singletonNoticeLogger.outputNotice(
  464. "SocksProxyPortInUse",
  465. noticeShowUser, "port", port)
  466. }
  467. // NoticeListeningSocksProxyPort is the selected port for the listening local SOCKS proxy
  468. func NoticeListeningSocksProxyPort(port int) {
  469. singletonNoticeLogger.outputNotice(
  470. "ListeningSocksProxyPort", 0,
  471. "port", port)
  472. }
  473. // NoticeHttpProxyPortInUse is a failure to use the configured LocalHttpProxyPort
  474. func NoticeHttpProxyPortInUse(port int) {
  475. singletonNoticeLogger.outputNotice(
  476. "HttpProxyPortInUse", noticeShowUser,
  477. "port", port)
  478. }
  479. // NoticeListeningHttpProxyPort is the selected port for the listening local HTTP proxy
  480. func NoticeListeningHttpProxyPort(port int) {
  481. singletonNoticeLogger.outputNotice(
  482. "ListeningHttpProxyPort", 0,
  483. "port", port)
  484. }
  485. // NoticeClientUpgradeAvailable is an available client upgrade, as per the handshake. The
  486. // client should download and install an upgrade.
  487. func NoticeClientUpgradeAvailable(version string) {
  488. singletonNoticeLogger.outputNotice(
  489. "ClientUpgradeAvailable", 0,
  490. "version", version)
  491. }
  492. // NoticeClientIsLatestVersion reports that an upgrade check was made and the client
  493. // is already the latest version. availableVersion is the version available for download,
  494. // if known.
  495. func NoticeClientIsLatestVersion(availableVersion string) {
  496. singletonNoticeLogger.outputNotice(
  497. "ClientIsLatestVersion", 0,
  498. "availableVersion", availableVersion)
  499. }
  500. // NoticeHomepages emits a series of NoticeHomepage, the sponsor homepages. The client
  501. // should display the sponsor's homepages.
  502. func NoticeHomepages(urls []string) {
  503. for i, url := range urls {
  504. noticeFlags := uint32(noticeIsHomepage)
  505. if i == 0 {
  506. noticeFlags |= noticeClearHomepages
  507. }
  508. if i == len(urls)-1 {
  509. noticeFlags |= noticeSyncHomepages
  510. }
  511. singletonNoticeLogger.outputNotice(
  512. "Homepage", noticeFlags,
  513. "url", url)
  514. }
  515. }
  516. // NoticeClientRegion is the client's region, as determined by the server and
  517. // reported to the client in the handshake.
  518. func NoticeClientRegion(region string) {
  519. singletonNoticeLogger.outputNotice(
  520. "ClientRegion", 0,
  521. "region", region)
  522. }
  523. // NoticeTunnels is how many active tunnels are available. The client should use this to
  524. // determine connecting/unexpected disconnect state transitions. When count is 0, the core is
  525. // disconnected; when count > 1, the core is connected.
  526. func NoticeTunnels(count int) {
  527. singletonNoticeLogger.outputNotice(
  528. "Tunnels", 0,
  529. "count", count)
  530. }
  531. // NoticeSessionId is the session ID used across all tunnels established by the controller.
  532. func NoticeSessionId(sessionId string) {
  533. singletonNoticeLogger.outputNotice(
  534. "SessionId", noticeIsDiagnostic,
  535. "sessionId", sessionId)
  536. }
  537. // NoticeUntunneled indicates than an address has been classified as untunneled and is being
  538. // accessed directly.
  539. //
  540. // Note: "address" should remain private; this notice should only be used for alerting
  541. // users, not for diagnostics logs.
  542. //
  543. func NoticeUntunneled(address string) {
  544. singletonNoticeLogger.outputNotice(
  545. "Untunneled", noticeShowUser,
  546. "address", address)
  547. }
  548. // NoticeSplitTunnelRegion reports that split tunnel is on for the given region.
  549. func NoticeSplitTunnelRegion(region string) {
  550. singletonNoticeLogger.outputNotice(
  551. "SplitTunnelRegion", noticeShowUser,
  552. "region", region)
  553. }
  554. // NoticeUpstreamProxyError reports an error when connecting to an upstream proxy. The
  555. // user may have input, for example, an incorrect address or incorrect credentials.
  556. func NoticeUpstreamProxyError(err error) {
  557. singletonNoticeLogger.outputNotice(
  558. "UpstreamProxyError", noticeShowUser,
  559. "message", err.Error())
  560. }
  561. // NoticeClientUpgradeDownloadedBytes reports client upgrade download progress.
  562. func NoticeClientUpgradeDownloadedBytes(bytes int64) {
  563. singletonNoticeLogger.outputNotice(
  564. "ClientUpgradeDownloadedBytes", noticeIsDiagnostic,
  565. "bytes", bytes)
  566. }
  567. // NoticeClientUpgradeDownloaded indicates that a client upgrade download
  568. // is complete and available at the destination specified.
  569. func NoticeClientUpgradeDownloaded(filename string) {
  570. singletonNoticeLogger.outputNotice(
  571. "ClientUpgradeDownloaded", 0,
  572. "filename", filename)
  573. }
  574. // NoticeBytesTransferred reports how many tunneled bytes have been
  575. // transferred since the last NoticeBytesTransferred. This is not a diagnostic
  576. // notice: the user app has requested this notice with EmitBytesTransferred
  577. // for functionality such as traffic display; and this frequent notice is not
  578. // intended to be included with feedback.
  579. func NoticeBytesTransferred(diagnosticID string, sent, received int64) {
  580. singletonNoticeLogger.outputNotice(
  581. "BytesTransferred", 0,
  582. "diagnosticID", diagnosticID,
  583. "sent", sent,
  584. "received", received)
  585. }
  586. // NoticeTotalBytesTransferred reports how many tunneled bytes have been
  587. // transferred in total up to this point. This is a diagnostic notice.
  588. func NoticeTotalBytesTransferred(diagnosticID string, sent, received int64) {
  589. singletonNoticeLogger.outputNotice(
  590. "TotalBytesTransferred", noticeIsDiagnostic,
  591. "diagnosticID", diagnosticID,
  592. "sent", sent,
  593. "received", received)
  594. }
  595. // NoticeLocalProxyError reports a local proxy error message. Repetitive
  596. // errors for a given proxy type are suppressed.
  597. func NoticeLocalProxyError(proxyType string, err error) {
  598. // For repeats, only consider the base error message, which is
  599. // the root error that repeats (the full error often contains
  600. // different specific values, e.g., local port numbers, but
  601. // the same repeating root).
  602. // Assumes error format of common.ContextError.
  603. repetitionMessage := err.Error()
  604. index := strings.LastIndex(repetitionMessage, ": ")
  605. if index != -1 {
  606. repetitionMessage = repetitionMessage[index+2:]
  607. }
  608. outputRepetitiveNotice(
  609. "LocalProxyError"+proxyType, repetitionMessage, 1,
  610. "LocalProxyError", noticeIsDiagnostic,
  611. "message", err.Error())
  612. }
  613. // NoticeBuildInfo reports build version info.
  614. func NoticeBuildInfo() {
  615. singletonNoticeLogger.outputNotice(
  616. "BuildInfo", noticeIsDiagnostic,
  617. "buildInfo", buildinfo.GetBuildInfo())
  618. }
  619. // NoticeExiting indicates that tunnel-core is exiting imminently.
  620. func NoticeExiting() {
  621. singletonNoticeLogger.outputNotice(
  622. "Exiting", 0)
  623. }
  624. // NoticeRemoteServerListResourceDownloadedBytes reports remote server list download progress.
  625. func NoticeRemoteServerListResourceDownloadedBytes(url string, bytes int64) {
  626. if !GetEmitNetworkParameters() {
  627. url = "[redacted]"
  628. }
  629. singletonNoticeLogger.outputNotice(
  630. "RemoteServerListResourceDownloadedBytes", noticeIsDiagnostic,
  631. "url", url,
  632. "bytes", bytes)
  633. }
  634. // NoticeRemoteServerListResourceDownloaded indicates that a remote server list download
  635. // completed successfully.
  636. func NoticeRemoteServerListResourceDownloaded(url string) {
  637. if !GetEmitNetworkParameters() {
  638. url = "[redacted]"
  639. }
  640. singletonNoticeLogger.outputNotice(
  641. "RemoteServerListResourceDownloaded", noticeIsDiagnostic,
  642. "url", url)
  643. }
  644. // NoticeSLOKSeeded indicates that the SLOK with the specified ID was received from
  645. // the Psiphon server. The "duplicate" flags indicates whether the SLOK was previously known.
  646. func NoticeSLOKSeeded(slokID string, duplicate bool) {
  647. singletonNoticeLogger.outputNotice(
  648. "SLOKSeeded", noticeIsDiagnostic,
  649. "slokID", slokID,
  650. "duplicate", duplicate)
  651. }
  652. // NoticeServerTimestamp reports server side timestamp as seen in the handshake.
  653. func NoticeServerTimestamp(timestamp string) {
  654. singletonNoticeLogger.outputNotice(
  655. "ServerTimestamp", 0,
  656. "timestamp", timestamp)
  657. }
  658. // NoticeActiveAuthorizationIDs reports the authorizations the server has accepted.
  659. // Each ID is a base64-encoded accesscontrol.Authorization.ID value.
  660. func NoticeActiveAuthorizationIDs(activeAuthorizationIDs []string) {
  661. // Never emit 'null' instead of empty list
  662. if activeAuthorizationIDs == nil {
  663. activeAuthorizationIDs = make([]string, 0)
  664. }
  665. singletonNoticeLogger.outputNotice(
  666. "ActiveAuthorizationIDs", 0,
  667. "IDs", activeAuthorizationIDs)
  668. }
  669. func NoticeBindToDevice(deviceInfo string) {
  670. outputRepetitiveNotice(
  671. "BindToDevice", deviceInfo, 0,
  672. "BindToDevice", 0, "deviceInfo", deviceInfo)
  673. }
  674. func NoticeNetworkID(networkID string) {
  675. outputRepetitiveNotice(
  676. "NetworkID", networkID, 0,
  677. "NetworkID", 0, "ID", networkID)
  678. }
  679. func NoticeLivenessTest(diagnosticID string, metrics *livenessTestMetrics, success bool) {
  680. singletonNoticeLogger.outputNotice(
  681. "LivenessTest", noticeIsDiagnostic,
  682. "diagnosticID", diagnosticID,
  683. "metrics", metrics,
  684. "success", success)
  685. }
  686. func NoticePruneServerEntry(serverEntryTag string) {
  687. singletonNoticeLogger.outputNotice(
  688. "PruneServerEntry", noticeIsDiagnostic,
  689. "serverEntryTag", serverEntryTag)
  690. }
  691. // NoticeEstablishTunnelTimeout reports that the configured EstablishTunnelTimeout
  692. // duration was exceeded.
  693. func NoticeEstablishTunnelTimeout(timeout time.Duration) {
  694. singletonNoticeLogger.outputNotice(
  695. "EstablishTunnelTimeout", noticeShowUser,
  696. "timeout", timeout)
  697. }
  698. func NoticeFragmentor(diagnosticID string, message string) {
  699. singletonNoticeLogger.outputNotice(
  700. "Fragmentor", noticeIsDiagnostic,
  701. "diagnosticID", diagnosticID,
  702. "message", message)
  703. }
  704. type repetitiveNoticeState struct {
  705. message string
  706. repeats int
  707. }
  708. var repetitiveNoticeMutex sync.Mutex
  709. var repetitiveNoticeStates = make(map[string]*repetitiveNoticeState)
  710. // outputRepetitiveNotice conditionally outputs a notice. Used for noticies which
  711. // often repeat in noisy bursts. For a repeat limit of N, the notice is emitted
  712. // with a "repeats" count on consecutive repeats up to the limit and then suppressed
  713. // until the repetitionMessage differs.
  714. func outputRepetitiveNotice(
  715. repetitionKey, repetitionMessage string, repeatLimit int,
  716. noticeType string, noticeFlags uint32, args ...interface{}) {
  717. repetitiveNoticeMutex.Lock()
  718. defer repetitiveNoticeMutex.Unlock()
  719. state, ok := repetitiveNoticeStates[repetitionKey]
  720. if !ok {
  721. state = new(repetitiveNoticeState)
  722. repetitiveNoticeStates[repetitionKey] = state
  723. }
  724. emit := true
  725. if repetitionMessage != state.message {
  726. state.message = repetitionMessage
  727. state.repeats = 0
  728. } else {
  729. state.repeats += 1
  730. if state.repeats > repeatLimit {
  731. emit = false
  732. }
  733. }
  734. if emit {
  735. if state.repeats > 0 {
  736. args = append(args, "repeats", state.repeats)
  737. }
  738. singletonNoticeLogger.outputNotice(
  739. noticeType, noticeFlags,
  740. args...)
  741. }
  742. }
  743. // ResetRepetitiveNotices resets the repetitive notice state, so
  744. // the next instance of any notice will not be supressed.
  745. func ResetRepetitiveNotices() {
  746. repetitiveNoticeMutex.Lock()
  747. defer repetitiveNoticeMutex.Unlock()
  748. repetitiveNoticeStates = make(map[string]*repetitiveNoticeState)
  749. }
  750. type noticeObject struct {
  751. NoticeType string `json:"noticeType"`
  752. Data json.RawMessage `json:"data"`
  753. Timestamp string `json:"timestamp"`
  754. }
  755. // GetNotice receives a JSON encoded object and attempts to parse it as a Notice.
  756. // The type is returned as a string and the payload as a generic map.
  757. func GetNotice(notice []byte) (
  758. noticeType string, payload map[string]interface{}, err error) {
  759. var object noticeObject
  760. err = json.Unmarshal(notice, &object)
  761. if err != nil {
  762. return "", nil, err
  763. }
  764. var objectPayload interface{}
  765. err = json.Unmarshal(object.Data, &objectPayload)
  766. if err != nil {
  767. return "", nil, err
  768. }
  769. return object.NoticeType, objectPayload.(map[string]interface{}), nil
  770. }
  771. // NoticeReceiver consumes a notice input stream and invokes a callback function
  772. // for each discrete JSON notice object byte sequence.
  773. type NoticeReceiver struct {
  774. mutex sync.Mutex
  775. buffer []byte
  776. callback func([]byte)
  777. }
  778. // NewNoticeReceiver initializes a new NoticeReceiver
  779. func NewNoticeReceiver(callback func([]byte)) *NoticeReceiver {
  780. return &NoticeReceiver{callback: callback}
  781. }
  782. // Write implements io.Writer.
  783. func (receiver *NoticeReceiver) Write(p []byte) (n int, err error) {
  784. receiver.mutex.Lock()
  785. defer receiver.mutex.Unlock()
  786. receiver.buffer = append(receiver.buffer, p...)
  787. index := bytes.Index(receiver.buffer, []byte("\n"))
  788. if index == -1 {
  789. return len(p), nil
  790. }
  791. notice := receiver.buffer[:index]
  792. receiver.callback(notice)
  793. if index == len(receiver.buffer)-1 {
  794. receiver.buffer = receiver.buffer[0:0]
  795. } else {
  796. receiver.buffer = receiver.buffer[index+1:]
  797. }
  798. return len(p), nil
  799. }
  800. // NewNoticeConsoleRewriter consumes JSON-format notice input and parses each
  801. // notice and rewrites in a more human-readable format more suitable for
  802. // console output. The data payload field is left as JSON.
  803. func NewNoticeConsoleRewriter(writer io.Writer) *NoticeReceiver {
  804. return NewNoticeReceiver(func(notice []byte) {
  805. var object noticeObject
  806. _ = json.Unmarshal(notice, &object)
  807. fmt.Fprintf(
  808. writer,
  809. "%s %s %s\n",
  810. object.Timestamp,
  811. object.NoticeType,
  812. string(object.Data))
  813. })
  814. }
  815. // NoticeWriter implements io.Writer and emits the contents of Write() calls
  816. // as Notices. This is to transform logger messages, if they can be redirected
  817. // to an io.Writer, to notices.
  818. type NoticeWriter struct {
  819. noticeType string
  820. }
  821. // NewNoticeWriter initializes a new NoticeWriter
  822. func NewNoticeWriter(noticeType string) *NoticeWriter {
  823. return &NoticeWriter{noticeType: noticeType}
  824. }
  825. // Write implements io.Writer.
  826. func (writer *NoticeWriter) Write(p []byte) (n int, err error) {
  827. singletonNoticeLogger.outputNotice(
  828. writer.noticeType, noticeIsDiagnostic,
  829. "message", string(p))
  830. return len(p), nil
  831. }
  832. // NoticeCommonLogger maps the common.Logger interface to the notice facility.
  833. // This is used to make the notice facility available to other packages that
  834. // don't import the "psiphon" package.
  835. func NoticeCommonLogger() common.Logger {
  836. return &commonLogger{}
  837. }
  838. type commonLogger struct {
  839. }
  840. func (logger *commonLogger) WithContext() common.LogContext {
  841. return &commonLogContext{
  842. context: common.GetParentContext(),
  843. }
  844. }
  845. func (logger *commonLogger) WithContextFields(fields common.LogFields) common.LogContext {
  846. return &commonLogContext{
  847. context: common.GetParentContext(),
  848. fields: fields,
  849. }
  850. }
  851. func (logger *commonLogger) LogMetric(metric string, fields common.LogFields) {
  852. singletonNoticeLogger.outputNotice(
  853. metric, noticeIsDiagnostic,
  854. listCommonFields(fields)...)
  855. }
  856. func listCommonFields(fields common.LogFields) []interface{} {
  857. fieldList := make([]interface{}, 0)
  858. for name, value := range fields {
  859. var formattedValue string
  860. if err, ok := value.(error); ok {
  861. formattedValue = err.Error()
  862. } else {
  863. formattedValue = fmt.Sprintf("%#v", value)
  864. }
  865. fieldList = append(fieldList, name, formattedValue)
  866. }
  867. return fieldList
  868. }
  869. type commonLogContext struct {
  870. context string
  871. fields common.LogFields
  872. }
  873. func (context *commonLogContext) outputNotice(
  874. noticeType string, args ...interface{}) {
  875. singletonNoticeLogger.outputNotice(
  876. noticeType, noticeIsDiagnostic,
  877. append(
  878. []interface{}{
  879. "message", fmt.Sprint(args...),
  880. "context", context.context},
  881. listCommonFields(context.fields)...)...)
  882. }
  883. func (context *commonLogContext) Debug(args ...interface{}) {
  884. // Ignored.
  885. }
  886. func (context *commonLogContext) Info(args ...interface{}) {
  887. context.outputNotice("Info", args...)
  888. }
  889. func (context *commonLogContext) Warning(args ...interface{}) {
  890. context.outputNotice("Alert", args...)
  891. }
  892. func (context *commonLogContext) Error(args ...interface{}) {
  893. context.outputNotice("Error", args...)
  894. }