HM-CC-TC geht plötzlich ohne Grund auf actuator 81%

ThorstenH · 13 April 2013, 11:19:09

Ich habe die alte Version (Release 5.4) genommen.
Log und dump hier:
https://dukepool.selfhost.me:5001/fbsharing/errCFotl

ThorstenH · 16 April 2013, 18:58:54

Scheint so, als träte das Problem seltener auf (neue Version mit repeat). Allerdings kann das auch an den gestiegenen Temperaturen draussen liegen. Gestern trat es wieder auf, leider habe ich kein tcpdump. Auffallend wieder der ausgebliebene Wert für actuator kurz vor dem Anstieg.

Ich kann versuchen, einen tcpdump durchgehend mitlaufen zu lassen.

TC:

Code Auswählen

2013-04-15_06:28:37 thermostat_kueche T: 19.6 H: 58
2013-04-15_06:28:37 thermostat_kueche measured-temp: 19.6
2013-04-15_06:28:37 thermostat_kueche humidity: 58
2013-04-15_06:28:59 thermostat_kueche actuator: 0 %
2013-04-15_06:31:00 thermostat_kueche T: 19.6 H: 58
2013-04-15_06:31:00 thermostat_kueche measured-temp: 19.6
2013-04-15_06:31:00 thermostat_kueche humidity: 58
2013-04-15_06:31:20 thermostat_kueche actuator: 0 %
2013-04-15_06:33:08 thermostat_kueche T: 19.6 H: 58
2013-04-15_06:33:08 thermostat_kueche measured-temp: 19.6
2013-04-15_06:33:08 thermostat_kueche humidity: 58
2013-04-15_06:36:05 thermostat_kueche T: 19.6 H: 58
2013-04-15_06:36:05 thermostat_kueche measured-temp: 19.6
2013-04-15_06:36:05 thermostat_kueche humidity: 58
2013-04-15_06:36:27 thermostat_kueche actuator: 17 %
2013-04-15_06:38:53 thermostat_kueche T: 19.6 H: 58
2013-04-15_06:38:53 thermostat_kueche measured-temp: 19.6
2013-04-15_06:38:53 thermostat_kueche humidity: 58

fhem:

Code Auswählen

