notice.go 30 KB

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