Author Topic: A driver always logs debug messages to log  (Read 1092 times)

valtonen

  • Full Member
  • ***
  • Posts: 217
    • View Profile
A driver always logs debug messages to log
« on: September 17, 2010, 01:51:14 am »
We have a driver which always logs debug messages to the log even when 'Record diagnostic information to the log (Normally Off)' checkbox is unchecked. In addition, it continues to log the debug data to the log even if the device is disabled.

I will send you the driver as a PM.

-Miika

valtonen

  • Full Member
  • ***
  • Posts: 217
    • View Profile
Re: A driver always logs debug messages to log
« Reply #1 on: September 17, 2010, 05:42:57 am »
I tried to test this situation a little more. The polling interval of the device was set to 1000 ms. Thus, the log gets messages every second:

Code: [Select]
<rec><dt>2010-09-17 12:33:36.3852548Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:36.3891549Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:36.6353924Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:36.6385354Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:37.3857745Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:37.3894862Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:38.3863665Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:38.3905821Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:39.3868392Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:39.3915122Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:40.3873377Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:40.3912121Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:41.3878739Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:41.3921076Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:42.3883553Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:42.3920845Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:43.2638058Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:43.2680254Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:43.3888658Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:43.3915455Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:44.3894157Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:44.3936496Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:45.3899378Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:45.3936821Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:33:46.3900671Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>

After shutting down all Elve services and starting them out again, I was able to repeat this by first enabling the device and turning on the debug logging and then by turning the debugging off, and then after 30+ seconds by disabling the device. After these steps, the device was still outputting the debug messages to the logs.

After this, if I enable the device, set debug logging on, adjust the polling interval to 10000 ms, and restart the device manually, the debug messages get to the logs every one second. If I then restart all Elve services and disable the logging and the device, the logs get messages from the Linet driver still every 10 seconds:

Code: [Select]
<rec><dt>2010-09-17 12:37:04.8846339Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:37:04.8893641Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:37:14.8872414Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:37:14.8900062Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:37:24.8847949Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:37:24.8879255Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:37:34.8831215Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:37:34.8868368Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:37:44.8867040Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:37:44.8911468Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:37:54.8884787Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:37:54.8914133Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:38:04.8851175Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:38:04.8881328Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:38:14.8826839Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:38:14.8854992Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:38:24.8865607Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:38:24.8921310Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:38:34.8882796Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:38:34.8913496Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:38:44.8848471Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:38:44.8892056Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:38:54.8842406Z</dt><s>Debug</s><msg>Linet Driver Data polled at: 1313</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>
<rec><dt>2010-09-17 12:38:54.8872182Z</dt><s>Debug</s><msg>Dining Light1:</msg><app>DriverService</app><ma>SUKKULA</ma><ct>Driver</ct><cn>Linet Driver : Linet Driver</cn></rec>

The logging is set to normal verbosity in clientconfig.xml.

-Miika

John Hughes

  • Administrator
  • Hero Member
  • *****
  • Posts: 2851
    • View Profile
    • Codecore Technologies
Re: A driver always logs debug messages to log
« Reply #2 on: September 17, 2010, 12:38:33 pm »
I believe the logger is working correctly.

It sounds to me like your driver is not disposing of the timer it uses.

Make sure you are disposing of any timers that your driver uses in the StopDriver() method.
John Hughes
Codecore Technologies

valtonen

  • Full Member
  • ***
  • Posts: 217
    • View Profile
Re: A driver always logs debug messages to log
« Reply #3 on: September 20, 2010, 02:24:57 am »
I believe the logger is working correctly.

It sounds to me like your driver is not disposing of the timer it uses.

Make sure you are disposing of any timers that your driver uses in the StopDriver() method.

Yes, you are absolutely right. Thanks for identifying the issue.

-Miika

John Hughes

  • Administrator
  • Hero Member
  • *****
  • Posts: 2851
    • View Profile
    • Codecore Technologies
Re: A driver always logs debug messages to log
« Reply #4 on: September 20, 2010, 08:30:15 am »
In a future version we may isolate drivers into their own AppDomain to prevent issues like this.
John Hughes
Codecore Technologies