notice.go 46 KB

1234567891011121314151617181920212223242526272829303132333435363738394041424344454647484950515253545556575859606162636465666768697071727374757677787980818283848586878889909192939495969798991001011021031041051061071081091101111121131141151161171181191201211221231241251261271281291301311321331341351361371381391401411421431441451461471481491501511521531541551561571581591601611621631641651661671681691701711721731741751761771781791801811821831841851861871881891901911921931941951961971981992002012022032042052062072082092102112122132142152162172182192202212222232242252262272282292302312322332342352362372382392402412422432442452462472482492502512522532542552562572582592602612622632642652662672682692702712722732742752762772782792802812822832842852862872882892902912922932942952962972982993003013023033043053063073083093103113123133143153163173183193203213223233243253263273283293303313323333343353363373383393403413423433443453463473483493503513523533543553563573583593603613623633643653663673683693703713723733743753763773783793803813823833843853863873883893903913923933943953963973983994004014024034044054064074084094104114124134144154164174184194204214224234244254264274284294304314324334344354364374384394404414424434444454464474484494504514524534544554564574584594604614624634644654664674684694704714724734744754764774784794804814824834844854864874884894904914924934944954964974984995005015025035045055065075085095105115125135145155165175185195205215225235245255265275285295305315325335345355365375385395405415425435445455465475485495505515525535545555565575585595605615625635645655665675685695705715725735745755765775785795805815825835845855865875885895905915925935945955965975985996006016026036046056066076086096106116126136146156166176186196206216226236246256266276286296306316326336346356366376386396406416426436446456466476486496506516526536546556566576586596606616626636646656666676686696706716726736746756766776786796806816826836846856866876886896906916926936946956966976986997007017027037047057067077087097107117127137147157167177187197207217227237247257267277287297307317327337347357367377387397407417427437447457467477487497507517527537547557567577587597607617627637647657667677687697707717727737747757767777787797807817827837847857867877887897907917927937947957967977987998008018028038048058068078088098108118128138148158168178188198208218228238248258268278288298308318328338348358368378388398408418428438448458468478488498508518528538548558568578588598608618628638648658668678688698708718728738748758768778788798808818828838848858868878888898908918928938948958968978988999009019029039049059069079089099109119129139149159169179189199209219229239249259269279289299309319329339349359369379389399409419429439449459469479489499509519529539549559569579589599609619629639649659669679689699709719729739749759769779789799809819829839849859869879889899909919929939949959969979989991000100110021003100410051006100710081009101010111012101310141015101610171018101910201021102210231024102510261027102810291030103110321033103410351036103710381039104010411042104310441045104610471048104910501051105210531054105510561057105810591060106110621063106410651066106710681069107010711072107310741075107610771078107910801081108210831084108510861087108810891090109110921093109410951096109710981099110011011102110311041105110611071108110911101111111211131114111511161117111811191120112111221123112411251126112711281129113011311132113311341135113611371138113911401141114211431144114511461147114811491150115111521153115411551156115711581159116011611162116311641165116611671168116911701171117211731174117511761177117811791180118111821183118411851186118711881189119011911192119311941195119611971198119912001201120212031204120512061207120812091210121112121213121412151216121712181219122012211222122312241225122612271228122912301231123212331234123512361237123812391240124112421243124412451246124712481249125012511252125312541255125612571258125912601261126212631264126512661267126812691270127112721273127412751276127712781279128012811282128312841285128612871288128912901291129212931294129512961297129812991300130113021303130413051306130713081309131013111312131313141315131613171318131913201321132213231324132513261327132813291330133113321333133413351336133713381339134013411342134313441345134613471348134913501351135213531354135513561357135813591360136113621363136413651366136713681369137013711372137313741375137613771378137913801381138213831384138513861387138813891390139113921393139413951396139713981399140014011402140314041405140614071408140914101411141214131414141514161417141814191420142114221423142414251426142714281429143014311432143314341435143614371438143914401441144214431444144514461447144814491450145114521453145414551456145714581459146014611462146314641465146614671468
  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. announcing int32,
  972. connectingClients int32,
  973. connectedClients int32,
  974. bytesUp int64,
  975. bytesDown int64) {
  976. singletonNoticeLogger.outputNotice(
  977. "InproxyProxyActivity", noticeIsNotDiagnostic,
  978. "announcing", announcing,
  979. "connectingClients", connectingClients,
  980. "connectedClients", connectedClients,
  981. "bytesUp", bytesUp,
  982. "bytesDown", bytesDown)
  983. }
  984. // NoticeInproxyProxyTotalActivity reports how many proxied bytes have been
  985. // transferred in total up to this point; in addition to current connection
  986. // status. This is a diagnostic notice.
  987. func NoticeInproxyProxyTotalActivity(
  988. announcing int32,
  989. connectingClients int32,
  990. connectedClients int32,
  991. totalBytesUp int64,
  992. totalBytesDown int64) {
  993. singletonNoticeLogger.outputNotice(
  994. "InproxyProxyTotalActivity", noticeIsDiagnostic,
  995. "announcing", announcing,
  996. "connectingClients", connectingClients,
  997. "connectedClients", connectedClients,
  998. "totalBytesUp", totalBytesUp,
  999. "totalBytesDown", totalBytesDown)
  1000. }
  1001. type repetitiveNoticeState struct {
  1002. message string
  1003. repeats int
  1004. }
  1005. var repetitiveNoticeMutex sync.Mutex
  1006. var repetitiveNoticeStates = make(map[string]*repetitiveNoticeState)
  1007. // outputRepetitiveNotice conditionally outputs a notice. Used for noticies which
  1008. // often repeat in noisy bursts. For a repeat limit of N, the notice is emitted
  1009. // with a "repeats" count on consecutive repeats up to the limit and then suppressed
  1010. // until the repetitionMessage differs.
  1011. func outputRepetitiveNotice(
  1012. repetitionKey, repetitionMessage string, repeatLimit int,
  1013. noticeType string, noticeFlags uint32, args ...interface{}) {
  1014. repetitiveNoticeMutex.Lock()
  1015. defer repetitiveNoticeMutex.Unlock()
  1016. state, keyFound := repetitiveNoticeStates[repetitionKey]
  1017. if !keyFound {
  1018. state = &repetitiveNoticeState{message: repetitionMessage}
  1019. repetitiveNoticeStates[repetitionKey] = state
  1020. }
  1021. emit := true
  1022. if keyFound {
  1023. if repetitionMessage != state.message {
  1024. state.message = repetitionMessage
  1025. state.repeats = 0
  1026. } else {
  1027. state.repeats += 1
  1028. if state.repeats > repeatLimit {
  1029. emit = false
  1030. }
  1031. }
  1032. }
  1033. if emit {
  1034. if state.repeats > 0 {
  1035. args = append(args, "repeats", state.repeats)
  1036. }
  1037. singletonNoticeLogger.outputNotice(
  1038. noticeType, noticeFlags,
  1039. args...)
  1040. }
  1041. }
  1042. // ResetRepetitiveNotices resets the repetitive notice state, so
  1043. // the next instance of any notice will not be supressed.
  1044. func ResetRepetitiveNotices() {
  1045. repetitiveNoticeMutex.Lock()
  1046. defer repetitiveNoticeMutex.Unlock()
  1047. repetitiveNoticeStates = make(map[string]*repetitiveNoticeState)
  1048. }
  1049. type noticeObject struct {
  1050. NoticeType string `json:"noticeType"`
  1051. Data json.RawMessage `json:"data"`
  1052. Timestamp string `json:"timestamp"`
  1053. }
  1054. // GetNotice receives a JSON encoded object and attempts to parse it as a Notice.
  1055. // The type is returned as a string and the payload as a generic map.
  1056. func GetNotice(notice []byte) (
  1057. noticeType string, payload map[string]interface{}, err error) {
  1058. var object noticeObject
  1059. err = json.Unmarshal(notice, &object)
  1060. if err != nil {
  1061. return "", nil, errors.Trace(err)
  1062. }
  1063. var data interface{}
  1064. err = json.Unmarshal(object.Data, &data)
  1065. if err != nil {
  1066. return "", nil, errors.Trace(err)
  1067. }
  1068. dataValue, ok := data.(map[string]interface{})
  1069. if !ok {
  1070. return "", nil, errors.TraceNew("invalid data value")
  1071. }
  1072. return object.NoticeType, dataValue, nil
  1073. }
  1074. // NoticeReceiver consumes a notice input stream and invokes a callback function
  1075. // for each discrete JSON notice object byte sequence.
  1076. type NoticeReceiver struct {
  1077. mutex sync.Mutex
  1078. buffer []byte
  1079. callback func([]byte)
  1080. }
  1081. // NewNoticeReceiver initializes a new NoticeReceiver
  1082. func NewNoticeReceiver(callback func([]byte)) *NoticeReceiver {
  1083. return &NoticeReceiver{callback: callback}
  1084. }
  1085. // Write implements io.Writer.
  1086. func (receiver *NoticeReceiver) Write(p []byte) (n int, err error) {
  1087. receiver.mutex.Lock()
  1088. defer receiver.mutex.Unlock()
  1089. receiver.buffer = append(receiver.buffer, p...)
  1090. index := bytes.Index(receiver.buffer, []byte("\n"))
  1091. if index == -1 {
  1092. return len(p), nil
  1093. }
  1094. notice := receiver.buffer[:index]
  1095. receiver.callback(notice)
  1096. if index == len(receiver.buffer)-1 {
  1097. receiver.buffer = receiver.buffer[0:0]
  1098. } else {
  1099. receiver.buffer = receiver.buffer[index+1:]
  1100. }
  1101. return len(p), nil
  1102. }
  1103. // NewNoticeConsoleRewriter consumes JSON-format notice input and parses each
  1104. // notice and rewrites in a more human-readable format more suitable for
  1105. // console output. The data payload field is left as JSON.
  1106. func NewNoticeConsoleRewriter(writer io.Writer) *NoticeReceiver {
  1107. return NewNoticeReceiver(func(notice []byte) {
  1108. var object noticeObject
  1109. _ = json.Unmarshal(notice, &object)
  1110. fmt.Fprintf(
  1111. writer,
  1112. "%s %s %s\n",
  1113. object.Timestamp,
  1114. object.NoticeType,
  1115. string(object.Data))
  1116. })
  1117. }
  1118. // NoticeWriter implements io.Writer and emits the contents of Write() calls
  1119. // as Notices. This is to transform logger messages, if they can be redirected
  1120. // to an io.Writer, to notices.
  1121. type NoticeWriter struct {
  1122. noticeType string
  1123. }
  1124. // NewNoticeWriter initializes a new NoticeWriter
  1125. func NewNoticeWriter(noticeType string) *NoticeWriter {
  1126. return &NoticeWriter{noticeType: noticeType}
  1127. }
  1128. // Write implements io.Writer.
  1129. func (writer *NoticeWriter) Write(p []byte) (n int, err error) {
  1130. singletonNoticeLogger.outputNotice(
  1131. writer.noticeType, noticeIsDiagnostic,
  1132. "message", string(p))
  1133. return len(p), nil
  1134. }
  1135. // NoticeLineWriter implements io.Writer and emits the contents of Write calls
  1136. // as Notices. NoticeLineWriter buffers writes and emits a notice for each
  1137. // complete, newline delimited line. Tab characters are replaced with spaces.
  1138. type NoticeLineWriter struct {
  1139. noticeType string
  1140. lineBuffer strings.Builder
  1141. }
  1142. // NoticeLineWriter initializes a new NoticeLineWriter
  1143. func NewNoticeLineWriter(noticeType string) *NoticeLineWriter {
  1144. return &NoticeLineWriter{noticeType: noticeType}
  1145. }
  1146. // Write implements io.Writer.
  1147. func (writer *NoticeLineWriter) Write(p []byte) (n int, err error) {
  1148. str := strings.ReplaceAll(string(p), "\t", " ")
  1149. for {
  1150. before, after, found := strings.Cut(str, "\n")
  1151. writer.lineBuffer.WriteString(before)
  1152. if !found {
  1153. return len(p), nil
  1154. }
  1155. singletonNoticeLogger.outputNotice(
  1156. writer.noticeType, noticeIsDiagnostic,
  1157. "message", writer.lineBuffer.String())
  1158. writer.lineBuffer.Reset()
  1159. if len(after) == 0 {
  1160. break
  1161. }
  1162. str = after
  1163. }
  1164. return len(p), nil
  1165. }
  1166. // NoticeCommonLogger maps the common.Logger interface to the notice facility.
  1167. // This is used to make the notice facility available to other packages that
  1168. // don't import the "psiphon" package.
  1169. func NoticeCommonLogger(debugLogging bool) common.Logger {
  1170. return &commonLogger{
  1171. debugLogging: debugLogging,
  1172. }
  1173. }
  1174. type commonLogger struct {
  1175. debugLogging bool
  1176. }
  1177. func (logger *commonLogger) WithTrace() common.LogTrace {
  1178. return &commonLogTrace{
  1179. trace: stacktrace.GetParentFunctionName(),
  1180. debugLogging: logger.debugLogging,
  1181. }
  1182. }
  1183. func (logger *commonLogger) WithTraceFields(fields common.LogFields) common.LogTrace {
  1184. return &commonLogTrace{
  1185. trace: stacktrace.GetParentFunctionName(),
  1186. fields: fields,
  1187. debugLogging: logger.debugLogging,
  1188. }
  1189. }
  1190. func (logger *commonLogger) LogMetric(metric string, fields common.LogFields) {
  1191. singletonNoticeLogger.outputNotice(
  1192. metric, noticeIsDiagnostic,
  1193. listCommonFields(fields)...)
  1194. }
  1195. func (log *commonLogger) IsLogLevelDebug() bool {
  1196. return log.debugLogging
  1197. }
  1198. func listCommonFields(fields common.LogFields) []interface{} {
  1199. fieldList := make([]interface{}, 0)
  1200. for name, value := range fields {
  1201. fieldList = append(fieldList, name, value)
  1202. }
  1203. return fieldList
  1204. }
  1205. type commonLogTrace struct {
  1206. trace string
  1207. fields common.LogFields
  1208. debugLogging bool
  1209. }
  1210. func (log *commonLogTrace) outputNotice(
  1211. noticeType string, args ...interface{}) {
  1212. singletonNoticeLogger.outputNotice(
  1213. noticeType, noticeIsDiagnostic,
  1214. append(
  1215. []interface{}{
  1216. "message", fmt.Sprint(args...),
  1217. "trace", log.trace},
  1218. listCommonFields(log.fields)...)...)
  1219. }
  1220. func (log *commonLogTrace) Debug(args ...interface{}) {
  1221. if !log.debugLogging {
  1222. return
  1223. }
  1224. log.outputNotice("Debug", args...)
  1225. }
  1226. func (log *commonLogTrace) Info(args ...interface{}) {
  1227. log.outputNotice("Info", args...)
  1228. }
  1229. func (log *commonLogTrace) Warning(args ...interface{}) {
  1230. log.outputNotice("Alert", args...)
  1231. }
  1232. func (log *commonLogTrace) Error(args ...interface{}) {
  1233. log.outputNotice("Error", args...)
  1234. }