How to log from own PyPi package?

Hi

I have my own package which works as expected when run with a test case. I also have my own hub in HA which works as expected based on my config file.

When I call my package from my hub to find the status of the devices, it never returns and my hub no longer loads the devices. (The initial discovery take about a minute, but the code does not return even after that.)

I have added logging in my HA hub and added debug logging for the component in the configuration file. I also use logging in my custom package. However, I cannot see the info/debug messages from the custom package in the HA log file. So I’m not able to see what the issue is.

Are there other log files that I should look for?

Thanks for the pointers.

Paul

HA logging sample: (visible in HA log)

    _LOGGER.info(str.format('Setting up {0} using module {1}.', _paradox_model, config.get(CONF_COMM_MODULE)))

PyPi logging sample: (not visible in HA log, but visible when run with a test script)

    loggingconfig = {'level': 'DEBUG',
        'format': '%(asctime)s %(levelname)s <%(name)s %(module)s %(funcName)s> %(message)s',
        'datefmt': '%a, %d %b %Y %H:%M:%S'}

    logging.basicConfig(**loggingconfig)

    _LOGGER.info(str.format("Connecting to Paradox on host: {0}, port: {1}",
                            self._prt_port, self._prt_speed))

My yaml file is as follows…

logger:
  default: info
  logs:
    homeassistant.components: info
    homeassistant.components.paradox: info
    homeassistant.components.paradox.pyparadox_alarm.alarm_panel: info
    pyparadox_alarm.alarm_panel: info 

However, it only shows the HA messages.

In my terminal window (extract below), I can see messages for [requests.packages.urllib3.connectionpool] but don’t know how I can get my messages for pyparadox_alarm to also display.

