Skip to content

Commit e5b6320

Browse files
ahrtrahrtr
committed
add log messages
Signed-off-by: Benjamin Wang <benjamin.ahrtr@gmail.com>
1 parent 008e27b commit e5b6320

File tree

3 files changed

+163
-24
lines changed

3 files changed

+163
-24
lines changed

‎bucket.go

+54-6
Original file line numberDiff line numberDiff line change
@@ -145,7 +145,16 @@ func (b *Bucket) openBucket(value []byte) *Bucket {
145145
// CreateBucket creates a new bucket at the given key and returns the new bucket.
146146
// Returns an error if the key already exists, if the bucket name is blank, or if the bucket name is too long.
147147
// The bucket instance is only valid for the lifetime of the transaction.
148-
func (b *Bucket) CreateBucket(key []byte) (*Bucket, error) {
148+
func (b *Bucket) CreateBucket(key []byte) (rb *Bucket, err error) {
149+
lg := b.tx.db.Logger()
150+
lg.Debugf("Creating bucket %q", string(key))
151+
defer func() {
152+
if err != nil {
153+
lg.Errorf("Creating bucket %q failed: %v", string(key), err)
154+
} else {
155+
lg.Debugf("Creating bucket %q successfully", string(key))
156+
}
157+
}()
149158
if b.tx.db == nil {
150159
return nil, errors.ErrTxClosed
151160
} else if !b.tx.writable {
@@ -192,7 +201,17 @@ func (b *Bucket) CreateBucket(key []byte) (*Bucket, error) {
192201
// CreateBucketIfNotExists creates a new bucket if it doesn't already exist and returns a reference to it.
193202
// Returns an error if the bucket name is blank, or if the bucket name is too long.
194203
// The bucket instance is only valid for the lifetime of the transaction.
195-
func (b *Bucket) CreateBucketIfNotExists(key []byte) (*Bucket, error) {
204+
func (b *Bucket) CreateBucketIfNotExists(key []byte) (rb *Bucket, err error) {
205+
lg := b.tx.db.Logger()
206+
lg.Debugf("Creating bucket if not exist %q", string(key))
207+
defer func() {
208+
if err != nil {
209+
lg.Errorf("Creating bucket if not exist %q failed: %v", string(key), err)
210+
} else {
211+
lg.Debugf("Creating bucket if not exist %q successfully", string(key))
212+
}
213+
}()
214+
196215
if b.tx.db == nil {
197216
return nil, errors.ErrTxClosed
198217
} else if !b.tx.writable {
@@ -249,7 +268,17 @@ func (b *Bucket) CreateBucketIfNotExists(key []byte) (*Bucket, error) {
249268

250269
// DeleteBucket deletes a bucket at the given key.
251270
// Returns an error if the bucket does not exist, or if the key represents a non-bucket value.
252-
func (b *Bucket) DeleteBucket(key []byte) error {
271+
func (b *Bucket) DeleteBucket(key []byte) (err error) {
272+
lg := b.tx.db.Logger()
273+
lg.Debugf("Deleting bucket %q", string(key))
274+
defer func() {
275+
if err != nil {
276+
lg.Errorf("Deleting bucket %q failed: %v", string(key), err)
277+
} else {
278+
lg.Debugf("Deleting bucket %q successfully", string(key))
279+
}
280+
}()
281+
253282
if b.tx.db == nil {
254283
return errors.ErrTxClosed
255284
} else if !b.Writable() {
@@ -269,7 +298,7 @@ func (b *Bucket) DeleteBucket(key []byte) error {
269298

270299
// Recursively delete all child buckets.
271300
child := b.Bucket(key)
272-
err := child.ForEachBucket(func(k []byte) error {
301+
err = child.ForEachBucket(func(k []byte) error {
273302
if err := child.DeleteBucket(k); err != nil {
274303
return fmt.Errorf("delete bucket: %s", err)
275304
}
@@ -316,7 +345,16 @@ func (b *Bucket) Get(key []byte) []byte {
316345
// If the key exist then its previous value will be overwritten.
317346
// Supplied value must remain valid for the life of the transaction.
318347
// Returns an error if the bucket was created from a read-only transaction, if the key is blank, if the key is too large, or if the value is too large.
319-
func (b *Bucket) Put(key []byte, value []byte) error {
348+
func (b *Bucket) Put(key []byte, value []byte) (err error) {
349+
lg := b.tx.db.Logger()
350+
lg.Debugf("Putting key %q", string(key))
351+
defer func() {
352+
if err != nil {
353+
lg.Errorf("Putting key %q failed: %v", string(key), err)
354+
} else {
355+
lg.Debugf("Putting key %q successfully", string(key))
356+
}
357+
}()
320358
if b.tx.db == nil {
321359
return errors.ErrTxClosed
322360
} else if !b.Writable() {
@@ -353,7 +391,17 @@ func (b *Bucket) Put(key []byte, value []byte) error {
353391
// Delete removes a key from the bucket.
354392
// If the key does not exist then nothing is done and a nil error is returned.
355393
// Returns an error if the bucket was created from a read-only transaction.
356-
func (b *Bucket) Delete(key []byte) error {
394+
func (b *Bucket) Delete(key []byte) (err error) {
395+
lg := b.tx.db.Logger()
396+
lg.Debugf("Deleting key %q", string(key))
397+
defer func() {
398+
if err != nil {
399+
lg.Errorf("Deleting key %q failed: %v", string(key), err)
400+
} else {
401+
lg.Debugf("Deleting key %q successfully", string(key))
402+
}
403+
}()
404+
357405
if b.tx.db == nil {
358406
return errors.ErrTxClosed
359407
} else if !b.Writable() {

‎db.go

+78-11
Original file line numberDiff line numberDiff line change
@@ -116,8 +116,7 @@ type DB struct {
116116
// Supported only on Unix via mlock/munlock syscalls.
117117
Mlock bool
118118

119-
// Logger is the logger used for bbolt.
120-
Logger Logger
119+
logger Logger
121120

122121
path string
123122
openFile func(string, int, os.FileMode) (*os.File, error)
@@ -176,10 +175,11 @@ func (db *DB) String() string {
176175
// If the file does not exist then it will be created automatically with a given file mode.
177176
// Passing in nil options will cause Bolt to open the database with the default options.
178177
// Note: For read/write transactions, ensure the owner has write permission on the created/opened database file, e.g. 0600
179-
func Open(path string, mode os.FileMode, options *Options) (*DB, error) {
180-
db := &DB{
178+
func Open(path string, mode os.FileMode, options *Options) (db *DB, err error) {
179+
db = &DB{
181180
opened: true,
182181
}
182+
183183
// Set default options if no options are provided.
184184
if options == nil {
185185
options = DefaultOptions
@@ -198,11 +198,21 @@ func Open(path string, mode os.FileMode, options *Options) (*DB, error) {
198198
db.AllocSize = common.DefaultAllocSize
199199

200200
if options.Logger == nil {
201-
db.Logger = getDiscardLogger()
201+
db.logger = getDiscardLogger()
202202
} else {
203-
db.Logger = options.Logger
203+
db.logger = options.Logger
204204
}
205205

206+
lg := db.Logger()
207+
lg.Infof("Opening db file (%s) with mode %x and with options: %s", path, mode, options)
208+
defer func() {
209+
if err != nil {
210+
lg.Errorf("Opening bbolt db (%s) failed: %v", path, err)
211+
} else {
212+
lg.Infof("Opening bbolt db (%s) successfully", path)
213+
}
214+
}()
215+
206216
flag := os.O_RDWR
207217
if options.ReadOnly {
208218
flag = os.O_RDONLY
@@ -219,9 +229,9 @@ func Open(path string, mode os.FileMode, options *Options) (*DB, error) {
219229
}
220230

221231
// Open data file and separate sync handler for metadata writes.
222-
var err error
223232
if db.file, err = db.openFile(path, flag, mode); err != nil {
224233
_ = db.close()
234+
lg.Errorf("failed to open db file (%s): %v", path, err)
225235
return nil, err
226236
}
227237
db.path = db.file.Name()
@@ -235,6 +245,7 @@ func Open(path string, mode os.FileMode, options *Options) (*DB, error) {
235245
// hold a lock at the same time) otherwise (options.ReadOnly is set).
236246
if err := flock(db, !db.readOnly, options.Timeout); err != nil {
237247
_ = db.close()
248+
lg.Errorf("failed to lock db file (%s), readonly: %t, error: %v", path, db.readOnly, err)
238249
return nil, err
239250
}
240251

@@ -249,12 +260,14 @@ func Open(path string, mode os.FileMode, options *Options) (*DB, error) {
249260
// Initialize the database if it doesn't exist.
250261
if info, err := db.file.Stat(); err != nil {
251262
_ = db.close()
263+
lg.Errorf("failed to get db file's stats (%s): %v", path, err)
252264
return nil, err
253265
} else if info.Size() == 0 {
254266
// Initialize new files with meta pages.
255267
if err := db.init(); err != nil {
256268
// clean up file descriptor on initialization fail
257269
_ = db.close()
270+
lg.Errorf("failed to initialize db file (%s): %v", path, err)
258271
return nil, err
259272
}
260273
} else {
@@ -263,7 +276,8 @@ func Open(path string, mode os.FileMode, options *Options) (*DB, error) {
263276
db.pageSize = pgSize
264277
} else {
265278
_ = db.close()
266-
return nil, berrors.ErrInvalid
279+
lg.Errorf("failed to get page size from db file (%s): %v", path, err)
280+
return nil, err
267281
}
268282
}
269283

@@ -277,6 +291,7 @@ func Open(path string, mode os.FileMode, options *Options) (*DB, error) {
277291
// Memory map the data file.
278292
if err := db.mmap(options.InitialMmapSize); err != nil {
279293
_ = db.close()
294+
lg.Errorf("failed to map db file (%s): %v", path, err)
280295
return nil, err
281296
}
282297

@@ -296,13 +311,13 @@ func Open(path string, mode os.FileMode, options *Options) (*DB, error) {
296311
err = tx.Commit()
297312
}
298313
if err != nil {
314+
lg.Errorf("starting readwrite transaction failed: %v", err)
299315
_ = db.close()
300316
return nil, err
301317
}
302318
}
303319

304320
// Mark the database as opened and return.
305-
db.Logger.Debug("bbolt opened successfully")
306321
return db, nil
307322
}
308323

@@ -435,9 +450,12 @@ func (db *DB) mmap(minsz int) (err error) {
435450
db.mmaplock.Lock()
436451
defer db.mmaplock.Unlock()
437452

453+
lg := db.Logger()
454+
438455
// Ensure the size is at least the minimum size.
439456
fileSize, err := db.fileSize()
440457
if err != nil {
458+
lg.Errorf("getting file size failed: %w", err)
441459
return err
442460
}
443461
var size = fileSize
@@ -446,6 +464,7 @@ func (db *DB) mmap(minsz int) (err error) {
446464
}
447465
size, err = db.mmapSize(size)
448466
if err != nil {
467+
lg.Errorf("getting map size failed: %w", err)
449468
return err
450469
}
451470

@@ -470,6 +489,7 @@ func (db *DB) mmap(minsz int) (err error) {
470489
// gofail: var mapError string
471490
// return errors.New(mapError)
472491
if err = mmap(db, size); err != nil {
492+
lg.Errorf("[GOOS: %s, GOARCH: %s] mmap failed, size: %d, error: %v", runtime.GOOS, runtime.GOARCH, size, err)
473493
return err
474494
}
475495

@@ -500,6 +520,7 @@ func (db *DB) mmap(minsz int) (err error) {
500520
err0 := db.meta0.Validate()
501521
err1 := db.meta1.Validate()
502522
if err0 != nil && err1 != nil {
523+
lg.Errorf("both meta pages are invalid, meta0: %v, meta1: %v", err0, err1)
503524
return err0
504525
}
505526

@@ -522,6 +543,7 @@ func (db *DB) munmap() error {
522543
// gofail: var unmapError string
523544
// return errors.New(unmapError)
524545
if err := munmap(db); err != nil {
546+
db.Logger().Errorf("[GOOS: %s, GOARCH: %s] munmap failed, db.datasz: %d, error: %v", runtime.GOOS, runtime.GOARCH, db.datasz, err)
525547
return fmt.Errorf("unmap error: " + err.Error())
526548
}
527549

@@ -569,6 +591,7 @@ func (db *DB) munlock(fileSize int) error {
569591
// gofail: var munlockError string
570592
// return errors.New(munlockError)
571593
if err := munlock(db, fileSize); err != nil {
594+
db.Logger().Errorf("[GOOS: %s, GOARCH: %s] munlock failed, fileSize: %d, db.datasz: %d, error: %v", runtime.GOOS, runtime.GOARCH, fileSize, db.datasz, err)
572595
return fmt.Errorf("munlock error: " + err.Error())
573596
}
574597
return nil
@@ -578,6 +601,7 @@ func (db *DB) mlock(fileSize int) error {
578601
// gofail: var mlockError string
579602
// return errors.New(mlockError)
580603
if err := mlock(db, fileSize); err != nil {
604+
db.Logger().Errorf("[GOOS: %s, GOARCH: %s] mlock failed, fileSize: %d, db.datasz: %d, error: %v", runtime.GOOS, runtime.GOARCH, fileSize, db.datasz, err)
581605
return fmt.Errorf("mlock error: " + err.Error())
582606
}
583607
return nil
@@ -628,9 +652,11 @@ func (db *DB) init() error {
628652

629653
// Write the buffer to our data file.
630654
if _, err := db.ops.writeAt(buf, 0); err != nil {
655+
db.Logger().Errorf("writeAt failed: %w", err)
631656
return err
632657
}
633658
if err := fdatasync(db); err != nil {
659+
db.Logger().Errorf("[GOOS: %s, GOARCH: %s] fdatasync failed: %w", runtime.GOOS, runtime.GOARCH, err)
634660
return err
635661
}
636662

@@ -713,13 +739,29 @@ func (db *DB) close() error {
713739
//
714740
// IMPORTANT: You must close read-only transactions after you are finished or
715741
// else the database will not reclaim old pages.
716-
func (db *DB) Begin(writable bool) (*Tx, error) {
742+
func (db *DB) Begin(writable bool) (t *Tx, err error) {
743+
db.Logger().Debugf("Starting a new transaction [writable: %t]", writable)
744+
defer func() {
745+
if err != nil {
746+
db.Logger().Errorf("Starting a new transaction [writable: %t] failed: %v", writable, err)
747+
} else {
748+
db.Logger().Debugf("Starting a new transaction [writable: %t] successfully", writable)
749+
}
750+
}()
751+
717752
if writable {
718753
return db.beginRWTx()
719754
}
720755
return db.beginTx()
721756
}
722757

758+
func (db *DB) Logger() Logger {
759+
if db == nil || db.logger == nil {
760+
return getDiscardLogger()
761+
}
762+
return db.logger
763+
}
764+
723765
func (db *DB) beginTx() (*Tx, error) {
724766
// Lock the meta pages while we initialize the transaction. We obtain
725767
// the meta lock before the mmap lock because that's the order that the
@@ -1053,7 +1095,18 @@ func safelyCall(fn func(*Tx) error, tx *Tx) (err error) {
10531095
//
10541096
// This is not necessary under normal operation, however, if you use NoSync
10551097
// then it allows you to force the database file to sync against the disk.
1056-
func (db *DB) Sync() error { return fdatasync(db) }
1098+
func (db *DB) Sync() (err error) {
1099+
db.Logger().Debug("Syncing bbolt db (%s)", db.path)
1100+
defer func() {
1101+
if err != nil {
1102+
db.Logger().Errorf("[GOOS: %s, GOARCH: %s] syncing bbolt db (%s) failed: %v", runtime.GOOS, runtime.GOARCH, db.path, err)
1103+
} else {
1104+
db.Logger().Debugf("Syncing bbolt db (%s) successfully", db.path)
1105+
}
1106+
}()
1107+
1108+
return fdatasync(db)
1109+
}
10571110

10581111
// Stats retrieves ongoing performance stats for the database.
10591112
// This is only updated when a transaction closes.
@@ -1142,8 +1195,10 @@ func (db *DB) allocate(txid common.Txid, count int) (*common.Page, error) {
11421195
// grow grows the size of the database to the given sz.
11431196
func (db *DB) grow(sz int) error {
11441197
// Ignore if the new size is less than available file size.
1198+
lg := db.Logger()
11451199
fileSize, err := db.fileSize()
11461200
if err != nil {
1201+
lg.Errorf("getting file size failed: %w", err)
11471202
return err
11481203
}
11491204
if sz <= fileSize {
@@ -1165,10 +1220,12 @@ func (db *DB) grow(sz int) error {
11651220
// gofail: var resizeFileError string
11661221
// return errors.New(resizeFileError)
11671222
if err := db.file.Truncate(int64(sz)); err != nil {
1223+
lg.Errorf("[GOOS: %s, GOARCH: %s] truncating file failed, size: %d, db.datasz: %d, error: %v", runtime.GOOS, runtime.GOARCH, sz, db.datasz, err)
11681224
return fmt.Errorf("file resize error: %s", err)
11691225
}
11701226
}
11711227
if err := db.file.Sync(); err != nil {
1228+
lg.Errorf("[GOOS: %s, GOARCH: %s] syncing file failed, db.datasz: %d, error: %v", runtime.GOOS, runtime.GOARCH, db.datasz, err)
11721229
return fmt.Errorf("file sync error: %s", err)
11731230
}
11741231
if db.Mlock {
@@ -1283,6 +1340,16 @@ type Options struct {
12831340
Logger Logger
12841341
}
12851342

1343+
func (o *Options) String() string {
1344+
if o == nil {
1345+
return "{}"
1346+
}
1347+
1348+
return fmt.Sprintf("{Timeout: %s, NoGrowSync: %t, NoFreelistSync: %t, PreLoadFreelist: %t, FreelistType: %s, ReadOnly: %t, MmapFlags: %x, InitialMmapSize: %d, PageSize: %d, NoSync: %t, OpenFile: %p, Mlock: %t, Logger: %p}",
1349+
o.Timeout, o.NoGrowSync, o.NoFreelistSync, o.PreLoadFreelist, o.FreelistType, o.ReadOnly, o.MmapFlags, o.InitialMmapSize, o.PageSize, o.NoSync, o.OpenFile, o.Mlock, o.Logger)
1350+
1351+
}
1352+
12861353
// DefaultOptions represent the options used if nil options are passed into Open().
12871354
// No timeout is used which will cause Bolt to wait indefinitely for a lock.
12881355
var DefaultOptions = &Options{

0 commit comments

Comments
 (0)