From b091582bb301c19d8211c9366ba40767dc0bf907 Mon Sep 17 00:00:00 2001 From: D4ryl00 Date: Tue, 14 Dec 2021 22:56:29 +0100 Subject: [PATCH] feat(ios): add logger + refacto logs Signed-off-by: D4ryl00 --- go/pkg/ble-driver/BertyDevice_darwin.h | 18 +- go/pkg/ble-driver/BertyDevice_darwin.m | 284 +++++++++++++----------- go/pkg/ble-driver/BleInterface_darwin.h | 9 +- go/pkg/ble-driver/BleInterface_darwin.m | 58 +++-- go/pkg/ble-driver/BleManager_darwin.h | 16 +- go/pkg/ble-driver/BleManager_darwin.m | 191 ++++++++-------- go/pkg/ble-driver/BleQueue.h | 4 +- go/pkg/ble-driver/BleQueue.m | 24 +- go/pkg/ble-driver/ConnectedPeer.h | 4 +- go/pkg/ble-driver/Logger.h | 42 ++++ go/pkg/ble-driver/Logger.m | 112 ++++++++++ go/pkg/ble-driver/PeerManager.h | 19 +- go/pkg/ble-driver/PeerManager.m | 78 +++---- go/pkg/ble-driver/bridge_darwin.go | 31 ++- 14 files changed, 566 insertions(+), 324 deletions(-) create mode 100644 go/pkg/ble-driver/Logger.h create mode 100644 go/pkg/ble-driver/Logger.m diff --git a/go/pkg/ble-driver/BertyDevice_darwin.h b/go/pkg/ble-driver/BertyDevice_darwin.h index 87ba4671..0a004e9d 100644 --- a/go/pkg/ble-driver/BertyDevice_darwin.h +++ b/go/pkg/ble-driver/BertyDevice_darwin.h @@ -9,14 +9,15 @@ #import #import -#import "BleManager_darwin.h" +#import "ConnectedPeer.h" #import "CircularQueue.h" #import "BleQueue.h" +#import "Logger.h" +#import "CountDownLatch_darwin.h" -#ifndef BertyDevice_h -#define BertyDevice_h -@class BertyDevice; -@class ConnectedPeer; +NS_ASSUME_NONNULL_BEGIN + +@class BleManager; typedef void (^BertyDeviceConnectCallbackBlockType)(BertyDevice * __nullable, NSError * __nullable); typedef void (^BertyDeviceServiceCallbackBlockType)(NSArray * __nullable, NSError * __nullable); @@ -26,6 +27,7 @@ typedef void (^BertyDeviceWriteCallbackBlockType)(NSError * __nullable); @interface BertyDevice : NSObject +@property (nonatomic, strong, nonnull) Logger *logger; @property (nonatomic, strong, nonnull) NSString *name; @property (nonatomic, strong, nonnull) NSDictionary *serviceDict; @property (nonatomic, strong, nullable) CBPeripheral *peripheral; @@ -48,8 +50,8 @@ typedef void (^BertyDeviceWriteCallbackBlockType)(NSError * __nullable); @property (nonatomic, strong, nonnull) CircularQueue *dataCache; @property (readwrite) BOOL isDisconnecting; -- (instancetype __nullable)initWithIdentifier:(NSString *__nonnull)identifier central:(BleManager *__nonnull)manager asClient:(BOOL)client; -- (instancetype __nullable)initWithPeripheral:(CBPeripheral *__nonnull)peripheral central:(BleManager *__nonnull)manager withName:(NSString *__nonnull)name; +- (instancetype __nullable)initWithIdentifier:(NSString *__nonnull)identifier logger:(Logger *__nonnull)logger central:(BleManager *__nonnull)manager asClient:(BOOL)client; +- (instancetype __nullable)initWithPeripheral:(CBPeripheral *__nonnull)peripheral logger:(Logger *__nonnull)logger central:(BleManager *__nonnull)manager withName:(NSString *__nonnull)name; - (void)closeBertyDevice; - (BOOL)writeToCharacteristic:(NSData *__nonnull)data forCharacteristic:(CBCharacteristic *__nonnull)characteristic withEOD:(BOOL)eod; - (void)handshake; @@ -80,4 +82,4 @@ API_AVAILABLE(ios(11.0)) - (BOOL)l2capWrite:(NSData *__nonnull)data; @end -#endif +NS_ASSUME_NONNULL_END diff --git a/go/pkg/ble-driver/BertyDevice_darwin.m b/go/pkg/ble-driver/BertyDevice_darwin.m index 1d7021f2..48ee8f77 100644 --- a/go/pkg/ble-driver/BertyDevice_darwin.m +++ b/go/pkg/ble-driver/BertyDevice_darwin.m @@ -7,14 +7,8 @@ // Copyright © 2019 berty. All rights reserved. // -#import - -#import "BleInterface_darwin.h" #import "BertyDevice_darwin.h" -#import "CircularQueue.h" -#import "PeerManager.h" -#import "ConnectedPeer.h" -#import "CountDownLatch_darwin.h" +#import "BleManager_darwin.h" extern unsigned short handlePeerFound(char *, char *); extern void receiveFromDevice(char *, void *, int); @@ -36,9 +30,9 @@ @implementation BertyDevice -- (instancetype)initWithPeripheral:(CBPeripheral *)peripheral +- (instancetype)initWithPeripheral:(CBPeripheral *)peripheral logger:(Logger *__nonnull)logger central:(BleManager *)manager withName:(NSString *__nonnull)name { - self = [self initWithIdentifier:[peripheral.identifier UUIDString] central:manager asClient:TRUE]; + self = [self initWithIdentifier:[peripheral.identifier UUIDString] logger:logger central:manager asClient:TRUE]; if (self) { _peripheral = [peripheral retain]; @@ -48,7 +42,7 @@ - (instancetype)initWithPeripheral:(CBPeripheral *)peripheral return self; } -- (instancetype)initWithIdentifier:(NSString *)identifier central:(BleManager *)manager asClient:(BOOL)client{ +- (instancetype)initWithIdentifier:(NSString *)identifier logger:(Logger *__nonnull)logger central:(BleManager *)manager asClient:(BOOL)client{ self = [super init]; if (self) { @@ -58,14 +52,15 @@ - (instancetype)initWithIdentifier:(NSString *)identifier central:(BleManager *) _serverSideIdentifier = [identifier retain]; } + _logger = logger; _peripheral = nil; _manager = manager; _remotePeerID = nil; _psm = 0; - _connectionQ = [[BleQueue alloc] init: dispatch_get_main_queue()]; - _writeQ = [[BleQueue alloc] init: dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_DEFAULT, 0)]; - _readQ = [[BleQueue alloc] init: dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_DEFAULT, 0)]; + _connectionQ = [[BleQueue alloc] init: dispatch_get_main_queue() logger:logger]; + _writeQ = [[BleQueue alloc] init: dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_DEFAULT, 0) logger:logger]; + _readQ = [[BleQueue alloc] init: dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_DEFAULT, 0) logger:logger]; BOOL (^peerIDHandler)(NSData *data) = ^BOOL(NSData *data) { return [self handlePeerID:data]; @@ -95,6 +90,7 @@ - (instancetype)initWithIdentifier:(NSString *)identifier central:(BleManager *) } - (void)dealloc { + [_logger release]; [_clientSideIdentifier release]; [_serverSideIdentifier release]; [_peripheral release]; @@ -120,7 +116,7 @@ - (NSString *__nonnull)getIdentifier { } - (void)closeL2cap { - os_log_debug(OS_LOG_BLE, "🟢 closeL2cap: device=%{public}@", [self getIdentifier]); + [self.logger d:@"closeL2cap: device=%@", [self.logger SensitiveNSObject:[self getIdentifier]]]; if (self.l2capChannel != nil) { [self.l2capChannel.inputStream close]; @@ -136,7 +132,7 @@ - (void)closeL2cap { - (void)closeBertyDevice { @synchronized (self) { - os_log_debug(OS_LOG_BLE, "🟢 closeBertyDevice: device=%{public}@", [self getIdentifier]); + [self.logger d:@"closeBertyDevice: device=%@", [self.logger SensitiveNSObject:[self getIdentifier]]]; if (!self.isDisconnecting) { self.isDisconnecting = TRUE; @@ -147,11 +143,11 @@ - (void)closeBertyDevice { [self closeL2cap]; if (self.peer != nil) { - [PeerManager unregisterDevice:self]; + [self.manager.peerManager unregisterDevice:self]; self.peer = nil; } } else { - os_log_debug(OS_LOG_BLE, "🟢 closeBertyDevice: device=%{public}@ is already disconnecting", [self getIdentifier]); + [self.logger d:@"closeBertyDevice: device=%@ is already disconnecting", [self.logger SensitiveNSObject:[self getIdentifier]]]; } self.isDisconnecting = FALSE; } @@ -159,7 +155,7 @@ - (void)closeBertyDevice { - (BOOL)handlePeerID:(NSData *__nonnull)peerIDData { if (self.peer != nil && [self.peer isConnected]) { - os_log_error(OS_LOG_BLE, "handlePeerID: device=%{public}@: peer already connected", [self getIdentifier]); + [self.logger e:@"handlePeerID: device=%@: peer already connected", [self.logger SensitiveNSObject:[self getIdentifier]]]; return FALSE; } @@ -175,11 +171,11 @@ - (BOOL)handlePeerID:(NSData *__nonnull)peerIDData { NSString *remotePeerID = [NSString stringWithUTF8String:[tmpData bytes]]; // reset tmpData [tmpData setLength:0]; - os_log_debug(OS_LOG_BLE, "handlePeerID: device=%{public}@: current peerID=%{public}@, new peerID=%{public}@", [self getIdentifier], self.remotePeerID, remotePeerID); + [self.logger d:@"handlePeerID: device=%@: current peerID=%@, new peerID=%@", [self.logger SensitiveNSObject:[self getIdentifier]], [self.logger SensitiveNSObject:self.remotePeerID], [self.logger SensitiveNSObject:remotePeerID]]; self.remotePeerID = remotePeerID; } else { @synchronized (tmpData) { - os_log_debug(OS_LOG_BLE, "handlePeerID: device=%{public}@: add to buffer data=%{public}@", [self getIdentifier], peerIDData); + [self.logger d:@"handlePeerID: device=%@: add to buffer data=%@", [self.logger SensitiveNSObject:[self getIdentifier]], [self.logger SensitiveNSObject:peerIDData]]; [tmpData appendData:peerIDData]; } } @@ -191,38 +187,40 @@ - (BOOL)putIncomingDataInCache:(NSData *__nonnull)data { [self.dataCache offer:data]; } @catch (NSException *e) { - os_log_error(OS_LOG_BLE, "putIncomingDataInCache: device=%{public}@: cannot add data in cache", [self getIdentifier]); + [self.logger e:@"putIncomingDataInCache error: device=%@: cannot add data in cache", [self.logger SensitiveNSObject:[self getIdentifier]]]; return FALSE; } return TRUE; } - (BOOL)handleIncomingData:(NSData *__nonnull)data { - os_log_debug(OS_LOG_BLE, "handleIncomingData() identifier=%{public}@ len=%lu base64=%{public}@", [self getIdentifier], [data length], [data base64EncodedStringWithOptions:0]); - [BleManager printLongLog:[BleManager NSDataToHex:data]]; + [self.logger d:@"handleIncomingData called: identifier=%@ len=%lu base64=%@", [self.logger SensitiveNSObject:[self getIdentifier]], [data length], [self.logger SensitiveNSObject:[data base64EncodedStringWithOptions:0]]]; + if ([self.logger showSensitiveData]) { + [BleManager printLongLog:[BleManager NSDataToHex:data]]; + } if (self.l2capClientHandshakeRunning) { [self.l2capHandshakeRecvData appendBytes:data length:[data length]]; if ([self.l2capHandshakeRecvData length] < L2CAP_HANDSHAKE_DATA) { - os_log_debug(OS_LOG_BLE, "handleIncomingData: device=%{public}@: client handshake received incompleted payload: length=%lu", [self getIdentifier], [self.l2capHandshakeRecvData length]); + [self.logger d:@"handleIncomingData: device=%@: client handshake received incompleted payload: length=%lu", [self.logger SensitiveNSObject:[self getIdentifier]], [self.l2capHandshakeRecvData length]]; } else if ([self.l2capHandshakeRecvData length] == L2CAP_HANDSHAKE_DATA) { if ([data isEqualToData:self.l2capHandshakeData]) { - os_log_debug(OS_LOG_BLE, "handleIncomingData: device=%{public}@: client handshake received payload", [self getIdentifier]); + [self.logger d:@"handleIncomingData: device=%@: client handshake received payload", [self.logger SensitiveNSObject:[self getIdentifier]]]; self.l2capHandshakeStepStatus = TRUE; dispatch_block_cancel(self.l2capHandshakeBlock); [self.l2capHandshakeLatch countDown]; } else { - os_log_error(OS_LOG_BLE, "handleIncomingData: device=%{public}@: client handshake received wrong payload", [self getIdentifier]); + [self.logger e:@"handleIncomingData: device=%@: client handshake received wrong payload", [self.logger SensitiveNSObject:[self getIdentifier]]]; dispatch_block_cancel(self.l2capHandshakeBlock); [self.l2capHandshakeLatch countDown]; [self.manager disconnect:self]; } } else { - os_log_error(OS_LOG_BLE, "handleIncomingData: device=%{public}@: client handshake received bigger payload than expected: length=%lu", [self getIdentifier], [self.l2capHandshakeRecvData length]); + [self.logger e:@"handleIncomingData: device=%@: client handshake received bigger payload than expected: length=%lu", [self.logger SensitiveNSObject:[self getIdentifier]], [self.l2capHandshakeRecvData length]];; } } else if (self.l2capServerHandshakeRunning) { if (!self.l2capHandshakeStepStatus) { - os_log_debug(OS_LOG_BLE, "handleIncomingData: device=%{public}@: server handshake received payload, going to write it back", [self getIdentifier]); + [self.logger d:@"handleIncomingData: device=%@: server handshake received payload, going to write it back", [self.logger SensitiveNSObject:[self getIdentifier]]]; // the server side needs to know when it receives all 1st step data, so it must count data len self.l2capHandshakeRecvDataLen += [data length]; @@ -232,25 +230,25 @@ - (BOOL)handleIncomingData:(NSData *__nonnull)data { } if (![self l2capWrite:data]) { - os_log_error(OS_LOG_BLE, "handleIncomingData: device=%{public}@: server handshake write error", [self getIdentifier]); + [self.logger e:@"handleIncomingData: device=%@: server handshake write error", [self.logger SensitiveNSObject:[self getIdentifier]]]; self.l2capServerHandshakeRunning = FALSE; self.l2capHandshakeStepStatus = FALSE; } } else if ([data isEqualToData:[self.manager.localPID dataUsingEncoding:NSUTF8StringEncoding]]) { - os_log_debug(OS_LOG_BLE, "handleIncomingData: device=%{public}@: server handshake received second payload", [self getIdentifier]); + [self.logger d:@"handleIncomingData: device=%@: server handshake received second payload", [self.logger SensitiveNSObject:[self getIdentifier]]]; self.l2capServerHandshakeRunning = FALSE; self.useL2cap = TRUE; } else { - os_log_error(OS_LOG_BLE, "handleIncomingData: device=%{public}@: server handshake received wrong payload", [self getIdentifier]); + [self.logger e:@"handleIncomingData: device=%@: server handshake received wrong payload", [self.logger SensitiveNSObject:[self getIdentifier]]]; } } else { if (!self.peer) { - os_log_error(OS_LOG_BLE, "handleIncomingData: device=%{public}@: peer not existing", [self getIdentifier]); + [self.logger e:@"handleIncomingData: device=%@: peer not existing", [self.logger SensitiveNSObject:[self getIdentifier]]]; return [self putIncomingDataInCache:data]; } if (![self.peer isConnected]) { - os_log(OS_LOG_BLE, "handleIncomingData: device=%{public}@: peer not connected, put data in cache", [self getIdentifier]); + [self.logger d:@"handleIncomingData: device=%@: peer not connected, put data in cache", [self.logger SensitiveNSObject:[self getIdentifier]]]; return [self putIncomingDataInCache:data]; } @@ -281,12 +279,12 @@ - (void)handshake { } } -- (BOOL) setNotifyValue { +- (BOOL)setNotifyValue { if (self.peripheral != nil && self.peripheral.state == CBPeripheralStateConnected) { - os_log_debug(OS_LOG_BLE, "handshake: going to subscribe to writer notifications"); + [self.logger d:@"setNotifyValue: going to subscribe to writer notifications"]; [self.writeQ add:^{ if (self.peripheral != nil && self.peripheral.state == CBPeripheralStateConnected) { - os_log_debug(OS_LOG_BLE, "handshake: subscribe to writer notifications"); + [self.logger d:@"setNotifyValue: subscribing to writer notifications"]; [self.peripheral setNotifyValue:TRUE forCharacteristic:self.writerCharacteristic]; } } withCallback:nil withDelay:0]; @@ -302,7 +300,7 @@ - (void)peripheral:(CBPeripheral *)peripheral didModifyServices:(NSArray 0) { NSData *received = [NSData dataWithBytes:buf length:len]; - os_log_debug(OS_LOG_BLE, "stream handleEvent: inputStream NSStreamEventHasBytesAvailable: device=%{public}@ read length=%lu value=%{public}@", [self getIdentifier], len, received); + [self.logger d:@"stream handleEvent: NSStreamEventHasBytesAvailable: device=%@ read length=%lu value=%@", [self.logger SensitiveNSObject:[self getIdentifier]], len, [self.logger SensitiveNSObject:received]]; [self handleIncomingData:received]; } else { - os_log_error(OS_LOG_BLE, "stream handleEvent error: NSStreamEventHasBytesAvailable: identifier=%{public}@: nothing to read", [self getIdentifier]); + [self.logger e:@"stream handleEvent error: NSStreamEventHasBytesAvailable: device=%@: nothing to read", [self.logger SensitiveNSObject:[self getIdentifier]]]; } break; } case NSStreamEventHasSpaceAvailable: { - os_log_debug(OS_LOG_BLE, "stream handleEvent: NSStreamEventHasSpaceAvailable: identifier=%{public}@", [self getIdentifier]); - + [self.logger d:@"stream handleEvent: NSStreamEventHasSpaceAvailable: device=%@", [self.logger SensitiveNSObject:[self getIdentifier]]]; + if ((self.peer != nil && [self.peer isConnected]) || self.l2capServerHandshakeRunning || self.l2capClientHandshakeRunning) { @synchronized (self.writerLatch) { if (self.l2capWriteData != nil) { @@ -846,13 +862,14 @@ - (void)stream:(NSStream *)stream handleEvent:(NSStreamEvent)eventCode { (void)memcpy(buf, readBytes, len); - os_log_debug(OS_LOG_BLE, "stream handleEvent: NSStreamEventHasSpaceAvailable: identifier=%{public}@ try to write data offset=%lu len=%lu base64=%{public}@ data=%{public}@", [self getIdentifier], self.l2capWriteIndex, len, [[NSData dataWithBytes:buf length:len] base64EncodedStringWithOptions:0], [BleManager NSDataToHex:[NSData dataWithBytes:buf length:len]]); + if ([self.logger showSensitiveData]) { + [self.logger d:@"stream handleEvent: NSStreamEventHasSpaceAvailable: device=%@ offset=%lu len=%lu base64=%@ data=%@", [self getIdentifier], self.l2capWriteIndex, len, [[NSData dataWithBytes:buf length:len] base64EncodedStringWithOptions:0], [BleManager NSDataToHex:[NSData dataWithBytes:buf length:len]]]; + } NSInteger wroteLen = [(NSOutputStream *)stream write:(const uint8_t *)buf maxLength:len]; - os_log_debug(OS_LOG_BLE, "stream handleEvent: NSStreamEventHasSpaceAvailable: identifier=%{public}@ wrote data offset=%lu len=%zd", [self getIdentifier], self.l2capWriteIndex, wroteLen); + [self.logger d:@"stream handleEvent: NSStreamEventHasSpaceAvailable: device=%@ wrote data offset=%lu len=%zd", [self.logger SensitiveNSObject:[self getIdentifier]], self.l2capWriteIndex, wroteLen]; if (wroteLen == -1) { - os_log_error(OS_LOG_BLE, "stream handleEvent error: NSStreamEventHasSpaceAvailable: identifier=%{public}@: write error", [self getIdentifier]); - + [self.logger e:@"stream handleEvent error: NSStreamEventHasSpaceAvailable: device=%@ write: error", [self.logger SensitiveNSObject:[self getIdentifier]]]; self.l2capWriteData = nil; [self.writeQ completedTask:[NSError errorWithDomain:@LOCAL_DOMAIN code:200 userInfo:@{@"Error reason": @"write error"}]]; @@ -861,44 +878,43 @@ - (void)stream:(NSStream *)stream handleEvent:(NSStreamEvent)eventCode { self.l2capWriteIndex += wroteLen; if ([self.l2capWriteData length] == self.l2capWriteIndex) { - os_log_debug(OS_LOG_BLE, "stream handleEvent: NSStreamEventHasSpaceAvailable: identifier=%{public}@: write completed", [self getIdentifier]); + [self.logger d:@"stream handleEvent: NSStreamEventHasSpaceAvailable: device=%@: write completed", [self.logger SensitiveNSObject:[self getIdentifier]]]; self.l2capWriteData = nil; [self.writeQ completedTask:nil]; } } else { - os_log_debug(OS_LOG_BLE, "stream handleEvent: NSStreamEventHasSpaceAvailable: identifier=%{public}@: no data to write", [self getIdentifier]); + [self.logger d:@"stream handleEvent: NSStreamEventHasSpaceAvailable: device=%@: no data to write", [self.logger SensitiveNSObject:[self getIdentifier]]]; } } } else { - os_log_error(OS_LOG_BLE, "stream handleEvent error: NSStreamEventHasSpaceAvailable: identifier=%{public}@: device is not connected", [self getIdentifier]); + [self.logger e:@"stream handleEvent error: NSStreamEventHasSpaceAvailable: device=%@: device is not connected", [self.logger SensitiveNSObject:[self getIdentifier]]]; } break; } case NSStreamEventErrorOccurred: { - os_log_debug(OS_LOG_BLE, "stream handleEvent: NSStreamEventErrorOccurred: identifier=%{public}@", [self getIdentifier]); + [self.logger d:@"stream handleEvent: NSStreamEventErrorOccurred: device=%@", [self.logger SensitiveNSObject:[self getIdentifier]]]; [self.manager disconnect:self]; break; } - case NSStreamEventEndEncountered: { - os_log_debug(OS_LOG_BLE, "stream handleEvent: NSStreamEventEndEncountered: identifier=%{public}@", [self getIdentifier]); + case NSStreamEventEndEncountered: { // (d4ryl00): not sure how to handle this case + [self.logger d:@"stream handleEvent: NSStreamEventEndEncountered: device=%@", [self.logger SensitiveNSObject:[self getIdentifier]]]; if (self.l2capChannel.outputStream == stream) { NSData *newData = [stream propertyForKey:NSStreamDataWrittenToMemoryStreamKey]; if (!newData) { - os_log_debug(OS_LOG_BLE, "stream handleEvent: NSStreamEventEndEncountered: identifier=%{public}@: no more data", [self getIdentifier]); + [self.logger d:@"stream handleEvent: NSStreamEventEndEncountered: device=%@: no more data", [self.logger SensitiveNSObject:[self getIdentifier]]]; } else { - os_log_debug(OS_LOG_BLE, "stream handleEvent: NSStreamEventEndEncountered: identifier=%{public}@: data to process", [self getIdentifier]); + [self.logger d:@"stream handleEvent: NSStreamEventEndEncountered: device=%@: data to process", [self.logger SensitiveNSObject:[self getIdentifier]]]; [self handleIncomingData:newData]; } } stream.delegate = nil; [stream close]; - os_log_error(OS_LOG_BLE, "stream handleEvent: NSStreamEventEndEncountered: identifier=%{public}@: thread name=%{public}@", [self getIdentifier], [[NSThread currentThread] name]); [stream removeFromRunLoop:[NSRunLoop currentRunLoop] forMode:NSDefaultRunLoopMode]; if (self.l2capThread != nil) { [self.l2capThread cancel]; diff --git a/go/pkg/ble-driver/BleInterface_darwin.h b/go/pkg/ble-driver/BleInterface_darwin.h index f615b02b..05f8e84d 100644 --- a/go/pkg/ble-driver/BleInterface_darwin.h +++ b/go/pkg/ble-driver/BleInterface_darwin.h @@ -11,12 +11,11 @@ #import #import +#import "BleManager_darwin.h" +#import "Logger.h" + #ifndef BleInterface_h #define BleInterface_h -@class BleManager; - -#define LOCAL_DOMAIN "tech.berty.bty.BLE" -extern os_log_t OS_LOG_BLE; void BLEStart(char *localPID); void BLEStop(void); @@ -26,5 +25,7 @@ void BLECloseConnWithPeer(char *remotePID); int BLEBridgeHandleFoundPeer(NSString *remotePID); void BLEBridgeHandleLostPeer(NSString *remotePID); void BLEBridgeReceiveFromPeer(NSString *remotePID, NSData *payload); +void BLEBridgeLog(enum level level, NSString *message); +void BLEUseExternalLogger(void); #endif /* BleInterface_h */ diff --git a/go/pkg/ble-driver/BleInterface_darwin.m b/go/pkg/ble-driver/BleInterface_darwin.m index b6b67117..eae65e9e 100644 --- a/go/pkg/ble-driver/BleInterface_darwin.m +++ b/go/pkg/ble-driver/BleInterface_darwin.m @@ -7,41 +7,50 @@ // Copyright © 2018 sacha. All rights reserved. // -#import #import "BleInterface_darwin.h" -#import "BertyDevice_darwin.h" -#import "ConnectedPeer.h" // This functions are Go functions so they aren't defined here extern int BLEHandleFoundPeer(char *); extern void BLEHandleLostPeer(char *); extern void BLEReceiveFromPeer(char *, void *, unsigned long); +extern void BLELog(enum level level, const char *message); -os_log_t OS_LOG_BLE = nil; +static BleManager *manager = nil; +BOOL useExternalLogger = FALSE; void handleException(NSException* exception) { - os_log_error(OS_LOG_BLE, "🔴 Unhandled exception %{public}@", exception); + NSLog(@"Unhandled exception %@", exception); } BleManager* getManager(void) { - static BleManager *manager = nil; - @synchronized([BleManager class]) { if(!manager) { - os_log(OS_LOG_BLE, "BleManager: initialization"); - manager = [[BleManager alloc] initScannerAndAdvertiser]; + NSLog(@"BleManager: initialization"); + manager = [[BleManager alloc] initDriver:useExternalLogger]; } } return manager; } +void releaseManager(void) { + @synchronized([BleManager class]) + { + if(manager) { + NSLog(@"releaseManager"); + [manager release]; + } + } +} + +#pragma mark - incoming API functions + void BLEStart(char *localPID) { - OS_LOG_BLE = os_log_create(LOCAL_DOMAIN, "protocol"); - os_log_debug(OS_LOG_BLE, "🟢 BLEStart()"); + NSLog(@"BLEStart called"); @autoreleasepool { NSString *localPIDString = [NSString stringWithUTF8String:localPID]; [getManager() setLocalPID:localPIDString]; + [getManager().logger i:@"BLEStart: pid=%@", [getManager().logger SensitiveNSObject:localPIDString]]; [getManager() setID:[localPIDString substringWithRange:NSMakeRange([localPIDString length] - 4, 4)]]; [getManager() startScanning]; [getManager() startAdvertising]; @@ -51,10 +60,11 @@ void BLEStart(char *localPID) { // TODO: Implement this, check if error void BLEStop(void) { - os_log_debug(OS_LOG_BLE, "🟢 BLEStop()"); + [getManager().logger i:@"BLEStop"]; [getManager() stopScanning]; [getManager() stopAdvertising]; [getManager() closeAllConnections]; + releaseManager(); } int BLESendToPeer(char *remotePID, void *payload, int length) { @@ -65,12 +75,12 @@ int BLESendToPeer(char *remotePID, void *payload, int length) { BertyDevice *bDevice = [getManager() findPeripheralFromPID:cPID]; if (bDevice == nil) { - os_log_error(OS_LOG_BLE, "BLESendToPeer error: no device found"); + [getManager().logger e:@"BLESendToPeer error: no device found"]; return 0; } if (bDevice.peer == nil) { - os_log_error(OS_LOG_BLE, "BLESendToPeer error: peer object not found"); + [getManager().logger e:@"BLESendToPeer error: peer object not found"]; return 0; } @@ -82,7 +92,7 @@ int BLESendToPeer(char *remotePID, void *payload, int length) { } else if ([bDevice.peer isServerReady]) { status = [getManager() writeAndNotify:bDevice data:cPayload]; } else { - os_log_error(OS_LOG_BLE, "BLESendToPeer error: device not connected"); + [getManager().logger e:@"BLESendToPeer error: device not connected"]; } } @@ -101,15 +111,22 @@ int BLEDialPeer(char *remotePID) { // TODO: Implement this void BLECloseConnWithPeer(char *remotePID) { - os_log_error(OS_LOG_BLE, "🟢 BLECloseConnWithPeer()"); + [getManager().logger i:@"BLECloseConnWithPeer called: remotePID=%@", [getManager().logger SensitiveString:remotePID]]; BertyDevice *bDevice = [getManager() findPeripheralFromPID:[NSString stringWithUTF8String:remotePID]]; if (bDevice != nil) { [getManager() disconnect:bDevice]; } } + +// Use BLEBridgeLog to write logs to the external logger +void BLEUseExternalLogger(void) { + useExternalLogger = TRUE; +} + +#pragma mark - outgoing API functions + int BLEBridgeHandleFoundPeer(NSString *remotePID) { - os_log_debug(OS_LOG_BLE, "BLEBridgeHandleFoundPeer called"); char *cPID = (char *)[remotePID UTF8String]; if (BLEHandleFoundPeer(cPID)) { return (1); @@ -118,7 +135,6 @@ int BLEBridgeHandleFoundPeer(NSString *remotePID) { } void BLEBridgeHandleLostPeer(NSString *remotePID) { - os_log_debug(OS_LOG_BLE, "BLEBridgeHandleLostPeer called"); char *cPID = (char *)[remotePID UTF8String]; BLEHandleLostPeer(cPID); } @@ -129,3 +145,9 @@ void BLEBridgeReceiveFromPeer(NSString *remotePID, NSData *payload) { int length = (int)[payload length]; BLEReceiveFromPeer(cPID, cPayload, length); } + +// Write logs to the external logger +void BLEBridgeLog(enum level level, NSString *message) { + char *cMessage = (char *)[message UTF8String]; + BLELog(level, cMessage); +} diff --git a/go/pkg/ble-driver/BleManager_darwin.h b/go/pkg/ble-driver/BleManager_darwin.h index c9f118a6..25562b25 100644 --- a/go/pkg/ble-driver/BleManager_darwin.h +++ b/go/pkg/ble-driver/BleManager_darwin.h @@ -8,14 +8,16 @@ #import #import -#import "CountDownLatch_darwin.h" + #import "BleInterface_darwin.h" +#import "BertyDevice_darwin.h" +#import "PeerManager.h" +#import "CountDownLatch_darwin.h" #import "WriteDataCache.h" -#ifndef BleManager_h -#define BleManager_h +#define LOCAL_DOMAIN "tech.berty.bty" -@class BertyDevice; +NS_ASSUME_NONNULL_BEGIN @interface BleManager : NSObject @@ -25,6 +27,8 @@ + (NSString *__nonnull)NSDataToHex:(NSData *__nonnull)data; + (void) printLongLog:(NSString *__nonnull)message; +@property (nonatomic, strong, nullable) Logger *logger; +@property (nonatomic, strong, nonnull) PeerManager *peerManager; @property (readwrite) BOOL pmEnable; @property (readwrite) BOOL cmEnable; @property (readwrite) int psm; @@ -48,7 +52,7 @@ @property (nonatomic, strong, nullable) CountDownLatch *writerLactch; @property (readwrite) BOOL writeStatus; -- (instancetype __nonnull) initScannerAndAdvertiser; +- (instancetype __nonnull) initDriver:(BOOL)useExternalLogger; - (void)addService; - (void)startScanning; - (void)toggleScanner:(NSTimer *__nonnull)timer; @@ -63,4 +67,4 @@ @end -#endif +NS_ASSUME_NONNULL_END diff --git a/go/pkg/ble-driver/BleManager_darwin.m b/go/pkg/ble-driver/BleManager_darwin.m index ba314650..998ed692 100644 --- a/go/pkg/ble-driver/BleManager_darwin.m +++ b/go/pkg/ble-driver/BleManager_darwin.m @@ -7,16 +7,7 @@ // Copyright © 2019 berty. All rights reserved. // -#import -#import "BleInterface_darwin.h" #import "BleManager_darwin.h" -#import "BertyDevice_darwin.h" -#import "PeerManager.h" -#import "ConnectedPeer.h" -#import "CircularQueue.h" -#import "WriteDataCache.h" -#import "CountDownLatch_darwin.h" -#import @implementation BleManager static NSString* const __nonnull SERVICE_UUID = @"00004240-0000-1000-8000-00805F9B34FB"; @@ -77,11 +68,17 @@ + (void) printLongLog:(NSString *__nonnull)message { } // TODO: No need to check error on this? -- (instancetype __nonnull) initScannerAndAdvertiser { - os_log_debug(OS_LOG_BLE, "🟢 peripheralManager: initScannerAndAdvertiser"); +- (instancetype __nonnull) initDriver:(BOOL)useExternalLogger { self = [super init]; if (self) { + BOOL showSensitiveData = FALSE; + if (useExternalLogger) { + _logger = [[Logger alloc] initWithExternalLoggerAndShowSensitiveData:showSensitiveData]; + } else { + _logger = [[Logger alloc] initLocalLoggerWithSubSystem:LOCAL_DOMAIN andCategorie:"BLE" showSensitiveData:showSensitiveData]; + } + _peerManager = [[PeerManager alloc] initWithLogger:_logger]; _cmEnable = FALSE; _pmEnable = FALSE; _scannerTimer = nil; @@ -107,7 +104,8 @@ - (instancetype __nonnull) initScannerAndAdvertiser { } - (void)initService { - os_log_debug(OS_LOG_BLE, "🟢 peripheralManager: initService"); + [self.logger d:@"initService called"]; + _scanning = FALSE; _serviceUUID = [[CBUUID UUIDWithString:SERVICE_UUID] retain]; _peerUUID = [[CBUUID UUIDWithString:PEER_ID_UUID] retain]; @@ -133,6 +131,8 @@ - (void)initService { } - (void)dealloc { + [_logger release]; + [_peerManager release]; [_bleOn release]; [_serviceAdded release]; [_bDevices release]; @@ -152,7 +152,8 @@ - (void)dealloc { - (void)addService { static dispatch_once_t onceToken; dispatch_once(&onceToken, ^{ - os_log_debug(OS_LOG_BLE, "🟢 peripheralManager: AddService: %{public}@", [self.serviceUUID UUIDString]); + [self.logger d:@"addService: service=%@", [self.serviceUUID UUIDString]]; + [self.bleOn await]; if (self.cmEnable && self.pmEnable) { [self.pManager addService:self.bertyService]; @@ -163,9 +164,9 @@ - (void)addService { - (void)peripheralManager:(CBPeripheralManager *)peripheral didAddService:(CBService *)service error:(nullable NSError *)error { if (error) { - os_log_error(OS_LOG_BLE, "🔴 didAddService() error: %{public}@", [error localizedFailureReason]); + [self.logger e:@"didAddService() error=%@", [error localizedFailureReason]]; } - os_log_debug(OS_LOG_BLE, "🟢 peripheralManager: didAddService: %{public}@", [service.UUID UUIDString]); + [self.logger d:@"didAddService: service=%@", [service.UUID UUIDString]]; [self.serviceAdded countDown]; } @@ -175,7 +176,8 @@ - (void)startScanning { @synchronized (self.cManager) { if (self.cmEnable && !self.scanning) { if (self.localPID != nil) { - os_log_debug(OS_LOG_BLE, "🟢 startScanning: localPID=%{public}@", self.localPID); + [self.logger d:@"startScanning called"]; + NSDictionary *options = [NSDictionary dictionaryWithObjectsAndKeys:[NSNumber numberWithBool:YES], CBCentralManagerScanOptionAllowDuplicatesKey, nil]; @@ -186,7 +188,7 @@ - (void)startScanning { self.scannerTimer = [NSTimer scheduledTimerWithTimeInterval:12.0 target:self selector:@selector(toggleScanner:) userInfo:nil repeats:YES]; }); } else { - os_log_error(OS_LOG_BLE, "startScanning error: localPID is null"); + [self.logger e:@"startScanning error: localPID is null"]; } } } @@ -194,10 +196,10 @@ - (void)startScanning { - (void)toggleScanner:(NSTimer*)timer { if ([self.cManager isScanning]) { - NSLog(@"toggleScanner: disable scanner"); + [self.logger d:@"toggleScanner: disable scanner"]; [self.cManager stopScan]; } else { - NSLog(@"toggleScanner: enable scanner"); + [self.logger d:@"toggleScanner: enable scanner"]; NSDictionary *options = [NSDictionary dictionaryWithObjectsAndKeys:[NSNumber numberWithBool:YES], CBCentralManagerScanOptionAllowDuplicatesKey, nil]; @@ -209,7 +211,8 @@ - (void)toggleScanner:(NSTimer*)timer { - (void)stopScanning { @synchronized (self.cManager) { if (self.cmEnable && self.scanning) { - NSLog(@"🟢 stopScanning called"); + [self.logger d:@"stopScanning called"]; + dispatch_async(dispatch_get_main_queue(), ^{ if (self.scannerTimer != nil) { if ([self.scannerTimer isValid]) { @@ -232,7 +235,7 @@ - (void)startAdvertising { @synchronized (self.pManager) { if (self.pmEnable && ![self.pManager isAdvertising]) { if (self.ID != nil) { - os_log_debug(OS_LOG_BLE, "🟢 startAdvertising() name=%{public}@", self.ID); + [self.logger d:@"startAdvertising called: ID=%@", [self.logger SensitiveNSObject:self.ID]]; // publish l2cap channel self.psm = 0; @@ -242,7 +245,7 @@ - (void)startAdvertising { [self.pManager startAdvertising:@{ CBAdvertisementDataLocalNameKey:self.ID, CBAdvertisementDataServiceUUIDsKey:@[self.serviceUUID]}]; } else { - os_log_error(OS_LOG_BLE, "startAdvertising error: local ID is null"); + [self.logger e:@"startAdvertising error: local ID is null"]; } } } @@ -250,26 +253,30 @@ - (void)startAdvertising { - (void)stopAdvertising { @synchronized (self.pManager) { + [self.logger d:@"stopAdvertising called"]; if (self.pmEnable && [self.pManager isAdvertising]) { - os_log_debug(OS_LOG_BLE, "🟢 stopAdvertising()"); if (@available(iOS 11.0, *)) { if (self.psm != 0) { [self.pManager unpublishL2CAPChannel:self.psm]; } } [self.pManager stopAdvertising]; + } else { + [self.logger e:@"stopAdvertising error: advertising not started"]; } } } // Only the client side can disconnect - (void)disconnect:(BertyDevice *__nonnull)device { + [self.logger d:@"closeAllConnections called: debice=%@", [self.logger SensitiveNSObject:[device clientSideIdentifier]]]; + if (device.peripheral != nil && device.clientSideIdentifier != nil) { - os_log_debug(OS_LOG_BLE, "🟢 disconnect: client device=%{public}@", [device clientSideIdentifier]); + [self.logger d:@"disconnect: client device=%@", [self.logger SensitiveNSObject:[device clientSideIdentifier]]]; if (device.peripheral.state == CBPeripheralStateConnecting || device.peripheral.state == CBPeripheralStateConnected) { [self.cManager cancelPeripheralConnection:device.peripheral]; } else { - os_log(OS_LOG_BLE, "🟢 disconnect: client device=%{public}@ not connected", [device clientSideIdentifier]); + [self.logger d:@"disconnect: client device=%@ not connected", [self.logger SensitiveNSObject:[device clientSideIdentifier]]]; return ; } } else { @@ -278,7 +285,8 @@ - (void)disconnect:(BertyDevice *__nonnull)device { } - (void)closeAllConnections { - os_log_debug(OS_LOG_BLE, "🟢 closeAllConnections()"); + [self.logger i:@"closeAllConnections called"]; + if (self.cmEnable) { @synchronized (self.bDevices) { for (BertyDevice *device in self.bDevices) { @@ -289,8 +297,10 @@ - (void)closeAllConnections { } - (BOOL)writeAndNotify:(BertyDevice *__nonnull)device data:(NSData *__nonnull)data { - os_log_debug(OS_LOG_BLE, "writeAndNotify: identifier=%{public}@ base64=%{public}@", [device getIdentifier], [data base64EncodedStringWithOptions:0]); - [BleManager printLongLog:[BleManager NSDataToHex:data]]; + [self.logger d:@"writeAndNotify: device=%@ base64=%@", [self.logger SensitiveNSObject:[device clientSideIdentifier]], [self.logger SensitiveNSObject:[data base64EncodedStringWithOptions:0]]]; + if ([self.logger showSensitiveData]) { + [BleManager printLongLog:[BleManager NSDataToHex:data]]; + } BOOL success = FALSE; NSUInteger mtu = device.cbCentral.maximumUpdateValueLength; @@ -299,7 +309,7 @@ - (BOOL)writeAndNotify:(BertyDevice *__nonnull)device data:(NSData *__nonnull)da while (offset < dataLen) { if (![device.peer isServerReady]) { - os_log_error(OS_LOG_BLE, "writeAndNotify error: identifier=%{public}@ server not connected", [device getIdentifier]); + [self.logger e:@"writeAndNotify error: device=%@ server not connected", [self.logger SensitiveNSObject:[device clientSideIdentifier]]]; return FALSE; } @@ -307,12 +317,14 @@ - (BOOL)writeAndNotify:(BertyDevice *__nonnull)device data:(NSData *__nonnull)da NSUInteger toWriteLen = (dataLen - offset) < mtu ? (dataLen - offset) : mtu; NSData *toWrite = [[data subdataWithRange:NSMakeRange(offset, toWriteLen)] retain]; - os_log_debug(OS_LOG_BLE, "writeAndNotify: identifier=%{public}@ mtu=%lu base64=%{public}@ data=%{public}@", [device getIdentifier], mtu, [toWrite base64EncodedStringWithOptions:0], [BleManager NSDataToHex:toWrite]); + if ([self.logger showSensitiveData]) { + [self.logger d:@"writeAndNotify: device=%@ mtu=%lu base64=%@ data=%@", [device getIdentifier], mtu, [toWrite base64EncodedStringWithOptions:0], [BleManager NSDataToHex:toWrite]]; + } // Need to add data to the cache prior to write it because sometime peripheralManagerIsReadyToUpdateSubscribers is called before data is put to the cache @synchronized (self.writeCache) { self.writeCache = [[WriteDataCache alloc] initWithDevice:device withData:toWrite]; - os_log(OS_LOG_BLE, "writeAndNotify: identifier=%{public}@: data put in cache successfully", [device getIdentifier]); + [self.logger d:@"writeAndNotify: device=%@: data put in cache successfully", [self.logger SensitiveNSObject:[device getIdentifier]]]; } success = [self.pManager updateValue:toWrite forCharacteristic:self.writerCharacteristic onSubscribedCentrals:@[device.cbCentral]]; @@ -320,7 +332,7 @@ - (BOOL)writeAndNotify:(BertyDevice *__nonnull)device data:(NSData *__nonnull)da if (success) { [self.writerLactch countDown]; } else { - os_log(OS_LOG_BLE, "writeAndNotify: identifier=%{public}@: operation queue is full and will be processed by the peripheralManagerIsReadyToUpdateSubscribers callback", [device getIdentifier]); + [self.logger d:@"writeAndNotify: device=%@: operation queue is full and will be processed by the peripheralManagerIsReadyToUpdateSubscribers callback", [self.logger SensitiveNSObject:[device getIdentifier]]]; } [self.writerLactch await]; @@ -344,7 +356,7 @@ - (BOOL)writeAndNotify:(BertyDevice *__nonnull)device data:(NSData *__nonnull)da offset += toWriteLen; } - os_log_debug(OS_LOG_BLE, "writeAndNotify: identifier=%{public}@: success=%d", [device getIdentifier], success); + [self.logger d:@"writeAndNotify: device=%@: success=%d", [self.logger SensitiveNSObject:[device getIdentifier]], success]; return success; } @@ -412,17 +424,14 @@ - (BertyDevice *)findPeripheralFromIdentifier:(NSUUID *)identifier { return result; } -#pragma mark - BleManager Connection Handler - - #pragma mark - CentraManagerDelegate - (void)centralManager:(CBCentralManager *)central didConnectPeripheral:(CBPeripheral *)peripheral { - os_log(OS_LOG_BLE, "🟢 didConnectPeripheral() %{public}@", [peripheral.identifier UUIDString]); + [self.logger i:@"didConnectPeripheral called: device=%@", [self.logger SensitiveNSObject:[peripheral.identifier UUIDString]]]; BertyDevice *bDevice = [self findPeripheral:peripheral]; if (bDevice == nil) { - os_log_debug(OS_LOG_BLE, "🟢 didConnectPeripheral(): device %{public}@ not found", [peripheral.identifier UUIDString]); + [self.logger e:@"didConnectPeripheral error: device=%@ not found", [self.logger SensitiveNSObject:[peripheral.identifier UUIDString]]]; [self.cManager cancelPeripheralConnection:peripheral]; return ; } @@ -430,11 +439,11 @@ - (void)centralManager:(CBCentralManager *)central didConnectPeripheral:(CBPerip } - (void)centralManager:(CBCentralManager *)central didFailToConnectPeripheral:(CBPeripheral *)peripheral error:(NSError *)error { - os_log(OS_LOG_BLE, "🔴 didFailToConnectPeripheral() %{public}@", [peripheral.identifier UUIDString]); + [self.logger i:@"didFailToConnectPeripheral called: device=%@", [self.logger SensitiveNSObject:[peripheral.identifier UUIDString]]]; BertyDevice *bDevice = [self findPeripheral:peripheral]; if (bDevice == nil) { - os_log_debug(OS_LOG_BLE, "🔴 didFailToConnectPeripheral(): device %{public}@ not found", [peripheral.identifier UUIDString]); + [self.logger e:@"didFailToConnectPeripheral error: device=%@ not found", [self.logger SensitiveNSObject:[peripheral.identifier UUIDString]]]; return ; } [bDevice handleConnect:error]; @@ -457,25 +466,24 @@ - (void)centralManager:(CBCentralManager *)central id = [[NSString alloc] initWithData:[data objectForKey:uuid] encoding:NSUTF8StringEncoding]; [id autorelease]; } else { - os_log_debug(OS_LOG_BLE, "didDiscoverPeripheral: CBAdvertisementDataServiceDataKey doesn't contains any data"); + [self.logger d:@"didDiscoverPeripheral error: device=%@: CBAdvertisementDataServiceDataKey doesn't contains any data", [self.logger SensitiveNSObject:[peripheral.identifier UUIDString]]]; return ; } } else { // verbose - // os_log_debug(OS_LOG_BLE, "🟡 didDiscoverPeripheral() device %{public}@ has not advertisement name", - // [peripheral.identifier UUIDString]); +// [self.logger e:@"didDiscoverPeripheral error: device=%@ has not advertisement name", [self.logger SensitiveNSObject:[peripheral.identifier UUIDString]]]; return ; } if ([id length] == 0) { - os_log_debug(OS_LOG_BLE, "🟡 didDiscoverPeripheral() device %{public}@ name is empty", - [peripheral.identifier UUIDString]); + [self.logger d:@"didDiscoverPeripheral error: device=%@: id is empty", [self.logger SensitiveNSObject:[peripheral.identifier UUIDString]]]; return ; } // only lower id can be client if ([self.ID compare:id] != NSOrderedAscending) { - // os_log_debug(OS_LOG_BLE, "didDiscoverPeripheral: device=%{public}@: greater ID, cancel client connection", peripheral.identifier); + // Verbose +// [self.logger d:@"didDiscoverPeripheral: device=%@: greater ID, cancel client connection", [self.logger SensitiveNSObject:[peripheral.identifier UUIDString]]]; return ; } @@ -486,7 +494,7 @@ - (void)centralManager:(CBCentralManager *)central } // peripheral already known by CBPeripheralManager (advertising) // adding info given by CBCentralManager (scanning) - os_log_debug(OS_LOG_BLE, "didDiscoverPeripheral: address=%@ name=%@: already known", peripheral.identifier, id); + [self.logger d:@"didDiscoverPeripheral: device=%@ id=%@: already known", [self.logger SensitiveNSObject:[peripheral.identifier UUIDString]], [self.logger SensitiveNSObject:id]]; nDevice.peripheral = peripheral; nDevice.clientSideIdentifier = [peripheral.identifier UUIDString]; } else { @@ -498,19 +506,19 @@ - (void)centralManager:(CBCentralManager *)central // TODO: retest if bDevices is still null after @synchronized @synchronized (self.bDevices) { - nDevice = [[BertyDevice alloc]initWithPeripheral:peripheral central:self withName:id]; + nDevice = [[BertyDevice alloc]initWithPeripheral:peripheral logger:self.logger central:self withName:id]; [self.bDevices addObject:nDevice]; [nDevice release]; - os_log_debug(OS_LOG_BLE, "🟢 didDiscoverPeripheral() device %{public}@ added to BleManager.bDevices", - [peripheral.identifier UUIDString]); + [self.logger d:@"didDiscoverPeripheral: device=%@ added to BleManager.bDevices", [self.logger SensitiveNSObject:[peripheral.identifier UUIDString]]]; } } - os_log_debug(OS_LOG_BLE, "🟢 didDiscoverPeripheral found device address=%@ name=%@", peripheral.identifier, id); + [self.logger d:@"didDiscoverPeripheral: device=%@ id=%@: found. Going to connect.", [self.logger SensitiveNSObject:[peripheral.identifier UUIDString]], [self.logger SensitiveNSObject:id]]; [nDevice connectWithOptions:nil]; } - (void)centralManager:(CBCentralManager *)central didDisconnectPeripheral:(CBPeripheral *)peripheral error:(NSError *)error { - os_log(OS_LOG_BLE, "🟡 didDisconnectPeripheral() for device %{public}@ with error %{public}@", [peripheral.identifier UUIDString], error); + [self.logger i:@"didDisconnectPeripheral called: device=%@ error=%@", [self.logger SensitiveNSObject:[peripheral.identifier UUIDString]], error]; + BertyDevice *device = [self findPeripheral:peripheral]; if (device != nil) { [device closeBertyDevice]; @@ -562,7 +570,7 @@ - (void)peripheralManagerDidUpdateState:(nonnull CBPeripheralManager *)periphera break; } } - os_log(OS_LOG_BLE, "peripheralManagerDidUpdateState: %{public}@", stateString); + [self.logger i:@"peripheralManagerDidUpdateState: %@", stateString]; [self.bleOn countDown]; } @@ -599,16 +607,16 @@ - (void)centralManagerDidUpdateState:(nonnull CBCentralManager *)central { break; } } - os_log(OS_LOG_BLE, "centralManagerDidUpdateState: %{public}@", stateString); + [self.logger i:@"centralManagerDidUpdateState: %@", stateString]; [self.bleOn countDown]; } - (void)peripheralManager:(CBPeripheralManager *)peripheral central:(CBCentral *)central didSubscribeToCharacteristic:(CBCharacteristic *)characteristic { - os_log_debug(OS_LOG_BLE, "peripheralManager didSubscribeToCharacteristic: identifier=%{public}@", [central.identifier UUIDString]); + [self.logger d:@"peripheralManager didSubscribeToCharacteristic called: device=%@", [self.logger SensitiveNSObject:[central.identifier UUIDString]]]; BertyDevice *device; if ((device = [self findPeripheralFromIdentifier:central.identifier]) == nil) { - os_log_error(OS_LOG_BLE, "peripheralManager didSubscribeToCharacteristic error: peripheral=%{public}@ not found", [central.identifier UUIDString]); + [self.logger e:@"peripheralManager didSubscribeToCharacteristic error: device=%@ not found", [self.logger SensitiveNSObject:[central.identifier UUIDString]]]; return ; } @@ -619,22 +627,22 @@ - (void)peripheralManager:(CBPeripheralManager *)peripheral central:(CBCentral * device.l2capServerHandshakeRunning = FALSE; // complete handshake - device.peer = [PeerManager registerDevice:device withPeerID:device.remotePeerID isClient:FALSE]; + device.peer = [self.peerManager registerDevice:device withPeerID:device.remotePeerID isClient:FALSE]; if (device.peer == nil) { - os_log_error(OS_LOG_BLE, "peripheralManager didSubscribeToCharacteristic(): identifier=%{public}@: registerDevice failed", [central.identifier UUIDString]); + [self.logger e:@"peripheralManager didSubscribeToCharacteristic error: device=%@: registerDevice failed", [self.logger SensitiveNSObject:[central.identifier UUIDString]]]; return ; } else { - os_log_debug(OS_LOG_BLE, "peripheralManager didSubscribeToCharacteristic(): identifier=%{public}@ registerDevice successed", [central.identifier UUIDString]); + [self.logger d:@"peripheralManager didSubscribeToCharacteristic: device=%@: registerDevice successed", [self.logger SensitiveNSObject:[central.identifier UUIDString]]]; } } // server disconnection callback entry point - (void)peripheralManager:(CBPeripheralManager *)peripheral central:(CBCentral *)central didUnsubscribeFromCharacteristic:(CBCharacteristic *)characteristic { - os_log_debug(OS_LOG_BLE, "peripheralManager didUnsubscribeFromCharacteristic: identifier=%{public}@", [central.identifier UUIDString]); + [self.logger d:@"peripheralManager didUnsubscribeFromCharacteristic called: device=%@", [self.logger SensitiveNSObject:[central.identifier UUIDString]]]; BertyDevice *device; if ((device = [self findPeripheralFromIdentifier:central.identifier]) == nil) { - os_log_error(OS_LOG_BLE, "peripheralManager didUnsubscribeFromCharacteristic error: peripheral=%{public}@ not found", [central.identifier UUIDString]); + [self.logger e:@"peripheralManager didUnsubscribeFromCharacteristic error: device=%@ not found", [self.logger SensitiveNSObject:[central.identifier UUIDString]]]; return ; } @@ -645,27 +653,29 @@ - (void)peripheralManager:(CBPeripheralManager *)peripheral central:(CBCentral * } - (void)peripheralManagerIsReadyToUpdateSubscribers:(CBPeripheralManager *)peripheral { - os_log_debug(OS_LOG_BLE, "peripheralManager peripheralManagerIsReadyToUpdateSubscribers called"); + [self.logger d:@"peripheralManager peripheralManagerIsReadyToUpdateSubscribers called"]; self.writeStatus = FALSE; @synchronized(self.writeCache) { if (self.writeCache != nil) { - os_log_debug(OS_LOG_BLE, "peripheralManagerIsReadyToUpdateSubscribers: identifier=%{public}@ base64=%{public}@ data=%{public}@", [self.writeCache.device getIdentifier], [self.writeCache.data base64EncodedStringWithOptions:0], [BleManager NSDataToHex:self.writeCache.data]); + if (self.logger.showSensitiveData) { + [self.logger d:@"peripheralManagerIsReadyToUpdateSubscribers: device=%@ base64=%@ data=%@", [self.writeCache.device getIdentifier], [self.writeCache.data base64EncodedStringWithOptions:0], [BleManager NSDataToHex:self.writeCache.data]]; + } if (self.writerLactch == nil) { - os_log_error(OS_LOG_BLE, "peripheralManagerIsReadyToUpdateSubscribers error: writer latch is null"); + [self.logger e:@"peripheralManagerIsReadyToUpdateSubscribers error: writer latch is null"]; return ; } if (self.writeCache.device.peer == nil) { - os_log_error(OS_LOG_BLE, "peripheralManagerIsReadyToUpdateSubscribers error: peer object not found"); + [self.logger e:@"peripheralManagerIsReadyToUpdateSubscribers error: peer object not found"]; [self.writerLactch countDown]; return ; } if (![self.writeCache.device.peer isServerReady]) { - os_log_error(OS_LOG_BLE, "peripheralManagerIsReadyToUpdateSubscribers error: server not connected"); + [self.logger e:@"peripheralManagerIsReadyToUpdateSubscribers error: server not connected"]; [self.writerLactch countDown]; return ; } @@ -673,10 +683,10 @@ - (void)peripheralManagerIsReadyToUpdateSubscribers:(CBPeripheralManager *)perip self.writeStatus = [self.pManager updateValue:self.writeCache.data forCharacteristic:self.writerCharacteristic onSubscribedCentrals:@[self.writeCache.device.cbCentral]]; if (self.writeStatus) { - os_log_debug(OS_LOG_BLE, "peripheralManagerIsReadyToUpdateSubscribers: identifier=%{public}@: data sent", [self.writeCache.device getIdentifier]); + [self.logger d:@"peripheralManagerIsReadyToUpdateSubscribers: device=%@: data sent", [self.logger SensitiveNSObject:[self.writeCache.device getIdentifier]]]; [self.writerLactch countDown]; } else { - os_log_error(OS_LOG_BLE, "peripheralManagerIsReadyToUpdateSubscribers: identifier=%{public}@: operation queue is full, try later", [self.writeCache.device getIdentifier]); + [self.logger d:@"peripheralManagerIsReadyToUpdateSubscribers: device=%@: operation queue is full, try later", [self.logger SensitiveNSObject:[self.writeCache.device getIdentifier]]]; return ; } } @@ -687,14 +697,14 @@ - (void)peripheralManagerIsReadyToUpdateSubscribers:(CBPeripheralManager *)perip - (void)peripheralManager:(CBPeripheralManager *)peripheral didReceiveReadRequest:(CBATTRequest *)request { - os_log_debug(OS_LOG_BLE, "didReceiveReadRequests() reader called for device=%{public}@ request.offset=%lu", [request.central.identifier UUIDString], request.offset); + [self.logger d:@"didReceiveReadRequests called: device=%@ offset=%lu", [self.logger SensitiveNSObject:[request.central.identifier UUIDString]], request.offset]; if ([request.characteristic.UUID isEqual:self.peerUUID]) { - os_log_debug(OS_LOG_BLE, "didReceiveReadRequests: peerID characteristic selected: %{public}@", [request.central.identifier UUIDString]); + [self.logger d:@"didReceiveReadRequests: device=%@: use peerID characteristic", [self.logger SensitiveNSObject:[request.central.identifier UUIDString]]]; BertyDevice *device = [self findPeripheralFromIdentifier:request.central.identifier]; if (device == nil || device.remotePeerID == nil) { - os_log_error(OS_LOG_BLE, "didReceiveReadRequests(): device=%{public}@: write peerID not completed", [request.central.identifier UUIDString]); + [self.logger e:@"didReceiveReadRequests: device=%@: need writeRequest completed before readRequest", [self.logger SensitiveNSObject:[request.central.identifier UUIDString]]]; [peripheral respondToRequest:request withResult:CBATTErrorReadNotPermitted]; return ; } @@ -708,7 +718,7 @@ - (void)peripheralManager:(CBPeripheralManager *)peripheral didReceiveReadReques [peripheral respondToRequest:request withResult:CBATTErrorSuccess]; [toSend release]; } else { - os_log_error(OS_LOG_BLE, "🔴 didReceiveReadRequests(): bad characteristic"); + [self.logger e:@"didReceiveReadRequests: device=%@: bad characteristic requested", [self.logger SensitiveNSObject:[request.central.identifier UUIDString]]]; [peripheral respondToRequest:request withResult:CBATTErrorRequestNotSupported]; return ; } @@ -718,13 +728,15 @@ - (void)peripheralManager:(CBPeripheralManager *)peripheral didReceiveReadReques #pragma mark - write - (void)peripheralManager:(CBPeripheralManager *)peripheral didReceiveWriteRequests:(NSArray *)requests { - BertyDevice *device; + BertyDevice *device; NSData *data = nil; for (CBATTRequest *request in requests) { - os_log_debug(OS_LOG_BLE, "didReceiveWriteRequests: identifier=%{public}@ base64=%{public}@", [request.central.identifier UUIDString], [data base64EncodedStringWithOptions:0]); - [BleManager printLongLog:[BleManager NSDataToHex:data]]; + [self.logger d:@"didReceiveWriteRequests: device=%@ base64=%@", [self.logger SensitiveNSObject:[request.central.identifier UUIDString]], [self.logger SensitiveNSObject:[data base64EncodedStringWithOptions:0]]]; + if (self.logger.showSensitiveData) { + [BleManager printLongLog:[BleManager NSDataToHex:data]]; + } CBMutableCharacteristic *characteristic; @@ -732,11 +744,10 @@ - (void)peripheralManager:(CBPeripheralManager *)peripheral didReceiveWriteReque // check if we hold a remote device of this type device = [self findPeripheralFromIdentifier:request.central.identifier]; if (device == nil) { - device = [[BertyDevice alloc]initWithIdentifier:[request.central.identifier UUIDString] central:self asClient:FALSE]; + device = [[BertyDevice alloc]initWithIdentifier:[request.central.identifier UUIDString] logger:self.logger central:self asClient:FALSE]; [self.bDevices addObject:device]; [device release]; - os_log_debug(OS_LOG_BLE, "🟢 didReceiveWriteRequests: identifier=%{public}@ added to BleManager.bDevices", - [request.central.identifier UUIDString]); + [self.logger d:@"didReceiveWriteRequests: device=%@ added to BleManager.bDevices", [self.logger SensitiveNSObject:[request.central.identifier UUIDString]]]; } } @@ -746,7 +757,7 @@ - (void)peripheralManager:(CBPeripheralManager *)peripheral didReceiveWriteReque else if ([request.characteristic.UUID isEqual:self.peerUUID]) { characteristic = self.peerIDCharacteristic; } else { - os_log_error(OS_LOG_BLE, "🔴 didReceiveWriteRequests(): bad characteristic"); + [self.logger e:@"didReceiveWriteRequests error: device=%@: bad characteristic requested", [self.logger SensitiveNSObject:[request.central.identifier UUIDString]]]; [device closeBertyDevice]; [peripheral respondToRequest:request withResult:CBATTErrorWriteNotPermitted]; return ; @@ -754,20 +765,16 @@ - (void)peripheralManager:(CBPeripheralManager *)peripheral didReceiveWriteReque data = request.value; - //os_log(OS_LOG_BLE, "request ACTUALDATA=%{public}@ VAL=%{public}@ UUID=%{public}@ P=%p", data, request.value, request.characteristic.UUID, data); - BOOL(^handler)(NSData *) = [device.characteristicHandlers objectForKey:[request.characteristic.UUID UUIDString]]; if (!handler(data)) { - os_log_error(OS_LOG_BLE, "🔴 didReceiveWriteRequests: handle failed"); + [self.logger e:@"didReceiveWriteRequests error: device=%@: handle failed", [self.logger SensitiveNSObject:[request.central.identifier UUIDString]]]; [device closeBertyDevice]; [peripheral respondToRequest:request withResult:CBATTErrorWriteNotPermitted]; } - // Handle Response back - + // Process response back request.value = [self.localPID dataUsingEncoding:NSUTF8StringEncoding]; } - [peripheral respondToRequest:[requests objectAtIndex:0] withResult:CBATTErrorSuccess]; } @@ -775,37 +782,37 @@ - (void)peripheralManager:(CBPeripheralManager *)peripheral didReceiveWriteReque - (void)peripheralManager:(CBPeripheralManager *)peripheral didPublishL2CAPChannel:(CBL2CAPPSM)PSM error:(NSError *)error { if (error != nil) { - os_log_error(OS_LOG_BLE, "peripheralManager didPublishL2CAPChannel error=%{public}@", error); + [self.logger e:@"peripheralManager didPublishL2CAPChannel error=%@", error]; return ; } - os_log_debug(OS_LOG_BLE, "peripheralManager didPublishL2CAPChannel: PSM=%hu", PSM); + [self.logger d:@"peripheralManager didPublishL2CAPChannel: PSM=%hu", PSM]; self.psm = PSM; } - (void)peripheralManager:(CBPeripheralManager *)peripheral didUnpublishL2CAPChannel:(CBL2CAPPSM)PSM error:(NSError *)error { - os_log_debug(OS_LOG_BLE, "peripheralManager didUnpublishL2CAPChannel called"); + [self.logger d:@"peripheralManager didUnpublishL2CAPChannel called"]; self.psm = 0; } - (void)peripheralManager:(CBPeripheralManager *)peripheral didOpenL2CAPChannel:(CBL2CAPChannel *)channel error:(NSError *)error API_AVAILABLE(ios(11.0)) { - os_log_debug(OS_LOG_BLE, "peripheralManager didOpenL2CAPChannel called: peripheral=%{public}@", [channel.peer.identifier UUIDString]); + [self.logger d:@"peripheralManager didOpenL2CAPChannel called: device=%@", [self.logger SensitiveNSObject:[channel.peer.identifier UUIDString]]]; if (error != nil) { - os_log_error(OS_LOG_BLE, "peripheralManager didOpenL2CAPChannel error=%{public}@", error); + [self.logger e:@"peripheralManager didOpenL2CAPChannel error=%@", error]; return ; } BertyDevice *device; if ((device = [self findPeripheralFromIdentifier:channel.peer.identifier]) == nil) { - os_log_error(OS_LOG_BLE, "peripheralManager didOpenL2CAPChannel error: peripheral=%{public}@ not found", [channel.peer.identifier UUIDString]); + [self.logger e:@"peripheralManager didOpenL2CAPChannel error: device=%@ not found", [self.logger SensitiveNSObject:[channel.peer.identifier UUIDString]]]; return ; } device.l2capChannel = channel; device.l2capThread = [[NSThread alloc] initWithBlock:^{ - os_log_debug(OS_LOG_BLE, "🟢 didOpenL2CAPChannel called: device=%{public}@: in thread", [device getIdentifier]); + [self.logger d:@"peripheralManager didOpenL2CAPChannel: device=%@: in thread", [self.logger SensitiveNSObject:[device getIdentifier]]]; channel.inputStream.delegate = device; [channel.inputStream scheduleInRunLoop:[NSRunLoop currentRunLoop] forMode:NSDefaultRunLoopMode]; diff --git a/go/pkg/ble-driver/BleQueue.h b/go/pkg/ble-driver/BleQueue.h index 9ce22a5f..e7214a48 100644 --- a/go/pkg/ble-driver/BleQueue.h +++ b/go/pkg/ble-driver/BleQueue.h @@ -6,6 +6,7 @@ // #import +#import "Logger.h" NS_ASSUME_NONNULL_BEGIN @@ -14,13 +15,14 @@ NS_ASSUME_NONNULL_BEGIN @interface BleQueue : NSObject @property (nonatomic, strong, nonnull) dispatch_queue_t queue; +@property (nonatomic, strong, nonnull) Logger *logger; @property (nonatomic, strong, nonnull) NSMutableArray *tasks; @property (readwrite) BOOL taskQueueBusy; @property (readwrite) BOOL isRetrying; @property (readwrite) int nbTries; @property (readwrite) int index; -- (instancetype __nullable) init:(dispatch_queue_t)queue; +- (instancetype __nullable) init:(dispatch_queue_t)queue logger:(Logger *__nonnull)logger; - (void) add:(void (^__nonnull)(void))block withCallback:(void (^__nullable)(NSError *))callback withDelay:(long)delay; - (void) completedTask:(NSError *__nullable)error; - (void) nextTask; diff --git a/go/pkg/ble-driver/BleQueue.m b/go/pkg/ble-driver/BleQueue.m index 3006d17a..8ed11d54 100644 --- a/go/pkg/ble-driver/BleQueue.m +++ b/go/pkg/ble-driver/BleQueue.m @@ -6,19 +6,18 @@ // Created by Rémi BARBERO on 03/05/2021. // -#import - #import "BleQueue.h" #import "TaskDelay.h" @implementation BleQueue -- (instancetype __nullable) init:(dispatch_queue_t) queue { +- (instancetype __nullable) init:(dispatch_queue_t)queue logger:(Logger *__nonnull)logger { self = [super init]; if (self) { _tasks = [[NSMutableArray alloc] init]; _queue = [queue retain]; + _logger = logger; } return self; @@ -28,6 +27,7 @@ - (void)dealloc { [_tasks removeAllObjects]; [_tasks release]; [_queue release]; + [_logger release]; [super dealloc]; } @@ -36,7 +36,7 @@ - (void) add:(void (^__nonnull)(void))block withCallback:(void (^__nullable)(NSE @synchronized (self.tasks) { TaskDelay *task = [[TaskDelay alloc] initWithBlock:block withCallback:callback withDelay:delay withIndex:(self.index++)]; [self.tasks addObject:task]; // add to the end of the array - NSLog(@"BleQueue: added task at index=%d count=%ld", task.index, [self.tasks count]); + [self.logger d:@"BleQueue: added task at index=%d count=%ld", task.index, [self.tasks count]]; [self nextTask]; [task release]; } @@ -47,12 +47,12 @@ - (void) completedTask:(NSError *__nullable)error { TaskDelay *currentTask; if ([self.tasks count] == 0) { - NSLog(@"BleQueue: completedTask error: no task running"); + [self.logger e:@"BleQueue: completedTask error: no task running"]; return ; } currentTask = [self.tasks objectAtIndex:0]; - NSLog(@"BleQueue: completedTask at index=%d", currentTask.index); + [self.logger d:@"BleQueue: completedTask at index=%d", currentTask.index]; if (currentTask.callback != nil) { dispatch_async(self.queue, ^{ currentTask.callback(error); @@ -71,17 +71,17 @@ - (void) nextTask { TaskDelay *nextTask; if (self.taskQueueBusy) { - NSLog(@"BleQueue: nextTask: another task is running"); + [self.logger d:@"BleQueue: nextTask: another task is running"]; return ; } if ([self.tasks count] == 0 ) { - NSLog(@"BleQueue: nextTask error: no task queued: count=%ld", [self.tasks count]); + [self.logger d:@"BleQueue: nextTask error: no task queued: count=%ld", [self.tasks count]]; return ; } nextTask = [self.tasks objectAtIndex:0]; - NSLog(@"BleQueue: nextTask at index=%d with delay=%ld", nextTask.index, nextTask.delay); + [self.logger d:@"BleQueue: nextTask at index=%d with delay=%ld", nextTask.index, nextTask.delay]; self.taskQueueBusy = TRUE; if (!self.isRetrying) { @@ -99,14 +99,14 @@ - (void) retryTask { self.taskQueueBusy = FALSE; if ([self.tasks count] == 0) { - NSLog(@"BleQueue: retryTask error: no task running"); + [self.logger e:@"BleQueue: retryTask error: no task running"]; } else { currentTask = [self.tasks objectAtIndex:0]; if (self.nbTries >= MAX_TRIES) { - NSLog(@"BleQueue: max number of tries reached, not retrying operation anymore for task index=%d", currentTask.index); + [self.logger d:@"BleQueue: max number of tries reached, not retrying operation anymore for task index=%d", currentTask.index]; [self.tasks removeObjectAtIndex:0]; } else { - NSLog(@"BleQueue: retrying task at index=%d", currentTask.index); + [self.logger d:@"BleQueue: retrying task at index=%d", currentTask.index]; self.isRetrying = TRUE; } } diff --git a/go/pkg/ble-driver/ConnectedPeer.h b/go/pkg/ble-driver/ConnectedPeer.h index f4e6a3e8..8d676eb5 100644 --- a/go/pkg/ble-driver/ConnectedPeer.h +++ b/go/pkg/ble-driver/ConnectedPeer.h @@ -7,10 +7,10 @@ #import -#import "BertyDevice_darwin.h" - NS_ASSUME_NONNULL_BEGIN +@class BertyDevice; + @interface ConnectedPeer : NSObject @property (nonatomic, assign, nullable) BertyDevice *client; diff --git a/go/pkg/ble-driver/Logger.h b/go/pkg/ble-driver/Logger.h new file mode 100644 index 00000000..5726afda --- /dev/null +++ b/go/pkg/ble-driver/Logger.h @@ -0,0 +1,42 @@ +// +// Logger.h +// BertyBridgeDemo +// +// Created by Rémi BARBERO on 08/12/2021. +// + +#import +#import + +NS_ASSUME_NONNULL_BEGIN + +#define SENSITIVE_MASK @"####" + +// Log levels +typedef NS_ENUM(uint8_t, level) { + Debug, + Info, + Warn, + Error, +}; + +@interface Logger : NSObject + +@property (nonatomic, strong, nonnull) os_log_t logger; +@property (readwrite) BOOL showSensitiveData; +@property (readwrite) BOOL useExternalLogger; + +- (instancetype __nonnull)initLocalLoggerWithSubSystem:(const char *)subSystem andCategorie:(const char*)categorie showSensitiveData:(BOOL)showSensitiveData; +- (instancetype __nonnull)initWithExternalLoggerAndShowSensitiveData:(BOOL)showSensitiveData; +- (void)log:(enum level)level withFormat:(NSString *__nonnull)format withArgs:(va_list)args; +- (void)d:(NSString *__nonnull)format, ...; +- (void)i:(NSString *__nonnull)format, ...; +- (void)e:(NSString *__nonnull)format, ...; +- (BOOL)showSensitiveData; +- (BOOL)useExternalLogger; +- (NSString *__nonnull)SensitiveNSObject:(id __nonnull)data; +- (NSString *__nonnull)SensitiveString:(const char *)data; + +@end + +NS_ASSUME_NONNULL_END diff --git a/go/pkg/ble-driver/Logger.m b/go/pkg/ble-driver/Logger.m new file mode 100644 index 00000000..9f0853c9 --- /dev/null +++ b/go/pkg/ble-driver/Logger.m @@ -0,0 +1,112 @@ +// +build darwin +// +// Logger.m +// BertyBridgeDemo +// +// Created by Rémi BARBERO on 08/12/2021. +// + +#import +#import "Logger.h" +#import "BleInterface_darwin.h" + +@implementation Logger + +- (instancetype __nonnull)initLocalLoggerWithSubSystem:(const char *)subSystem andCategorie:(const char*)categorie showSensitiveData:(BOOL)showSensitiveData { + self = [super init]; + + if (self) { + _logger = os_log_create(subSystem, categorie); + _useExternalLogger = FALSE; + _showSensitiveData = showSensitiveData; + } + + return self; +} + +- (instancetype __nonnull)initWithExternalLoggerAndShowSensitiveData:(BOOL)showSensitiveData { + self = [super init]; + + if (self) { + _logger = nil; + _useExternalLogger = TRUE; + _showSensitiveData = showSensitiveData; + } + + return self; +} + +- (void)log:(enum level)level withFormat:(NSString *__nonnull)format withArgs:(va_list)args { + NSString *message = [[NSString alloc] initWithFormat:format arguments:args]; + + if (self.useExternalLogger) { + BLEBridgeLog(level, message); + } else { + if (self.logger == nil) { + NSLog(@"log error: logger is not set"); + } else { + uint8_t osLevel; + switch (level) { + case Debug: + osLevel = OS_LOG_TYPE_DEBUG; + break ; + case Info: + osLevel = OS_LOG_TYPE_INFO; + break ; + case Error: + osLevel = OS_LOG_TYPE_ERROR; + break ; + default: + osLevel = OS_LOG_TYPE_DEFAULT; + break ; + } + + os_log_with_type(self.logger, osLevel, "%@", message); + } + } + + [message release]; +} + +- (void)d:(NSString *__nonnull)format, ... { + va_list args; + va_start(args, format); + [self log:Debug withFormat:format withArgs:args]; + va_end(args); +} + +- (void)i:(NSString *__nonnull)format, ... { + va_list args; + va_start(args, format); + [self log:Info withFormat:format withArgs:args]; + va_end(args); +} + +- (void)e:(NSString *__nonnull)format, ... { + va_list args; + va_start(args, format); + [self log:Error withFormat:format withArgs:args]; + va_end(args); +} + +- (NSString *__nonnull)SensitiveNSObject:(id __nonnull)data { + if (self.showSensitiveData) { + return [NSString stringWithFormat:@"%@", data]; + } else { + return SENSITIVE_MASK; + } +} + +- (NSString *__nonnull)SensitiveString:(const char *)data { + if (data == nil) { + return @""; + } + + if (self.showSensitiveData) { + return [NSString stringWithFormat:@"%s", data]; + } else { + return SENSITIVE_MASK; + } +} + +@end diff --git a/go/pkg/ble-driver/PeerManager.h b/go/pkg/ble-driver/PeerManager.h index e15835ca..7c6c3683 100644 --- a/go/pkg/ble-driver/PeerManager.h +++ b/go/pkg/ble-driver/PeerManager.h @@ -6,18 +6,25 @@ // #import + +#import "Logger.h" #import "ConnectedPeer.h" NS_ASSUME_NONNULL_BEGIN +@class BertyDevice; + @interface PeerManager : NSObject -+ (NSMutableDictionary *__nonnull)connectedPeers; -+ (ConnectedPeer *__nonnull)getPeer:(NSString *__nonnull) peerID; -+ (ConnectedPeer *__nullable)registerDevice:(BertyDevice *__nonnull)device withPeerID:(NSString *__nonnull)peerID isClient:(BOOL)isClient; -+ (void)unregisterDevice:(BertyDevice *)device; -+ (void)removePeer:(NSString *__nonnull) peerID; -+ (void)removeAllPeers; +@property (nonatomic, strong, nonnull) NSMutableDictionary *connectedPeers; +@property (nonatomic, strong, nonnull) Logger *logger; + +- (instancetype __nonnull)initWithLogger:(Logger *__nonnull)logger; +- (ConnectedPeer *__nonnull)getPeer:(NSString *__nonnull) peerID; +- (ConnectedPeer *__nullable)registerDevice:(BertyDevice *__nonnull)device withPeerID:(NSString *__nonnull)peerID isClient:(BOOL)isClient; +- (void)unregisterDevice:(BertyDevice *)device; +- (void)removePeer:(NSString *__nonnull) peerID; +- (void)removeAllPeers; @end diff --git a/go/pkg/ble-driver/PeerManager.m b/go/pkg/ble-driver/PeerManager.m index 192e671d..22742f50 100644 --- a/go/pkg/ble-driver/PeerManager.m +++ b/go/pkg/ble-driver/PeerManager.m @@ -7,53 +7,53 @@ // #import "PeerManager.h" +#import "BleInterface_darwin.h" @implementation PeerManager -static NSMutableDictionary *connectedPeers = nil; - -- (void)dealloc { - [connectedPeers release]; - connectedPeers = nil; +- (instancetype __nonnull)initWithLogger:(Logger *__nonnull)logger { + self = [super init]; - [super dealloc]; + if (self) { + _logger = logger; + _connectedPeers = [[NSMutableDictionary alloc] init]; + } + + return self; } -+ (NSMutableDictionary *__nonnull)connectedPeers { +- (void)dealloc { + [_connectedPeers release]; + [_logger release]; - @synchronized (connectedPeers) { - if (connectedPeers == nil) { - connectedPeers = [[NSMutableDictionary alloc] init]; - } - return connectedPeers; - } + [super dealloc]; } -+ (ConnectedPeer *__nonnull)getPeer:(NSString *__nonnull) peerID { - os_log_debug(OS_LOG_BLE, "getPeer called: peerID=%{public}@", peerID); +- (ConnectedPeer *__nonnull)getPeer:(NSString *__nonnull) peerID { + [self.logger d:@"getPeer called: peerID=%@", [self.logger SensitiveNSObject:peerID]]; ConnectedPeer *peer; - @synchronized (connectedPeers) { - if ((peer = [[PeerManager connectedPeers] objectForKey:peerID]) != nil) { - os_log_debug(OS_LOG_BLE, "getPeer: peerID=%{public}@ already created", peerID); + @synchronized (_connectedPeers) { + if ((peer = [self.connectedPeers objectForKey:peerID]) != nil) { + [self.logger d:@"getPeer: peerID=%@ alread created", [self.logger SensitiveNSObject:peerID]]; return peer; } - os_log_debug(OS_LOG_BLE, "getPeer: peerID=%{public}@ created", peerID); + [self.logger d:@"getPeer: peerID=%@ created", [self.logger SensitiveNSObject:peerID]]; peer = [[ConnectedPeer alloc] init]; - [[PeerManager connectedPeers] setObject:peer forKey:peerID]; + [self.connectedPeers setObject:peer forKey:peerID]; [peer release]; return peer; } } -+ (ConnectedPeer *__nullable)registerDevice:(BertyDevice *__nonnull)device withPeerID:(NSString *__nonnull)peerID isClient:(BOOL)isClient { - os_log_debug(OS_LOG_BLE, "registerDevice called: identifier=%{public}@ peer=%{public}@ isClient=%d", [device getIdentifier], peerID, isClient); +- (ConnectedPeer *__nullable)registerDevice:(BertyDevice *__nonnull)device withPeerID:(NSString *__nonnull)peerID isClient:(BOOL)isClient { + [self.logger d:@"registerDevice called: identifier=%@ peer=%@ isClient=%d", [self.logger SensitiveNSObject:[device getIdentifier]], [self.logger SensitiveNSObject:peerID], isClient]; ConnectedPeer *peer; - @synchronized (connectedPeers) { + @synchronized (_connectedPeers) { peer = [self getPeer:peerID]; if (isClient) { peer.client = device; @@ -66,7 +66,7 @@ + (ConnectedPeer *__nullable)registerDevice:(BertyDevice *__nonnull)device withP peer.connected = TRUE; if (!BLEBridgeHandleFoundPeer(peerID)) { - os_log_error(OS_LOG_BLE, "registerDevice failed: identifier=%{public}@ HandleFoundPeer failed: peer=%{public}@", [device getIdentifier], peerID); + [self.logger e:@"registerDevice error: device=%@ peer=%@: HandleFoundPeer failed", [self.logger SensitiveNSObject:[device getIdentifier]], [self.logger SensitiveNSObject:peerID]]; return NULL; } @@ -76,40 +76,40 @@ + (ConnectedPeer *__nullable)registerDevice:(BertyDevice *__nonnull)device withP return peer; } -+ (void)unregisterDevice:(BertyDevice *)device { - os_log_debug(OS_LOG_BLE, "unregisterDevice called: identifier=%{public}@ peerID=%{public}@", [device getIdentifier], device.remotePeerID); +- (void)unregisterDevice:(BertyDevice *)device { + [self.logger d:@"unregisterDevice called: device=%@ peerID=%@", [self.logger SensitiveNSObject:[device getIdentifier]], [self.logger SensitiveNSObject:device.remotePeerID]]; ConnectedPeer *peer; - @synchronized (connectedPeers) { - if ((peer = [[PeerManager connectedPeers] objectForKey:device.remotePeerID]) == nil) { - os_log_error(OS_LOG_BLE, "unregisterDevice failed: peerID=%{public}@ not found", device.remotePeerID); + @synchronized (_connectedPeers) { + if ((peer = [self.connectedPeers objectForKey:device.remotePeerID]) == nil) { + [self.logger e:@"unregisterDevice called: device=%@ peerID=%@: peerID not found", [self.logger SensitiveNSObject:[device getIdentifier]], [self.logger SensitiveNSObject:device.remotePeerID]]; return ; } if ([peer isConnected]) { - os_log_debug(OS_LOG_BLE, "unregisterDevice: peerID=%{public}@: calling HandleLostPeer", device.remotePeerID); + [self.logger d:@"unregisterDevice called: device=%{public}@ peerID=%{public}@: calling HandleLostPeer", [self.logger SensitiveNSObject:[device getIdentifier]], [self.logger SensitiveNSObject:device.remotePeerID]]; BLEBridgeHandleLostPeer(device.remotePeerID); peer.connected = FALSE; } - [PeerManager removePeer:device.remotePeerID]; + [self removePeer:device.remotePeerID]; } } -+ (void)removePeer:(NSString *__nonnull) peerID { - os_log_debug(OS_LOG_BLE, "removePeer called: peerID=%{public}@", peerID); +- (void)removePeer:(NSString *__nonnull) peerID { + [self.logger d:@"removePeer called: peerID=%{public}@", [self.logger SensitiveNSObject:peerID]]; - @synchronized (connectedPeers) { - [[PeerManager connectedPeers] removeObjectForKey:peerID]; + @synchronized (_connectedPeers) { + [self.connectedPeers removeObjectForKey:peerID]; } } -+ (void)removeAllPeers { - os_log_debug(OS_LOG_BLE, "removeAllPeers called"); +- (void)removeAllPeers { + [self.logger d:@"removeAllPeers called"]; - @synchronized (connectedPeers) { - [[PeerManager connectedPeers] removeAllObjects]; + @synchronized (_connectedPeers) { + [self.connectedPeers removeAllObjects]; } } diff --git a/go/pkg/ble-driver/bridge_darwin.go b/go/pkg/ble-driver/bridge_darwin.go index c7620543..d77abdca 100644 --- a/go/pkg/ble-driver/bridge_darwin.go +++ b/go/pkg/ble-driver/bridge_darwin.go @@ -8,10 +8,12 @@ package ble #cgo darwin LDFLAGS: -framework Foundation -framework CoreBluetooth #include #import "BleInterface_darwin.h" +#import "Logger.h" */ import "C" import ( + "fmt" "unsafe" "go.uber.org/zap" @@ -21,6 +23,8 @@ import ( const Supported = true +var gLogger *zap.Logger + type Driver struct { protocolCode int protocolName string @@ -33,9 +37,12 @@ var _ proximity.ProximityDriver = (*Driver)(nil) func NewDriver(logger *zap.Logger) proximity.ProximityDriver { if logger == nil { logger = zap.NewNop() + } else { + logger = logger.Named("BLE") + logger.Debug("NewDriver()") + C.BLEUseExternalLogger() } - logger = logger.Named("BLE") - logger.Debug("NewDriver()") + gLogger = logger return &Driver{ protocolCode: ProtocolCode, @@ -81,6 +88,26 @@ func BLEReceiveFromPeer(remotePID *C.char, payload unsafe.Pointer, length C.int) t.(proximity.ProximityTransport).ReceiveFromPeer(goPID, goPayload) } +//export BLELog +func BLELog(level C.enum_level, message *C.char) { //nolint:golint + if gLogger == nil { + fmt.Println("logger not found") + return + } + + goMessage := C.GoString(message) + switch level { + case C.Debug: + gLogger.Debug(goMessage) + case C.Info: + gLogger.Info(goMessage) + case C.Warn: + gLogger.Warn(goMessage) + case C.Error: + gLogger.Error(goMessage) + } +} + func (d *Driver) Start(localPID string) { cPID := C.CString(localPID) defer C.free(unsafe.Pointer(cPID))