notice.go 46 KB

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