16-09-24 08:42:34 INFO (MainThread) [homeassistant.components.paradox] Setting up EVO48 on port /dev/ttyUSB0.
16-09-24 08:42:34 INFO (MainThread) [homeassistant.components.paradox] Paradox controller initialised as EVO48.
16-09-24 08:42:34 INFO (MainThread) [homeassistant.components.paradox] Load Paradox Alarm partitions as platform.
16-09-24 08:42:34 INFO (MainThread) [homeassistant.components.paradox] Load Paradox Alarm zones as platform.
16-09-24 08:42:34 INFO (MainThread) [homeassistant.components.paradox] Start discovery of Paradox Alarm panel.
16-09-24 08:42:34 INFO (MainThread) [homeassistant.components.paradox] Waiting for Paradox discovery…
16-09-24 08:42:34 INFO (ThreadPool Worker 2) [homeassistant.loader] Loaded alarm_control_panel from homeassistant.components.alarm_control_panel
16-09-24 08:42:34 INFO (ThreadPool Worker 5) [homeassistant.loader] Loaded binary_sensor from homeassistant.components.binary_sensor
16-09-24 08:42:35 INFO (MainThread) [homeassistant.components.paradox] Waiting for Paradox discovery…
16-09-24 08:42:36 INFO (MainThread) [homeassistant.components.paradox] Waiting for Paradox discovery…
16-09-24 08:42:37 INFO (MainThread) [homeassistant.components.paradox] Waiting for Paradox discovery…
16-09-24 08:42:38 INFO (MainThread) [homeassistant.components.paradox] Waiting for Paradox discovery…
16-09-24 08:42:39 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=paradox>
16-09-24 08:42:39 INFO (ThreadPool Worker 2) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=alarm_disarm, domain=alarm_control_panel>
16-09-24 08:42:39 INFO (ThreadPool Worker 2) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=alarm_arm_home, domain=alarm_control_panel>
16-09-24 08:42:39 INFO (ThreadPool Worker 2) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=alarm_arm_away, domain=alarm_control_panel>
16-09-24 08:42:39 INFO (ThreadPool Worker 2) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=alarm_trigger, domain=alarm_control_panel>
16-09-24 08:42:39 INFO (ThreadPool Worker 2) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=alarm_control_panel>
16-09-24 08:42:39 INFO (ThreadPool Worker 2) [homeassistant.core] Bus:Handling <Event platform_discovered[L]: discovered=partitions=1=name=House, 2=name=Perimeter, code=None, service=load_platform.alarm_control_panel, platform=paradox>
16-09-24 08:42:39 INFO (ThreadPool Worker 5) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=binary_sensor>
16-09-24 08:42:39 INFO (ThreadPool Worker 5) [homeassistant.core] Bus:Handling <Event platform_discovered[L]: discovered=zones=2=name=Main Bedroom, type=motion, service=load_platform.binary_sensor, platform=paradox>
16-09-24 08:42:39 INFO (ThreadPool Worker 2) [homeassistant.loader] Loaded alarm_control_panel.paradox from homeassistant.components.alarm_control_panel.paradox
16-09-24 08:42:39 INFO (ThreadPool Worker 2) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=alarm_control_panel.evo48, old_state=None, new_state=<state alarm_control_panel.evo48=disarmed; code_format=None, friendly_name=EVO48, changed_by=None @ 2016-09-24T08:42:39.939231+02:00>>
16-09-24 08:42:39 INFO (ThreadPool Worker 5) [homeassistant.loader] Loaded binary_sensor.paradox from homeassistant.components.binary_sensor.paradox
16-09-24 08:42:39 INFO (ThreadPool Worker 5) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.main_bedroom, old_state=None, new_state=<state binary_sensor.main_bedroom=on; friendly_name=Main Bedroom, sensor_class=motion @ 2016-09-24T08:42:39.995958+02:00>>
16-09-24 08:42:40 INFO (ThreadPool Worker 2) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=alarm_control_panel.evo48_2, old_state=None, new_state=<state alarm_control_panel.evo48_2=disarmed; code_format=None, friendly_name=EVO48, changed_by=None @ 2016-09-24T08:42:40.019346+02:00>>
16-09-24 08:42:40 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=process, domain=conversation>
16-09-24 08:42:40 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=conversation>
16-09-24 08:42:40 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=history>
16-09-24 08:42:40 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=None, new_state=<state sun.sun=above_horizon; next_setting=2016-09-24T16:43:25+00:00, next_rising=2016-09-25T04:29:36+00:00, azimuth=0, elevation=0, friendly_name=Sun @ 2016-09-24T08:42:40.544923+02:00>>
16-09-24 08:42:40 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=sun>
16-09-24 08:42:40 INFO (MainThread) [homeassistant.loader] Loaded sensor.yr from homeassistant.components.sensor.yr
16-09-24 08:42:40 INFO (MainThread) [requests.packages.urllib3.connectionpool] Starting new HTTP connection (1): api.yr.no
16-09-24 08:42:41 INFO (MainThread) [requests.packages.urllib3.connectionpool] Starting new HTTP connection (1): api.met.no
16-09-24 08:42:44 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.yr_symbol, old_state=None, new_state=<state sensor.yr_symbol=4; friendly_name=yr Symbol, entity_picture=//api.met.no/weatherapi/weathericon/1.1/?symbol=4;content_type=image/png, about=Weather forecast from yr.no, delivered by the Norwegian Meteorological Institute and the NRK @ 2016-09-24T08:42:44.417603+02:00>>
16-09-24 08:42:44 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=sensor>
16-09-24 08:42:44 INFO (MainThread) [homeassistant.core] Starting Home Assistant (15 threads)
16-09-24 08:42:44 INFO (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_start[L]>
16-09-24 08:42:44 INFO (Timer) [homeassistant.core] Timer:starting

Hi Paul,

You should be able to log from a third party package without any issues,

Although basicConfig should be called first by HASS and subsequently ignored (see here why). I would suggest still removing the logger setup here and rather setup the logger in your test scripts (if you really have to set it up, since py.test should have a default logger format for you).

Hope this helps, seems like you’ve progressed well!

Hi Johann,

Thanks for the pointers.

I have removed the basic config you pointed out, but still no messages.

When looking in the requests.packages.urllib3.connectionpool.py I also cannot see anything specific that they are doing differently. It is not referenced in my yaml file, so I presume I don’t have to specify my components/packages specifically before my messages should start displaying.

I also added some .info messages in the init function as I know that is being executed and because most of my messages are submitted as .debug messages.

As a last resort I also forced my code to crash just to make sure it was executing/using the code that I was busy altering.

I’ll do some more digging to see what I can find.

Ok, that’s a bit embarrassing… It would help to not put the logging code inside a block of code that has been commented out :blush: (Damn you nano editor… :wink:)

So that was the issue with trying to log from the init function, but once that was working I could start to trace back to why logging from the other functions were not working.

It turns out that the problem with logging from the other functions was that my call to the .start function failed, but not in a way that caused Python to crash or even report on it. It just ignored the line and of course, it cannot log if it is not being executed. i.e. I had myclass.start in stead of myclass.start()

Finally, I can get back on track…

Glad you’re back on track

Nano is not ideal for development :smile: You should really try Notepad++ with NppFTP plugin (from Windows). Proper highlighting etc