2013.04.15 06:26:28.581 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:26:28.585 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAC348E IDcnt:0004
2013.04.15 06:26:53.607 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:26:53.611 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAC9653 IDcnt:0004
2013.04.15 06:27:18.628 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:27:18.632 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AACF814 IDcnt:0004
2013.04.15 06:27:43.653 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:27:43.657 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAD59D8 IDcnt:0004
2013.04.15 06:27:45.241 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AAD6003 d:FF r:FFCB     m:B8 8670 1CDFBA 000000 00D736
2013.04.15 06:28:05.241 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AADAE26 d:FF r:FFCB     m:B8 A258 1CDFBA 1CF1FC 0000
2013.04.15 06:28:07.405 1: HMLAN_Parse: HMLAN1 R:E1CF1FC   stat:0000 t:4AADAEA9 d:FF r:FFCB     m:B8 8202 1CF1FC 1CDFBA 010100003C
2013.04.15 06:28:10.612 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:28:10.615 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AADC32A IDcnt:0004
2013.04.15 06:28:32.645 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:4AAE1936 d:FF r:FFC1     m:DD 8670 1BF932 000000 00DB2F
2013.04.15 06:28:35.852 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:28:35.855 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAE25C6 IDcnt:0004
2013.04.15 06:28:36.229 1: HMLAN_Parse: HMLAN1 R:E1CE123   stat:0000 t:4AAE2737 d:FF r:FFB3     m:7D 8670 1CE123 000000 00C43A
2013.04.15 06:28:40.625 1: HMLAN_Parse: HMLAN1 R:E1CE75F   stat:0000 t:4AAE3863 d:FF r:FFCD     m:77 8670 1CE75F 000000 00DA42
2013.04.15 06:28:52.645 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:4AAE6759 d:FF r:FFC1     m:DD A258 1BF932 1C4DD3 000D
2013.04.15 06:28:54.820 1: HMLAN_Parse: HMLAN1 R:E1C4DD3   stat:0000 t:4AAE67DA d:FF r:FFBB     m:DD 8202 1C4DD3 1BF932 01010A0030
2013.04.15 06:28:58.094 1: HMLAN_Parse: HMLAN1 R:E1CE123   stat:0000 t:4AAE755A d:FF r:FFB4     m:7D A258 1CE123 1CF1E3 0000
2013.04.15 06:29:00.278 1: HMLAN_Parse: HMLAN1 R:E1CF1E3   stat:0000 t:4AAE75DF d:FF r:FFB7     m:7D 8202 1CF1E3 1CE123 0101000033
2013.04.15 06:29:03.515 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:29:03.515 1: HMLAN_Parse: HMLAN1 R:E1CE75F   stat:0000 t:4AAE8686 d:FF r:FFCD     m:77 A258 1CE75F 1CED2A 0000
2013.04.15 06:29:05.717 1: HMLAN_Parse: HMLAN1 R:E1CED2A   stat:0000 t:4AAE8708 d:FF r:FFC2     m:77 8202 1CED2A 1CE75F 010100003E
2013.04.15 06:29:08.931 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:29:08.931 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAE91D9 IDcnt:0004
2013.04.15 06:29:08.934 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAEA701 IDcnt:0004
2013.04.15 06:29:33.956 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:29:33.960 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAF08C7 IDcnt:0004
2013.04.15 06:29:58.982 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:29:58.986 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAF6A8C IDcnt:0004
2013.04.15 06:30:14.747 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AAFA81A d:FF r:FFCB     m:B9 8670 1CDFBA 000000 00D636
2013.04.15 06:30:23.990 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:30:23.994 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAFCC40 IDcnt:0004
2013.04.15 06:30:34.747 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AAFF63D d:FF r:FFCB     m:B9 A258 1CDFBA 1CF1FC 0000
2013.04.15 06:30:36.913 1: HMLAN_Parse: HMLAN1 R:E1CF1FC   stat:0000 t:4AAFF6C0 d:FF r:FFCB     m:B9 8202 1CF1FC 1CDFBA 010100003C
2013.04.15 06:30:49.000 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:30:49.004 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB02DF6 IDcnt:0004
2013.04.15 06:30:58.735 1: HMLAN_Parse: HMLAN1 R:E1CE123   stat:0000 t:4AB053F5 d:FF r:FFB3     m:7E 8670 1CE123 000000 00C43A
2013.04.15 06:31:06.651 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:4AB072E2 d:FF r:FFC1     m:DE 8670 1BF932 000000 00DB2F
2013.04.15 06:31:14.005 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:31:14.009 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB08FA6 IDcnt:0004
2013.04.15 06:31:18.734 1: HMLAN_Parse: HMLAN1 R:E1CE123   stat:0000 t:4AB0A217 d:FF r:FFB2     m:7E A258 1CE123 1C494E 0000
2013.04.15 06:31:20.893 1: HMLAN_Parse: HMLAN1 R:E1C494E   stat:0000 t:4AB0A29C d:FF r:FFC1     m:7E 8202 1C494E 1CE123 0101000033
2013.04.15 06:31:24.095 1: HMLAN_Parse: HMLAN1 R:E1CE75F   stat:0000 t:4AB0AD67 d:FF r:FFCD     m:78 8670 1CE75F 000000 00DA42
2013.04.15 06:31:27.306 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:4AB0C104 d:FF r:FFC1     m:DE A258 1BF932 1C0ABF 000D
2013.04.15 06:31:29.481 1: HMLAN_Parse: HMLAN1 R:E1C0ABF   stat:0000 t:4AB0C189 d:FF r:FFB0     m:DE 8202 1C0ABF 1BF932 01010A003B
2013.04.15 06:31:39.013 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:31:39.016 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB0F159 IDcnt:0004
2013.04.15 06:31:41.630 1: HMLAN_Parse: HMLAN1 R:E1CE75F   stat:0000 t:4AB0FB8A d:FF r:FFCD     m:78 A258 1CE75F 1CED2A 0000
2013.04.15 06:31:43.778 1: HMLAN_Parse: HMLAN1 R:E1CED2A   stat:0000 t:4AB0FC0C d:FF r:FFC2     m:78 8202 1CED2A 1CE75F 010100003E
2013.04.15 06:32:04.015 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:32:04.019 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB15307 IDcnt:0004
2013.04.15 06:32:29.041 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:32:29.045 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB1B4CD IDcnt:0004
2013.04.15 06:32:30.001 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AB1B884 d:FF r:FFCA     m:BA 8670 1CDFBA 000000 00D636
2013.04.15 06:32:50.001 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AB206A6 d:FF r:FFCA     m:BA A258 1CDFBA 1CF1FC 0000
2013.04.15 06:32:52.165 1: HMLAN_Parse: HMLAN1 R:E1CF1FC   stat:0000 t:4AB2072A d:FF r:FFCB     m:BA 8202 1CF1FC 1CDFBA 010100003C
2013.04.15 06:32:55.378 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:32:55.430 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB21BE1 IDcnt:0004
2013.04.15 06:33:06.740 1: HMLAN_Parse: HMLAN1 R:E1CE123   stat:0000 t:4AB2480C d:FF r:FFB0     m:7F 8670 1CE123 000000 00C43A
2013.04.15 06:33:20.438 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:33:20.442 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB27D99 IDcnt:0004
2013.04.15 06:33:26.156 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:4AB293E7 d:FF r:FFC1     m:DF 8670 1BF932 000000 00DB2F
2013.04.15 06:33:45.456 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:33:45.460 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB2DF56 IDcnt:0004
2013.04.15 06:33:46.157 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:4AB2E20A d:FF r:FFC1     m:DF A258 1BF932 1BFC15 000D
2013.04.15 06:33:48.326 1: HMLAN_Parse: HMLAN1 R:E1BFC15   stat:0000 t:4AB2E28E d:FF r:FFC6     m:DF 8202 1BFC15 1BF932 01010A002F
2013.04.15 06:33:51.587 1: HMLAN_Parse: HMLAN1 R:E1CE75F   stat:0000 t:4AB2E9C4 d:FF r:FFCD     m:79 8670 1CE75F 000000 00DA42
2013.04.15 06:34:08.135 1: HMLAN_Parse: HMLAN1 R:E1CE75F   stat:0000 t:4AB337E7 d:FF r:FFCD     m:79 A258 1CE75F 1CED2A 0000
2013.04.15 06:34:10.290 1: HMLAN_Parse: HMLAN1 R:E1CED2A   stat:0000 t:4AB33869 d:FF r:FFC3     m:79 8202 1CED2A 1CE75F 0101000041
2013.04.15 06:34:13.492 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:34:13.524 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB34CFB IDcnt:0004
2013.04.15 06:34:30.755 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AB39047 d:FF r:FFCA     m:BB 8670 1CDFBA 000000 00D636
2013.04.15 06:34:38.527 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:34:38.531 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB3AEAD IDcnt:0004
2013.04.15 06:34:50.755 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AB3DE6A d:FF r:FFCB     m:BB A258 1CDFBA 1CF1FC 0000
2013.04.15 06:34:52.919 1: HMLAN_Parse: HMLAN1 R:E1CF1FC   stat:0000 t:4AB3DEED d:FF r:FFCB     m:BB 8202 1CF1FC 1CDFBA 010100003C
2013.04.15 06:35:03.529 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:35:03.533 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB4105A IDcnt:0004
2013.04.15 06:35:28.554 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:35:28.558 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB4721F IDcnt:0004
2013.04.15 06:35:31.162 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:4AB47C45 d:FF r:FFC1     m:E0 8670 1BF932 000000 00DB2F
2013.04.15 06:35:51.161 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:4AB4CA68 d:FF r:FFC1     m:E0 A258 1BF932 1C4DD3 000D
2013.04.15 06:35:53.335 1: HMLAN_Parse: HMLAN1 R:E1C4DD3   stat:0000 t:4AB4CAEA d:FF r:FFB9     m:E0 8202 1C4DD3 1BF932 01010A0030
2013.04.15 06:35:56.620 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:35:56.624 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB4DFC5 IDcnt:0004
2013.04.15 06:36:00.139 1: HMLAN_Parse: HMLAN1 R:E1CE75F   stat:0000 t:4AB4ED7B d:FF r:FFCD     m:7A 8670 1CE75F 000000 00DA42
2013.04.15 06:36:04.246 1: HMLAN_Parse: HMLAN1 R:E1CE123   stat:0000 t:4AB4FD87 d:FF r:FFB1     m:80 8670 1CE123 000000 00C43A
2013.04.15 06:36:20.139 1: HMLAN_Parse: HMLAN1 R:E1CE75F   stat:0000 t:4AB53B9E d:FF r:FFCD     m:7A A258 1CE75F 1CED2A 0000
2013.04.15 06:36:22.299 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:36:22.299 1: HMLAN_Parse: HMLAN1 R:E1CED2A   stat:0000 t:4AB53C21 d:FF r:FFC3     m:7A 8202 1CED2A 1CE75F 0101000044
2013.04.15 06:36:25.509 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:36:25.563 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB54417 IDcnt:0004
2013.04.15 06:36:25.563 1: HMLAN_Parse: HMLAN1 R:E1CE123   stat:0000 t:4AB54BAA d:FF r:FFB1     m:80 A258 1CE123 1C494E 002B
2013.04.15 06:36:27.771 1: HMLAN_Parse: HMLAN1 R:E1C494E   stat:0000 t:4AB54C2F d:FF r:FFC1     m:80 8202 1C494E 1CE123 0101000033
2013.04.15 06:36:31.538 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB550D6 IDcnt:0004
2013.04.15 06:36:50.583 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:36:50.586 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB5B297 IDcnt:0004
2013.04.15 06:37:15.597 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:37:15.600 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB61450 IDcnt:0004
2013.04.15 06:37:21.011 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AB6296F d:FF r:FFCB     m:BC 8670 1CDFBA 000000 00D636
2013.04.15 06:37:40.615 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:37:40.619 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB6760F IDcnt:0004
2013.04.15 06:37:41.011 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AB67792 d:FF r:FFCA     m:BC A258 1CDFBA 1CF1FC 0000
2013.04.15 06:37:43.174 1: HMLAN_Parse: HMLAN1 R:E1CF1FC   stat:0000 t:4AB67815 d:FF r:FFCB     m:BC 8202 1CF1FC 1CDFBA 010100003C
2013.04.15 06:38:05.619 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:38:05.623 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB6D7BE IDcnt:0004
2013.04.15 06:38:25.918 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:4AB72703 d:FF r:FFC1     m:E1 8670 1BF932 000000 00DB2F
2013.04.15 06:38:30.622 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:38:30.626 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB7396D IDcnt:0004
2013.04.15 06:38:45.918 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:4AB77526 d:FF r:FFC1     m:E1 A258 1BF932 1C0ABF 000D
2013.04.15 06:38:48.091 1: HMLAN_Parse: HMLAN1 R:E1C0ABF   stat:0000 t:4AB775AB d:FF r:FFAE     m:E1 8202 1C0ABF 1BF932 01010A003B
2013.04.15 06:38:51.363 1: HMLAN_Parse: HMLAN1 R:E1CE123   stat:0000 t:4AB77B56 d:FF r:FFB1     m:81 8670 1CE123 000000 00C43A
2013.04.15 06:38:55.625 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:38:55.629 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB79B1B IDcnt:0004
2013.04.15 06:39:01.895 1: HMLAN_Parse: HMLAN1 R:E1CE75F   stat:0000 t:4AB7B391 d:FF r:FFCD     m:7B 8670 1CE75F 000000 00DA42
2013.04.15 06:39:07.502 1: HMLAN_Parse: HMLAN1 R:E1CE123   stat:0000 t:4AB7C979 d:FF r:FFB1     m:81 A258 1CE123 1CF1E3 002B
2013.04.15 06:39:09.679 1: HMLAN_Parse: HMLAN1 R:E1CF1E3   stat:0000 t:4AB7C9FE d:FF r:FFB8     m:81 8202 1CF1E3 1CE123 0101220033
2013.04.15 06:39:20.634 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:39:20.638 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB7FCD0 IDcnt:0004
2013.04.15 06:39:21.895 1: HMLAN_Parse: HMLAN1 R:E1CE75F   stat:0000 t:4AB801B4 d:FF r:FFCD     m:7B A258 1CE75F 1CED2A 0000
2013.04.15 06:39:24.054 1: HMLAN_Parse: HMLAN1 R:E1CED2A   stat:0000 t:4AB80236 d:FF r:FFC3     m:7B 8202 1CED2A 1CE75F 0101000044
2013.04.15 06:39:45.654 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:39:45.658 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB85E8F IDcnt:0004
2013.04.15 06:39:56.766 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AB889F0 d:FF r:FFCB     m:BD 8670 1CDFBA 000000 00D636
2013.04.15 06:40:10.661 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:40:10.665 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB8C042 IDcnt:0004
2013.04.15 06:40:16.766 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AB8D813 d:FF r:FFCA     m:BD A258 1CDFBA 1CF1FC 0000
2013.04.15 06:40:18.931 1: HMLAN_Parse: HMLAN1 R:E1CF1FC   stat:0000 t:4AB8D896 d:FF r:FFCB     m:BD 8202 1CF1FC 1CDFBA 010100003C
2013.04.15 06:40:35.676 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:40:35.680 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB921FC IDcnt:0004

