notice.go 45 KB

12345678910111213141516171819202122232425262728293031323334353637383940414243444546474849505152535455565758596061626364656667686970717273747576777879808182838485868788899091929394959697989910010110210310410510610710810911011111211311411511611711811912012112212312412512612712812913013113213313413513613713813914014114214314414514614714814915015115215315415515615715815916016116216316416516616716816917017117217317417517617717817918018118218318418518618718818919019119219319419519619719819920020120220320420520620720820921021121221321421521621721821922022122222322422522622722822923023123223323423523623723823924024124224324424524624724824925025125225325425525625725825926026126226326426526626726826927027127227327427527627727827928028128228328428528628728828929029129229329429529629729829930030130230330430530630730830931031131231331431531631731831932032132232332432532632732832933033133233333433533633733833934034134234334434534634734834935035135235335435535635735835936036136236336436536636736836937037137237337437537637737837938038138238338438538638738838939039139239339439539639739839940040140240340440540640740840941041141241341441541641741841942042142242342442542642742842943043143243343443543643743843944044144244344444544644744844945045145245345445545645745845946046146246346446546646746846947047147247347447547647747847948048148248348448548648748848949049149249349449549649749849950050150250350450550650750850951051151251351451551651751851952052152252352452552652752852953053153253353453553653753853954054154254354454554654754854955055155255355455555655755855956056156256356456556656756856957057157257357457557657757857958058158258358458558658758858959059159259359459559659759859960060160260360460560660760860961061161261361461561661761861962062162262362462562662762862963063163263363463563663763863964064164264364464564664764864965065165265365465565665765865966066166266366466566666766866967067167267367467567667767867968068168268368468568668768868969069169269369469569669769869970070170270370470570670770870971071171271371471571671771871972072172272372472572672772872973073173273373473573673773873974074174274374474574674774874975075175275375475575675775875976076176276376476576676776876977077177277377477577677777877978078178278378478578678778878979079179279379479579679779879980080180280380480580680780880981081181281381481581681781881982082182282382482582682782882983083183283383483583683783883984084184284384484584684784884985085185285385485585685785885986086186286386486586686786886987087187287387487587687787887988088188288388488588688788888989089189289389489589689789889990090190290390490590690790890991091191291391491591691791891992092192292392492592692792892993093193293393493593693793893994094194294394494594694794894995095195295395495595695795895996096196296396496596696796896997097197297397497597697797897998098198298398498598698798898999099199299399499599699799899910001001100210031004100510061007100810091010101110121013101410151016101710181019102010211022102310241025102610271028102910301031103210331034103510361037103810391040104110421043104410451046104710481049105010511052105310541055105610571058105910601061106210631064106510661067106810691070107110721073107410751076107710781079108010811082108310841085108610871088108910901091109210931094109510961097109810991100110111021103110411051106110711081109111011111112111311141115111611171118111911201121112211231124112511261127112811291130113111321133113411351136113711381139114011411142114311441145114611471148114911501151115211531154115511561157115811591160116111621163116411651166116711681169117011711172117311741175117611771178117911801181118211831184118511861187118811891190119111921193119411951196119711981199120012011202120312041205120612071208120912101211121212131214121512161217121812191220122112221223122412251226122712281229123012311232123312341235123612371238123912401241124212431244124512461247124812491250125112521253125412551256125712581259126012611262126312641265126612671268126912701271127212731274127512761277127812791280128112821283128412851286128712881289129012911292129312941295129612971298129913001301130213031304130513061307130813091310131113121313131413151316131713181319132013211322132313241325132613271328132913301331133213331334133513361337133813391340134113421343134413451346134713481349135013511352135313541355135613571358135913601361136213631364136513661367136813691370137113721373137413751376137713781379138013811382138313841385138613871388138913901391139213931394139513961397139813991400140114021403140414051406140714081409141014111412141314141415141614171418141914201421142214231424142514261427142814291430143114321433143414351436143714381439144014411442144314441445144614471448144914501451145214531454145514561457145814591460
  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. "candidateNumber", dialParams.CandidateNumber,
  415. "establishedTunnelsCount", dialParams.EstablishedTunnelsCount,
  416. "networkType", dialParams.GetNetworkType(),
  417. }
  418. if GetEmitNetworkParameters() {
  419. // Omit appliedTacticsTag as that is emitted in another notice.
  420. if dialParams.BPFProgramName != "" {
  421. args = append(args, "clientBPF", dialParams.BPFProgramName)
  422. }
  423. if dialParams.SelectedSSHClientVersion {
  424. args = append(args, "SSHClientVersion", dialParams.SSHClientVersion)
  425. }
  426. if dialParams.UpstreamProxyType != "" {
  427. args = append(args, "upstreamProxyType", dialParams.UpstreamProxyType)
  428. }
  429. if dialParams.UpstreamProxyCustomHeaderNames != nil {
  430. args = append(args, "upstreamProxyCustomHeaderNames", strings.Join(dialParams.UpstreamProxyCustomHeaderNames, ","))
  431. }
  432. if dialParams.ServerEntry.ProviderID != "" {
  433. args = append(args, "providerID", dialParams.ServerEntry.ProviderID)
  434. }
  435. if dialParams.FrontingProviderID != "" {
  436. args = append(args, "frontingProviderID", dialParams.FrontingProviderID)
  437. }
  438. if dialParams.MeekDialAddress != "" {
  439. args = append(args, "meekDialAddress", dialParams.MeekDialAddress)
  440. }
  441. if protocol.TunnelProtocolUsesFrontedMeek(dialParams.TunnelProtocol) {
  442. meekResolvedIPAddress := dialParams.MeekResolvedIPAddress.Load().(string)
  443. if meekResolvedIPAddress != "" {
  444. nonredacted := common.EscapeRedactIPAddressString(meekResolvedIPAddress)
  445. args = append(args, "meekResolvedIPAddress", nonredacted)
  446. }
  447. }
  448. if dialParams.MeekSNIServerName != "" {
  449. args = append(args, "meekSNIServerName", dialParams.MeekSNIServerName)
  450. }
  451. if dialParams.MeekHostHeader != "" {
  452. args = append(args, "meekHostHeader", dialParams.MeekHostHeader)
  453. }
  454. // MeekTransformedHostName is meaningful when meek is used, which is when MeekDialAddress != ""
  455. if dialParams.MeekDialAddress != "" {
  456. args = append(args, "meekTransformedHostName", dialParams.MeekTransformedHostName)
  457. }
  458. if dialParams.TLSOSSHSNIServerName != "" {
  459. args = append(args, "tlsOSSHSNIServerName", dialParams.TLSOSSHSNIServerName)
  460. }
  461. if dialParams.TLSOSSHTransformedSNIServerName {
  462. args = append(args, "tlsOSSHTransformedSNIServerName", dialParams.TLSOSSHTransformedSNIServerName)
  463. }
  464. if dialParams.TLSFragmentClientHello {
  465. args = append(args, "tlsFragmentClientHello", dialParams.TLSFragmentClientHello)
  466. }
  467. if dialParams.SelectedUserAgent {
  468. args = append(args, "userAgent", dialParams.UserAgent)
  469. }
  470. if dialParams.SelectedTLSProfile {
  471. args = append(args, "TLSProfile", dialParams.TLSProfile)
  472. args = append(args, "TLSVersion", dialParams.GetTLSVersionForMetrics())
  473. }
  474. // dialParams.ServerEntry.Region is emitted above.
  475. if dialParams.ServerEntry.LocalSource != "" {
  476. args = append(args, "serverEntrySource", dialParams.ServerEntry.LocalSource)
  477. }
  478. localServerEntryTimestamp := common.TruncateTimestampToHour(
  479. dialParams.ServerEntry.LocalTimestamp)
  480. if localServerEntryTimestamp != "" {
  481. args = append(args, "serverEntryTimestamp", localServerEntryTimestamp)
  482. }
  483. if dialParams.DialPortNumber != "" {
  484. args = append(args, "dialPortNumber", dialParams.DialPortNumber)
  485. }
  486. if dialParams.QUICVersion != "" {
  487. args = append(args, "QUICVersion", dialParams.QUICVersion)
  488. }
  489. if dialParams.QUICDialSNIAddress != "" {
  490. args = append(args, "QUICDialSNIAddress", dialParams.QUICDialSNIAddress)
  491. }
  492. if dialParams.QUICDisablePathMTUDiscovery {
  493. args = append(args, "QUICDisableClientPathMTUDiscovery", dialParams.QUICDisablePathMTUDiscovery)
  494. }
  495. if dialParams.DialDuration > 0 {
  496. args = append(args, "dialDuration", dialParams.DialDuration)
  497. }
  498. if dialParams.NetworkLatencyMultiplier != 0.0 {
  499. args = append(args, "networkLatencyMultiplier", dialParams.NetworkLatencyMultiplier)
  500. }
  501. if dialParams.ConjureTransport != "" {
  502. args = append(args, "conjureTransport", dialParams.ConjureTransport)
  503. }
  504. usedSteeringIP := false
  505. if dialParams.SteeringIP != "" {
  506. nonredacted := common.EscapeRedactIPAddressString(dialParams.SteeringIP)
  507. args = append(args, "steeringIP", nonredacted)
  508. usedSteeringIP = true
  509. }
  510. if dialParams.ResolveParameters != nil && !usedSteeringIP {
  511. // See dialParams.ResolveParameters comment in getBaseAPIParameters.
  512. if dialParams.ResolveParameters.PreresolvedIPAddress != "" {
  513. meekDialDomain, _, _ := net.SplitHostPort(dialParams.MeekDialAddress)
  514. if dialParams.ResolveParameters.PreresolvedDomain == meekDialDomain {
  515. nonredacted := common.EscapeRedactIPAddressString(dialParams.ResolveParameters.PreresolvedIPAddress)
  516. args = append(args, "DNSPreresolved", nonredacted)
  517. }
  518. }
  519. if dialParams.ResolveParameters.PreferAlternateDNSServer {
  520. nonredacted := common.EscapeRedactIPAddressString(dialParams.ResolveParameters.AlternateDNSServer)
  521. args = append(args, "DNSPreferred", nonredacted)
  522. }
  523. if dialParams.ResolveParameters.ProtocolTransformName != "" {
  524. args = append(args, "DNSTransform", dialParams.ResolveParameters.ProtocolTransformName)
  525. }
  526. if postDial {
  527. args = append(args, "DNSQNameMismatches", dialParams.ResolveParameters.GetQNameMismatches())
  528. args = append(args, "DNSAttempt", dialParams.ResolveParameters.GetFirstAttemptWithAnswer())
  529. }
  530. }
  531. if dialParams.HTTPTransformerParameters != nil {
  532. if dialParams.HTTPTransformerParameters.ProtocolTransformSpec != nil {
  533. args = append(args, "HTTPTransform", dialParams.HTTPTransformerParameters.ProtocolTransformName)
  534. }
  535. }
  536. if dialParams.OSSHObfuscatorSeedTransformerParameters != nil {
  537. if dialParams.OSSHObfuscatorSeedTransformerParameters.TransformSpec != nil {
  538. args = append(args, "SeedTransform", dialParams.OSSHObfuscatorSeedTransformerParameters.TransformName)
  539. }
  540. }
  541. if dialParams.ObfuscatedQUICNonceTransformerParameters != nil {
  542. if dialParams.ObfuscatedQUICNonceTransformerParameters.TransformSpec != nil {
  543. args = append(args, "SeedTransform", dialParams.ObfuscatedQUICNonceTransformerParameters.TransformName)
  544. }
  545. }
  546. if dialParams.OSSHPrefixSpec != nil {
  547. if dialParams.OSSHPrefixSpec.Spec != nil {
  548. args = append(args, "OSSHPrefix", dialParams.OSSHPrefixSpec.Name)
  549. }
  550. }
  551. if dialParams.DialConnMetrics != nil {
  552. metrics := dialParams.DialConnMetrics.GetMetrics()
  553. for name, value := range metrics {
  554. args = append(args, name, value)
  555. }
  556. }
  557. if dialParams.DialConnNoticeMetrics != nil {
  558. metrics := dialParams.DialConnNoticeMetrics.GetNoticeMetrics()
  559. for name, value := range metrics {
  560. args = append(args, name, value)
  561. }
  562. }
  563. if dialParams.ObfuscatedSSHConnMetrics != nil {
  564. metrics := dialParams.ObfuscatedSSHConnMetrics.GetMetrics()
  565. for name, value := range metrics {
  566. args = append(args, name, value)
  567. }
  568. }
  569. if protocol.TunnelProtocolUsesInproxy(dialParams.TunnelProtocol) {
  570. metrics := dialParams.GetInproxyMetrics()
  571. for name, value := range metrics {
  572. args = append(args, name, value)
  573. }
  574. }
  575. if dialParams.ShadowsocksPrefixSpec != nil {
  576. if dialParams.ShadowsocksPrefixSpec.Spec != nil {
  577. args = append(args, "ShadowsocksPrefix", dialParams.ShadowsocksPrefixSpec.Name)
  578. }
  579. }
  580. }
  581. singletonNoticeLogger.outputNotice(
  582. noticeType, noticeIsDiagnostic,
  583. args...)
  584. }
  585. // NoticeConnectingServer reports parameters and details for a single connection attempt
  586. func NoticeConnectingServer(dialParams *DialParameters) {
  587. noticeWithDialParameters("ConnectingServer", dialParams, false)
  588. }
  589. // NoticeConnectedServer reports parameters and details for a single successful connection
  590. func NoticeConnectedServer(dialParams *DialParameters) {
  591. noticeWithDialParameters("ConnectedServer", dialParams, true)
  592. }
  593. // NoticeRequestingTactics reports parameters and details for a tactics request attempt
  594. func NoticeRequestingTactics(dialParams *DialParameters) {
  595. noticeWithDialParameters("RequestingTactics", dialParams, false)
  596. }
  597. // NoticeRequestedTactics reports parameters and details for a successful tactics request
  598. func NoticeRequestedTactics(dialParams *DialParameters) {
  599. noticeWithDialParameters("RequestedTactics", dialParams, true)
  600. }
  601. // NoticeActiveTunnel is a successful connection that is used as an active tunnel for port forwarding
  602. func NoticeActiveTunnel(diagnosticID, protocol string) {
  603. singletonNoticeLogger.outputNotice(
  604. "ActiveTunnel", noticeIsDiagnostic,
  605. "diagnosticID", diagnosticID,
  606. "protocol", protocol)
  607. }
  608. // NoticeConnectedServerRegion reports the region of the connected server
  609. func NoticeConnectedServerRegion(serverRegion string) {
  610. singletonNoticeLogger.outputNotice(
  611. "ConnectedServerRegion", 0,
  612. "serverRegion", serverRegion)
  613. }
  614. // NoticeSocksProxyPortInUse is a failure to use the configured LocalSocksProxyPort
  615. func NoticeSocksProxyPortInUse(port int) {
  616. singletonNoticeLogger.outputNotice(
  617. "SocksProxyPortInUse", 0,
  618. "port", port)
  619. }
  620. // NoticeListeningSocksProxyPort is the selected port for the listening local SOCKS proxy
  621. func NoticeListeningSocksProxyPort(port int) {
  622. singletonNoticeLogger.outputNotice(
  623. "ListeningSocksProxyPort", 0,
  624. "port", port)
  625. }
  626. // NoticeHttpProxyPortInUse is a failure to use the configured LocalHttpProxyPort
  627. func NoticeHttpProxyPortInUse(port int) {
  628. singletonNoticeLogger.outputNotice(
  629. "HttpProxyPortInUse", 0,
  630. "port", port)
  631. }
  632. // NoticeListeningHttpProxyPort is the selected port for the listening local HTTP proxy
  633. func NoticeListeningHttpProxyPort(port int) {
  634. singletonNoticeLogger.outputNotice(
  635. "ListeningHttpProxyPort", 0,
  636. "port", port)
  637. }
  638. // NoticeClientUpgradeAvailable is an available client upgrade, as per the handshake. The
  639. // client should download and install an upgrade.
  640. func NoticeClientUpgradeAvailable(version string) {
  641. singletonNoticeLogger.outputNotice(
  642. "ClientUpgradeAvailable", 0,
  643. "version", version)
  644. }
  645. // NoticeClientIsLatestVersion reports that an upgrade check was made and the client
  646. // is already the latest version. availableVersion is the version available for download,
  647. // if known.
  648. func NoticeClientIsLatestVersion(availableVersion string) {
  649. singletonNoticeLogger.outputNotice(
  650. "ClientIsLatestVersion", 0,
  651. "availableVersion", availableVersion)
  652. }
  653. // NoticeHomepages emits a series of NoticeHomepage, the sponsor homepages. The client
  654. // should display the sponsor's homepages.
  655. func NoticeHomepages(urls []string) {
  656. for i, url := range urls {
  657. noticeFlags := uint32(noticeIsHomepage)
  658. if i == 0 {
  659. noticeFlags |= noticeClearHomepages
  660. }
  661. if i == len(urls)-1 {
  662. noticeFlags |= noticeSyncHomepages
  663. }
  664. singletonNoticeLogger.outputNotice(
  665. "Homepage", noticeFlags,
  666. "url", url)
  667. }
  668. }
  669. // NoticeClientRegion is the client's region, as determined by the server and
  670. // reported to the client in the handshake.
  671. func NoticeClientRegion(region string) {
  672. singletonNoticeLogger.outputNotice(
  673. "ClientRegion", 0,
  674. "region", region)
  675. }
  676. // NoticeClientAddress is the client's public network address, the IP address
  677. // and port, as seen by the server and reported to the client in the
  678. // handshake.
  679. //
  680. // Note: "address" should remain private and not included in diagnostics logs.
  681. func NoticeClientAddress(address string) {
  682. singletonNoticeLogger.outputNotice(
  683. "ClientAddress", noticeSkipRedaction,
  684. "address", address)
  685. }
  686. // NoticeTunnels is how many active tunnels are available. The client should use this to
  687. // determine connecting/unexpected disconnect state transitions. When count is 0, the core is
  688. // disconnected; when count > 1, the core is connected.
  689. func NoticeTunnels(count int) {
  690. singletonNoticeLogger.outputNotice(
  691. "Tunnels", 0,
  692. "count", count)
  693. }
  694. // NoticeSessionId is the session ID used across all tunnels established by the controller.
  695. func NoticeSessionId(sessionId string) {
  696. singletonNoticeLogger.outputNotice(
  697. "SessionId", noticeIsDiagnostic,
  698. "sessionId", sessionId)
  699. }
  700. // NoticeSplitTunnelRegions reports that split tunnel is on for the given country codes.
  701. func NoticeSplitTunnelRegions(regions []string) {
  702. singletonNoticeLogger.outputNotice(
  703. "SplitTunnelRegions", 0,
  704. "regions", regions)
  705. }
  706. // NoticeUntunneled indicates than an address has been classified as untunneled and is being
  707. // accessed directly.
  708. //
  709. // Note: "address" should remain private; this notice should only be used for alerting
  710. // users, not for diagnostics logs.
  711. func NoticeUntunneled(address string) {
  712. outputRepetitiveNotice(
  713. "Untunneled", address, 0,
  714. "Untunneled", noticeSkipRedaction, "address", address)
  715. }
  716. // NoticeUpstreamProxyError reports an error when connecting to an upstream proxy. The
  717. // user may have input, for example, an incorrect address or incorrect credentials.
  718. func NoticeUpstreamProxyError(err error) {
  719. message := err.Error()
  720. outputRepetitiveNotice(
  721. "UpstreamProxyError", message, 0,
  722. "UpstreamProxyError", 0,
  723. "message", message)
  724. }
  725. // NoticeClientUpgradeDownloadedBytes reports client upgrade download progress.
  726. func NoticeClientUpgradeDownloadedBytes(bytes int64) {
  727. singletonNoticeLogger.outputNotice(
  728. "ClientUpgradeDownloadedBytes", noticeIsDiagnostic,
  729. "bytes", bytes)
  730. }
  731. // NoticeClientUpgradeDownloaded indicates that a client upgrade download
  732. // is complete and available at the destination specified.
  733. func NoticeClientUpgradeDownloaded(filename string) {
  734. singletonNoticeLogger.outputNotice(
  735. "ClientUpgradeDownloaded", 0,
  736. "filename", filename)
  737. }
  738. // NoticeBytesTransferred reports how many tunneled bytes have been
  739. // transferred since the last NoticeBytesTransferred. This is not a diagnostic
  740. // notice: the user app has requested this notice with EmitBytesTransferred
  741. // for functionality such as traffic display; and this frequent notice is not
  742. // intended to be included with feedback. The noticeIsNotDiagnostic flag
  743. // ensures that these notices are emitted to the host application but not written
  744. // to the diagnostic file to avoid cluttering it with frequent updates.
  745. func NoticeBytesTransferred(diagnosticID string, sent, received int64) {
  746. singletonNoticeLogger.outputNotice(
  747. "BytesTransferred", noticeIsNotDiagnostic,
  748. "diagnosticID", diagnosticID,
  749. "sent", sent,
  750. "received", received)
  751. }
  752. // NoticeTotalBytesTransferred reports how many tunneled bytes have been
  753. // transferred in total up to this point. This is a diagnostic notice.
  754. func NoticeTotalBytesTransferred(diagnosticID string, sent, received int64) {
  755. singletonNoticeLogger.outputNotice(
  756. "TotalBytesTransferred", noticeIsDiagnostic,
  757. "diagnosticID", diagnosticID,
  758. "sent", sent,
  759. "received", received)
  760. }
  761. // NoticeLocalProxyError reports a local proxy error message. Repetitive
  762. // errors for a given proxy type are suppressed.
  763. func NoticeLocalProxyError(proxyType string, err error) {
  764. // For repeats, only consider the base error message, which is
  765. // the root error that repeats (the full error often contains
  766. // different specific values, e.g., local port numbers, but
  767. // the same repeating root).
  768. // Assumes error format of errors.Trace.
  769. repetitionMessage := err.Error()
  770. index := strings.LastIndex(repetitionMessage, ": ")
  771. if index != -1 {
  772. repetitionMessage = repetitionMessage[index+2:]
  773. }
  774. outputRepetitiveNotice(
  775. "LocalProxyError-"+proxyType, repetitionMessage, 1,
  776. "LocalProxyError", noticeIsDiagnostic,
  777. "message", err.Error())
  778. }
  779. // NoticeBuildInfo reports build version info.
  780. func NoticeBuildInfo() {
  781. singletonNoticeLogger.outputNotice(
  782. "BuildInfo", noticeIsDiagnostic,
  783. "buildInfo", buildinfo.GetBuildInfo())
  784. }
  785. // NoticeExiting indicates that tunnel-core is exiting imminently.
  786. func NoticeExiting() {
  787. singletonNoticeLogger.outputNotice(
  788. "Exiting", 0)
  789. }
  790. // NoticeRemoteServerListResourceDownloadedBytes reports remote server list download progress.
  791. func NoticeRemoteServerListResourceDownloadedBytes(url string, bytes int64, duration time.Duration) {
  792. if !GetEmitNetworkParameters() {
  793. url = "[redacted]"
  794. }
  795. singletonNoticeLogger.outputNotice(
  796. "RemoteServerListResourceDownloadedBytes", noticeIsDiagnostic,
  797. "url", url,
  798. "bytes", bytes,
  799. "duration", duration.String())
  800. }
  801. // NoticeRemoteServerListResourceDownloaded indicates that a remote server list download
  802. // completed successfully.
  803. func NoticeRemoteServerListResourceDownloaded(url string) {
  804. if !GetEmitNetworkParameters() {
  805. url = "[redacted]"
  806. }
  807. singletonNoticeLogger.outputNotice(
  808. "RemoteServerListResourceDownloaded", noticeIsDiagnostic,
  809. "url", url)
  810. }
  811. // NoticeSLOKSeeded indicates that the SLOK with the specified ID was received from
  812. // the Psiphon server. The "duplicate" flags indicates whether the SLOK was previously known.
  813. func NoticeSLOKSeeded(slokID string, duplicate bool) {
  814. singletonNoticeLogger.outputNotice(
  815. "SLOKSeeded", noticeIsDiagnostic,
  816. "slokID", slokID,
  817. "duplicate", duplicate)
  818. }
  819. // NoticeServerTimestamp reports server side timestamp as seen in the handshake.
  820. func NoticeServerTimestamp(diagnosticID string, timestamp string) {
  821. singletonNoticeLogger.outputNotice(
  822. "ServerTimestamp", 0,
  823. "diagnosticID", diagnosticID,
  824. "timestamp", timestamp)
  825. }
  826. // NoticeActiveAuthorizationIDs reports the authorizations the server has accepted.
  827. // Each ID is a base64-encoded accesscontrol.Authorization.ID value.
  828. func NoticeActiveAuthorizationIDs(diagnosticID string, activeAuthorizationIDs []string) {
  829. // Never emit 'null' instead of empty list
  830. if activeAuthorizationIDs == nil {
  831. activeAuthorizationIDs = []string{}
  832. }
  833. singletonNoticeLogger.outputNotice(
  834. "ActiveAuthorizationIDs", 0,
  835. "diagnosticID", diagnosticID,
  836. "IDs", activeAuthorizationIDs)
  837. }
  838. // NoticeTrafficRateLimits reports the tunnel traffic rate limits in place for
  839. // this client, as reported by the server at the start of the tunnel. Values
  840. // of 0 indicate no limit. Values of -1 indicate that the server did not
  841. // report rate limits.
  842. //
  843. // Limitation: any rate limit changes during the lifetime of the tunnel are
  844. // not reported.
  845. func NoticeTrafficRateLimits(
  846. diagnosticID string, upstreamBytesPerSecond, downstreamBytesPerSecond int64) {
  847. singletonNoticeLogger.outputNotice(
  848. "TrafficRateLimits", 0,
  849. "diagnosticID", diagnosticID,
  850. "upstreamBytesPerSecond", upstreamBytesPerSecond,
  851. "downstreamBytesPerSecond", downstreamBytesPerSecond)
  852. }
  853. func NoticeBindToDevice(deviceInfo string) {
  854. outputRepetitiveNotice(
  855. "BindToDevice", deviceInfo, 0,
  856. "BindToDevice", 0, "deviceInfo", deviceInfo)
  857. }
  858. func NoticeNetworkID(networkID string) {
  859. outputRepetitiveNotice(
  860. "NetworkID", networkID, 0,
  861. "NetworkID", 0, "ID", networkID)
  862. }
  863. func NoticeLivenessTest(diagnosticID string, metrics *livenessTestMetrics, success bool) {
  864. if GetEmitNetworkParameters() {
  865. singletonNoticeLogger.outputNotice(
  866. "LivenessTest", noticeIsDiagnostic,
  867. "diagnosticID", diagnosticID,
  868. "metrics", metrics,
  869. "success", success)
  870. }
  871. }
  872. func NoticePruneServerEntry(serverEntryTag string) {
  873. singletonNoticeLogger.outputNotice(
  874. "PruneServerEntry", noticeIsDiagnostic,
  875. "serverEntryTag", serverEntryTag)
  876. }
  877. // NoticeEstablishTunnelTimeout reports that the configured EstablishTunnelTimeout
  878. // duration was exceeded.
  879. func NoticeEstablishTunnelTimeout(timeout time.Duration) {
  880. singletonNoticeLogger.outputNotice(
  881. "EstablishTunnelTimeout", 0,
  882. "timeout", timeout.String())
  883. }
  884. func NoticeFragmentor(diagnosticID string, message string) {
  885. if GetEmitNetworkParameters() {
  886. singletonNoticeLogger.outputNotice(
  887. "Fragmentor", noticeIsDiagnostic,
  888. "diagnosticID", diagnosticID,
  889. "message", message)
  890. }
  891. }
  892. // NoticeApplicationParameters reports application parameters.
  893. func NoticeApplicationParameters(keyValues parameters.KeyValues) {
  894. // Never emit 'null' instead of empty object
  895. if keyValues == nil {
  896. keyValues = parameters.KeyValues{}
  897. }
  898. outputRepetitiveNotice(
  899. "ApplicationParameters", fmt.Sprintf("%+v", keyValues), 0,
  900. "ApplicationParameters", 0,
  901. "parameters", keyValues)
  902. }
  903. // NoticeServerAlert reports server alerts. Each distinct server alert is
  904. // reported at most once per session.
  905. func NoticeServerAlert(alert protocol.AlertRequest) {
  906. // Never emit 'null' instead of empty list
  907. actionURLs := alert.ActionURLs
  908. if actionURLs == nil {
  909. actionURLs = []string{}
  910. }
  911. // This key ensures that each distinct server alert will appear, not repeat,
  912. // and not interfere with other alerts appearing.
  913. repetitionKey := fmt.Sprintf("ServerAlert-%+v", alert)
  914. outputRepetitiveNotice(
  915. repetitionKey, "", 0,
  916. "ServerAlert", 0,
  917. "reason", alert.Reason,
  918. "subject", alert.Subject,
  919. "actionURLs", actionURLs)
  920. }
  921. // NoticeBursts reports tunnel data transfer burst metrics.
  922. func NoticeBursts(diagnosticID string, burstMetrics common.LogFields) {
  923. if GetEmitNetworkParameters() {
  924. singletonNoticeLogger.outputNotice(
  925. "Bursts", noticeIsDiagnostic,
  926. append([]interface{}{"diagnosticID", diagnosticID}, listCommonFields(burstMetrics)...)...)
  927. }
  928. }
  929. // NoticeHoldOffTunnel reports tunnel hold-offs.
  930. func NoticeHoldOffTunnel(diagnosticID string, duration time.Duration) {
  931. if GetEmitNetworkParameters() {
  932. singletonNoticeLogger.outputNotice(
  933. "HoldOffTunnel", noticeIsDiagnostic,
  934. "diagnosticID", diagnosticID,
  935. "duration", duration.String())
  936. }
  937. }
  938. // NoticeSkipServerEntry reports a reason for skipping a server entry when
  939. // preparing dial parameters. To avoid log noise, the server entry
  940. // diagnosticID is not emitted and each reason is reported at most once per
  941. // session.
  942. func NoticeSkipServerEntry(format string, args ...interface{}) {
  943. reason := fmt.Sprintf(format, args...)
  944. repetitionKey := fmt.Sprintf("SkipServerEntryReason-%+v", reason)
  945. outputRepetitiveNotice(
  946. repetitionKey, "", 0,
  947. "SkipServerEntry", 0, "reason", reason)
  948. }
  949. // NoticeInproxyMustUpgrade reports that an in-proxy component requires an app
  950. // upgrade. Currently this includes running a proxy; and running a client in
  951. // personal pairing mode. The receiver should alert the user to upgrade the
  952. // app.
  953. //
  954. // There is at most one InproxyMustUpgrade notice emitted per controller run,
  955. // and an InproxyMustUpgrade notice is followed by a tunnel-core shutdown.
  956. func NoticeInproxyMustUpgrade() {
  957. singletonNoticeLogger.outputNotice(
  958. "InproxyMustUpgrade", 0)
  959. }
  960. // NoticeInproxyProxyActivity reports proxy usage statistics. The stats are
  961. // for activity since the last NoticeInproxyProxyActivity report.
  962. //
  963. // This is not a diagnostic notice: the user app has requested this notice
  964. // with EmitInproxyProxyActivity for functionality such as traffic display;
  965. // and this frequent notice is not intended to be included with feedback.
  966. func NoticeInproxyProxyActivity(
  967. connectingClients int32,
  968. connectedClients int32,
  969. bytesUp int64,
  970. bytesDown int64) {
  971. singletonNoticeLogger.outputNotice(
  972. "InproxyProxyActivity", noticeIsNotDiagnostic,
  973. "connectingClients", connectingClients,
  974. "connectedClients", connectedClients,
  975. "bytesUp", bytesUp,
  976. "bytesDown", bytesDown)
  977. }
  978. // NoticeInproxyProxyTotalActivity reports how many proxied bytes have been
  979. // transferred in total up to this point; in addition to current connection
  980. // status. This is a diagnostic notice.
  981. func NoticeInproxyProxyTotalActivity(
  982. connectingClients int32,
  983. connectedClients int32,
  984. totalBytesUp int64,
  985. totalBytesDown int64) {
  986. singletonNoticeLogger.outputNotice(
  987. "InproxyProxyTotalActivity", noticeIsDiagnostic,
  988. "connectingClients", connectingClients,
  989. "connectedClients", connectedClients,
  990. "totalBytesUp", totalBytesUp,
  991. "totalBytesDown", totalBytesDown)
  992. }
  993. type repetitiveNoticeState struct {
  994. message string
  995. repeats int
  996. }
  997. var repetitiveNoticeMutex sync.Mutex
  998. var repetitiveNoticeStates = make(map[string]*repetitiveNoticeState)
  999. // outputRepetitiveNotice conditionally outputs a notice. Used for noticies which
  1000. // often repeat in noisy bursts. For a repeat limit of N, the notice is emitted
  1001. // with a "repeats" count on consecutive repeats up to the limit and then suppressed
  1002. // until the repetitionMessage differs.
  1003. func outputRepetitiveNotice(
  1004. repetitionKey, repetitionMessage string, repeatLimit int,
  1005. noticeType string, noticeFlags uint32, args ...interface{}) {
  1006. repetitiveNoticeMutex.Lock()
  1007. defer repetitiveNoticeMutex.Unlock()
  1008. state, keyFound := repetitiveNoticeStates[repetitionKey]
  1009. if !keyFound {
  1010. state = &repetitiveNoticeState{message: repetitionMessage}
  1011. repetitiveNoticeStates[repetitionKey] = state
  1012. }
  1013. emit := true
  1014. if keyFound {
  1015. if repetitionMessage != state.message {
  1016. state.message = repetitionMessage
  1017. state.repeats = 0
  1018. } else {
  1019. state.repeats += 1
  1020. if state.repeats > repeatLimit {
  1021. emit = false
  1022. }
  1023. }
  1024. }
  1025. if emit {
  1026. if state.repeats > 0 {
  1027. args = append(args, "repeats", state.repeats)
  1028. }
  1029. singletonNoticeLogger.outputNotice(
  1030. noticeType, noticeFlags,
  1031. args...)
  1032. }
  1033. }
  1034. // ResetRepetitiveNotices resets the repetitive notice state, so
  1035. // the next instance of any notice will not be supressed.
  1036. func ResetRepetitiveNotices() {
  1037. repetitiveNoticeMutex.Lock()
  1038. defer repetitiveNoticeMutex.Unlock()
  1039. repetitiveNoticeStates = make(map[string]*repetitiveNoticeState)
  1040. }
  1041. type noticeObject struct {
  1042. NoticeType string `json:"noticeType"`
  1043. Data json.RawMessage `json:"data"`
  1044. Timestamp string `json:"timestamp"`
  1045. }
  1046. // GetNotice receives a JSON encoded object and attempts to parse it as a Notice.
  1047. // The type is returned as a string and the payload as a generic map.
  1048. func GetNotice(notice []byte) (
  1049. noticeType string, payload map[string]interface{}, err error) {
  1050. var object noticeObject
  1051. err = json.Unmarshal(notice, &object)
  1052. if err != nil {
  1053. return "", nil, errors.Trace(err)
  1054. }
  1055. var data interface{}
  1056. err = json.Unmarshal(object.Data, &data)
  1057. if err != nil {
  1058. return "", nil, errors.Trace(err)
  1059. }
  1060. dataValue, ok := data.(map[string]interface{})
  1061. if !ok {
  1062. return "", nil, errors.TraceNew("invalid data value")
  1063. }
  1064. return object.NoticeType, dataValue, nil
  1065. }
  1066. // NoticeReceiver consumes a notice input stream and invokes a callback function
  1067. // for each discrete JSON notice object byte sequence.
  1068. type NoticeReceiver struct {
  1069. mutex sync.Mutex
  1070. buffer []byte
  1071. callback func([]byte)
  1072. }
  1073. // NewNoticeReceiver initializes a new NoticeReceiver
  1074. func NewNoticeReceiver(callback func([]byte)) *NoticeReceiver {
  1075. return &NoticeReceiver{callback: callback}
  1076. }
  1077. // Write implements io.Writer.
  1078. func (receiver *NoticeReceiver) Write(p []byte) (n int, err error) {
  1079. receiver.mutex.Lock()
  1080. defer receiver.mutex.Unlock()
  1081. receiver.buffer = append(receiver.buffer, p...)
  1082. index := bytes.Index(receiver.buffer, []byte("\n"))
  1083. if index == -1 {
  1084. return len(p), nil
  1085. }
  1086. notice := receiver.buffer[:index]
  1087. receiver.callback(notice)
  1088. if index == len(receiver.buffer)-1 {
  1089. receiver.buffer = receiver.buffer[0:0]
  1090. } else {
  1091. receiver.buffer = receiver.buffer[index+1:]
  1092. }
  1093. return len(p), nil
  1094. }
  1095. // NewNoticeConsoleRewriter consumes JSON-format notice input and parses each
  1096. // notice and rewrites in a more human-readable format more suitable for
  1097. // console output. The data payload field is left as JSON.
  1098. func NewNoticeConsoleRewriter(writer io.Writer) *NoticeReceiver {
  1099. return NewNoticeReceiver(func(notice []byte) {
  1100. var object noticeObject
  1101. _ = json.Unmarshal(notice, &object)
  1102. fmt.Fprintf(
  1103. writer,
  1104. "%s %s %s\n",
  1105. object.Timestamp,
  1106. object.NoticeType,
  1107. string(object.Data))
  1108. })
  1109. }
  1110. // NoticeWriter implements io.Writer and emits the contents of Write() calls
  1111. // as Notices. This is to transform logger messages, if they can be redirected
  1112. // to an io.Writer, to notices.
  1113. type NoticeWriter struct {
  1114. noticeType string
  1115. }
  1116. // NewNoticeWriter initializes a new NoticeWriter
  1117. func NewNoticeWriter(noticeType string) *NoticeWriter {
  1118. return &NoticeWriter{noticeType: noticeType}
  1119. }
  1120. // Write implements io.Writer.
  1121. func (writer *NoticeWriter) Write(p []byte) (n int, err error) {
  1122. singletonNoticeLogger.outputNotice(
  1123. writer.noticeType, noticeIsDiagnostic,
  1124. "message", string(p))
  1125. return len(p), nil
  1126. }
  1127. // NoticeLineWriter implements io.Writer and emits the contents of Write calls
  1128. // as Notices. NoticeLineWriter buffers writes and emits a notice for each
  1129. // complete, newline delimited line. Tab characters are replaced with spaces.
  1130. type NoticeLineWriter struct {
  1131. noticeType string
  1132. lineBuffer strings.Builder
  1133. }
  1134. // NoticeLineWriter initializes a new NoticeLineWriter
  1135. func NewNoticeLineWriter(noticeType string) *NoticeLineWriter {
  1136. return &NoticeLineWriter{noticeType: noticeType}
  1137. }
  1138. // Write implements io.Writer.
  1139. func (writer *NoticeLineWriter) Write(p []byte) (n int, err error) {
  1140. str := strings.ReplaceAll(string(p), "\t", " ")
  1141. for {
  1142. before, after, found := strings.Cut(str, "\n")
  1143. writer.lineBuffer.WriteString(before)
  1144. if !found {
  1145. return len(p), nil
  1146. }
  1147. singletonNoticeLogger.outputNotice(
  1148. writer.noticeType, noticeIsDiagnostic,
  1149. "message", writer.lineBuffer.String())
  1150. writer.lineBuffer.Reset()
  1151. if len(after) == 0 {
  1152. break
  1153. }
  1154. str = after
  1155. }
  1156. return len(p), nil
  1157. }
  1158. // NoticeCommonLogger maps the common.Logger interface to the notice facility.
  1159. // This is used to make the notice facility available to other packages that
  1160. // don't import the "psiphon" package.
  1161. func NoticeCommonLogger(debugLogging bool) common.Logger {
  1162. return &commonLogger{
  1163. debugLogging: debugLogging,
  1164. }
  1165. }
  1166. type commonLogger struct {
  1167. debugLogging bool
  1168. }
  1169. func (logger *commonLogger) WithTrace() common.LogTrace {
  1170. return &commonLogTrace{
  1171. trace: stacktrace.GetParentFunctionName(),
  1172. debugLogging: logger.debugLogging,
  1173. }
  1174. }
  1175. func (logger *commonLogger) WithTraceFields(fields common.LogFields) common.LogTrace {
  1176. return &commonLogTrace{
  1177. trace: stacktrace.GetParentFunctionName(),
  1178. fields: fields,
  1179. debugLogging: logger.debugLogging,
  1180. }
  1181. }
  1182. func (logger *commonLogger) LogMetric(metric string, fields common.LogFields) {
  1183. singletonNoticeLogger.outputNotice(
  1184. metric, noticeIsDiagnostic,
  1185. listCommonFields(fields)...)
  1186. }
  1187. func (log *commonLogger) IsLogLevelDebug() bool {
  1188. return log.debugLogging
  1189. }
  1190. func listCommonFields(fields common.LogFields) []interface{} {
  1191. fieldList := make([]interface{}, 0)
  1192. for name, value := range fields {
  1193. fieldList = append(fieldList, name, value)
  1194. }
  1195. return fieldList
  1196. }
  1197. type commonLogTrace struct {
  1198. trace string
  1199. fields common.LogFields
  1200. debugLogging bool
  1201. }
  1202. func (log *commonLogTrace) outputNotice(
  1203. noticeType string, args ...interface{}) {
  1204. singletonNoticeLogger.outputNotice(
  1205. noticeType, noticeIsDiagnostic,
  1206. append(
  1207. []interface{}{
  1208. "message", fmt.Sprint(args...),
  1209. "trace", log.trace},
  1210. listCommonFields(log.fields)...)...)
  1211. }
  1212. func (log *commonLogTrace) Debug(args ...interface{}) {
  1213. if !log.debugLogging {
  1214. return
  1215. }
  1216. log.outputNotice("Debug", args...)
  1217. }
  1218. func (log *commonLogTrace) Info(args ...interface{}) {
  1219. log.outputNotice("Info", args...)
  1220. }
  1221. func (log *commonLogTrace) Warning(args ...interface{}) {
  1222. log.outputNotice("Alert", args...)
  1223. }
  1224. func (log *commonLogTrace) Error(args ...interface{}) {
  1225. log.outputNotice("Error", args...)
  1226. }