source: code/trunk/server.go@ 748

Last change on this file since 748 was 747, checked in by contact, 4 years ago

Add Logger.Debugf

Makes it easy to print debugging messages which aren't targeted at
the user. See [1] for motivation.

[1]: https://dave.cheney.net/2015/11/05/lets-talk-about-logging

File size: 9.1 KB
Line 
1package soju
2
3import (
4 "context"
5 "errors"
6 "fmt"
7 "io"
8 "log"
9 "mime"
10 "net"
11 "net/http"
12 "runtime/debug"
13 "sync"
14 "sync/atomic"
15 "time"
16
17 "github.com/prometheus/client_golang/prometheus"
18 "github.com/prometheus/client_golang/prometheus/promauto"
19 "gopkg.in/irc.v3"
20 "nhooyr.io/websocket"
21
22 "git.sr.ht/~emersion/soju/config"
23)
24
25// TODO: make configurable
26var retryConnectMinDelay = time.Minute
27var retryConnectMaxDelay = 10 * time.Minute
28var retryConnectJitter = time.Minute
29var connectTimeout = 15 * time.Second
30var writeTimeout = 10 * time.Second
31var upstreamMessageDelay = 2 * time.Second
32var upstreamMessageBurst = 10
33var backlogTimeout = 10 * time.Second
34var handleDownstreamMessageTimeout = 10 * time.Second
35var downstreamRegisterTimeout = 30 * time.Second
36var chatHistoryLimit = 1000
37var backlogLimit = 4000
38
39type Logger interface {
40 Printf(format string, v ...interface{})
41 Debugf(format string, v ...interface{})
42}
43
44type logger struct {
45 *log.Logger
46 debug bool
47}
48
49func (l logger) Debugf(format string, v ...interface{}) {
50 if !l.debug {
51 return
52 }
53 l.Logger.Printf(format, v...)
54}
55
56func NewLogger(out io.Writer, debug bool) Logger {
57 return logger{
58 Logger: log.New(log.Writer(), "", log.LstdFlags),
59 debug: debug,
60 }
61}
62
63type prefixLogger struct {
64 logger Logger
65 prefix string
66}
67
68var _ Logger = (*prefixLogger)(nil)
69
70func (l *prefixLogger) Printf(format string, v ...interface{}) {
71 v = append([]interface{}{l.prefix}, v...)
72 l.logger.Printf("%v"+format, v...)
73}
74
75func (l *prefixLogger) Debugf(format string, v ...interface{}) {
76 v = append([]interface{}{l.prefix}, v...)
77 l.logger.Debugf("%v"+format, v...)
78}
79
80type int64Gauge struct {
81 v int64 // atomic
82}
83
84func (g *int64Gauge) Add(delta int64) {
85 atomic.AddInt64(&g.v, delta)
86}
87
88func (g *int64Gauge) Value() int64 {
89 return atomic.LoadInt64(&g.v)
90}
91
92func (g *int64Gauge) Float64() float64 {
93 return float64(g.Value())
94}
95
96type Config struct {
97 Hostname string
98 Title string
99 LogPath string
100 HTTPOrigins []string
101 AcceptProxyIPs config.IPSet
102 MaxUserNetworks int
103 MultiUpstream bool
104 MOTD string
105 UpstreamUserIPs []*net.IPNet
106}
107
108type Server struct {
109 Logger Logger
110 Identd *Identd // can be nil
111 MetricsRegistry prometheus.Registerer // can be nil
112
113 config atomic.Value // *Config
114 db Database
115 stopWG sync.WaitGroup
116
117 lock sync.Mutex
118 listeners map[net.Listener]struct{}
119 users map[string]*user
120
121 metrics struct {
122 downstreams int64Gauge
123 upstreams int64Gauge
124
125 upstreamOutMessagesTotal prometheus.Counter
126 upstreamInMessagesTotal prometheus.Counter
127 downstreamOutMessagesTotal prometheus.Counter
128 downstreamInMessagesTotal prometheus.Counter
129
130 upstreamConnectErrorsTotal prometheus.Counter
131 }
132}
133
134func NewServer(db Database) *Server {
135 srv := &Server{
136 Logger: NewLogger(log.Writer(), true),
137 db: db,
138 listeners: make(map[net.Listener]struct{}),
139 users: make(map[string]*user),
140 }
141 srv.config.Store(&Config{
142 Hostname: "localhost",
143 MaxUserNetworks: -1,
144 MultiUpstream: true,
145 })
146 return srv
147}
148
149func (s *Server) prefix() *irc.Prefix {
150 return &irc.Prefix{Name: s.Config().Hostname}
151}
152
153func (s *Server) Config() *Config {
154 return s.config.Load().(*Config)
155}
156
157func (s *Server) SetConfig(cfg *Config) {
158 s.config.Store(cfg)
159}
160
161func (s *Server) Start() error {
162 s.registerMetrics()
163
164 users, err := s.db.ListUsers(context.TODO())
165 if err != nil {
166 return err
167 }
168
169 s.lock.Lock()
170 for i := range users {
171 s.addUserLocked(&users[i])
172 }
173 s.lock.Unlock()
174
175 return nil
176}
177
178func (s *Server) registerMetrics() {
179 factory := promauto.With(s.MetricsRegistry)
180
181 factory.NewGaugeFunc(prometheus.GaugeOpts{
182 Name: "soju_users_active",
183 Help: "Current number of active users",
184 }, func() float64 {
185 s.lock.Lock()
186 n := len(s.users)
187 s.lock.Unlock()
188 return float64(n)
189 })
190
191 factory.NewGaugeFunc(prometheus.GaugeOpts{
192 Name: "soju_downstreams_active",
193 Help: "Current number of downstream connections",
194 }, s.metrics.downstreams.Float64)
195
196 factory.NewGaugeFunc(prometheus.GaugeOpts{
197 Name: "soju_upstreams_active",
198 Help: "Current number of upstream connections",
199 }, s.metrics.upstreams.Float64)
200
201 s.metrics.upstreamOutMessagesTotal = factory.NewCounter(prometheus.CounterOpts{
202 Name: "soju_upstream_out_messages_total",
203 Help: "Total number of outgoing messages sent to upstream servers",
204 })
205
206 s.metrics.upstreamInMessagesTotal = factory.NewCounter(prometheus.CounterOpts{
207 Name: "soju_upstream_in_messages_total",
208 Help: "Total number of incoming messages received from upstream servers",
209 })
210
211 s.metrics.downstreamOutMessagesTotal = factory.NewCounter(prometheus.CounterOpts{
212 Name: "soju_downstream_out_messages_total",
213 Help: "Total number of outgoing messages sent to downstream clients",
214 })
215
216 s.metrics.downstreamInMessagesTotal = factory.NewCounter(prometheus.CounterOpts{
217 Name: "soju_downstream_in_messages_total",
218 Help: "Total number of incoming messages received from downstream clients",
219 })
220
221 s.metrics.upstreamConnectErrorsTotal = factory.NewCounter(prometheus.CounterOpts{
222 Name: "soju_upstream_connect_errors_total",
223 Help: "Total number of upstream connection errors",
224 })
225}
226
227func (s *Server) Shutdown() {
228 s.lock.Lock()
229 for ln := range s.listeners {
230 if err := ln.Close(); err != nil {
231 s.Logger.Printf("failed to stop listener: %v", err)
232 }
233 }
234 for _, u := range s.users {
235 u.events <- eventStop{}
236 }
237 s.lock.Unlock()
238
239 s.stopWG.Wait()
240
241 if err := s.db.Close(); err != nil {
242 s.Logger.Printf("failed to close DB: %v", err)
243 }
244}
245
246func (s *Server) createUser(ctx context.Context, user *User) (*user, error) {
247 s.lock.Lock()
248 defer s.lock.Unlock()
249
250 if _, ok := s.users[user.Username]; ok {
251 return nil, fmt.Errorf("user %q already exists", user.Username)
252 }
253
254 err := s.db.StoreUser(ctx, user)
255 if err != nil {
256 return nil, fmt.Errorf("could not create user in db: %v", err)
257 }
258
259 return s.addUserLocked(user), nil
260}
261
262func (s *Server) forEachUser(f func(*user)) {
263 s.lock.Lock()
264 for _, u := range s.users {
265 f(u)
266 }
267 s.lock.Unlock()
268}
269
270func (s *Server) getUser(name string) *user {
271 s.lock.Lock()
272 u := s.users[name]
273 s.lock.Unlock()
274 return u
275}
276
277func (s *Server) addUserLocked(user *User) *user {
278 s.Logger.Printf("starting bouncer for user %q", user.Username)
279 u := newUser(s, user)
280 s.users[u.Username] = u
281
282 s.stopWG.Add(1)
283
284 go func() {
285 defer func() {
286 if err := recover(); err != nil {
287 s.Logger.Printf("panic serving user %q: %v\n%v", user.Username, err, debug.Stack())
288 }
289 }()
290
291 u.run()
292
293 s.lock.Lock()
294 delete(s.users, u.Username)
295 s.lock.Unlock()
296
297 s.stopWG.Done()
298 }()
299
300 return u
301}
302
303var lastDownstreamID uint64 = 0
304
305func (s *Server) handle(ic ircConn) {
306 defer func() {
307 if err := recover(); err != nil {
308 s.Logger.Printf("panic serving downstream %q: %v\n%v", ic.RemoteAddr(), err, debug.Stack())
309 }
310 }()
311
312 s.metrics.downstreams.Add(1)
313 id := atomic.AddUint64(&lastDownstreamID, 1)
314 dc := newDownstreamConn(s, ic, id)
315 if err := dc.runUntilRegistered(); err != nil {
316 if !errors.Is(err, io.EOF) {
317 dc.logger.Printf("%v", err)
318 }
319 } else {
320 dc.user.events <- eventDownstreamConnected{dc}
321 if err := dc.readMessages(dc.user.events); err != nil {
322 dc.logger.Printf("%v", err)
323 }
324 dc.user.events <- eventDownstreamDisconnected{dc}
325 }
326 dc.Close()
327 s.metrics.downstreams.Add(-1)
328}
329
330func (s *Server) Serve(ln net.Listener) error {
331 s.lock.Lock()
332 s.listeners[ln] = struct{}{}
333 s.lock.Unlock()
334
335 s.stopWG.Add(1)
336
337 defer func() {
338 s.lock.Lock()
339 delete(s.listeners, ln)
340 s.lock.Unlock()
341
342 s.stopWG.Done()
343 }()
344
345 for {
346 conn, err := ln.Accept()
347 if isErrClosed(err) {
348 return nil
349 } else if err != nil {
350 return fmt.Errorf("failed to accept connection: %v", err)
351 }
352
353 go s.handle(newNetIRCConn(conn))
354 }
355}
356
357func (s *Server) ServeHTTP(w http.ResponseWriter, req *http.Request) {
358 conn, err := websocket.Accept(w, req, &websocket.AcceptOptions{
359 Subprotocols: []string{"text.ircv3.net"}, // non-compliant, fight me
360 OriginPatterns: s.Config().HTTPOrigins,
361 })
362 if err != nil {
363 s.Logger.Printf("failed to serve HTTP connection: %v", err)
364 return
365 }
366
367 isProxy := false
368 if host, _, err := net.SplitHostPort(req.RemoteAddr); err == nil {
369 if ip := net.ParseIP(host); ip != nil {
370 isProxy = s.Config().AcceptProxyIPs.Contains(ip)
371 }
372 }
373
374 // Only trust the Forwarded header field if this is a trusted proxy IP
375 // to prevent users from spoofing the remote address
376 remoteAddr := req.RemoteAddr
377 if isProxy {
378 forwarded := parseForwarded(req.Header)
379 if forwarded["for"] != "" {
380 remoteAddr = forwarded["for"]
381 }
382 }
383
384 s.handle(newWebsocketIRCConn(conn, remoteAddr))
385}
386
387func parseForwarded(h http.Header) map[string]string {
388 forwarded := h.Get("Forwarded")
389 if forwarded == "" {
390 return map[string]string{
391 "for": h.Get("X-Forwarded-For"),
392 "proto": h.Get("X-Forwarded-Proto"),
393 "host": h.Get("X-Forwarded-Host"),
394 }
395 }
396 // Hack to easily parse header parameters
397 _, params, _ := mime.ParseMediaType("hack; " + forwarded)
398 return params
399}
400
401type ServerStats struct {
402 Users int
403 Downstreams int64
404 Upstreams int64
405}
406
407func (s *Server) Stats() *ServerStats {
408 var stats ServerStats
409 s.lock.Lock()
410 stats.Users = len(s.users)
411 s.lock.Unlock()
412 stats.Downstreams = s.metrics.downstreams.Value()
413 stats.Upstreams = s.metrics.upstreams.Value()
414 return &stats
415}
Note: See TracBrowser for help on using the repository browser.