diff --git a/README.md b/README.md index a522b92..02b4f8d 100644 --- a/README.md +++ b/README.md @@ -96,6 +96,7 @@ If you are curious you can enable tracing to see what flows in and out of device ``` >>> tls.trace_enabled=True >>> usb.trace_enabled=True +>>> logging.basicConfig(level=logging.DEBUG) >>> db.dump_all() >tls> 17: 4b00000b0053746757696e64736f7200 >cmd> 1703030050c00a7ff1cf76e90f168141b4bc519ca9598eacb575ff01b7552a3707be8506b246d5272cb119e7b8b3eccd991cb7d8387245953ff1da62cebfb07fae7e47b9b536fb1a82185cc9399d30625ee3c1451f diff --git a/dbus_service/dbus-service b/dbus_service/dbus-service index 12f3ce4..ff84755 100755 --- a/dbus_service/dbus-service +++ b/dbus_service/dbus-service @@ -1,5 +1,6 @@ #!/usr/bin/env python3 +import signal import argparse import re import os @@ -10,8 +11,9 @@ import dbus.mainloop.glib import dbus.service from binascii import hexlify, unhexlify dbus.mainloop.glib.DBusGMainLoop(set_as_default=True) -from gi.repository import GObject, GLib +from gi.repository import GLib import logging +import logging.handlers from validitysensor import init from validitysensor.tls import tls @@ -25,7 +27,7 @@ GLib.threads_init() INTERFACE_NAME='io.github.uunicorn.Fprint.Device' -loop = GObject.MainLoop() +loop = GLib.MainLoop() usb.quit = lambda e: loop.quit() @@ -53,7 +55,7 @@ class Device(dbus.service.Object): return [] rc = [subtype_to_string(f['subtype']) for f in usr.fingers] - print(repr(rc)) + logging.debug(repr(rc)) return rc except Exception as e: raise e @@ -115,7 +117,7 @@ class Device(dbus.service.Object): try: # TODO hardcode the username and finger for now z=enroll(uid2identity(uid), 0xf5) - print('Enroll was successfull') + logging.debug('Enroll was successfull') self.EnrollStatus('enroll-completed', True) except Exception as e: self.EnrollStatus('enroll-failed', True) @@ -187,9 +189,14 @@ if __name__ == '__main__': args = parser.parse_args() if args.debug: - logging.basicConfig(level=logging.DEBUG) + level = logging.DEBUG usb.trace_enabled = True tls.trace_enabled = True + else: + level = logging.INFO + + handler = logging.handlers.SysLogHandler(address = '/dev/log') + logging.basicConfig(level=level, handlers=[handler]) backoff() @@ -203,7 +210,7 @@ if __name__ == '__main__': init.open_devpath(*map(int, z.groups())) except RebootException: - print('Initialization ended up in rebooting the sensor. Normal exit.') + logging.debug('Initialization ended up in rebooting the sensor. Normal exit.') sys.exit(0) bus = dbus.SystemBus() @@ -224,5 +231,15 @@ if __name__ == '__main__': # Kick off the open-fprintd if it was not started yet bus.get_object('net.reactivated.Fprint', '/net/reactivated/Fprint/Manager') - loop.run() + def die(x): + logging.info('Cought signal %d. Stopping...' % x) + loop.quit() + + GLib.unix_signal_add(GLib.PRIORITY_DEFAULT, signal.SIGINT, die, signal.SIGINT) + GLib.unix_signal_add(GLib.PRIORITY_DEFAULT, signal.SIGTERM, die, signal.SIGINT) + try: + loop.run() + except Exception as e: + logging.exception('Oops', e) + raise e diff --git a/debian/python3-validity.prerm b/debian/python3-validity.prerm index 3f77718..13f6a56 100644 --- a/debian/python3-validity.prerm +++ b/debian/python3-validity.prerm @@ -2,9 +2,8 @@ set -e -# Stop the socket on remove so syslog-ng is not restarted via socket activation if [ -x "/usr/bin/deb-systemd-invoke" ] && [ "$1" = remove ]; then - deb-systemd-invoke stop 'python3-validity@*' || true + deb-systemd-invoke stop 'python3-validity.service' || true fi #DEBHELPER# diff --git a/debian/python3-validity.service b/debian/python3-validity.service new file mode 100644 index 0000000..299c599 --- /dev/null +++ b/debian/python3-validity.service @@ -0,0 +1,8 @@ +[Unit] +Description=python-validity driver dbus service + +[Service] +Type=simple +ExecStart=/usr/lib/python-validity/dbus-service --debug +Restart=no + diff --git a/debian/python3-validity.udev b/debian/python3-validity.udev index 776cf26..d9ca628 100644 --- a/debian/python3-validity.udev +++ b/debian/python3-validity.udev @@ -11,8 +11,11 @@ LABEL="python_validity_match" #TAG+="validity" -ACTION=="add|change", RUN+="/bin/systemctl --no-block start python3-validity@usb-$env{BUSNUM}-$env{DEVNUM}.service" -ACTION=="remove", RUN+="/bin/systemctl --no-block stop python3-validity@usb-$env{BUSNUM}-$env{DEVNUM}.service" +ACTION=="add|change", ATTR{power/control}="auto", RUN+="/bin/systemctl --no-block start python3-validity.service" +ACTION=="remove", RUN+="/bin/systemctl --no-block stop python3-validity.service" + +#ACTION=="add|change", RUN+="/bin/systemctl --no-block start python3-validity@usb-$env{BUSNUM}-$env{DEVNUM}.service" +#ACTION=="remove", RUN+="/bin/systemctl --no-block stop python3-validity@usb-$env{BUSNUM}-$env{DEVNUM}.service" # TODO: Figure out why the following is not working properly instead: #TAG+="systemd", ENV{SYSTEMD_WANTS}+="python3-validity@usb-$env{BUSNUM}-$env{DEVNUM}.service" diff --git a/debian/python3-validity@.service b/debian/python3-validity@.service deleted file mode 100644 index d69c127..0000000 --- a/debian/python3-validity@.service +++ /dev/null @@ -1,10 +0,0 @@ -[Unit] -Description=python-validity driver dbus service for %I -#StopWhenUnneeded=true - -[Service] -Type=simple -ExecStart=/usr/lib/python-validity/dbus-service --devpath %i -StandardOutput=syslog -Restart=no - diff --git a/scripts/prototype.py b/scripts/prototype.py index b83782b..2d648f8 100644 --- a/scripts/prototype.py +++ b/scripts/prototype.py @@ -7,6 +7,7 @@ from validitysensor.sid import * from validitysensor.init import open as open9x from threading import Condition from time import sleep +import logging import code #usb.trace_enabled = True diff --git a/validitysensor/db.py b/validitysensor/db.py index 8446db4..486b6d7 100644 --- a/validitysensor/db.py +++ b/validitysensor/db.py @@ -1,4 +1,5 @@ +import logging from .util import unhex from .tls import tls from .util import assert_status diff --git a/validitysensor/init.py b/validitysensor/init.py index 29508a4..738e357 100644 --- a/validitysensor/init.py +++ b/validitysensor/init.py @@ -1,5 +1,7 @@ import atexit +import signal +import logging from validitysensor.usb import usb from validitysensor.tls import tls @@ -10,11 +12,13 @@ from validitysensor.upload_fwext import upload_fwext from validitysensor.init_db import init_db def close(): + logging.debug('In atexit handler') if usb.dev is not None: # Send the reboot command before closing the device. # Without it the sensor seems to keep creating new TLS sessions and eventually runs out of memory. # The reboot command may fail if we're shutting down because the device is already gone. try: + logging.debug('atexit: forcing reboot') reboot() except RebootException: pass @@ -36,6 +40,7 @@ def open_common(): # Don't attempt to autoreboot unless we finished initializing the sensor successfully. # Otherwise if there is a bug in initialization, we may end up in a loop constantly rebooting the device. atexit.register(close) + logging.debug('atexit registered') def open(): usb.open() diff --git a/validitysensor/init_db.py b/validitysensor/init_db.py index aebb49a..ef95c49 100644 --- a/validitysensor/init_db.py +++ b/validitysensor/init_db.py @@ -1,5 +1,6 @@ from struct import pack, unpack +import logging from .db import db from .usb import usb @@ -15,13 +16,13 @@ def machine_id_rec_value(b): def init_db(machine_guid='e7260876-58db-4d27-8c40-8d13110d6a71'): stg = db.get_user_storage(name='StgWindsor') if stg == None: - print('Creating a new user storage object') + logging.info('Creating a new user storage object') db.new_user_storate() rc = db.get_storage_data() if rc == []: - print('Creating a host machine GUID record') + logging.info('Creating a host machine GUID record') stg = db.get_user_storage(name='StgWindsor') db.new_record(stg.dbid, 0x8, stg.dbid, machine_id_rec_value(machine_guid)) rc = db.get_storage_data() diff --git a/validitysensor/init_flash.py b/validitysensor/init_flash.py index 7744dca..a83f213 100644 --- a/validitysensor/init_flash.py +++ b/validitysensor/init_flash.py @@ -2,6 +2,7 @@ import os from struct import pack, unpack from binascii import hexlify, unhexlify +import logging from hashlib import sha256 import hmac @@ -86,7 +87,7 @@ def serialize_partition(p): return b def partition_flash(info, layout, client_public): - print('Detected Flash IC: %s, %d bytes' % (info.ic.name, info.ic.size)) + logging.info('Detected Flash IC: %s, %d bytes' % (info.ic.name, info.ic.size)) cmd = unhex('4f 0000 0000') cmd += with_hdr(0, serialize_flash_params(info.ic)) @@ -106,10 +107,10 @@ def init_flash(): info = get_flash_info() if len(info.partitions) > 0: - print('Flash has %d partitions.' % len(info.partitions)) + logging.info('Flash has %d partitions.' % len(info.partitions)) return else: - print('Flash was not initialized yet. Formatting...') + logging.info('Flash was not initialized yet. Formatting...') assert_status(usb.cmd(reset_blob)) diff --git a/validitysensor/sensor.py b/validitysensor/sensor.py index fa5a4e7..20f1112 100644 --- a/validitysensor/sensor.py +++ b/validitysensor/sensor.py @@ -2,6 +2,7 @@ from enum import Enum from hashlib import sha256 import os.path +import logging from .tls import tls from .usb import usb from .db import db, subtype_to_string @@ -199,7 +200,7 @@ class Sensor(): self.interrupt_cb = None self.device_info = identify_sensor() - print('Opening sensor: %s' % self.device_info.name) + logging.info('Opening sensor: %s' % self.device_info.name) self.type_info = SensorTypeInfo.get_by_type(self.device_info.type) if self.device_info.type == 0x199: @@ -558,10 +559,10 @@ class Sensor(): if start != b'\xff' * 0x44: if clean_slate[:0x44] == start: - print('Calibration data already matches the data on the flash.') + logging.info('Calibration data already matches the data on the flash.') return else: - print('Calibration flash already written. Erasing.') + logging.info('Calibration flash already written. Erasing.') erase_flash(6) write_flash_all(6, 0, clean_slate) @@ -577,13 +578,12 @@ class Sensor(): hs, zeroes = start[0:0x20], start[0x20:0x40] if zeroes != b'\0'*0x20: - print('Unexpected contents in calibration flash partition') + logging.warning('Unexpected contents in calibration flash partition') return False img = read_flash_all(6, 0x44, l) if hs != sha256(img).digest(): - print('Calibration flash hash mismatch') - print(hexlify(hs), hexlify(img)) + logging.warning('Calibration flash hash mismatch') return False return True @@ -593,23 +593,23 @@ class Sensor(): if os.path.isfile(calib_data_path): with open(calib_data_path, 'rb') as f: self.calib_data = f.read() - print('Calibration data loaded from a file.') + logging.info('Calibration data loaded from a file.') if self.check_clean_slate(): return else: - print('No calibration data on the flash. Calibrating...') + logging.info('No calibration data on the flash. Calibrating...') else: self.calib_data = b'' - print('No calibration data was loaded. Calibrating...') + logging.info('No calibration data was loaded. Calibrating...') for i in range(0, self.calibration_iterations): - print('Calibration iteration %d...' % i) + logging.debug('Calibration iteration %d...' % i) rsp = tls.cmd(self.build_cmd_02(CaptureMode.CALIBRATE)) assert_status(rsp) self.process_calibration_results(self.average(usb.read_82())) - print('Requesting a blank image...') + logging.debug('Requesting a blank image...') # Get the "clean slate" image to store on the flash for fine-grained after-capture adjustments rsp = tls.cmd(self.build_cmd_02(CaptureMode.CALIBRATE)) @@ -753,7 +753,7 @@ class Sensor(): elif tag == 3: tid = res[magic_len:magic_len+l] else: - print('Ignoring unknown tag %x' % tag) + logging.warning('Ignoring unknown tag %x' % tag) res=res[magic_len+l:] diff --git a/validitysensor/tls.py b/validitysensor/tls.py index 7379e0a..d61b161 100644 --- a/validitysensor/tls.py +++ b/validitysensor/tls.py @@ -3,6 +3,7 @@ import hmac import sys import os import pickle +import logging from struct import pack, unpack from binascii import * @@ -143,7 +144,7 @@ class Tls(): def trace(self, s): if self.trace_enabled: - print(s) + logging.debug(s) def app(self, b): b = b() if callable(b) else b diff --git a/validitysensor/upload_fwext.py b/validitysensor/upload_fwext.py index be5c073..24d1b28 100644 --- a/validitysensor/upload_fwext.py +++ b/validitysensor/upload_fwext.py @@ -1,6 +1,7 @@ from binascii import hexlify, unhexlify from time import ctime +import logging from os.path import basename from .tls import tls @@ -25,10 +26,10 @@ def default_fwext_name(): def upload_fwext(fw_path=None): fwi=get_fw_info(2) if fwi != None: - print('Detected firmware version %d.%d (%s))' % (fwi.major, fwi.minor, ctime(fwi.buildtime))) + logging.info('Detected firmware version %d.%d (%s))' % (fwi.major, fwi.minor, ctime(fwi.buildtime))) return else: - print('No firmware detected. Uploading...') + logging.info('No firmware detected. Uploading...') # no idea what this is: write_hw_reg32(0x8000205c, 7) @@ -36,7 +37,7 @@ def upload_fwext(fw_path=None): raise Exception('Unexpected register value') dev=identify_sensor() - print('Sensor: %s' % dev.name) + logging.debug('Sensor: %s' % dev.name) # ^ TODO -- what is the real reason to detect HW at this stage? # just a guess: perhaps it is used to construct fwext filename @@ -45,7 +46,7 @@ def upload_fwext(fw_path=None): if not fw_path: fw_path = default_name elif basename(fw_path) != default_name: - print('WARNING: Your device fw is supposed to be called {}'.format( + logging.warning('WARNING: Your device fw is supposed to be called {}'.format( default_name)) with open(fw_path, 'rb') as f: @@ -62,7 +63,7 @@ def upload_fwext(fw_path=None): if fwi == None: raise Exception('No firmware detected') - print('Loaded FWExt version %d.%d (%s), %d modules' % (fwi.major, fwi.minor, ctime(fwi.buildtime), len(fwi.modules))) + logging.info('Loaded FWExt version %d.%d (%s), %d modules' % (fwi.major, fwi.minor, ctime(fwi.buildtime), len(fwi.modules))) # Reboot reboot() diff --git a/validitysensor/usb.py b/validitysensor/usb.py index db80f5d..8671e02 100644 --- a/validitysensor/usb.py +++ b/validitysensor/usb.py @@ -1,4 +1,5 @@ +import logging import usb.core as ucore from binascii import * from .util import assert_status, unhex @@ -80,7 +81,7 @@ class Usb(): (err,), rsp = unpack('