martinp876 · 17 April 2013, 11:27:39

Die Aenderung wirkt, auch wenn dei Ursache immer noch unklar ist. Im log sind 2 Events, die haetten einen reconnect ausgeloest.
Facts:
- HMLAN beantwortet doch ALLE 'K', wenn auch spaet
- Das Problem tritt auf wenn quasi zeitgleich zum Senden eine Message empfangen wird.
- die Antworten kommen erst nach einem Erneuten senden einer Nachricht.
Mutmassungen:
- Das Problem liegt im TCP-stack deines Devices oder des Empfangsstack des HMLAN
- es ist eine race-condition bei gleichzeitigen senden/empfangen. Die Bearbeitung der Queue bleibt haengen. Ist also ein SW bug. Entweder in deinem OS TCP/IP stack oder im HMLAN, gleich Stelle.
Der TCPdump sollte uns sagen welche der beiden Seiten es ist

Events siehe Unten, FHEM ist damit aus dem Schneider

Gruss
Martin

06:29:03.515 HMLAN_Send: I:K
#zeitgleich eine message empfangen
06:29:03.515 HMLAN_Parse: R:E1CE75F stat:0000 t:4AAE8686 d:FF r:FFCD m:77 A258 1CE75F 1CED2A 0000
06:29:05.717 HMLAN_Parse: R:E1CED2A stat:0000 t:4AAE8708 d:FF r:FFC2 m:77 8202 1CED2A 1CE75F 010100003E
06:29:08.931 HMLAN_Send: I:K
# sofort antwort auf 'k'
06:29:08.931 HMLAN_Parse: V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAE91D9 IDcnt:0004
# sofort 2. Antwort (auf 2. k?)
06:29:08.934 HMLAN_Parse: V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAEA701 IDcnt:0004

