Commit 0aae1602 authored by thaag's avatar thaag
Browse files

bugfix: updated loggers to current concept

parent c2785c58
......@@ -14,10 +14,13 @@ import logging
import dug_seis.acquisition.card_manager as card_manager
import os.path
logger = logging.getLogger('dug-seis')
def acquisition_(param):
logging.info('Acquisition script started')
logging.info('==========================')
logger.info('Acquisition script started')
logger.info('==========================')
# print("logger name: " + logger.name);
# print("logger level: " + logging.getLevelName(logger.level));
param['Acquisition']['simulation_mode'] = False # should be False, or no real data is recorded when True!
# 32 * 1024 * 1024 # in bytes (amount of data processed per python call)
......@@ -40,21 +43,21 @@ def acquisition_(param):
def _check_if_hardware_needs_to_be_simulated(param):
if param['Acquisition']['simulation_mode']:
logging.warning('param["Acquisition"]["simulation_mode"] = True, this is for testing purposes only.'
logger.warning('param["Acquisition"]["simulation_mode"] = True, this is for testing purposes only.'
' This setting should never be pushed to Git, the real system does only record simulated'
' data this way. A computer without the acquisition hardware will detect the missing hardware'
' and ask to change to the simulation mode automatically.')
input('...')
else:
if _check_if_hardware_driver_can_be_loaded():
logging.info('Hardware driver found, running on real hardware')
logger.info('Hardware driver found, running on real hardware')
else:
user_input = input("\nCould not load hardware driver, to simulate hardware press: enter or (y)es?")
if user_input == 'y' or user_input == 'Y' or user_input == 'yes' or user_input == '':
param['Acquisition']['simulation_mode'] = True
logging.info('Could not load hardware driver, user requested simulation of hardware.')
logger.info('Could not load hardware driver, user requested simulation of hardware.')
else:
logging.info('Could not load hardware driver, user abort.')
logger.info('Could not load hardware driver, user abort.')
return
......@@ -74,4 +77,4 @@ def _write_used_param_to_log_recursive(param_dict, sub_group):
_write_used_param_to_log_recursive(value, '')
else:
# print('{}: {}'.format(key, value))
logging.info('{}: {}'.format(key, value))
logger.info('{}: {}'.format(key, value))
......@@ -13,6 +13,7 @@ from dug_seis.acquisition.data_to_asdf import DataToASDF
from dug_seis.acquisition.hardware_mockup import SimulatedHardware
logger = logging.getLogger('dug-seis')
def run(param):
bytes_per_transfer = param['Acquisition']['bytes_per_transfer']
......@@ -68,7 +69,7 @@ def run(param):
data_to_asdf.data_to_asdf([card1.read_data(), card2.read_data()])
card1.data_has_been_read()
card2.data_has_been_read()
logging.debug("loop took: {:.2f} sec, processing for: {:.2f} -> {}%"
logger.debug("loop took: {:.2f} sec, processing for: {:.2f} -> {}%"
.format(time.time()-time_stamp_this_loop, time.time()-timestamp_before_eval,
int((time.time() - timestamp_before_eval)/(time.time() - time_stamp_this_loop)*100.0)))
time_stamp_this_loop = time.time()
......
......@@ -16,6 +16,7 @@ import pyasdf
from dug_seis.acquisition.flat_response_stationxml import get_flat_response_inventory
logger = logging.getLogger('dug-seis')
class DataToASDF:
......@@ -54,11 +55,11 @@ class DataToASDF:
def _check_if_folders_exist_create_if_needed(self):
if not os.path.isdir(self.folder):
os.makedirs(self.folder)
logging.info("creating folder: {}".format(self.folder))
logger.info("creating folder: {}".format(self.folder))
if not os.path.isdir(self.folder_tmp):
os.makedirs(self.folder_tmp)
logging.info("creating folder_tmp: {}".format(self.folder_tmp))
logger.info("creating folder_tmp: {}".format(self.folder_tmp))
def _create_new_file(self):
"""Creates a new file.
......@@ -68,12 +69,12 @@ class DataToASDF:
file_name = file_name.replace(":", "_")
folder_file_name = "{0}{1}".format(self.folder_tmp, file_name)
# print("_create_new_file with folder_file_name = {0}".format(folder_file_name))
logging.info("_create_new_file with folder_file_name = {0}".format(folder_file_name))
logger.info("_create_new_file with folder_file_name = {0}".format(folder_file_name))
self._time_age_of_file = time.time()
# logging.info("self.compression = {}, type = {}".format(self.compression, type(self.compression)))
# logger.info("self.compression = {}, type = {}".format(self.compression, type(self.compression)))
if self.compression == 'None':
# logging.info("if self.compression = None: -> true")
# logger.info("if self.compression = None: -> true")
self._file_handle = pyasdf.ASDFDataSet(folder_file_name, compression=None)
else:
self._file_handle = pyasdf.ASDFDataSet(folder_file_name, compression=self.compression)
......@@ -87,13 +88,13 @@ class DataToASDF:
def _create_new_file_if_needed(self):
# check if file_handle exists
if self._file_handle is None:
# logging.info("no file found creating new file.\n")
# logger.info("no file found creating new file.\n")
self._check_if_folders_exist_create_if_needed()
self._create_new_file()
# check if file is too old
if self._time_age_of_file + self.file_length_sec < time.time():
# logging.info("file too old, creating new file.\n")
# logger.info("file too old, creating new file.\n")
self._create_new_file()
def _add_all_station_xml_s(self, ds):
......@@ -143,30 +144,30 @@ class DataToASDF:
for i in range(16):
self.stats['station'] = self._get_station_name(i + 16 * card_nr)
stream += Trace(np_data[i], header=self.stats) # without transpose np_data[:, i]
# logging.info("{}, {}\n".format(self.stats['station'], self.stats['starttime']))
# logger.info("{}, {}\n".format(self.stats['station'], self.stats['starttime']))
del np_data
if self._really_verbose_timing_output:
logging.debug("stream += Trace: {0:.3f} sec, ".format(time.time() - time_tmp))
logger.debug("stream += Trace: {0:.3f} sec, ".format(time.time() - time_tmp))
card_nr += 1
time_tmp = time.time()
self._create_new_file_if_needed()
if self._really_verbose_timing_output:
logging.debug("_create_new_file_if_needed(): {0:.3f} sec, ".format(time.time() - time_tmp))
logger.debug("_create_new_file_if_needed(): {0:.3f} sec, ".format(time.time() - time_tmp))
time_tmp = time.time()
self._file_handle.append_waveforms(stream, tag="raw_recording")
if self._really_verbose_timing_output:
logging.debug("append_waveforms: {0:.3f} sec".format(time.time() - time_tmp))
logger.debug("append_waveforms: {0:.3f} sec".format(time.time() - time_tmp))
# starttime for next segment
self.stats['starttime'] = UTCDateTime(self.stats['starttime']) +\
self._nr_of_datapoints / self._sampling_rate
# logging.info("self.stats[ starttime ] = {}".format(self.stats['starttime']))
# logger.info("self.stats[ starttime ] = {}".format(self.stats['starttime']))
del stream
if self._really_verbose_timing_output:
logging.debug("end of data_to_asdf.py cycle used time: {0:.3f} sec"
logger.debug("end of data_to_asdf.py cycle used time: {0:.3f} sec"
.format(time.time() - time_start_buffer_data_available))
......@@ -5,6 +5,7 @@ import logging
from math import sin
from ctypes import create_string_buffer
logger = logging.getLogger('dug-seis')
def generate_data_for_pv_buffer(size, amount):
# amount can be 0...4
......@@ -13,18 +14,18 @@ def generate_data_for_pv_buffer(size, amount):
ts = time.time()
if amount == 0:
logging.info("pv_buffer with no data, all zero, will lead to high compression rate -> small files, low load")
logger.info("pv_buffer with no data, all zero, will lead to high compression rate -> small files, low load")
if amount > 2:
logging.info("generating random data for all channels storing in RAM ringbuffer: pv_buffer")
logger.info("generating random data for all channels storing in RAM ringbuffer: pv_buffer")
if amount > 3:
fill_percent = 100
logging.info("only filling up {}% of buffer, to speed things up".format(fill_percent))
logging.info("the part which is not filled is 0 and leads to a high compression rate -> small files, low load")
logger.info("only filling up {}% of buffer, to speed things up".format(fill_percent))
logger.info("the part which is not filled is 0 and leads to a high compression rate -> small files, low load")
for i in range(int(len(pv_buffer) * fill_percent / 100)):
pv_buffer[i] = random.randrange(0, 255)
if time.time() > ts:
logging.info("all channels random. i: {}, {}%".format(i, int(i / size * 100)))
logger.info("all channels random. i: {}, {}%".format(i, int(i / size * 100)))
ts = time.time() + 2
# return pv_buffer
fill_percent = 100 # 100 fills up all buffer
......@@ -38,7 +39,7 @@ def generate_data_for_pv_buffer(size, amount):
pv_buffer[i] = value & 0xff
pv_buffer[i + 1] = (value >> 8) & 0xff
if time.time() > ts:
logging.info("channel 0 and 16 sine wave 20000 amplitude. i: {}, {}%".format(i, int(i / size * 100)))
logger.info("channel 0 and 16 sine wave 20000 amplitude. i: {}, {}%".format(i, int(i / size * 100)))
ts = time.time() + 2
if amount > 1:
......@@ -49,7 +50,7 @@ def generate_data_for_pv_buffer(size, amount):
pv_buffer[i + 1] = (value >> 8) & 0xff
value += 1
if time.time() > ts:
logging.info("channel 1 and 18 ramp upwards, +1 per time step.i:{}, {}%".format(i, int(i / size * 100)))
logger.info("channel 1 and 18 ramp upwards, +1 per time step.i:{}, {}%".format(i, int(i / size * 100)))
ts = time.time() + 2
if amount > 1:
......@@ -59,8 +60,8 @@ def generate_data_for_pv_buffer(size, amount):
pv_buffer[i] = value & 0xff
pv_buffer[i + 1] = (value >> 8) & 0xff
if time.time() > ts:
logging.info("channel 4 and 20 sine wave 32768 amplitude. i: {}, {}%".format(i, int(i / size * 100)))
logger.info("channel 4 and 20 sine wave 32768 amplitude. i: {}, {}%".format(i, int(i / size * 100)))
ts = time.time() + 2
logging.info("generation for this card finished")
logger.info("generation for this card finished")
return pv_buffer
......@@ -6,6 +6,7 @@ from math import floor
from dug_seis.acquisition.generate_simulated_data import generate_data_for_pv_buffer
logger = logging.getLogger('dug-seis')
class SimulatedHardware:
def __init__(self, param):
......@@ -42,7 +43,7 @@ class SimulatedHardware:
if self._l_pc_pos == self._ram_buffer_size:
self._l_pc_pos = 0
if self._l_pc_pos > self._ram_buffer_size:
logging.error("Something is wrong, ram_buffer_size should be dividable by bytes_per_transfer")
logger.error("Something is wrong, ram_buffer_size should be dividable by bytes_per_transfer")
def _simulated_init_card(self, param):
self._timestamp_last_call = time.time()
......
......@@ -20,8 +20,9 @@ if os.path.isfile("c:\\windows\\system32\\spcm_win64.dll") or os.path.isfile("c:
else:
pass
# logging at import messes with the later logging settings, no logging needed here
# logging.warning('one_card.py: problems loading the hardware driver. simulation still available.')
# logger.warning('one_card.py: problems loading the hardware driver. simulation still available.')
logger = logging.getLogger('dug-seis')
class Card:
......@@ -45,20 +46,20 @@ class Card:
self.scaling_this_card = [i * 2 / 65536 for i in gain_selection[0:16]] # e.g. 16 bit to +- 10'000 mV
else:
self.scaling_this_card = [i * 2 / 65536 for i in gain_selection[16:32]]
# logging.info("scaling_this_card: {}".format(', '.join(str(e) for e in self.scaling_this_card)))
# logger.info("scaling_this_card: {}".format(', '.join(str(e) for e in self.scaling_this_card)))
def init_card(self, param):
"""Initialise card. Setup card parameters. Reserve buffers for DMA data transfer."""
logging.info("init card: {}".format(self.card_nr))
logger.info("init card: {}".format(self.card_nr))
if self.card_nr == 0 or self.card_nr == 1:
self.h_card, self._pv_buffer = sdt_init_card(param, self.card_nr)
else:
logging.error("card_nr needs to be 0 or 1, received:{}".format(self.card_nr))
logger.error("card_nr needs to be 0 or 1, received:{}".format(self.card_nr))
def print_settings(self):
selected_range = c_int32(0)
spcm_dwGetParam_i32(self.h_card, regs.SPC_AMP0, byref(selected_range))
logging.info("selectedRange: +- {0:.3f} mV\n".format(selected_range.value))
logger.info("selectedRange: +- {0:.3f} mV\n".format(selected_range.value))
def wait_for_data(self):
"""Wait for a data package(l_notify_size) to be ready.
......@@ -67,9 +68,9 @@ class Card:
dw_error = spcm_dwSetParam_i32(self.h_card, regs.SPC_M2CMD, regs.M2CMD_DATA_WAITDMA)
if dw_error != err.ERR_OK:
if dw_error == err.ERR_TIMEOUT:
logging.error("{0} ... Timeout".format(self.card_nr))
logger.error("{0} ... Timeout".format(self.card_nr))
else:
logging.error("{0} ... Error: {1:d}".format(self.card_nr, dw_error))
logger.error("{0} ... Error: {1:d}".format(self.card_nr, dw_error))
def read_status(self):
"""Read the status of the card. SPC_M2STATUS."""
......@@ -77,7 +78,7 @@ class Card:
spcm_dwGetParam_i32(self.h_card, regs.SPC_M2STATUS, byref(l_status))
if regs.M2STAT_EXTRA_OVERRUN >> 0x4 & l_status.value:
logging.error("overrun or underrun detected: M2STAT_EXTRA_OVERRUN")
logger.error("overrun or underrun detected: M2STAT_EXTRA_OVERRUN")
return l_status.value
def nr_of_bytes_available(self):
......@@ -116,11 +117,11 @@ class Card:
def stop_recording(self):
"""Send the stop command to the card."""
logging.info("card {0} stopped.".format(self.card_nr))
logger.info("card {0} stopped.".format(self.card_nr))
spcm_dwSetParam_i32(self.h_card, regs.SPC_M2CMD, regs.M2CMD_CARD_STOP | regs.M2CMD_DATA_STOPDMA)
def close(self):
"""Close the handle to the card."""
if self.h_card is not None:
spcm_vClose(self.h_card)
logging.info("card {0} closed.".format(self.card_nr))
logger.info("card {0} closed.".format(self.card_nr))
......@@ -13,6 +13,7 @@ from dug_seis.acquisition.hardware_driver.pyspcm import SPCM_BUF_DATA, SPCM_DIR_
from ctypes import c_int32, c_uint64
from ctypes import create_string_buffer, byref, c_void_p
logger = logging.getLogger('dug-seis')
def sz_type_to_name(l_card_type):
"""sz_type_to_name: doing name translation."""
......@@ -37,7 +38,7 @@ def sz_type_to_name(l_card_type):
def init_card(param, card_nr):
"""Initialise card. Setup card parameters. Reserve buffers for DMA data transfer."""
logging.debug("Initializing card {} sdt_init...".format(card_nr))
logger.debug("Initializing card {} sdt_init...".format(card_nr))
sampling_frequency = param['Acquisition']['hardware_settings']['sampling_frequency']
qw_buffer_size = c_uint64(param['Acquisition']['hardware_settings']['ram_buffer_size'])
......@@ -54,7 +55,7 @@ def init_card(param, card_nr):
h_card = spcm_hOpen(create_string_buffer(b'/dev/spcm1'))
gain_selection_this_card = gain_selection[16:32]
if h_card is None:
logging.error("card {} not found...".format(card_nr))
logger.error("card {} not found...".format(card_nr))
return -1
# exit ()
......@@ -68,9 +69,9 @@ def init_card(param, card_nr):
s_card_name = sz_type_to_name(l_card_type.value)
if l_fnc_type.value == regs.SPCM_TYPE_AI:
logging.info("Found: {0} sn {1:05d}".format(s_card_name, l_serial_number.value))
logger.info("Found: {0} sn {1:05d}".format(s_card_name, l_serial_number.value))
else:
logging.error("Card: {0} sn {1:05d} not supported by example".format(s_card_name, l_serial_number.value))
logger.error("Card: {0} sn {1:05d} not supported by example".format(s_card_name, l_serial_number.value))
return -1
""" do a simple FIFO setup """
......@@ -96,7 +97,7 @@ def init_card(param, card_nr):
# set sample rate
spcm_dwSetParam_i32(h_card, regs.SPC_SAMPLERATE, sampling_frequency)
logging.info("using: {0} sps".format(sampling_frequency))
logger.info("using: {0} sps".format(sampling_frequency))
# no clock output
spcm_dwSetParam_i32(h_card, regs.SPC_CLOCKOUT, 0)
......@@ -106,12 +107,12 @@ def init_card(param, card_nr):
range_max = c_int32(0)
l_number_of_ranges = c_int32(0)
spcm_dwGetParam_i32(h_card, regs.SPC_READIRCOUNT, byref(l_number_of_ranges))
logging.debug("card {}: nr of available ranges: {}".format(card_nr, l_number_of_ranges.value))
logger.debug("card {}: nr of available ranges: {}".format(card_nr, l_number_of_ranges.value))
for i in range(l_number_of_ranges.value):
spcm_dwGetParam_i32(h_card, regs.SPC_READRANGEMIN0 + i, byref(range_min))
spcm_dwGetParam_i32(h_card, regs.SPC_READRANGEMAX0 + i, byref(range_max))
logging.debug("card {}, range nr {}: {}mV to {}mV".format(card_nr, i, range_min.value, range_max.value))
logger.debug("card {}, range nr {}: {}mV to {}mV".format(card_nr, i, range_min.value, range_max.value))
# set input range 50, 100, 250, 500, 1000, 2000, 5000, 10000 mV
selected_range = c_int32(0)
......@@ -119,7 +120,7 @@ def init_card(param, card_nr):
spcm_dwSetParam_i32(h_card, regs.SPC_AMP0 + i * 100, gain_selection_this_card[i])
spcm_dwGetParam_i32(h_card, regs.SPC_AMP0 + i * 100, byref(selected_range))
logging.info("card {}, channel {} selected range: {}mV".format(card_nr, i, selected_range.value))
logger.info("card {}, channel {} selected range: {}mV".format(card_nr, i, selected_range.value))
""" define the data buffer """
# we try to use continuous memory if available and big enough
......@@ -127,13 +128,13 @@ def init_card(param, card_nr):
qw_cont_buf_len = c_uint64(0)
spcm_dwGetContBuf_i64(h_card, SPCM_BUF_DATA, byref(pv_buffer),
byref(qw_cont_buf_len))
logging.debug("ContBuf length: {0:d}".format(qw_cont_buf_len.value))
logger.debug("ContBuf length: {0:d}".format(qw_cont_buf_len.value))
if qw_cont_buf_len.value >= qw_buffer_size.value:
logging.info("Using continuous buffer")
logger.info("Using continuous buffer")
else:
pv_buffer = create_string_buffer(qw_buffer_size.value)
logging.info("Using buffer allocated by user program")
logger.info("Using buffer allocated by user program")
spcm_dwDefTransfer_i64(h_card, SPCM_BUF_DATA, SPCM_DIR_CARDTOPC, l_notify_size.value, pv_buffer, c_uint64(0),
qw_buffer_size)
......
......@@ -25,6 +25,7 @@ else:
# logging at import messes with the later logging settings, no logging needed here
# logging.warning('star_hub.py: problems loading the hardware driver. simulation still available.')
logger = logging.getLogger('dug-seis')
class StarHub:
def __init__(self):
......@@ -33,15 +34,15 @@ class StarHub:
def init_star_hub(self, card_list):
"""Initialise the star hub."""
logging.info("init star hub")
logger.info("init star hub")
# open handle for star-hub
self.h_sync = spcm_hOpen(create_string_buffer(b'sync0'))
logging.debug("star-hub handler:{0}".format(self.h_sync))
logger.debug("star-hub handler:{0}".format(self.h_sync))
if self.h_sync is None:
logging.error("Could not open star-hub...")
logger.error("Could not open star-hub...")
return -1
# setup star-hub
......@@ -59,7 +60,7 @@ class StarHub:
# print("card nr i: {0:d}, serial:{1}\n".format(i, l_serial_number.value))
if l_features.value & (regs.SPCM_FEAT_STARHUB5 | regs.SPCM_FEAT_STARHUB16):
logging.info("Star hub found on card nr:{}, serial:{}".format(i, l_serial_number.value))
logger.info("Star hub found on card nr:{}, serial:{}".format(i, l_serial_number.value))
break
i += 1
......@@ -72,11 +73,11 @@ class StarHub:
if dw_error != 0: # != ERR_OK
sz_error_text_buffer = create_string_buffer(regs.ERRORTEXTLEN)
spcm_dwGetErrorInfo_i32(self.h_sync, None, None, sz_error_text_buffer)
logging.error("sz_error_text_buffer.value: {0}".format(sz_error_text_buffer.value))
logger.error("sz_error_text_buffer.value: {0}".format(sz_error_text_buffer.value))
return -1
def close(self):
"""Close the star hub."""
if self.h_sync is not None:
spcm_vClose(self.h_sync)
logging.info("Star hub closed.")
logger.info("Star hub closed.")
Supports Markdown
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment