source: code/trunk/user.go@ 493

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

Introduce per-user logger

Adds the username to log lines.

File size: 16.6 KB
RevLine 
[101]1package soju
2
3import (
[385]4 "crypto/sha256"
5 "encoding/binary"
[395]6 "encoding/hex"
[218]7 "fmt"
[101]8 "time"
[103]9
10 "gopkg.in/irc.v3"
[101]11)
12
[165]13type event interface{}
14
15type eventUpstreamMessage struct {
[103]16 msg *irc.Message
17 uc *upstreamConn
18}
19
[218]20type eventUpstreamConnectionError struct {
21 net *network
22 err error
23}
24
[196]25type eventUpstreamConnected struct {
26 uc *upstreamConn
27}
28
[179]29type eventUpstreamDisconnected struct {
30 uc *upstreamConn
31}
32
[218]33type eventUpstreamError struct {
34 uc *upstreamConn
35 err error
36}
37
[165]38type eventDownstreamMessage struct {
[103]39 msg *irc.Message
40 dc *downstreamConn
41}
42
[166]43type eventDownstreamConnected struct {
44 dc *downstreamConn
45}
46
[167]47type eventDownstreamDisconnected struct {
48 dc *downstreamConn
49}
50
[435]51type eventChannelDetach struct {
52 uc *upstreamConn
53 name string
54}
55
[376]56type eventStop struct{}
57
[480]58type deliveredClientMap map[string]string // client name -> msg ID
59
[485]60type deliveredStore struct {
61 m deliveredCasemapMap
62}
63
64func newDeliveredStore() deliveredStore {
65 return deliveredStore{deliveredCasemapMap{newCasemapMap(0)}}
66}
67
68func (ds deliveredStore) HasTarget(target string) bool {
69 return ds.m.Value(target) != nil
70}
71
72func (ds deliveredStore) LoadID(target, clientName string) string {
73 clients := ds.m.Value(target)
74 if clients == nil {
75 return ""
76 }
77 return clients[clientName]
78}
79
80func (ds deliveredStore) StoreID(target, clientName, msgID string) {
81 clients := ds.m.Value(target)
82 if clients == nil {
83 clients = make(deliveredClientMap)
84 ds.m.SetValue(target, clients)
85 }
86 clients[clientName] = msgID
87}
88
89func (ds deliveredStore) ForEachTarget(f func(target string)) {
90 for _, entry := range ds.m.innerMap {
91 f(entry.originalKey)
92 }
93}
94
[489]95func (ds deliveredStore) ForEachClient(f func(clientName string)) {
96 clients := make(map[string]struct{})
97 for _, entry := range ds.m.innerMap {
98 delivered := entry.value.(deliveredClientMap)
99 for clientName := range delivered {
100 clients[clientName] = struct{}{}
101 }
102 }
103
104 for clientName := range clients {
105 f(clientName)
106 }
107}
108
[101]109type network struct {
110 Network
[202]111 user *user
112 stopped chan struct{}
[131]113
[482]114 conn *upstreamConn
115 channels channelCasemapMap
[485]116 delivered deliveredStore
[482]117 lastError error
118 casemap casemapping
[101]119}
120
[267]121func newNetwork(user *user, record *Network, channels []Channel) *network {
[478]122 m := channelCasemapMap{newCasemapMap(0)}
[267]123 for _, ch := range channels {
[283]124 ch := ch
[478]125 m.SetValue(ch.Name, &ch)
[267]126 }
127
[101]128 return &network{
[482]129 Network: *record,
130 user: user,
131 stopped: make(chan struct{}),
132 channels: m,
[485]133 delivered: newDeliveredStore(),
[482]134 casemap: casemapRFC1459,
[101]135 }
136}
137
[218]138func (net *network) forEachDownstream(f func(*downstreamConn)) {
139 net.user.forEachDownstream(func(dc *downstreamConn) {
140 if dc.network != nil && dc.network != net {
141 return
142 }
143 f(dc)
144 })
145}
146
[311]147func (net *network) isStopped() bool {
148 select {
149 case <-net.stopped:
150 return true
151 default:
152 return false
153 }
154}
155
[385]156func userIdent(u *User) string {
157 // The ident is a string we will send to upstream servers in clear-text.
158 // For privacy reasons, make sure it doesn't expose any meaningful user
159 // metadata. We just use the base64-encoded hashed ID, so that people don't
160 // start relying on the string being an integer or following a pattern.
161 var b [64]byte
162 binary.LittleEndian.PutUint64(b[:], uint64(u.ID))
163 h := sha256.Sum256(b[:])
[395]164 return hex.EncodeToString(h[:16])
[385]165}
166
[101]167func (net *network) run() {
168 var lastTry time.Time
169 for {
[311]170 if net.isStopped() {
[202]171 return
172 }
173
[398]174 if dur := time.Now().Sub(lastTry); dur < retryConnectDelay {
175 delay := retryConnectDelay - dur
[493]176 net.user.logger.Printf("waiting %v before trying to reconnect to %q", delay.Truncate(time.Second), net.Addr)
[101]177 time.Sleep(delay)
178 }
179 lastTry = time.Now()
180
181 uc, err := connectToUpstream(net)
182 if err != nil {
[493]183 net.user.logger.Printf("failed to connect to upstream server %q: %v", net.Addr, err)
[218]184 net.user.events <- eventUpstreamConnectionError{net, fmt.Errorf("failed to connect: %v", err)}
[101]185 continue
186 }
187
[385]188 if net.user.srv.Identd != nil {
189 net.user.srv.Identd.Store(uc.RemoteAddr().String(), uc.LocalAddr().String(), userIdent(&net.user.User))
190 }
191
[101]192 uc.register()
[197]193 if err := uc.runUntilRegistered(); err != nil {
[399]194 text := err.Error()
195 if regErr, ok := err.(registrationError); ok {
196 text = string(regErr)
197 }
198 uc.logger.Printf("failed to register: %v", text)
199 net.user.events <- eventUpstreamConnectionError{net, fmt.Errorf("failed to register: %v", text)}
[197]200 uc.Close()
201 continue
202 }
[101]203
[311]204 // TODO: this is racy with net.stopped. If the network is stopped
205 // before the user goroutine receives eventUpstreamConnected, the
206 // connection won't be closed.
[196]207 net.user.events <- eventUpstreamConnected{uc}
[165]208 if err := uc.readMessages(net.user.events); err != nil {
[101]209 uc.logger.Printf("failed to handle messages: %v", err)
[218]210 net.user.events <- eventUpstreamError{uc, fmt.Errorf("failed to handle messages: %v", err)}
[101]211 }
212 uc.Close()
[179]213 net.user.events <- eventUpstreamDisconnected{uc}
[385]214
215 if net.user.srv.Identd != nil {
216 net.user.srv.Identd.Delete(uc.RemoteAddr().String(), uc.LocalAddr().String())
217 }
[101]218 }
219}
220
[309]221func (net *network) stop() {
[311]222 if !net.isStopped() {
[202]223 close(net.stopped)
224 }
225
[279]226 if net.conn != nil {
227 net.conn.Close()
[202]228 }
229}
230
[435]231func (net *network) detach(ch *Channel) {
232 if ch.Detached {
233 return
[267]234 }
[435]235 ch.Detached = true
[493]236 net.user.logger.Printf("network %q: detaching channel %q", net.GetName(), ch.Name)
[435]237
238 if net.conn != nil {
[478]239 uch := net.conn.channels.Value(ch.Name)
240 if uch != nil {
[435]241 uch.updateAutoDetach(0)
242 }
[222]243 }
[284]244
[435]245 net.forEachDownstream(func(dc *downstreamConn) {
246 dc.SendMessage(&irc.Message{
247 Prefix: dc.prefix(),
248 Command: "PART",
249 Params: []string{dc.marshalEntity(net, ch.Name), "Detach"},
250 })
251 })
252}
[284]253
[435]254func (net *network) attach(ch *Channel) {
255 if !ch.Detached {
256 return
257 }
258 ch.Detached = false
[493]259 net.user.logger.Printf("network %q: attaching channel %q", net.GetName(), ch.Name)
[284]260
[435]261 var uch *upstreamChannel
262 if net.conn != nil {
[478]263 uch = net.conn.channels.Value(ch.Name)
[284]264
[435]265 net.conn.updateChannelAutoDetach(ch.Name)
266 }
[284]267
[435]268 net.forEachDownstream(func(dc *downstreamConn) {
269 dc.SendMessage(&irc.Message{
270 Prefix: dc.prefix(),
271 Command: "JOIN",
272 Params: []string{dc.marshalEntity(net, ch.Name)},
273 })
274
275 if uch != nil {
276 forwardChannel(dc, uch)
[284]277 }
278
[453]279 dc.sendTargetBacklog(net, ch.Name)
[435]280 })
[222]281}
282
283func (net *network) deleteChannel(name string) error {
[478]284 ch := net.channels.Value(name)
285 if ch == nil {
[416]286 return fmt.Errorf("unknown channel %q", name)
287 }
[435]288 if net.conn != nil {
[478]289 uch := net.conn.channels.Value(ch.Name)
290 if uch != nil {
[435]291 uch.updateAutoDetach(0)
292 }
293 }
294
[416]295 if err := net.user.srv.db.DeleteChannel(ch.ID); err != nil {
[267]296 return err
297 }
[478]298 net.channels.Delete(name)
[267]299 return nil
[222]300}
301
[478]302func (net *network) updateCasemapping(newCasemap casemapping) {
303 net.casemap = newCasemap
304 net.channels.SetCasemapping(newCasemap)
[485]305 net.delivered.m.SetCasemapping(newCasemap)
[478]306 if net.conn != nil {
307 net.conn.channels.SetCasemapping(newCasemap)
308 for _, entry := range net.conn.channels.innerMap {
309 uch := entry.value.(*upstreamChannel)
310 uch.Members.SetCasemapping(newCasemap)
311 }
312 }
313}
314
[489]315func (net *network) storeClientDeliveryReceipts(clientName string) {
316 if !net.user.hasPersistentMsgStore() {
317 return
318 }
319
320 var receipts []DeliveryReceipt
321 net.delivered.ForEachTarget(func(target string) {
322 msgID := net.delivered.LoadID(target, clientName)
323 if msgID == "" {
324 return
325 }
326 receipts = append(receipts, DeliveryReceipt{
327 Target: target,
328 InternalMsgID: msgID,
329 })
330 })
331
332 if err := net.user.srv.db.StoreClientDeliveryReceipts(net.ID, clientName, receipts); err != nil {
[493]333 net.user.logger.Printf("failed to store delivery receipts for user %q, client %q, network %q: %v", net.user.Username, clientName, net.GetName(), err)
[489]334 }
335}
336
[101]337type user struct {
338 User
[493]339 srv *Server
340 logger Logger
[101]341
[165]342 events chan event
[377]343 done chan struct{}
[103]344
[101]345 networks []*network
346 downstreamConns []*downstreamConn
[439]347 msgStore messageStore
[177]348
349 // LIST commands in progress
[179]350 pendingLISTs []pendingLIST
[101]351}
352
[177]353type pendingLIST struct {
354 downstreamID uint64
355 // list of per-upstream LIST commands not yet sent or completed
356 pendingCommands map[int64]*irc.Message
357}
358
[101]359func newUser(srv *Server, record *User) *user {
[493]360 logger := &prefixLogger{srv.Logger, fmt.Sprintf("user %q: ", record.Username)}
361
[439]362 var msgStore messageStore
[423]363 if srv.LogPath != "" {
[439]364 msgStore = newFSMessageStore(srv.LogPath, record.Username)
[442]365 } else {
366 msgStore = newMemoryMessageStore()
[423]367 }
368
[101]369 return &user{
[489]370 User: *record,
371 srv: srv,
[493]372 logger: logger,
[489]373 events: make(chan event, 64),
374 done: make(chan struct{}),
375 msgStore: msgStore,
[101]376 }
377}
378
379func (u *user) forEachNetwork(f func(*network)) {
380 for _, network := range u.networks {
381 f(network)
382 }
383}
384
385func (u *user) forEachUpstream(f func(uc *upstreamConn)) {
386 for _, network := range u.networks {
[279]387 if network.conn == nil {
[101]388 continue
389 }
[279]390 f(network.conn)
[101]391 }
392}
393
394func (u *user) forEachDownstream(f func(dc *downstreamConn)) {
395 for _, dc := range u.downstreamConns {
396 f(dc)
397 }
398}
399
400func (u *user) getNetwork(name string) *network {
401 for _, network := range u.networks {
402 if network.Addr == name {
403 return network
404 }
[201]405 if network.Name != "" && network.Name == name {
406 return network
407 }
[101]408 }
409 return nil
410}
411
[313]412func (u *user) getNetworkByID(id int64) *network {
413 for _, net := range u.networks {
414 if net.ID == id {
415 return net
416 }
417 }
418 return nil
419}
420
[101]421func (u *user) run() {
[423]422 defer func() {
423 if u.msgStore != nil {
424 if err := u.msgStore.Close(); err != nil {
[493]425 u.logger.Printf("failed to close message store for user %q: %v", u.Username, err)
[423]426 }
427 }
428 close(u.done)
429 }()
[377]430
[421]431 networks, err := u.srv.db.ListNetworks(u.ID)
[101]432 if err != nil {
[493]433 u.logger.Printf("failed to list networks for user %q: %v", u.Username, err)
[101]434 return
435 }
436
437 for _, record := range networks {
[283]438 record := record
[267]439 channels, err := u.srv.db.ListChannels(record.ID)
440 if err != nil {
[493]441 u.logger.Printf("failed to list channels for user %q, network %q: %v", u.Username, record.GetName(), err)
[359]442 continue
[267]443 }
444
445 network := newNetwork(u, &record, channels)
[101]446 u.networks = append(u.networks, network)
447
[489]448 if u.hasPersistentMsgStore() {
449 receipts, err := u.srv.db.ListDeliveryReceipts(record.ID)
450 if err != nil {
[493]451 u.logger.Printf("failed to load delivery receipts for user %q, network %q: %v", u.Username, network.GetName(), err)
[489]452 return
453 }
454
455 for _, rcpt := range receipts {
456 network.delivered.StoreID(rcpt.Target, rcpt.Client, rcpt.InternalMsgID)
457 }
458 }
459
[101]460 go network.run()
461 }
[103]462
[165]463 for e := range u.events {
464 switch e := e.(type) {
[196]465 case eventUpstreamConnected:
[198]466 uc := e.uc
[199]467
468 uc.network.conn = uc
469
[198]470 uc.updateAway()
[218]471
472 uc.forEachDownstream(func(dc *downstreamConn) {
[276]473 dc.updateSupportedCaps()
[223]474 sendServiceNOTICE(dc, fmt.Sprintf("connected to %s", uc.network.GetName()))
[296]475
476 dc.updateNick()
[218]477 })
478 uc.network.lastError = nil
[179]479 case eventUpstreamDisconnected:
[313]480 u.handleUpstreamDisconnected(e.uc)
481 case eventUpstreamConnectionError:
482 net := e.net
[199]483
[313]484 stopped := false
485 select {
486 case <-net.stopped:
487 stopped = true
488 default:
[179]489 }
[199]490
[313]491 if !stopped && (net.lastError == nil || net.lastError.Error() != e.err.Error()) {
[218]492 net.forEachDownstream(func(dc *downstreamConn) {
[223]493 sendServiceNOTICE(dc, fmt.Sprintf("failed connecting/registering to %s: %v", net.GetName(), e.err))
[218]494 })
495 }
496 net.lastError = e.err
497 case eventUpstreamError:
498 uc := e.uc
499
500 uc.forEachDownstream(func(dc *downstreamConn) {
[223]501 sendServiceNOTICE(dc, fmt.Sprintf("disconnected from %s: %v", uc.network.GetName(), e.err))
[218]502 })
503 uc.network.lastError = e.err
[165]504 case eventUpstreamMessage:
505 msg, uc := e.msg, e.uc
[175]506 if uc.isClosed() {
[133]507 uc.logger.Printf("ignoring message on closed connection: %v", msg)
508 break
509 }
[103]510 if err := uc.handleMessage(msg); err != nil {
511 uc.logger.Printf("failed to handle message %q: %v", msg, err)
512 }
[435]513 case eventChannelDetach:
514 uc, name := e.uc, e.name
[478]515 c := uc.network.channels.Value(name)
516 if c == nil || c.Detached {
[435]517 continue
518 }
519 uc.network.detach(c)
520 if err := uc.srv.db.StoreChannel(uc.network.ID, c); err != nil {
[493]521 u.logger.Printf("failed to store updated detached channel %q: %v", c.Name, err)
[435]522 }
[166]523 case eventDownstreamConnected:
524 dc := e.dc
[168]525
526 if err := dc.welcome(); err != nil {
527 dc.logger.Printf("failed to handle new registered connection: %v", err)
528 break
529 }
530
[166]531 u.downstreamConns = append(u.downstreamConns, dc)
[198]532
[467]533 dc.forEachNetwork(func(network *network) {
534 if network.lastError != nil {
535 sendServiceNOTICE(dc, fmt.Sprintf("disconnected from %s: %v", network.GetName(), network.lastError))
536 }
537 })
538
[198]539 u.forEachUpstream(func(uc *upstreamConn) {
540 uc.updateAway()
541 })
[167]542 case eventDownstreamDisconnected:
543 dc := e.dc
[204]544
[167]545 for i := range u.downstreamConns {
546 if u.downstreamConns[i] == dc {
547 u.downstreamConns = append(u.downstreamConns[:i], u.downstreamConns[i+1:]...)
548 break
549 }
550 }
[198]551
[489]552 dc.forEachNetwork(func(net *network) {
553 net.storeClientDeliveryReceipts(dc.clientName)
554 })
555
[198]556 u.forEachUpstream(func(uc *upstreamConn) {
557 uc.updateAway()
558 })
[165]559 case eventDownstreamMessage:
560 msg, dc := e.msg, e.dc
[133]561 if dc.isClosed() {
562 dc.logger.Printf("ignoring message on closed connection: %v", msg)
563 break
564 }
[103]565 err := dc.handleMessage(msg)
566 if ircErr, ok := err.(ircError); ok {
567 ircErr.Message.Prefix = dc.srv.prefix()
568 dc.SendMessage(ircErr.Message)
569 } else if err != nil {
570 dc.logger.Printf("failed to handle message %q: %v", msg, err)
571 dc.Close()
572 }
[376]573 case eventStop:
574 u.forEachDownstream(func(dc *downstreamConn) {
575 dc.Close()
576 })
577 for _, n := range u.networks {
578 n.stop()
[489]579
580 n.delivered.ForEachClient(func(clientName string) {
581 n.storeClientDeliveryReceipts(clientName)
582 })
[376]583 }
584 return
[165]585 default:
[493]586 u.logger.Printf("received unknown event type: %T", e)
[103]587 }
588 }
[101]589}
590
[313]591func (u *user) handleUpstreamDisconnected(uc *upstreamConn) {
592 uc.network.conn = nil
593
594 uc.endPendingLISTs(true)
595
[478]596 for _, entry := range uc.channels.innerMap {
597 uch := entry.value.(*upstreamChannel)
[435]598 uch.updateAutoDetach(0)
599 }
600
[313]601 uc.forEachDownstream(func(dc *downstreamConn) {
602 dc.updateSupportedCaps()
603 })
604
605 if uc.network.lastError == nil {
606 uc.forEachDownstream(func(dc *downstreamConn) {
607 sendServiceNOTICE(dc, fmt.Sprintf("disconnected from %s", uc.network.GetName()))
608 })
609 }
610}
611
612func (u *user) addNetwork(network *network) {
613 u.networks = append(u.networks, network)
614 go network.run()
615}
616
617func (u *user) removeNetwork(network *network) {
618 network.stop()
619
620 u.forEachDownstream(func(dc *downstreamConn) {
621 if dc.network != nil && dc.network == network {
622 dc.Close()
623 }
624 })
625
626 for i, net := range u.networks {
627 if net == network {
628 u.networks = append(u.networks[:i], u.networks[i+1:]...)
629 return
630 }
631 }
632
633 panic("tried to remove a non-existing network")
634}
635
636func (u *user) createNetwork(record *Network) (*network, error) {
637 if record.ID != 0 {
[144]638 panic("tried creating an already-existing network")
639 }
640
[313]641 network := newNetwork(u, record, nil)
[421]642 err := u.srv.db.StoreNetwork(u.ID, &network.Network)
[101]643 if err != nil {
644 return nil, err
645 }
[144]646
[313]647 u.addNetwork(network)
[144]648
[101]649 return network, nil
650}
[202]651
[313]652func (u *user) updateNetwork(record *Network) (*network, error) {
653 if record.ID == 0 {
654 panic("tried updating a new network")
655 }
[202]656
[313]657 network := u.getNetworkByID(record.ID)
658 if network == nil {
659 panic("tried updating a non-existing network")
660 }
661
[421]662 if err := u.srv.db.StoreNetwork(u.ID, record); err != nil {
[313]663 return nil, err
664 }
665
666 // Most network changes require us to re-connect to the upstream server
667
[478]668 channels := make([]Channel, 0, network.channels.Len())
669 for _, entry := range network.channels.innerMap {
670 ch := entry.value.(*Channel)
[313]671 channels = append(channels, *ch)
672 }
673
674 updatedNetwork := newNetwork(u, record, channels)
675
676 // If we're currently connected, disconnect and perform the necessary
677 // bookkeeping
678 if network.conn != nil {
679 network.stop()
680 // Note: this will set network.conn to nil
681 u.handleUpstreamDisconnected(network.conn)
682 }
683
684 // Patch downstream connections to use our fresh updated network
685 u.forEachDownstream(func(dc *downstreamConn) {
686 if dc.network != nil && dc.network == network {
687 dc.network = updatedNetwork
[202]688 }
[313]689 })
[202]690
[313]691 // We need to remove the network after patching downstream connections,
692 // otherwise they'll get closed
693 u.removeNetwork(network)
[202]694
[313]695 // This will re-connect to the upstream server
696 u.addNetwork(updatedNetwork)
697
698 return updatedNetwork, nil
699}
700
701func (u *user) deleteNetwork(id int64) error {
702 network := u.getNetworkByID(id)
703 if network == nil {
704 panic("tried deleting a non-existing network")
[202]705 }
706
[313]707 if err := u.srv.db.DeleteNetwork(network.ID); err != nil {
708 return err
709 }
710
711 u.removeNetwork(network)
712 return nil
[202]713}
[252]714
715func (u *user) updatePassword(hashed string) error {
716 u.User.Password = hashed
[324]717 return u.srv.db.StoreUser(&u.User)
[252]718}
[376]719
720func (u *user) stop() {
721 u.events <- eventStop{}
[377]722 <-u.done
[376]723}
[489]724
725func (u *user) hasPersistentMsgStore() bool {
726 if u.msgStore == nil {
727 return false
728 }
729 _, isMem := u.msgStore.(*memoryMessageStore)
730 return !isMem
731}
Note: See TracBrowser for help on using the repository browser.