============ 2. event===========
06:36:22.299 HMLAN_Send: I:K
#zeitgleich eine message empfangen
06:36:22.299 HMLAN_Parse: R:E1CED2A stat:0000 t:4AB53C21 d:FF r:FFC3 m:7A 8202 1CED2A 1CE75F 0101000044
06:36:25.509 HMLAN_Send: I:K
# sofort antwort auf 'k'
06:36:25.563 HMLAN_Parse: V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB54417 IDcnt:0004
06:36:25.563 HMLAN_Parse: R:E1CE123 stat:0000 t:4AB54BAA d:FF r:FFB1 m:80 A258 1CE123 1C494E 002B
06:36:27.771 HMLAN_Parse: R:E1C494E stat:0000 t:4AB54C2F d:FF r:FFC1 m:80 8202 1C494E 1CE123 0101000033
# 6 sec bis Antwort (auf 2. k?)
06:36:31.538 HMLAN_Parse: V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB550D6 IDcnt:0004
.

ThorstenH · 18 April 2013, 19:37:47

Kannst du mir noch sagen, wie ich die Stellen im "neuen" Log (also mit repeat) erkenne, an denen früher ein disconnect stattgefunden hätte? Oder besser: wie finde ich die repeats? Ich kann dann im tcpdump nachsehen, was auf der Leitung zu diesem Zeitpunkt geschieht.

