notice.go 29 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724725726727728729730731732733734735736737738739740741742743744745746747748749750751752753754755756757758759760761762763764765766767768769770771772773774775776777778779780781782783784785786787788789790791792793794795796797798799800801802803804805806807808809810811812813814815816817818819820821822823824825826827828829830831832833834835836837838839840841842843844845846847848849850851852853854855856857858859860861862863864865866867868869870871872873874875876877878879880881882883884885886887888889890891892893894895896897898899900901902903904905906907908909910911912913914915916917918919920921922923924925926927928929930931932
  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 protocol
  318. func NoticeCandidateServers(region, protocol string, count int) {
  319. singletonNoticeLogger.outputNotice(
  320. "CandidateServers", noticeIsDiagnostic,
  321. "region", region,
  322. "protocol", protocol,
  323. "count", count)
  324. }
  325. // NoticeAvailableEgressRegions is what regions are available for egress from.
  326. // Consecutive reports of the same list of regions are suppressed.
  327. func NoticeAvailableEgressRegions(regions []string) {
  328. sortedRegions := append([]string(nil), regions...)
  329. sort.Strings(sortedRegions)
  330. repetitionMessage := strings.Join(sortedRegions, "")
  331. outputRepetitiveNotice(
  332. "AvailableEgressRegions", repetitionMessage, 0,
  333. "AvailableEgressRegions", 0, "regions", sortedRegions)
  334. }
  335. func noticeServerDialStats(noticeType, ipAddress, region, protocol string, tunnelDialStats *TunnelDialStats) {
  336. args := []interface{}{
  337. "ipAddress", ipAddress,
  338. "region", region,
  339. "protocol", protocol,
  340. }
  341. if tunnelDialStats.SelectedSSHClientVersion {
  342. args = append(args, "SSHClientVersion", tunnelDialStats.SSHClientVersion)
  343. }
  344. if tunnelDialStats.UpstreamProxyType != "" {
  345. args = append(args, "upstreamProxyType", tunnelDialStats.UpstreamProxyType)
  346. }
  347. if tunnelDialStats.UpstreamProxyCustomHeaderNames != nil {
  348. args = append(args, "upstreamProxyCustomHeaderNames", strings.Join(tunnelDialStats.UpstreamProxyCustomHeaderNames, ","))
  349. }
  350. if tunnelDialStats.MeekDialAddress != "" {
  351. args = append(args, "meekDialAddress", tunnelDialStats.MeekDialAddress)
  352. }
  353. if tunnelDialStats.MeekResolvedIPAddress != "" {
  354. args = append(args, "meekResolvedIPAddress", tunnelDialStats.MeekResolvedIPAddress)
  355. }
  356. if tunnelDialStats.MeekSNIServerName != "" {
  357. args = append(args, "meekSNIServerName", tunnelDialStats.MeekSNIServerName)
  358. }
  359. if tunnelDialStats.MeekHostHeader != "" {
  360. args = append(args, "meekHostHeader", tunnelDialStats.MeekHostHeader)
  361. }
  362. // MeekTransformedHostName is meaningful when meek is used, which is when MeekDialAddress != ""
  363. if tunnelDialStats.MeekDialAddress != "" {
  364. args = append(args, "meekTransformedHostName", tunnelDialStats.MeekTransformedHostName)
  365. }
  366. if tunnelDialStats.SelectedUserAgent {
  367. args = append(args, "userAgent", tunnelDialStats.UserAgent)
  368. }
  369. if tunnelDialStats.SelectedTLSProfile {
  370. args = append(args, "TLSProfile", tunnelDialStats.TLSProfile)
  371. }
  372. singletonNoticeLogger.outputNotice(
  373. noticeType, noticeIsDiagnostic,
  374. args...)
  375. }
  376. // NoticeConnectingServer reports parameters and details for a single connection attempt
  377. func NoticeConnectingServer(ipAddress, region, protocol string, tunnelDialStats *TunnelDialStats) {
  378. noticeServerDialStats(
  379. "ConnectingServer", ipAddress, region, protocol, tunnelDialStats)
  380. }
  381. // NoticeConnectedServer reports parameters and details for a single successful connection
  382. func NoticeConnectedServer(ipAddress, region, protocol string, tunnelDialStats *TunnelDialStats) {
  383. noticeServerDialStats(
  384. "ConnectedServer", ipAddress, region, protocol, tunnelDialStats)
  385. }
  386. // NoticeActiveTunnel is a successful connection that is used as an active tunnel for port forwarding
  387. func NoticeActiveTunnel(ipAddress, protocol string, isTCS bool) {
  388. singletonNoticeLogger.outputNotice(
  389. "ActiveTunnel", noticeIsDiagnostic,
  390. "ipAddress", ipAddress,
  391. "protocol", protocol,
  392. "isTCS", isTCS)
  393. }
  394. // NoticeSocksProxyPortInUse is a failure to use the configured LocalSocksProxyPort
  395. func NoticeSocksProxyPortInUse(port int) {
  396. singletonNoticeLogger.outputNotice(
  397. "SocksProxyPortInUse",
  398. noticeShowUser, "port", port)
  399. }
  400. // NoticeListeningSocksProxyPort is the selected port for the listening local SOCKS proxy
  401. func NoticeListeningSocksProxyPort(port int) {
  402. singletonNoticeLogger.outputNotice(
  403. "ListeningSocksProxyPort", 0,
  404. "port", port)
  405. }
  406. // NoticeHttpProxyPortInUse is a failure to use the configured LocalHttpProxyPort
  407. func NoticeHttpProxyPortInUse(port int) {
  408. singletonNoticeLogger.outputNotice(
  409. "HttpProxyPortInUse", noticeShowUser,
  410. "port", port)
  411. }
  412. // NoticeListeningHttpProxyPort is the selected port for the listening local HTTP proxy
  413. func NoticeListeningHttpProxyPort(port int) {
  414. singletonNoticeLogger.outputNotice(
  415. "ListeningHttpProxyPort", 0,
  416. "port", port)
  417. }
  418. // NoticeClientUpgradeAvailable is an available client upgrade, as per the handshake. The
  419. // client should download and install an upgrade.
  420. func NoticeClientUpgradeAvailable(version string) {
  421. singletonNoticeLogger.outputNotice(
  422. "ClientUpgradeAvailable", 0,
  423. "version", version)
  424. }
  425. // NoticeClientIsLatestVersion reports that an upgrade check was made and the client
  426. // is already the latest version. availableVersion is the version available for download,
  427. // if known.
  428. func NoticeClientIsLatestVersion(availableVersion string) {
  429. singletonNoticeLogger.outputNotice(
  430. "ClientIsLatestVersion", 0,
  431. "availableVersion", availableVersion)
  432. }
  433. // NoticeHomepages emits a series of NoticeHomepage, the sponsor homepages. The client
  434. // should display the sponsor's homepages.
  435. func NoticeHomepages(urls []string) {
  436. for i, url := range urls {
  437. noticeFlags := uint32(noticeIsHomepage)
  438. if i == 0 {
  439. noticeFlags |= noticeClearHomepages
  440. }
  441. if i == len(urls)-1 {
  442. noticeFlags |= noticeSyncHomepages
  443. }
  444. singletonNoticeLogger.outputNotice(
  445. "Homepage", noticeFlags,
  446. "url", url)
  447. }
  448. }
  449. // NoticeClientVerificationRequired indicates that client verification is required, as
  450. // indicated by the handshake. The client should submit a client verification payload.
  451. // Empty nonce is allowed, if ttlSeconds is 0 the client should not send verification
  452. // payload to the server. If resetCache is set the client must always perform a new
  453. // verification and update its cache
  454. func NoticeClientVerificationRequired(nonce string, ttlSeconds int, resetCache bool) {
  455. singletonNoticeLogger.outputNotice(
  456. "ClientVerificationRequired", 0,
  457. "nonce", nonce,
  458. "ttlSeconds", ttlSeconds,
  459. "resetCache", resetCache)
  460. }
  461. // NoticeClientRegion is the client's region, as determined by the server and
  462. // reported to the client in the handshake.
  463. func NoticeClientRegion(region string) {
  464. singletonNoticeLogger.outputNotice(
  465. "ClientRegion", 0,
  466. "region", region)
  467. }
  468. // NoticeTunnels is how many active tunnels are available. The client should use this to
  469. // determine connecting/unexpected disconnect state transitions. When count is 0, the core is
  470. // disconnected; when count > 1, the core is connected.
  471. func NoticeTunnels(count int) {
  472. singletonNoticeLogger.outputNotice(
  473. "Tunnels", 0,
  474. "count", count)
  475. }
  476. // NoticeSessionId is the session ID used across all tunnels established by the controller.
  477. func NoticeSessionId(sessionId string) {
  478. singletonNoticeLogger.outputNotice(
  479. "SessionId", noticeIsDiagnostic,
  480. "sessionId", sessionId)
  481. }
  482. func NoticeImpairedProtocolClassification(impairedProtocolClassification map[string]int) {
  483. singletonNoticeLogger.outputNotice(
  484. "ImpairedProtocolClassification", noticeIsDiagnostic,
  485. "classification", impairedProtocolClassification)
  486. }
  487. // NoticeUntunneled indicates than an address has been classified as untunneled and is being
  488. // accessed directly.
  489. //
  490. // Note: "address" should remain private; this notice should only be used for alerting
  491. // users, not for diagnostics logs.
  492. //
  493. func NoticeUntunneled(address string) {
  494. singletonNoticeLogger.outputNotice(
  495. "Untunneled", noticeShowUser,
  496. "address", address)
  497. }
  498. // NoticeSplitTunnelRegion reports that split tunnel is on for the given region.
  499. func NoticeSplitTunnelRegion(region string) {
  500. singletonNoticeLogger.outputNotice(
  501. "SplitTunnelRegion", noticeShowUser,
  502. "region", region)
  503. }
  504. // NoticeUpstreamProxyError reports an error when connecting to an upstream proxy. The
  505. // user may have input, for example, an incorrect address or incorrect credentials.
  506. func NoticeUpstreamProxyError(err error) {
  507. singletonNoticeLogger.outputNotice(
  508. "UpstreamProxyError", noticeShowUser,
  509. "message", err.Error())
  510. }
  511. // NoticeClientUpgradeDownloadedBytes reports client upgrade download progress.
  512. func NoticeClientUpgradeDownloadedBytes(bytes int64) {
  513. singletonNoticeLogger.outputNotice(
  514. "ClientUpgradeDownloadedBytes", noticeIsDiagnostic,
  515. "bytes", bytes)
  516. }
  517. // NoticeClientUpgradeDownloaded indicates that a client upgrade download
  518. // is complete and available at the destination specified.
  519. func NoticeClientUpgradeDownloaded(filename string) {
  520. singletonNoticeLogger.outputNotice(
  521. "ClientUpgradeDownloaded", 0,
  522. "filename", filename)
  523. }
  524. // NoticeBytesTransferred reports how many tunneled bytes have been
  525. // transferred since the last NoticeBytesTransferred, for the tunnel
  526. // to the server at ipAddress. This is not a diagnostic notice: the
  527. // user app has requested this notice with EmitBytesTransferred for
  528. // functionality such as traffic display; and this frequent notice
  529. // is not intended to be included with feedback.
  530. func NoticeBytesTransferred(ipAddress string, sent, received int64) {
  531. singletonNoticeLogger.outputNotice(
  532. "BytesTransferred", 0,
  533. "sent", sent,
  534. "received", received)
  535. }
  536. // NoticeTotalBytesTransferred reports how many tunneled bytes have been
  537. // transferred in total up to this point, for the tunnel to the server
  538. // at ipAddress. This is a diagnostic notice.
  539. func NoticeTotalBytesTransferred(ipAddress string, sent, received int64) {
  540. singletonNoticeLogger.outputNotice(
  541. "TotalBytesTransferred", noticeIsDiagnostic,
  542. "ipAddress", ipAddress,
  543. "sent", sent,
  544. "received", received)
  545. }
  546. // NoticeLocalProxyError reports a local proxy error message. Repetitive
  547. // errors for a given proxy type are suppressed.
  548. func NoticeLocalProxyError(proxyType string, err error) {
  549. // For repeats, only consider the base error message, which is
  550. // the root error that repeats (the full error often contains
  551. // different specific values, e.g., local port numbers, but
  552. // the same repeating root).
  553. // Assumes error format of common.ContextError.
  554. repetitionMessage := err.Error()
  555. index := strings.LastIndex(repetitionMessage, ": ")
  556. if index != -1 {
  557. repetitionMessage = repetitionMessage[index+2:]
  558. }
  559. outputRepetitiveNotice(
  560. "LocalProxyError"+proxyType, repetitionMessage, 1,
  561. "LocalProxyError", noticeIsDiagnostic,
  562. "message", err.Error())
  563. }
  564. // NoticeBuildInfo reports build version info.
  565. func NoticeBuildInfo() {
  566. singletonNoticeLogger.outputNotice(
  567. "BuildInfo", noticeIsDiagnostic,
  568. "buildInfo", common.GetBuildInfo())
  569. }
  570. // NoticeExiting indicates that tunnel-core is exiting imminently.
  571. func NoticeExiting() {
  572. singletonNoticeLogger.outputNotice(
  573. "Exiting", 0)
  574. }
  575. // NoticeRemoteServerListResourceDownloadedBytes reports remote server list download progress.
  576. func NoticeRemoteServerListResourceDownloadedBytes(url string, bytes int64) {
  577. singletonNoticeLogger.outputNotice(
  578. "RemoteServerListResourceDownloadedBytes", noticeIsDiagnostic,
  579. "url", url,
  580. "bytes", bytes)
  581. }
  582. // NoticeRemoteServerListResourceDownloaded indicates that a remote server list download
  583. // completed successfully.
  584. func NoticeRemoteServerListResourceDownloaded(url string) {
  585. singletonNoticeLogger.outputNotice(
  586. "RemoteServerListResourceDownloaded", noticeIsDiagnostic,
  587. "url", url)
  588. }
  589. func NoticeClientVerificationRequestCompleted(ipAddress string) {
  590. // TODO: remove "Notice" prefix
  591. singletonNoticeLogger.outputNotice(
  592. "NoticeClientVerificationRequestCompleted", noticeIsDiagnostic,
  593. "ipAddress", ipAddress)
  594. }
  595. // NoticeSLOKSeeded indicates that the SLOK with the specified ID was received from
  596. // the Psiphon server. The "duplicate" flags indicates whether the SLOK was previously known.
  597. func NoticeSLOKSeeded(slokID string, duplicate bool) {
  598. singletonNoticeLogger.outputNotice(
  599. "SLOKSeeded", noticeIsDiagnostic,
  600. "slokID", slokID,
  601. "duplicate", duplicate)
  602. }
  603. // NoticeServerTimestamp reports server side timestamp as seen in the handshake
  604. func NoticeServerTimestamp(timestamp string) {
  605. singletonNoticeLogger.outputNotice(
  606. "ServerTimestamp", 0,
  607. "timestamp", timestamp)
  608. }
  609. type repetitiveNoticeState struct {
  610. message string
  611. repeats int
  612. }
  613. var repetitiveNoticeMutex sync.Mutex
  614. var repetitiveNoticeStates = make(map[string]*repetitiveNoticeState)
  615. // outputRepetitiveNotice conditionally outputs a notice. Used for noticies which
  616. // often repeat in noisy bursts. For a repeat limit of N, the notice is emitted
  617. // with a "repeats" count on consecutive repeats up to the limit and then suppressed
  618. // until the repetitionMessage differs.
  619. func outputRepetitiveNotice(
  620. repetitionKey, repetitionMessage string, repeatLimit int,
  621. noticeType string, noticeFlags uint32, args ...interface{}) {
  622. repetitiveNoticeMutex.Lock()
  623. defer repetitiveNoticeMutex.Unlock()
  624. state, ok := repetitiveNoticeStates[repetitionKey]
  625. if !ok {
  626. state = new(repetitiveNoticeState)
  627. repetitiveNoticeStates[repetitionKey] = state
  628. }
  629. emit := true
  630. if repetitionMessage != state.message {
  631. state.message = repetitionMessage
  632. state.repeats = 0
  633. } else {
  634. state.repeats += 1
  635. if state.repeats > repeatLimit {
  636. emit = false
  637. }
  638. }
  639. if emit {
  640. if state.repeats > 0 {
  641. args = append(args, "repeats", state.repeats)
  642. }
  643. singletonNoticeLogger.outputNotice(
  644. noticeType, noticeFlags,
  645. args...)
  646. }
  647. }
  648. type noticeObject struct {
  649. NoticeType string `json:"noticeType"`
  650. Data json.RawMessage `json:"data"`
  651. Timestamp string `json:"timestamp"`
  652. }
  653. // GetNotice receives a JSON encoded object and attempts to parse it as a Notice.
  654. // The type is returned as a string and the payload as a generic map.
  655. func GetNotice(notice []byte) (
  656. noticeType string, payload map[string]interface{}, err error) {
  657. var object noticeObject
  658. err = json.Unmarshal(notice, &object)
  659. if err != nil {
  660. return "", nil, err
  661. }
  662. var objectPayload interface{}
  663. err = json.Unmarshal(object.Data, &objectPayload)
  664. if err != nil {
  665. return "", nil, err
  666. }
  667. return object.NoticeType, objectPayload.(map[string]interface{}), nil
  668. }
  669. // NoticeReceiver consumes a notice input stream and invokes a callback function
  670. // for each discrete JSON notice object byte sequence.
  671. type NoticeReceiver struct {
  672. mutex sync.Mutex
  673. buffer []byte
  674. callback func([]byte)
  675. }
  676. // NewNoticeReceiver initializes a new NoticeReceiver
  677. func NewNoticeReceiver(callback func([]byte)) *NoticeReceiver {
  678. return &NoticeReceiver{callback: callback}
  679. }
  680. // Write implements io.Writer.
  681. func (receiver *NoticeReceiver) Write(p []byte) (n int, err error) {
  682. receiver.mutex.Lock()
  683. defer receiver.mutex.Unlock()
  684. receiver.buffer = append(receiver.buffer, p...)
  685. index := bytes.Index(receiver.buffer, []byte("\n"))
  686. if index == -1 {
  687. return len(p), nil
  688. }
  689. notice := receiver.buffer[:index]
  690. receiver.callback(notice)
  691. if index == len(receiver.buffer)-1 {
  692. receiver.buffer = receiver.buffer[0:0]
  693. } else {
  694. receiver.buffer = receiver.buffer[index+1:]
  695. }
  696. return len(p), nil
  697. }
  698. // NewNoticeConsoleRewriter consumes JSON-format notice input and parses each
  699. // notice and rewrites in a more human-readable format more suitable for
  700. // console output. The data payload field is left as JSON.
  701. func NewNoticeConsoleRewriter(writer io.Writer) *NoticeReceiver {
  702. return NewNoticeReceiver(func(notice []byte) {
  703. var object noticeObject
  704. _ = json.Unmarshal(notice, &object)
  705. fmt.Fprintf(
  706. writer,
  707. "%s %s %s\n",
  708. object.Timestamp,
  709. object.NoticeType,
  710. string(object.Data))
  711. })
  712. }
  713. // NoticeWriter implements io.Writer and emits the contents of Write() calls
  714. // as Notices. This is to transform logger messages, if they can be redirected
  715. // to an io.Writer, to notices.
  716. type NoticeWriter struct {
  717. noticeType string
  718. }
  719. // NewNoticeWriter initializes a new NoticeWriter
  720. func NewNoticeWriter(noticeType string) *NoticeWriter {
  721. return &NoticeWriter{noticeType: noticeType}
  722. }
  723. // Write implements io.Writer.
  724. func (writer *NoticeWriter) Write(p []byte) (n int, err error) {
  725. singletonNoticeLogger.outputNotice(
  726. writer.noticeType, noticeIsDiagnostic,
  727. "message", string(p))
  728. return len(p), nil
  729. }
  730. // NoticeCommonLogger maps the common.Logger interface to the notice facility.
  731. // This is used to make the notice facility available to other packages that
  732. // don't import the "psiphon" package.
  733. func NoticeCommonLogger() common.Logger {
  734. return &commonLogger{}
  735. }
  736. type commonLogger struct {
  737. }
  738. func (logger *commonLogger) WithContext() common.LogContext {
  739. return &commonLogContext{
  740. context: common.GetParentContext(),
  741. }
  742. }
  743. func (logger *commonLogger) WithContextFields(fields common.LogFields) common.LogContext {
  744. return &commonLogContext{
  745. context: common.GetParentContext(),
  746. fields: fields,
  747. }
  748. }
  749. func (logger *commonLogger) LogMetric(metric string, fields common.LogFields) {
  750. singletonNoticeLogger.outputNotice(
  751. metric, noticeIsDiagnostic,
  752. listCommonFields(fields)...)
  753. }
  754. func listCommonFields(fields common.LogFields) []interface{} {
  755. fieldList := make([]interface{}, 0)
  756. for name, value := range fields {
  757. var formattedValue string
  758. if err, ok := value.(error); ok {
  759. formattedValue = err.Error()
  760. } else {
  761. formattedValue = fmt.Sprintf("%#v", value)
  762. }
  763. fieldList = append(fieldList, name, formattedValue)
  764. }
  765. return fieldList
  766. }
  767. type commonLogContext struct {
  768. context string
  769. fields common.LogFields
  770. }
  771. func (context *commonLogContext) outputNotice(
  772. noticeType string, args ...interface{}) {
  773. singletonNoticeLogger.outputNotice(
  774. noticeType, noticeIsDiagnostic,
  775. append(
  776. []interface{}{
  777. "message", fmt.Sprint(args...),
  778. "context", context.context},
  779. listCommonFields(context.fields)...)...)
  780. }
  781. func (context *commonLogContext) Debug(args ...interface{}) {
  782. // Ignored.
  783. }
  784. func (context *commonLogContext) Info(args ...interface{}) {
  785. context.outputNotice("Info", args)
  786. }
  787. func (context *commonLogContext) Warning(args ...interface{}) {
  788. context.outputNotice("Alert", args)
  789. }
  790. func (context *commonLogContext) Error(args ...interface{}) {
  791. context.outputNotice("Error", args)
  792. }