Nur zum Verständnis: FHEM muss dem HMLAN stetig "K" (Keepalive?) Nachrichten schicken, damit HMLAN erkennt, dass FHEM noch lebt und nicht die Verbindung trennt? Wer hat in der alten Version die Verbindung getrennt? HMLAN oder FHEM?

martinp876 · 19 April 2013, 08:37:33

jedes
HMLAN_Send: I:K

wird mit einem
HMLAN_Parse: V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB550D6 IDcnt:0004
beantwortet.
wenn 2
HMLAN_Send: I:K
HMLAN_Send: I:K
kommen war es ein repeat.

filteren auf
filtere auf
cat <logfile> |egrep 'I:K|sNo:'

und du solltest ein gleichmaessiges Muster erhalten.
HMLAN_Send: I:K
HMLAN_Parse: V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB550D6 IDcnt:0004
HMLAN_Send: I:K
HMLAN_Parse: V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB550D6 IDcnt:0004
HMLAN_Send: I:K
HMLAN_Parse: V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB550D6 IDcnt:0004
HMLAN_Send: I:K
HMLAN_Send: I:K <<<<<<<<<<<<<<<<<< fehler
HMLAN_Parse: V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB550D6 IDcnt:0004
HMLAN_Send: I:K
HMLAN_Parse: V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB550D6 IDcnt:0004

ThorstenH · 19 April 2013, 19:47:34

Hallo Martin,

ein Repeat laut fhem log um 18:27:04

FHEM Log

Code Auswählen

2013.04.19 18:26:32.786 1: HMLAN_Send:  HMLAN1 I:K
2013.04.19 18:26:32.790 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:61D9BC1F IDcnt:0005
2013.04.19 18:26:56.448 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:61DA1887 d:FF r:FFC1     m:D6 8670 1BF932 000000 00CA29
2013.04.19 18:27:00.586 1: HMLAN_Send:  HMLAN1 I:K
2013.04.19 18:27:00.587 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:61DA238A d:FF r:FFCD     m:B6 8670 1CDFBA 000000 00B428
2013.04.19 18:27:04.769 1: HMLAN_Send:  HMLAN1 I:K
2013.04.19 18:27:04.770 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:61DA28BB IDcnt:0005
2013.04.19 18:27:04.773 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:61DA3913 IDcnt:0005
2013.04.19 18:27:16.448 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:61DA66AA d:FF r:FFC2     m:D6 A258 1BF932 1C4DD3 0000
2013.04.19 18:27:19.250 1: HMLAN_Parse: HMLAN1 R:E1CE123   stat:0000 t:61DA6715 d:FF r:FFB2     m:80 8670 1CE123 000000 00C030
2013.04.19 18:27:23.391 1: HMLAN_Parse: HMLAN1 R:E1C4DD3   stat:0000 t:61DA672C d:FF r:FFB7     m:D6 8202 1C4DD3 1BF932 010100002F
2013.04.19 18:27:27.656 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:61DA71AD d:FF r:FFCD     m:B6 A258 1CDFBA 1CF1FC 0000
2013.04.19 18:27:30.440 1: HMLAN_Parse: HMLAN1 R:E1CF1FC   stat:0000 t:61DA7230 d:FF r:FFCD     m:B6 8202 1CF1FC 1CDFBA 0101000033
2013.04.19 18:27:34.608 1: HMLAN_Send:  HMLAN1 I:K
2013.04.19 18:27:34.664 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:61DAADA6 IDcnt:0005

Wie auch bei den anderen Vorfällen findet man einen Zusammenhang zwischen praktisch gleichzeitigem:
FHEM Log

Code Auswählen

2013.04.19 18:27:00.586 1: HMLAN_Send:  HMLAN1 I:K
2013.04.19 18:27:00.587 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:61DA238A d:FF r:FFCD     m:B6 8670 1CDFBA 000000 00B428

Dabei ist "HMLAN_Parse" wohl nicht als "Empfang", sondern als "Verarbeitung" zu deuten. Laut tcpdump empängt fhem die dazugehörige Nachricht nämlich nicht um "18:27:00.587" (HMLAN_PARSE), sondern um 18:26:59.266277 und bestätigt den Erhalt um "18:26:59.266306" (ACK).

Direkt danach folgende Kommunikation zwischen fhem und HMLAN:
tcpdump

Code Auswählen


18:27:00.586699 : fhem sendet "K"
18:27:00.587005 : HMLAN bestätigt "K" mit ACK
18:27:00.589472 : HMLAN sendet Antwort "...03C1..."
18:27:00.589490 : fhem bestätigt "...03C1..." mit ACK
18:27:04.770099 : fhem sendet "K"
18:27:04.770463 : HMLAN bestätigt "K" mit ACK
18:27:04.772951 : HMLAN sendet Antwort "...03C1..."
18:27:04.772965 : fhem bestätigt "...03C1..." mit ACK

Im tcpdump sieht man also, dass die Antwort auf die "K"s sofort kommen, fhem in diesem Fall aber fast 4 Sekunden glaubt, es komme keine Antwort. Daraufhin der repeat um "18:27:04.770099", obwohl völlig überflüssig. Im fhem log erscheinen die Antworten später dann beide um "18:27:04", was zumindest für die erste Antwort nicht korrekt ist.

Irgendwie habe ich das Gefühl, dass fhem an dieser Stelle nicht ganz richtig arbeitet. Es muss gar kein repeat gesendet werden. Aber warum wird ohne repeat die Verbindung dann (in der alten Version) getrennt?

Grüße
Thorsten

martinp876 · 19 April 2013, 20:40:54

ZitatDabei ist "HMLAN_Parse" wohl nicht als "Empfang", sondern als "Verarbeitung" zu deuten.

kaum moeglich. Empfangen vorbereiten kann ich nicht, wenn ich nicht hellsehen kann.

ZitatLaut tcpdump empängt fhem die dazugehörige Nachricht nämlich nicht um "18:27:00.587" (HMLAN_PARSE), sondern um 18:26:59.266277 .

passt. TCP empfaengt im 26:59 und schiebt es in den socket zu FHEM. Wann es FHEM verarbeitet ist spaeter.

ZitatIm tcpdump sieht man also, dass die Antwort auf die "K"s sofort kommen, fhem in diesem Fall aber fast 4 Sekunden glaubt, es komme keine Antwort. Daraufhin der repeat um "18:27:04.770099", obwohl völlig überflüssig. Im fhem log erscheinen die Antworten später dann beide um "18:27:04", was zumindest für die erste Antwort nicht korrekt ist.

da hast du recht. Sieht aus, als ob FHEM vergisst, den socket zu lesen.
Das ist insofern nicht schlecht, da wir es quasi in der Hand haben.
Jetzt beginnt das Suchen an einer andern Stelle (haette ich nicht erwartet, siehe da...)
Der Log hat sich schon einmal gelohnt

Gruss
Martin

martinp876 · 22 April 2013, 15:26:58

Hi Thorsten,

zwischenfrage: dein System laeuft nicht auf DOS/windos?

Gruss
Martin

ThorstenH · 22 April 2013, 17:54:05

Synology diskstation ds412+
Linux, Intel CPU

ThorstenH · 22 April 2013, 23:21:47

Ich habe woanders gelesen, dass dblog durch bulk inserts den main thread evtl. für ein paar Sekunden blockiert.
Link

Könnte das die Ursache sein? Ich habe dblog im Einsatz und zeichen alles auf (7 VDs, 4 TCs, 1 Homematic). In den Prozessen sorgt der mysqld alle paar Minuten(vielleicht auch alle paar Sekunden) für 100% CPU Last auf einer Core (von 4).

martinp876 · 23 April 2013, 09:09:59

kann ich nicht ausschliessen, dass es etwas damit zu tun hat.
Wenn es ausschliesslich mit Systemauslastung zu tun haetten koennte man es a) mit laengeren Warten erschlagen(hat nicht funktioniert) und b) wuerde ganz FHEM verzoegert, also auch der 'response missing' timeout.
Da ist also noch etwas anderes.
Ich versuche gerade einmal das Timing zu analysieren, HMLAN Zeitstempel versus FHEM Verarbeitung. Mit braucht FHEM 5-6 sec um Nachrichten zu verarbeiten.
Habe noch keine erfahrungswerte, ich hoffe aber doch nicht!

Hast du noch einmal einen normale log deines Systms, raw messages, ein bisschen laenger. Werdem ir einen von meinem System ziehen und vergleichen.

Gruss
Martin

ThorstenH · 23 April 2013, 22:50:27

vom heutigen Tag die RAW Messages.
Ich werde testweise dblog mal rausnehmen und schauen was passiert.

martinp876 · 24 April 2013, 11:01:41

Hi,

ich gehe jetzt davon aus, dass es an der Langsamheit deines Systems liegt. Siehe Erklaerungen unten.
Ich kann nicht sehen, dass FHEM jemals 2 Nachrichten schneller als ~3sec bearbeitet.

Bin auf deinen Test mit 'ohne dblog' gespannt.
Muss einmal feststellen, ob diese Verzoegerung normal ist.

Gruss
Martin

## msg empfangen, 3 auf einmal in FHEM eingetroffen
00:04:06.588 1: HMLAN/RAW: /E1BF932,0000,72824771,FF,FFC1,0186701BF93200000000DE29
E1CDFBA,0000,728277CD,FF,FFCA,E4A2581CDFBA1CF1FC0200
E1CF1FC,0000,72827850,FF,FFCC,E482021CF1FC1CDFBA0101000034
# FHEM bearbeitet alle drei, eine sofort, die andere nach 5 bzw 8 sec.
00:04:06.588 1: HMLAN_Parse: HMLAN1 R:E1BF932 stat:0000 t:72824771 d:FF r:FFC1 m:01 8670 1BF932 000000 00DE29
00:04:11.464 1: HMLAN_Parse: HMLAN1 R:E1CDFBA stat:0000 t:728277CD d:FF r:FFCA m:E4 A258 1CDFBA 1CF1FC 0200
00:04:14.705 1: HMLAN_Parse: HMLAN1 R:E1CF1FC stat:0000 t:72827850 d:FF r:FFCC m:E4 8202 1CF1FC 1CDFBA 0101000034

#fhem sendet keepalive, gleichzeitig werden 2 messages empfangen
00:04:19.513 1: HMLAN_Send: HMLAN1 I:K
00:04:19.514 1: HMLAN/RAW: /E1BF932,0000,72829594,FF,FFC1,01 A258 1BF932 1BFC15 000F
E1BFC15,0000,72829617,FF,FFC7,01 8202 1BFC15 1BF932 01010C0030
#Eine wird sofort bearbeitet, die 2. erst nach 3 sec
00:04:19.514 1: HMLAN_Parse: HMLAN1 R:E1BF932 stat:0000 t:72829594 d:FF r:FFC1 m:01 A258 1BF932 1BFC15 000F
00:04:22.768 1: HMLAN_Parse: HMLAN1 R:E1BFC15 stat:0000 t:72829617 d:FF r:FFC7 m:01 8202 1BFC15 1BF932 01010C0030
# weil FHEM so langsam ist laeuft der Timer aus.
00:04:27.671 1: HMLAN_Send: HMLAN1 I:K
00:04:27.671 1: HMLAN/RAW: /HHM-LAN-IF,03C1,IEQ0061959,139779,DE7474,7282ABB2,0005
00:04:27.672 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:7282ABB2 IDcnt:0005
00:04:27.674 1: HMLAN/RAW: /HHM-LAN-IF,03C1,IEQ0061959,139779,DE7474,7282CB90,0005
00:04:27.674 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:7282CB90 IDcnt:0005

ThorstenH · 24 April 2013, 18:07:38

Hallo Martin,

das sieht ohne dblog wesentlich besser aus, zumindest kann ich auf den ersten Blick keine repeats entdecken.
So Sachen "FireAndForget" Sachen wie Logs wegschreiben würde ich aus der fhem Verarbeitung entkoppeln, damit die wirklich wichtigen Dingen nicht aufgehalten werden. Ich kenne mich mit Perl allerdings zu wenig aus, vermute aber, dass da so etwas gehen müsste.

Grüße
Thorsten

martinp876 · 25 April 2013, 09:08:57

Hi Thorsten,

klar, perl kann das schon. Eine einfache Variante ist auch schon vorgesehen. Man kann Ablaeufe entkoppelt, das ist sogar sehr einfach. Dann hat man das problem es wieder zu koppeln.
In deinem Fall sehe ich folgendes (soweit ich die Anwendugn verstanden habe):
Daten aus FHEM werden in Files geschrieben, eine Ruckmeldung an FHEM ist nicht erforderlich. Das ist ein relativ einfacher Fall.
Das Entkoppeln bringt aber nur dann etwas, wenn die CPU nicht zu 100% ausgelastet ist.
Falls deine CPU aber zu 100% dicht ist bekommt FHEM auch keine Processing time. Dann must du an der naechsten Schraube drehen und Process-prios verstellen: FHEM hoeher als logfiles schreiben...

DBlog klassifizieren ich als 'non-realtime' und 'time-consuming', wuerde sich also lohnen, ueber entkoppeln nachzudenken. Wenn deine CPU aber bei DBlog an den Anschlag faehrt ist das Resultat fraglich, da muesste mehr gemacht werden.

Gruss, Martin