98_freezemon.pm 52 KB

1234567891011121314151617181920212223242526272829303132333435363738394041424344454647484950515253545556575859606162636465666768697071727374757677787980818283848586878889909192939495969798991001011021031041051061071081091101111121131141151161171181191201211221231241251261271281291301311321331341351361371381391401411421431441451461471481491501511521531541551561571581591601611621631641651661671681691701711721731741751761771781791801811821831841851861871881891901911921931941951961971981992002012022032042052062072082092102112122132142152162172182192202212222232242252262272282292302312322332342352362372382392402412422432442452462472482492502512522532542552562572582592602612622632642652662672682692702712722732742752762772782792802812822832842852862872882892902912922932942952962972982993003013023033043053063073083093103113123133143153163173183193203213223233243253263273283293303313323333343353363373383393403413423433443453463473483493503513523533543553563573583593603613623633643653663673683693703713723733743753763773783793803813823833843853863873883893903913923933943953963973983994004014024034044054064074084094104114124134144154164174184194204214224234244254264274284294304314324334344354364374384394404414424434444454464474484494504514524534544554564574584594604614624634644654664674684694704714724734744754764774784794804814824834844854864874884894904914924934944954964974984995005015025035045055065075085095105115125135145155165175185195205215225235245255265275285295305315325335345355365375385395405415425435445455465475485495505515525535545555565575585595605615625635645655665675685695705715725735745755765775785795805815825835845855865875885895905915925935945955965975985996006016026036046056066076086096106116126136146156166176186196206216226236246256266276286296306316326336346356366376386396406416426436446456466476486496506516526536546556566576586596606616626636646656666676686696706716726736746756766776786796806816826836846856866876886896906916926936946956966976986997007017027037047057067077087097107117127137147157167177187197207217227237247257267277287297307317327337347357367377387397407417427437447457467477487497507517527537547557567577587597607617627637647657667677687697707717727737747757767777787797807817827837847857867877887897907917927937947957967977987998008018028038048058068078088098108118128138148158168178188198208218228238248258268278288298308318328338348358368378388398408418428438448458468478488498508518528538548558568578588598608618628638648658668678688698708718728738748758768778788798808818828838848858868878888898908918928938948958968978988999009019029039049059069079089099109119129139149159169179189199209219229239249259269279289299309319329339349359369379389399409419429439449459469479489499509519529539549559569579589599609619629639649659669679689699709719729739749759769779789799809819829839849859869879889899909919929939949959969979989991000100110021003100410051006100710081009101010111012101310141015101610171018101910201021102210231024102510261027102810291030103110321033103410351036103710381039104010411042104310441045104610471048104910501051105210531054105510561057105810591060106110621063106410651066106710681069107010711072107310741075107610771078107910801081108210831084108510861087108810891090109110921093109410951096109710981099110011011102110311041105110611071108110911101111111211131114111511161117111811191120112111221123112411251126112711281129113011311132113311341135113611371138113911401141114211431144114511461147114811491150115111521153115411551156115711581159116011611162116311641165116611671168116911701171117211731174117511761177117811791180118111821183118411851186118711881189119011911192119311941195119611971198119912001201120212031204120512061207120812091210121112121213121412151216121712181219122012211222122312241225122612271228122912301231123212331234123512361237123812391240124112421243124412451246124712481249125012511252125312541255125612571258125912601261126212631264126512661267126812691270127112721273127412751276127712781279128012811282128312841285128612871288128912901291129212931294129512961297129812991300130113021303130413051306130713081309131013111312131313141315131613171318131913201321132213231324132513261327132813291330133113321333133413351336133713381339134013411342134313441345134613471348134913501351135213531354135513561357135813591360136113621363136413651366136713681369137013711372137313741375137613771378137913801381138213831384138513861387138813891390139113921393139413951396139713981399140014011402140314041405140614071408140914101411141214131414141514161417141814191420142114221423
  1. # $Id: 98_freezemon.pm 16571 2018-04-08 19:57:54Z KernSani $
  2. ##############################################################################
  3. #
  4. # 98_FreezeMon.pm
  5. # An FHEM Perl module that tries to combine some features of PERFMON and apptime
  6. #
  7. # Copyright by KernSani
  8. # based on 99_PERFMON and apptime
  9. #
  10. # Fhem is free software: you can redistribute it and/or modify
  11. # it under the terms of the GNU General Public License as published by
  12. # the Free Software Foundation, either version 2 of the License, or
  13. # (at your option) any later version.
  14. #
  15. # Fhem is distributed in the hope that it will be useful,
  16. # but WITHOUT ANY WARRANTY; without even the implied warranty of
  17. # MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
  18. # GNU General Public License for more details.
  19. #
  20. # You should have received a copy of the GNU General Public License
  21. # along with fhem. If not, see <http://www.gnu.org/licenses/>.
  22. #
  23. ##############################################################################
  24. # Changelog:
  25. # 0.0.20: Internal changes
  26. # improved handling of blocking calls
  27. # fm_extraSeconds not used anymore
  28. # aligned disable/active/inactive to other modules (at)
  29. # 0.0.19: unwrap Log3 function when set inactive
  30. # suppress warnings when redefining subs
  31. # Monitoring callFn (fm_CatchFnCalls)
  32. # Monitoring Commands (fm_CatchCmds)
  33. # adjusted log levels
  34. # 0.0.18: fixed unnecessary call of blocking function
  35. # 0.0.17: fixed Warning when fm_logFile is not maintained
  36. # Freeze-Handling non-blocking
  37. # New attribute fm_whitelistSub
  38. # 0.0.16: Minor Logging changes
  39. # Auto-delete Logfiles via fm_logKeep
  40. # 0.0.15: New InternalTimer Handling (#81365) - Thanks to Ansgar (noansi)
  41. # New logging function (fm_logFile, fm_logExtraSeconds) incl. get function - Thanks Andy (gandy)
  42. # Fixed unescaped characters in commandref (helmut, #84992)
  43. # 0.0.14: Issue with prioQueues (#769427)
  44. # Fixed German Umlauts in German Commandref
  45. # 0.0.13: added extended Details attribute
  46. # optimization of logging
  47. # 0.0.12: problem with older perl versions (Forum #764462)
  48. # Small improvement in device detection
  49. # added ignoreDev and ignorMode attribute
  50. # 0.0.11: added date to "get freeze" popup
  51. # fixed readingsbulkupdate behaviour
  52. # fixed that freezemon is inactive after restart
  53. # removed gplots
  54. # 0.0.10: added set commands active, inactive and clear
  55. # added gplot files
  56. # minor bug fixes
  57. # 0.0.09: fixed incomplete renaming of Attribute fm_freezeThreshold
  58. # 0.0.08: trimming of very long lines in "get freeze"
  59. # start freezemon only after INITIALIZED|REREADCFG (and as late as possible)
  60. # 0.0.07: just for fun - added some color to "get freeze"
  61. # Fixed bug with uninitialized value (Thanks Micheal.Winkler)
  62. # 0.0.06: Code cleanup
  63. # Fixed bug with dayLast reading
  64. # 0.0.05: Experimental coding to improve bad guy detection
  65. # German and English documentation added
  66. # 0.0.04: Added Get function to get last 20 freezes
  67. # 0.0.03: Added dynamic loglevel attribute fm_log
  68. # Added missing "isDisabled" check in define function
  69. # Do some checks not every second
  70. # Fixed PERL WARNING "uninitialized value" if no Device found
  71. # minor adjustments and bugfixes
  72. # 0.0.02: Fixed logical issue with freezetime Attribute
  73. # Renamed Attributes
  74. # added dayLast readings
  75. # fixed delete attribute "disable"
  76. # fixed issue with missing svref_2object
  77. # minor adjustments and bugfixes
  78. # 0.0.01: initial version
  79. ##############################################################################
  80. ##############################################################################
  81. # Todo:
  82. #
  83. #
  84. ##############################################################################
  85. package main;
  86. use strict;
  87. use warnings;
  88. use Data::Dumper;
  89. use POSIX;
  90. use Time::HiRes qw(gettimeofday);
  91. use Time::HiRes qw(tv_interval);
  92. use B qw(svref_2object);
  93. use Blocking;
  94. use vars qw($FW_CSRF);
  95. my $version = "0.0.20";
  96. my @logqueue = ();
  97. my @fmCmd = ();
  98. my @fmFn = ();
  99. ###################################
  100. sub freezemon_Initialize($) {
  101. my ($hash) = @_;
  102. my $name = $hash->{NAME};
  103. # Module specific attributes
  104. my @freezemon_attr =
  105. (
  106. "fm_forceApptime:0,1 fm_freezeThreshold disable:0,1 fm_log fm_ignoreDev fm_ignoreMode:off,single,all fm_extDetail:0,1 fm_logExtraSeconds fm_logFile fm_logKeep fm_whitelistSub fm_CatchFnCalls:0,1 fm_CatchCmds:0,1"
  107. );
  108. $hash->{GetFn} = "freezemon_Get";
  109. $hash->{SetFn} = "freezemon_Set";
  110. $hash->{DefFn} = "freezemon_Define";
  111. $hash->{UndefFn} = "freezemon_Undefine";
  112. $hash->{NotifyFn} = "freezemon_Notify";
  113. $hash->{NotifyDev} = "global";
  114. $hash->{NotifyOrderPrefix} = "99-"; # we want to be notified late.
  115. $hash->{AttrFn} = "freezemon_Attr";
  116. $hash->{AttrList} = join( " ", @freezemon_attr ) . " " . $readingFnAttributes;
  117. #map new Attribute names
  118. $hash->{AttrRenameMap} = {
  119. "fmForceApptime" => "fm_forceApptime:",
  120. "fmFreezeTime" => "fm_freezeThreshold"
  121. };
  122. }
  123. ###################################
  124. sub freezemon_Define($$) {
  125. my ( $hash, $def ) = @_;
  126. my @a = split( "[ \t][ \t]*", $def );
  127. RemoveInternalTimer($hash);
  128. my $usage = "syntax: define <name> freezemon";
  129. my ( $name, $type ) = @a;
  130. if ( int(@a) != 2 ) {
  131. return $usage;
  132. }
  133. Log3 $name, 3, "freezemon defined $name $type";
  134. $hash->{VERSION} = $version;
  135. $hash->{NAME} = $name;
  136. # start the timer
  137. Log3 $name, 5, "[$name] => Define IsDisabled:" . IsDisabled($name) . " init_done:$init_done";
  138. if ( !IsDisabled($name) && $init_done ) {
  139. freezemon_start($hash);
  140. }
  141. elsif ( IsDisabled($name) ) {
  142. $hash->{STATE} = "inactive";
  143. $hash->{helper}{DISABLED} = 1;
  144. }
  145. $hash->{VERSION} = $version;
  146. return undef;
  147. }
  148. ###################################
  149. sub freezemon_Undefine($$) {
  150. my ( $hash, $name ) = @_;
  151. RemoveInternalTimer($hash);
  152. BlockingKill( $hash->{helper}{blocking}{pid} ) if ( defined( $hash->{helper}{blocking}{pid} ) );
  153. freezemon_unwrap_all($hash);
  154. return undef;
  155. }
  156. ###################################
  157. sub freezemon_Notify($$) {
  158. my ( $hash, $dev ) = @_;
  159. my $name = $hash->{NAME}; # own name / hash
  160. my $events = deviceEvents( $dev, 1 );
  161. return ""
  162. if ( IsDisabled($name) ); # Return without any further action if the module is disabled
  163. return if ( !grep( m/^INITIALIZED|REREADCFG$/, @{$events} ) );
  164. freezemon_start($hash);
  165. }
  166. ###################################
  167. sub freezemon_processFreeze($) {
  168. my ($hash) = @_;
  169. my $name = $hash->{NAME};
  170. my $pid = $hash->{helper}{blocking}{pid};
  171. my $log = freezemon_dump_log( $hash, $hash->{helper}{TIMER}, $hash->{helper}{msg} );
  172. return $name;
  173. }
  174. ###################################
  175. sub freezemon_freezeDone($) {
  176. my ($name) = @_;
  177. my $hash = $defs{$name};
  178. Log3 $name, 5, "[Freezemon] $name: Blocking Call with PID $hash->{helper}{blocking}{pid} ended";
  179. delete( $hash->{helper}{blocking} );
  180. }
  181. ###################################
  182. sub freezemon_freezeAbort($) {
  183. my ($hash) = @_;
  184. my $name = $hash->{NAME};
  185. Log3 $name, 1, "[Freezemon] $name: Blocking Call with PID $hash->{helper}{blocking}{pid} aborted due to timeout";
  186. delete( $hash->{helper}{blocking} );
  187. return $name;
  188. }
  189. ###################################
  190. sub freezemon_processBlocking($) {
  191. my ($e) = @_;
  192. my $name = $e->{NAME};
  193. my $log = freezemon_dump_log2( $name, $e->{msg}, $e->{logfile}, $e->{logqueue} );
  194. return $name;
  195. }
  196. ###################################
  197. sub freezemon_ProcessTimer($) {
  198. my ($hash) = @_;
  199. my $name = $hash->{NAME};
  200. #RemoveInternalTimer($hash);
  201. my $now = gettimeofday();
  202. my $freeze = $now - $hash->{helper}{TIMER};
  203. #Check Freezes
  204. if ( $freeze > AttrVal( $name, "fm_freezeThreshold", 1 ) ) {
  205. delete $hash->{helper}{logqueue};
  206. $hash->{helper}{logqueue} = \@logqueue;
  207. $hash->{helper}{now} = $now;
  208. $hash->{helper}{freeze} = $freeze;
  209. my $now = $hash->{helper}{now};
  210. my $freeze = $hash->{helper}{freeze};
  211. my ( $seconds, $microseconds ) = gettimeofday();
  212. my $t0 = [gettimeofday];
  213. my @t = localtime($seconds);
  214. my $tim = sprintf(
  215. "%04d.%02d.%02d %02d:%02d:%02d.%03d",
  216. $t[5] + 1900,
  217. $t[4] + 1,
  218. $t[3], $t[2], $t[1], $t[0], $microseconds / 1000
  219. );
  220. Log3 $name, 5, "[Freezemon] $name: ----------- Starting Freeze handling at $tim ---------------------";
  221. my $dev = "";
  222. my $guys = "";
  223. my $idevFlag = "";
  224. my $nidevFlag = "";
  225. my $found = 0;
  226. my $start = strftime( "%H:%M:%S", localtime( $hash->{helper}{TIMER} ) );
  227. my $end = strftime( "%H:%M:%S", localtime($now) );
  228. $freeze = int( $freeze * 1000 ) / 1000;
  229. #Build a hash of devices to ignore
  230. my @idevs = split( ",", AttrVal( $name, "fm_ignoreDev", "" ) );
  231. my %id = map { $_ => 1 } @idevs;
  232. my %blacklist = map { $_ => 1 } split( ",", AttrVal( $name, "fm_whitelistSub", "" ) );
  233. # Commands
  234. foreach my $entry (@fmCmd) {
  235. if ( exists( $id{ @$entry[1] } ) ) {
  236. $idevFlag = @$entry[1];
  237. }
  238. else {
  239. $nidevFlag = @$entry[1];
  240. }
  241. if ( exists( $blacklist{ @$entry[0] } ) ) {
  242. Log3 $name, 5, "[Freezemon] $name whitelisted: " . @$entry[0];
  243. next;
  244. }
  245. $dev .= "cmd-" . @$entry[0] . "(" . @$entry[1] . ") ";
  246. }
  247. #Functions
  248. foreach my $entry (@fmFn) {
  249. if ( exists( $id{ @$entry[1] } ) ) {
  250. $idevFlag = @$entry[1];
  251. }
  252. else {
  253. $nidevFlag = @$entry[1];
  254. }
  255. if ( exists( $blacklist{ @$entry[0] } ) ) {
  256. Log3 $name, 5, "[Freezemon] $name whitelisted: " . @$entry[0];
  257. next;
  258. }
  259. $dev .= "fn-" . @$entry[0] . "(" . @$entry[1] . ") ";
  260. }
  261. #get the timers that were executed in last cycle
  262. my $first = $intAtA[0]->{TRIGGERTIME};
  263. foreach my $c ( $hash->{helper}{inAt} ) {
  264. foreach my $d (@$c) {
  265. last if ( $d->{TRIGGERTIME} >= $first );
  266. my $devname = freezemon_getDevice( $hash, $d );
  267. if ( exists( $id{$devname} ) ) {
  268. $idevFlag = $devname;
  269. }
  270. else {
  271. $nidevFlag = $devname;
  272. }
  273. if ( exists( $blacklist{ $d->{FN} } ) ) {
  274. Log3 $name, 5, "[Freezemon] $name whitelisted: " . $d->{FN};
  275. next;
  276. }
  277. $dev .= "tmr-" . $d->{FN} . "(" . $devname . ") ";
  278. }
  279. }
  280. # prioQueues are not unique, so we are using the old way...
  281. if ( $hash->{helper}{apptime} ne "" ) {
  282. my @olddev = split( " ", $hash->{helper}{apptime} );
  283. my @newdev = split( " ", freezemon_apptime($hash) );
  284. my %nd = map { $_ => 1 } @newdev;
  285. foreach my $d (@olddev) {
  286. if ( !exists( $nd{$d} ) ) {
  287. my @a = split( ":", $d );
  288. if ( exists( $id{ $a[1] } ) ) {
  289. $idevFlag = $a[1];
  290. }
  291. else {
  292. $nidevFlag = $a[1];
  293. }
  294. if ( exists( $blacklist{ $a[0] } ) ) {
  295. Log3 $name, 5, "[Freezemon] $name whitelisted: " . $a[0];
  296. next;
  297. }
  298. $dev .= "prio-" . $a[0] . "(" . $a[1] . ") ";
  299. }
  300. }
  301. }
  302. my $exists = undef;
  303. if ( $dev eq "" ) {
  304. $dev = "no bad guy found :-(";
  305. }
  306. #check ignorDev
  307. my $imode = "off";
  308. if ( AttrVal( $name, "fm_ignoreDev", undef ) ) {
  309. $imode = AttrVal( $name, "fm_ignoreMode", "all" );
  310. }
  311. #In "all" mode all found devices have to be in ignoreDevs (i.e. we're done if one is not in ignoreDev
  312. if ( $imode eq "all" and $nidevFlag ne "" ) {
  313. Log3 $name, 5, "[Freezemon] $name logging: $dev in $imode mode, because $nidevFlag is not ignored";
  314. $exists = 1;
  315. }
  316. #In "single" mode a single found device has to be in ignoreDevs (i.e. we're done if one is in ignoreDev
  317. elsif ( $imode eq "single" and $idevFlag ne "" ) {
  318. Log3 $name, 5, "[Freezemon] $name: ignoring $dev in $imode mode, because $idevFlag is ignored";
  319. $exists = undef;
  320. }
  321. else {
  322. $exists = 1;
  323. }
  324. if ($exists) {
  325. # determine relevant loglevel
  326. my $loglevel = 1;
  327. my %params = map { split /\:/, $_ } ( split /\ /, AttrVal( $name, "fm_log", "" ) );
  328. foreach my $param ( reverse sort { $a <=> $b } keys %params ) {
  329. if ( $freeze > $param ) {
  330. $loglevel = $params{$param};
  331. last;
  332. }
  333. }
  334. # Create Log(
  335. $hash->{helper}{msg} =
  336. strftime(
  337. "[Freezemon] $name: possible freeze starting at %H:%M:%S, delay is $freeze possibly caused by: $dev",
  338. localtime( $hash->{helper}{TIMER} ) );
  339. my @t = localtime($seconds);
  340. my $log = ResolveDateWildcards( AttrVal( $name, "fm_logFile", undef ), @t );
  341. # BlockingCall for Logfile creation /create a queue
  342. if ( AttrVal( $name, "fm_logFile", "" ) ne "" ) {
  343. my @cqueue = @logqueue;
  344. my %lqueue = (
  345. logqueue => \@cqueue,
  346. msg => $hash->{helper}{msg},
  347. logfile => $log
  348. );
  349. my @aqueue;
  350. if ( defined( $hash->{helper}{logfilequeue} ) ) {
  351. @aqueue = @{ $hash->{helper}{logfilequeue} };
  352. }
  353. push @aqueue, \%lqueue;
  354. $hash->{helper}{logfilequeue} = \@aqueue;
  355. }
  356. Log3 $name, $loglevel, $hash->{helper}{msg};
  357. # Build hash with 20 last freezes
  358. my @freezes = ();
  359. my $dev2 = $dev =~ s/,/#&%/rg;
  360. push @freezes, split( ",", ReadingsVal( $name, ".fm_freezes", "" ) );
  361. push @freezes,
  362. strftime( "%Y-%m-%d", localtime )
  363. . freezemon_logLink( $name, $log )
  364. . ": s:$start e:$end f:$freeze d:$dev2";
  365. #while (keys @freezes > 20) { #problem with older Perl versions
  366. while ( scalar(@freezes) > 20 ) {
  367. shift @freezes;
  368. }
  369. my $freezelist = join( ",", @freezes );
  370. my $fcDay = ReadingsVal( $name, "fcDay", 0 ) + 1;
  371. my $ftDay = ReadingsVal( $name, "ftDay", 0 ) + $freeze;
  372. readingsBeginUpdate($hash);
  373. readingsBulkUpdate( $hash, ".fm_freezes", $freezelist, 0 );
  374. readingsBulkUpdate( $hash, "state", "s:$start e:$end f:$freeze d:$dev" );
  375. readingsBulkUpdate( $hash, "freezeTime", $freeze );
  376. readingsBulkUpdate( $hash, "fcDay", $fcDay );
  377. readingsBulkUpdate( $hash, "ftDay", $ftDay );
  378. readingsBulkUpdate( $hash, "freezeDevice", $dev );
  379. readingsEndUpdate( $hash, 1 );
  380. }
  381. else {
  382. Log3 $name, 5, "[Freezemon] $name - $dev was ignored";
  383. }
  384. ( $seconds, $microseconds ) = gettimeofday();
  385. @t = localtime($seconds);
  386. $tim = sprintf(
  387. "%04d.%02d.%02d %02d:%02d:%02d.%03d",
  388. $t[5] + 1900,
  389. $t[4] + 1,
  390. $t[3], $t[2], $t[1], $t[0], $microseconds / 1000
  391. );
  392. my $ms = tv_interval($t0);
  393. Log3 $name, 5, "[Freezemon] $name: ----------- Ending Freeze handling at $tim after $ms --------";
  394. }
  395. #freezemon_purge_log_before( $hash, $hash->{helper}{TIMER} - AttrVal( $name, "fm_logExtraSeconds", 0 ) )
  396. # if ( AttrVal( $name, "fm_logFile", "" ) ne "" );
  397. undef(@logqueue);
  398. undef(@fmCmd);
  399. undef(@fmFn);
  400. # ---- Some stuff not required every second
  401. $hash->{helper}{intCount} //= 0;
  402. $hash->{helper}{intCount} += 1;
  403. if ( $hash->{helper}{intCount} >= 60 ) {
  404. $hash->{helper}{intCount} = 0;
  405. #Update dayLast readings if we have a new day
  406. my $last = ReadingsVal( $name, ".lastDay", "" );
  407. my $dnow = strftime( "%Y-%m-%d", localtime );
  408. if ( $last eq "" ) {
  409. readingsSingleUpdate( $hash, ".lastDay", $dnow, 0 );
  410. }
  411. elsif ( $dnow gt $last ) {
  412. my $fcDay = ReadingsVal( $name, "fcDay", 0 );
  413. my $ftDay = ReadingsVal( $name, "ftDay", 0 );
  414. readingsBeginUpdate($hash);
  415. readingsBulkUpdate( $hash, "fcDayLast", $fcDay );
  416. readingsBulkUpdate( $hash, "ftDayLast", $ftDay );
  417. readingsBulkUpdate( $hash, "fcDay", 0 );
  418. readingsBulkUpdate( $hash, "ftDay", 0 );
  419. readingsBulkUpdate( $hash, ".lastDay", $dnow, 0 );
  420. readingsEndUpdate( $hash, 1 );
  421. }
  422. # check if apptime is active
  423. if ( AttrVal( $name, "fm_forceApptime", 0 ) == 1
  424. and !defined( $cmds{"apptime"} ) )
  425. {
  426. no warnings;
  427. fhem( "apptime", 1 );
  428. }
  429. # check apptime overwrote freezemon CallFn
  430. freezemon_install_callFn_wrapper( $hash, 1 ) if AttrVal( $name, "fm_CatchFnCalls", 0 ) == 1;
  431. # let's get rid of old logs
  432. if ( my $keep = AttrVal( $name, "fm_logKeep", undef ) ) {
  433. my @fl = freezemon_getLogFiles( $name, 1 );
  434. my $path = freezemon_getLogPath($name);
  435. my $max = scalar(@fl) - $keep;
  436. for ( my $i = 0 ; $i < $max ; $i++ ) {
  437. Log3 $name, 4, "[Freezemon] $name: Deleting $fl[$i]";
  438. unlink("$path/$fl[$i]");
  439. }
  440. }
  441. }
  442. # process logqueue non-blocking every 5 seconds
  443. if ( $hash->{helper}{intCount} % 5 == 0 ) {
  444. if ( !defined( $hash->{helper}{blocking} ) ) {
  445. my $e = shift @{ $hash->{helper}{logfilequeue} };
  446. if ( defined($e) ) {
  447. #$hash->{helper}{logentry} = $e;
  448. $e->{NAME} = $name;
  449. $hash->{helper}{blocking} =
  450. BlockingCall( "freezemon_processBlocking", $e, "freezemon_freezeDone", 120, "freezemon_freezeAbort",
  451. $hash );
  452. Log3 $name, 5, "[Freezemon] $name: Blocking Call started with PID $hash->{helper}{blocking}{pid}";
  453. }
  454. }
  455. }
  456. # start next timer
  457. $hash->{helper}{fn} = "";
  458. $hash->{helper}{apptime} = freezemon_apptime($hash);
  459. $hash->{helper}{inAt} = [@intAtA];
  460. $hash->{helper}{TIMER} = int($now) + 1;
  461. InternalTimer( $hash->{helper}{TIMER}, 'freezemon_ProcessTimer', $hash, 0 );
  462. }
  463. ###################################
  464. sub freezemon_Set($@) {
  465. my ( $hash, $name, $cmd, @args ) = @_;
  466. my $usage = "Unknown argument $cmd, choose one of active:noArg inactive:noArg clear:noArg";
  467. return "\"set $name\" needs at least one argument" unless ( defined($cmd) );
  468. if ( $cmd eq "inactive" ) {
  469. RemoveInternalTimer($hash);
  470. readingsSingleUpdate( $hash, "state", "inactive", 1 );
  471. $hash->{helper}{DISABLED} = 1;
  472. freezemon_unwrap_all($hash);
  473. }
  474. elsif ( $cmd eq "active" ) {
  475. if ( IsDisabled($name) && !AttrVal( $name, "disable", undef ) ) {
  476. freezemon_start($hash);
  477. }
  478. else {
  479. return "Freezemon $name is already active";
  480. }
  481. }
  482. elsif ( $cmd eq "clear" ) {
  483. readingsBeginUpdate($hash);
  484. readingsBulkUpdate( $hash, "fcDayLast", 0, 1 );
  485. readingsBulkUpdate( $hash, "ftDayLast", 0, 1 );
  486. readingsBulkUpdate( $hash, "fcDay", 0, 1 );
  487. readingsBulkUpdate( $hash, "ftDay", 0, 1 );
  488. readingsBulkUpdate( $hash, ".lastDay", "", 1 );
  489. readingsBulkUpdate( $hash, ".fm_freezes", "", 1 );
  490. if ( !IsDisabled($name) ) {
  491. readingsBulkUpdate( $hash, "state", "initialized", 1 );
  492. }
  493. readingsBulkUpdate( $hash, "freezeTime", 0, 1 );
  494. readingsBulkUpdate( $hash, "freezeDevice", "", 1 );
  495. readingsEndUpdate( $hash, 1 );
  496. }
  497. else {
  498. return $usage;
  499. }
  500. return undef;
  501. }
  502. ###################################
  503. sub freezemon_Get($@) {
  504. my ( $hash, @a ) = @_;
  505. my $name = $hash->{NAME};
  506. my $state = $hash->{STATE};
  507. my $ret = "";
  508. my $usage = 'Unknown argument $a[1], choose one of freeze:noArg log:';
  509. return "\"get $name\" needs at least one argument" unless ( defined( $a[1] ) );
  510. #get the logfiles
  511. my @fl = freezemon_getLogFiles($name);
  512. my $sfl = join( ",", @fl );
  513. $usage .= $sfl;
  514. # Get freeze entries
  515. if ( $a[1] eq "freeze" ) {
  516. my @colors = ( "red", "yellow", "green", "white", "gray" );
  517. my @freezes = split( ",", ReadingsVal( $name, ".fm_freezes", "" ) );
  518. foreach (@freezes) {
  519. my $loglevel = 1;
  520. my $freeze = $_;
  521. if ( $freeze =~ /f:(.*)d:/ ) {
  522. $freeze = $1;
  523. }
  524. my %params = map { split /\:/, $_ } ( split /\ /, AttrVal( $name, "fm_log", "" ) );
  525. foreach my $param ( reverse sort { $a <=> $b } keys %params ) {
  526. if ( $freeze > $param ) {
  527. $loglevel = $params{$param};
  528. last;
  529. }
  530. }
  531. $_ =~ s/(?<=.{240}).{1,}$/.../;
  532. $_ =~ s/&%%CSRF%%/$FW_CSRF/;
  533. $_ =~ s/#&%/,/g;
  534. $ret .= "<font color='$colors[$loglevel-1]'><b>" . $loglevel . "</b></font> - " . $_ . "<br>";
  535. }
  536. return "<html>" . $ret . "</html>";
  537. }
  538. elsif ( $a[1] eq "log" ) {
  539. return "No Filename given" if ( !defined( $a[2] ) );
  540. # extract the filename from given argument (in case it comes with path)
  541. my $gf = $a[2];
  542. if ( $gf =~ m,^(.*)/([^/]*)$, ) {
  543. $gf = $2;
  544. }
  545. my $path = freezemon_getLogPath($name);
  546. # Build the complete path (using global logfile parameter if necessary)
  547. $path = "$path/$gf";
  548. if ( !open( my $fh, $path ) ) {
  549. return "Couldn't open $path";
  550. }
  551. else {
  552. my $ret = "<html><br><a name='top'></a><a href='#end_of_file'>jump to the end</a><br><br>";
  553. while ( my $row = <$fh> ) {
  554. $ret .= $row . "<br>";
  555. }
  556. $ret .= "<br><a name='end_of_file'></a><a href='#top'>jump to the top</a><br/><br/></html>";
  557. return $ret;
  558. }
  559. }
  560. # return usage hint
  561. else {
  562. return $usage;
  563. }
  564. return undef;
  565. }
  566. ###################################
  567. sub freezemon_Attr($) {
  568. my ( $cmd, $name, $aName, $aVal ) = @_;
  569. my $hash = $defs{$name};
  570. # $cmd can be "del" or "set"
  571. # $name is device name
  572. # aName and aVal are Attribute name and value
  573. #Log3 $name, 3, "$cmd $aName $aVal";
  574. if ( $cmd eq "set" ) {
  575. if ( $aName eq "fm_forceApptime" ) {
  576. if ( $aVal > 1 or $aVal < 0 ) {
  577. Log3 $name, 3, "$name: $aName is either 0 or 1: $aVal";
  578. return "Attribute " . $aName . " is either 0 or 1";
  579. }
  580. }
  581. elsif ( $aName eq "fm_freezeThreshold" ) {
  582. if ( !looks_like_number($aVal) ) {
  583. return "Attribute " . $aName . " has to be a number (seconds) ";
  584. }
  585. }
  586. elsif ( $aName eq "fm_logKeep" ) {
  587. if ( !looks_like_number($aVal) or $aVal <= 0 ) {
  588. return "Attribute " . $aName . " has to be a number > 0";
  589. }
  590. }
  591. elsif ( $aName eq "fm_logFile" ) {
  592. if ( $aVal ne "" ) {
  593. $aVal =~ m,^(.*)/([^/]*)$,;
  594. my $path = $1;
  595. $path =~ s/%L/$attr{global}{logdir}/g if ( $path =~ m/%/ && $attr{global}{logdir} );
  596. if ( opendir( DH, $path ) ) {
  597. freezemon_install_log_wrapper($hash);
  598. closedir(DH);
  599. }
  600. else {
  601. return "Attribute " . $aName . ": $path is not a valid directory";
  602. }
  603. }
  604. else {
  605. return "Attribute " . $aName . ": Enter a valid path or delete the attribute to disable.";
  606. }
  607. }
  608. elsif ( $aName eq "fm_CatchFnCalls" ) {
  609. if ( $aVal ne 0 ) {
  610. freezemon_install_callFn_wrapper($hash);
  611. }
  612. else {
  613. Log3( "", 0, "[Freezemon] $name: Unwrapping CallFn" );
  614. {
  615. no warnings;
  616. *main::CallFn = $hash->{helper}{mycallFn};
  617. }
  618. }
  619. }
  620. elsif ( $aName eq "fm_CatchCmds" ) {
  621. if ( $aVal ne 0 ) {
  622. freezemon_install_analyzeCommand_wrapper($hash);
  623. }
  624. elsif ( exists( $hash->{helper}{analyzeCommand} ) ) {
  625. Log3( "", 0, "[Freezemon] $name: Unwrapping analyzeCommand" );
  626. {
  627. #no warnings;
  628. *main::AnalyzeCommand = $hash->{helper}{analyzeCommand};
  629. }
  630. }
  631. else {
  632. Log3( "", 0, "[Freezemon] $name: Unwrapping analyzeCommand - nothing to do" );
  633. }
  634. }
  635. elsif ( $aName eq "disable" ) {
  636. if ( $aVal == 1 ) {
  637. RemoveInternalTimer($hash);
  638. readingsSingleUpdate( $hash, "state", "inactive", 1 );
  639. $hash->{helper}{DISABLED} = 1;
  640. freezemon_unwrap_all($hash);
  641. }
  642. elsif ( $aVal == 0 ) {
  643. freezemon_start($hash);
  644. }
  645. }
  646. }
  647. elsif ( $cmd eq "del" ) {
  648. if ( $aName eq "disable" ) {
  649. freezemon_start($hash);
  650. }
  651. elsif ( $aName eq "fm_logFile" ) {
  652. my $status = Log3( "", 100, "" );
  653. Log3( "", 0, "[Freezemon] $name: Unwrapping Log3" );
  654. *main::Log3 = $hash->{helper}{Log3};
  655. }
  656. elsif ( $aName eq "fm_CatchFnCalls" ) {
  657. Log3( "", 0, "[Freezemon] $name: Unwrapping CallFn" );
  658. {
  659. no warnings;
  660. *main::CallFn = $hash->{helper}{mycallFn};
  661. }
  662. }
  663. elsif ( $aName eq "fm_CatchCmds" ) {
  664. Log3( "", 0, "[Freezemon] $name: Unwrapping AnalyzeCommand" );
  665. {
  666. no warnings;
  667. *main::AnalyzeCommand = $hash->{helper}{analyzeCommand};
  668. }
  669. }
  670. }
  671. return undef;
  672. }
  673. ###################################
  674. # Helper Functions #
  675. ###################################
  676. ###################################
  677. sub freezemon_start($) {
  678. my ($hash) = @_;
  679. my $name = $hash->{NAME};
  680. if ( exists( $hash->{helper}{DISABLED} )
  681. and $hash->{helper}{DISABLED} == 1 )
  682. {
  683. readingsSingleUpdate( $hash, "state", "initialized", 0 );
  684. freezemon_install_log_wrapper($hash) if AttrVal( $name, "fm_logFile", "" ) ne "";
  685. freezemon_install_callFn_wrapper($hash) if AttrVal( $name, "fm_CatchFnCalls", 0 ) == 1;
  686. freezemon_install_analyzeCommand_wrapper($hash) if AttrVal( $name, "fm_CatchCmds", 0 ) == 1;
  687. }
  688. $hash->{helper}{DISABLED} = 0;
  689. my $next = int( gettimeofday() ) + 1;
  690. $hash->{helper}{TIMER} = $next;
  691. InternalTimer( $next, 'freezemon_ProcessTimer', $hash, 0 );
  692. Log3 $name, 2,
  693. "[Freezemon] $name: ready to watch out for delays greater than "
  694. . AttrVal( $name, "fm_freezeThreshold", 1 )
  695. . " second(s)";
  696. if ( AttrVal( $name, "fm_logExtraSeconds", undef ) ) {
  697. Log3 $name, 1,
  698. "[Freezemon] $name: Attribute fm_logExtraSeconds is deprecated and not considered anymore by Freezemon. Please delete the attribute.";
  699. }
  700. }
  701. ###################################
  702. sub freezemon_apptime($) {
  703. my ($hash) = @_;
  704. my $name = $hash->{NAME};
  705. my $ret = "";
  706. my ( $fn, $tim, $cv, $fnname, $arg, $shortarg );
  707. if (%prioQueues) {
  708. foreach my $prio ( keys %prioQueues ) {
  709. foreach my $entry ( @{ $prioQueues{$prio} } ) {
  710. #Log3 $name, 5, "Freezemon: entry is ".Dumper($entry);
  711. $cv = svref_2object( $entry->{fn} );
  712. $fnname = $cv->GV->NAME;
  713. $ret .= $fnname;
  714. $shortarg = ( defined( $entry->{arg} ) ? $entry->{arg} : "" );
  715. #Log3 $name, 5, "Freezemon: found a prioQueue arg ".ref($shortarg);
  716. if ( ref($shortarg) eq "HASH" ) {
  717. if ( !defined( $shortarg->{NAME} ) ) {
  718. $shortarg = "N/A";
  719. }
  720. else {
  721. $shortarg = $shortarg->{NAME};
  722. }
  723. }
  724. elsif ( ref($shortarg) eq "ARRAY" ) {
  725. $shortarg = $entry->{arg};
  726. }
  727. ( $shortarg, undef ) = split( /:|;/, $shortarg, 2 );
  728. $ret .= ":" . $shortarg . " ";
  729. #Log3 $name, 5, "Freezemon: found a prioQueue, returning $ret";
  730. }
  731. }
  732. }
  733. return $ret;
  734. }
  735. ###################################
  736. sub freezemon_getDevice($$) {
  737. my ( $hash, $d ) = @_;
  738. my $name = $hash->{NAME};
  739. my $fn = $d->{FN};
  740. if ( ref($fn) ne "" ) {
  741. my $cv = svref_2object($fn);
  742. my $fnname = $cv->GV->NAME;
  743. return $fnname;
  744. }
  745. my $arg = $d->{ARG};
  746. my $shortarg = ( defined($arg) ? $arg : "" );
  747. if ( ref($shortarg) eq "HASH" ) {
  748. if ( !defined( $shortarg->{NAME} ) ) {
  749. if ( AttrVal( $name, "fm_extDetail", 0 ) == 1 ) {
  750. if ( $fn eq "BlockingKill" or $fn eq "BlockingStart" ) {
  751. $shortarg = $shortarg->{abortArg}{NAME} if defined( $shortarg->{abortArg}{NAME} );
  752. }
  753. elsif ( $fn eq "HttpUtils_Err" ) {
  754. #Log3 $name, 5, "[Freezemon] HttpUtils_Err found" . Dumper($shortarg);
  755. if ( defined( $shortarg->{hash}{hash}{NAME} ) ) {
  756. $shortarg = $shortarg->{hash}{hash}{NAME};
  757. }
  758. }
  759. elsif ( $fn = "FileLog_dailySwitch" ) {
  760. $shortarg = $shortarg->{NotifyFn};
  761. }
  762. else {
  763. #Log3 $name, 5, "[Freezemon] $name found something without a name $fn" . Dumper($shortarg);
  764. $shortarg = "N/A";
  765. }
  766. }
  767. else {
  768. $shortarg = "N/A";
  769. }
  770. }
  771. else {
  772. $shortarg = $shortarg->{NAME};
  773. }
  774. }
  775. elsif ( ref($shortarg) eq "REF" ) {
  776. if ( $fn eq "DOIF_TimerTrigger" ) {
  777. my $deref = ${$arg}; #seems like $arg is a reference to a scalar which in turm is a reference to a hash
  778. $shortarg = $deref->{'hash'}{NAME}; #at least in DOIF_TimerTrigger
  779. }
  780. else {
  781. #Log3 $name, 5, "[Freezemon] $name found a REF $fn " . Dumper( ${$arg} );
  782. }
  783. }
  784. else {
  785. #Log3 $name, 3, "[Freezemon] $name found something that's not a HASH $fn ".ref($shortarg)." ".Dumper($shortarg);
  786. $shortarg = "N/A";
  787. }
  788. if ( !defined($shortarg) ) {
  789. #Log3 $name, 5, "Freezemon: something went wrong $fn " . Dumper($arg);
  790. $shortarg = "";
  791. }
  792. else {
  793. ( $shortarg, undef ) = split( /:|;/, $shortarg, 2 );
  794. }
  795. return $shortarg;
  796. }
  797. ###################################
  798. sub freezemon_unwrap_all($) {
  799. my ($hash) = @_;
  800. my $name = $hash->{NAME};
  801. Log3( "", 0, "[Freezemon] $name: Unwrapping CallFn" );
  802. {
  803. no warnings;
  804. *main::CallFn = $hash->{helper}{mycallFn} if defined( $hash->{helper}{mycallFn} );
  805. }
  806. Log3( "", 0, "[Freezemon] $name: Unwrapping analyzeCommand" );
  807. {
  808. no warnings;
  809. *main::AnalyzeCommand = $hash->{helper}{analyzeCommand} if defined( $hash->{helper}{analyzeCommand} );
  810. }
  811. my $status = Log3( "", 100, "" );
  812. Log3( "", 0, "[Freezemon] $name: Unwrapping Log3" );
  813. {
  814. no warnings;
  815. *main::Log3 = $hash->{helper}{Log3} if defined( $hash->{helper}{Log3} );
  816. }
  817. }
  818. ###################################
  819. sub freezemon_callFn($@) {
  820. my ( $lfn, @args ) = @_;
  821. # take current time, then immediately call the original function
  822. my $t0 = [gettimeofday];
  823. my $result = $lfn->(@args);
  824. my $ms = tv_interval($t0);
  825. my $d = $args[0];
  826. my $n = $args[1];
  827. if ( $ms >= 0.5 ) {
  828. push @fmFn, [ $n, $d ];
  829. #$fm_fn .= "$n:$d ";
  830. Log3 undef, 3, "[Freezemon] Long function call detected $n:$d - $ms seconds";
  831. }
  832. return $result;
  833. }
  834. ###################################
  835. sub freezemon_analyzeCommand($$$;$) {
  836. my ( $lfn, $cl, $cmd, $cfc ) = @_;
  837. # take current time, then immediately call the original function
  838. my $t0 = [gettimeofday];
  839. my $result = $lfn->( $cl, $cmd, $cfc );
  840. my $ms = tv_interval($t0);
  841. my $d = "";
  842. my $n = $cmd;
  843. if ( exists( $cl->{SNAME} ) ) {
  844. $d = $cl->{SNAME};
  845. }
  846. else {
  847. $d = "Command";
  848. }
  849. if ( $ms >= 0.5 ) {
  850. push @fmCmd, [ $n, $d ];
  851. #$fm_fn .= "$n:$d ";
  852. Log3 undef, 3, "[Freezemon] Long running Command detected $n:$d - $ms seconds";
  853. }
  854. return $result;
  855. }
  856. ###################################
  857. sub freezemon_checkCallFnWrap() {
  858. return "freezemon called";
  859. }
  860. ###################################
  861. sub freezemon_Log3($$$$) {
  862. my ( $lfn, $dev, $loglevel, $text ) = @_;
  863. # take current time, then immediately call the original log function
  864. my ( $seconds, $microseconds ) = gettimeofday();
  865. my $result = $lfn->( $dev, $loglevel, $text );
  866. my @entry = ( $seconds + $microseconds * 1e-6, $dev, $loglevel, $text );
  867. push( @logqueue, \@entry ) unless ( $loglevel > 5 );
  868. # print LOG "logqueue has now ".(scalar @logqueue)." entries";
  869. return $result;
  870. }
  871. ###################################
  872. sub freezemon_wrap_callFn($) {
  873. my ($fn) = @_;
  874. return sub(@) {
  875. my @a = @_;
  876. return "already wrapped" if $a[1] eq "freezemon_checkCallFnWrap";
  877. return freezemon_callFn( $fn, @a );
  878. }
  879. }
  880. ###################################
  881. sub freezemon_wrap_analyzeCommand($) {
  882. my ($fn) = @_;
  883. return sub($$;$) {
  884. my ( $cl, $cmd, $cfc ) = @_;
  885. return "already wrapped" if ( defined($cl) && $cl eq "freezemon" );
  886. #return $fn if ( $b == 100 );
  887. return freezemon_analyzeCommand( $fn, $cl, $cmd, $cfc );
  888. }
  889. }
  890. ###################################
  891. sub freezemon_wrap_Log3($) {
  892. my ($fn) = @_;
  893. return sub($$$) {
  894. my ( $a, $b, $c ) = @_;
  895. return "already wrapped" if ( $b == 99 );
  896. return $fn if ( $b == 100 );
  897. return freezemon_Log3( $fn, $a, $b, $c );
  898. }
  899. }
  900. ###################################
  901. #AnalyzeCommand($$;$)
  902. sub freezemon_install_analyzeCommand_wrapper($;$) {
  903. my ( $hash, $nolog ) = @_;
  904. my $name = $hash->{NAME};
  905. $name = "FreezeMon" unless defined($name);
  906. my $status = AnalyzeCommand( "freezemon", "" );
  907. if ( !defined($status) || $status ne "already wrapped" ) {
  908. $hash->{helper}{mycallFn} = \&AnalyzeCommand;
  909. Log3( "", 3, "[Freezemon] $name: Wrapping AnalyzeCommand" );
  910. {
  911. no warnings;
  912. *main::AnalyzeCommand = freezemon_wrap_analyzeCommand( \&AnalyzeCommand );
  913. }
  914. }
  915. elsif ( !defined($nolog) ) {
  916. Log3 $name, 5, "[Freezemon] $name: AnalyzeCommand already wrapped";
  917. }
  918. }
  919. ###################################
  920. sub freezemon_install_callFn_wrapper($;$) {
  921. my ( $hash, $nolog ) = @_;
  922. my $name = $hash->{NAME};
  923. $name = "FreezeMon" unless defined($name);
  924. my $status = CallFn( $name, "freezemon_checkCallFnWrap" );
  925. if ( !defined($status) || $status ne "already wrapped" ) {
  926. $hash->{helper}{mycallFn} = \&CallFn;
  927. Log3( "", 3, "[Freezemon] $name: Wrapping CallFn" );
  928. {
  929. no warnings;
  930. *main::CallFn = freezemon_wrap_callFn( \&CallFn );
  931. }
  932. }
  933. elsif ( !defined($nolog) ) {
  934. Log3 $name, 5, "[Freezemon] $name: CallFn already wrapped";
  935. }
  936. }
  937. ###################################
  938. sub freezemon_install_log_wrapper($) {
  939. my ($hash) = @_;
  940. my $name = $hash->{NAME};
  941. $name = "FreezeMon" unless defined($name);
  942. my $status = Log3( "", 99, "" );
  943. if ( !defined($status) || $status ne "already wrapped" ) {
  944. Log3( "", 3, "[Freezemon] $name: Wrapping Log3" );
  945. $hash->{helper}{Log3} = \&Log3;
  946. {
  947. no warnings;
  948. *main::Log3 = freezemon_wrap_Log3( \&Log3 );
  949. }
  950. }
  951. else {
  952. Log3 $name, 5, "[Freezemon] $name: Log3 is already wrapped";
  953. }
  954. }
  955. ###################################
  956. sub freezemon_purge_log_before($$) {
  957. my ( $hash, $before ) = @_;
  958. my $name = $hash->{NAME};
  959. my @t = localtime($before);
  960. my $tim = sprintf( "%04d.%02d.%02d %02d:%02d:%02d.%03d", $t[5] + 1900, $t[4] + 1, $t[3], $t[2], $t[1], $t[0], 0 );
  961. #Log3 $hash, 5, "[Freezemon] $name: purging log entries before $tim.";
  962. my $cnt = 0;
  963. while ( scalar @logqueue > 0 && $logqueue[0]->[0] < $before ) {
  964. shift @logqueue;
  965. $cnt += 1;
  966. }
  967. #Log3 $hash, 5, "[Freezemon] $name: $cnt entries purged from logqueue, size is now ".(scalar @logqueue);
  968. }
  969. ###################################
  970. sub freezemon_dump_log2($$$$) {
  971. my ( $name, $msg, $logfile, $queue ) = @_;
  972. #my $name = $hash->{NAME};
  973. #my @queue = @{ $hash->{helper}{logqueue} };
  974. return unless scalar @$queue;
  975. my ( $seconds, $microseconds ) = gettimeofday();
  976. my $currlogfile = $logfile;
  977. return unless defined($currlogfile) && $currlogfile ne "";
  978. Log3 $name, 4, "[Freezemon] $name: dumping " . ( scalar @$queue ) . " log entries to $currlogfile";
  979. open( fm_LOG, ">>$currlogfile" ) || return ("Can't open $currlogfile: $!");
  980. print fm_LOG "=========================================================\n";
  981. print fm_LOG $msg . "\n";
  982. my $last_ts;
  983. foreach my $entry (@$queue) {
  984. my ( $ts, $dev, $loglevel, $text ) = @$entry;
  985. my $seconds = int($ts);
  986. my $microseconds = int( 1e6 * ( $ts - $seconds ) );
  987. $dev = $dev->{NAME} if ( defined($dev) && ref($dev) eq "HASH" );
  988. #next if ( defined($dev) && ( $dev eq $name ) );
  989. my @t = localtime($seconds);
  990. my $tim = sprintf(
  991. "%04d.%02d.%02d %02d:%02d:%02d.%03d",
  992. $t[5] + 1900,
  993. $t[4] + 1,
  994. $t[3], $t[2], $t[1], $t[0], $microseconds / 1000
  995. );
  996. printf fm_LOG "--- log skips %9.3f secs.\n", $ts - $last_ts if ( defined($last_ts) && $ts - $last_ts > 1 );
  997. print fm_LOG "$tim $loglevel: $text\n";
  998. $last_ts = $ts;
  999. }
  1000. print fm_LOG $msg . "\n";
  1001. close(fm_LOG);
  1002. return $currlogfile;
  1003. }
  1004. ###################################
  1005. sub freezemon_dump_log($$$) {
  1006. my ( $hash, $start, $msg ) = @_;
  1007. my $name = $hash->{NAME};
  1008. my @queue = @{ $hash->{helper}{logqueue} };
  1009. return unless scalar @queue;
  1010. my ( $seconds, $microseconds ) = gettimeofday();
  1011. my $currlogfile = $hash->{helper}{logfile};
  1012. return unless defined($currlogfile) && $currlogfile ne "";
  1013. Log3 $name, 4, "[Freezemon] $name: dumping " . ( scalar @queue ) . " log entries to $currlogfile";
  1014. open( fm_LOG, ">>$currlogfile" ) || return ("Can't open $currlogfile: $!");
  1015. print fm_LOG "=========================================================\n";
  1016. print fm_LOG $msg . "\n";
  1017. my $last_ts;
  1018. foreach my $entry (@queue) {
  1019. my ( $ts, $dev, $loglevel, $text ) = @$entry;
  1020. my $seconds = int($ts);
  1021. my $microseconds = int( 1e6 * ( $ts - $seconds ) );
  1022. $dev = $dev->{NAME} if ( defined($dev) && ref($dev) eq "HASH" );
  1023. #next if ( defined($dev) && ( $dev eq $name ) );
  1024. my @t = localtime($seconds);
  1025. my $tim = sprintf(
  1026. "%04d.%02d.%02d %02d:%02d:%02d.%03d",
  1027. $t[5] + 1900,
  1028. $t[4] + 1,
  1029. $t[3], $t[2], $t[1], $t[0], $microseconds / 1000
  1030. );
  1031. printf fm_LOG "--- log skips %9.3f secs.\n", $ts - $last_ts if ( defined($last_ts) && $ts - $last_ts > 1 );
  1032. print fm_LOG "$tim $loglevel: $text\n";
  1033. $last_ts = $ts;
  1034. }
  1035. print fm_LOG $msg . "\n";
  1036. close(fm_LOG);
  1037. return $currlogfile;
  1038. }
  1039. ###################################
  1040. sub freezemon_logLink($$) {
  1041. my ( $name, $link ) = @_;
  1042. return "" if !$link;
  1043. my $ret = "<a href='$FW_ME?cmd=" . urlEncode("get $name log $link") . "&%%CSRF%%'> [Log]</a>";
  1044. return $ret;
  1045. }
  1046. ###################################
  1047. sub freezemon_getLogFiles($;$) {
  1048. my ( $name, $reverse ) = @_;
  1049. my @fl;
  1050. my $path = freezemon_getLogPath($name);
  1051. return @fl if ( !$path );
  1052. my $lf = AttrVal( $name, "fm_logFile", "" );
  1053. $lf =~ m,^(.*)/([^/%]*).*$,;
  1054. my $pattern = $2;
  1055. if ( opendir( DH, $path ) ) {
  1056. while ( my $f = readdir(DH) ) {
  1057. push( @fl, $f ) if ( $f =~ /$pattern.*/ );
  1058. }
  1059. closedir(DH);
  1060. if ( !$reverse ) {
  1061. @fl = sort { ( CORE::stat("$path/$b") )[9] <=> ( CORE::stat("$path/$a") )[9] } @fl;
  1062. }
  1063. else {
  1064. @fl = sort { ( CORE::stat("$path/$a") )[9] <=> ( CORE::stat("$path/$b") )[9] } @fl;
  1065. }
  1066. }
  1067. return @fl;
  1068. }
  1069. ###################################
  1070. sub freezemon_getLogPath($) {
  1071. my ($name) = @_;
  1072. my $lf = AttrVal( $name, "fm_logFile", "" );
  1073. return undef if $lf eq "";
  1074. $lf =~ m,^(.*)/([^/%]*).*$,;
  1075. my $path = $1;
  1076. $path =~ s/%L/$attr{global}{logdir}/g if ( $path =~ m/%/ && $attr{global}{logdir} );
  1077. return $path;
  1078. }
  1079. 1;
  1080. =pod
  1081. =item helper
  1082. =item summary An adjusted version of PERFMON that helps detecting freezes
  1083. =item summary_DE Eine angepasste Version von PERFMON, die beim Erkennen von freezes hilft
  1084. =begin html
  1085. <a name="freezemon"></a>
  1086. <h3>freezemon</h3>
  1087. <div>
  1088. <ul>
  1089. FREEZEMON monitors - similar to PERFMON possible freezes, however FREEZEMON is a real module, hence it has:<br><br>
  1090. <ul>
  1091. <li>Readings - which might be logged for easier analysis</li>
  1092. <li>Attributes - to influence the behaviour of the module</li>
  1093. <li>additional functionality - which tries to identify the device causing the freeze</li>
  1094. </ul>
  1095. It's recommended to deactivate PERFMON once FREEZEMON is active. They anyways detect the same freezes thus everything would be duplicated.<br><br>
  1096. <b>Please note!</b> FREEZEMON just does an educated guess, which device could have caused the freeze based on timers that were supposed to run. There might be a lot of other factors (internal or external) causing freezes. FREEZEMON doesn't replace a more detailed analysis. The module just tries to give you some hints what could be optimized.<br><br>
  1097. <a name="freezemonDefine"></a>
  1098. <b>Define</b>
  1099. <ul>
  1100. FREEZEMON will be defined without Parameters.
  1101. <br><br>
  1102. <code>define &lt;devicename&gt; freezemon</code><br><br>
  1103. With that freezemon is active (and you should see a message in the log) <br><br>
  1104. </ul>
  1105. <a name="freezemonSet"></a>
  1106. <b>Set</b>
  1107. <ul>
  1108. <ul>
  1109. <li>inactive: disables the device (similar to attribute "disable", however without the need to save</li>
  1110. <li>active: reactivates the device after it was set inactive</li>
  1111. <li>clear: clears all readings (including the list of the last 20 freezes.)</li>
  1112. </ul>
  1113. </ul>
  1114. <a name="freezemonGet"></a>
  1115. <b>Get</b>
  1116. <ul>
  1117. <ul>
  1118. <li>freeze: returns the last 20 (in compact view, like in state) - This is for a quick overview. For detailed analysis the data should be logged.</li>
  1119. <li>log: provides direct access to the logfiles written when fm_logFile is active</li>
  1120. </ul>
  1121. </ul>
  1122. <a name="freezemonReadings"></a>
  1123. <b>Readings</b>
  1124. <ul>
  1125. <ul>
  1126. <li>freezeTime: Duration of the freeze</li>
  1127. <li>freezeDevice: List of functions(Devices) that possibly caused the freeze</li>
  1128. <li>fcDay: cumulated no. of freezes per day</li>
  1129. <li>ftDay: cumulated duration of freezes per day</li>
  1130. <li>fcDayLast: stores cumulated no. of freezes of the last day (for daily plots)</li>
  1131. <li>fcDayLast: stores cumulated duration of freezes of the last day (for daily plots)</li>
  1132. <li>state: s:&lt;startTime&gt; e:&lt;endTime&gt; f:&lt;Duration&gt; d:&lt;Devices&gt;</li>;
  1133. </ul>
  1134. </ul>
  1135. <a name="freezemonAttributes"></a>
  1136. <b>Attributes</b>
  1137. <ul>
  1138. <ul>
  1139. <li>fm_catchCallFn: if enabled FHEM internal function calls are monitored additionally, in some cases this might give additional hints on who's causing the freeze </li>
  1140. <li>fm_catchCmds: if enabled FHEM commands are monitored additionally, in some cases this might give additional hints on who's causing the freeze </li>
  1141. <li>fm_extDetail: provides in some cases extended details for recognized freezes. In some cases it was reported that FHEM crashes, so please be careful.</li>
  1142. <li>fm_freezeThreshold: Value in seconds (Default: 1) - Only freezes longer than fm_freezeThreshold will be considered as a freeze</li>
  1143. <li>fm_forceApptime: When FREEZEMON is active, apptime will automatically be started (if not yet active)</li>
  1144. <li>fm_ignoreDev: list of comma separated Device names. If all devices possibly causing a freeze are in the list, the freeze will be ignored (not logged)</li>
  1145. <li>fm_ignoreMode: takes the values off,single or all. If you have added devices to fm_ignoreDev then ignoreMode acts as follows: <br>
  1146. all: A freeze will only be ignored, if all devices probably causing the freeze are part of the ignore list. This might result in more freezes being logged than expected.<br>
  1147. single: A freeze will be ignored as soon as one device possibly causing the freeze is listed in the ignore list. With this setting you might miss freezes.<br>
  1148. off: All freezes will be logged.<br>
  1149. If the attribute is not set, while the ignore list is maintained, mode "all" will be used.</li>
  1150. <li>fm_log: dynamic loglevel, takes a string like 10:1 5:2 1:3 , which means: freezes > 10 seconds will be logged with loglevel 1 , >5 seconds with loglevel 2 etc...</li>
  1151. <li>fm_logFile: takes a valid file name (like e.g. ./log/freeze-%Y%m%d-%H%M%S.log). If set, logs messages of loglevel 5 (even if global loglevel is < 5) before a freeze in separate file.</li>
  1152. <li>fm_logExtraSeconds: obsolete attribute, not used anymore and should be deleted.</li>
  1153. <li>fm_logKeep: A number that defines how many logFiles should be kept. If set all logfiles except the latest n freezemon logfiles will be deleted regularly.</li>
  1154. <li>fm_whitelistSub: Comma-separated list of subroutines that you're sure that don't cause a freeze. Whitelisted Subs do not appear in the "possibly caused by" list. Typically you would list subroutines here that frequently appear in the "possibly caused by" list, but you're really sure they are NOT the issue. Note: The subroutine is the initial part (before the devicename in brackets) in freezemon log messages. </li>
  1155. <li>disable: activate/deactivate freeze detection</li>
  1156. </ul>
  1157. </ul>
  1158. </ul>
  1159. </div>
  1160. =end html
  1161. =begin html_DE
  1162. <a name="freezemon"></a>
  1163. <h3>freezemon</h3>
  1164. <div>
  1165. <ul>
  1166. FREEZEMON Überwacht - Ähnlich wie PERFMON mögliche Freezes, allerdings ist FREEZEMON ein echtes Modul und hat daher:<br>
  1167. <ul>
  1168. <li>Readings - die geloggt werden können und damit viel einfacher ausgewertet werden können</li>
  1169. <li>Attribute - mit denen das Verhalten von freezemon beeinflusst werden kann</li>
  1170. <li>zusätzliche Funktionalität - die versucht das den Freeze verursachende Device zu identifizieren</li>
  1171. </ul>
  1172. Ich würde empfehlen, PERFMON zu deaktivieren, wenn FREEZEMON aktiv ist, da beide auf die selbe Art Freezes erkennen und dann nur alles doppelt kommt.
  1173. <b>Bitte beachten!</b> FREEZEMON versucht nur intelligent zu erraten, welches Device einen freeze verursacht haben könnte (basierend auf den Timern die laufen sollten). Es gibt eine Menge anderer Faktoren (intern oder extern) die einen Freeze verursachen können. FREEZEMON ersetzt keine detaillierte Analyse. Das Modul versucht nur Hinweise zu geben, was optimiert werden könnte.<br><br>
  1174. <br>
  1175. <br>
  1176. <a name="freezemonDefine"></a>
  1177. <b>Define</b>
  1178. <ul>
  1179. FREEZEMON wird ohne Parameter definiert.<br><br>
  1180. <code>define &lt;devicename&gt; freezemon</code><br><br>
  1181. damit ist der Freezemon aktiv (im Log sollte eine entsprechende Meldung geschrieben werden)
  1182. <br><br>
  1183. </ul>
  1184. <a name="freezemonSet"></a>
  1185. <b>Set</b>
  1186. <ul>
  1187. <ul>
  1188. <li>inactive: deaktiviert das Device (identisch zum Attribut "disable", aber ohne die Notwendigkeit su "saven".</li>
  1189. <li>active: reaktiviert das Device nachdem es auf inactive gesetzt wurde</li>
  1190. <li>clear: Löscht alle readings (inklusive der Liste der letzten 20 Freezes).</li>
  1191. </ul>
  1192. </ul>
  1193. <a name="freezemonGet"></a>
  1194. <b>Get</b>
  1195. <ul>
  1196. <ul>
  1197. <li>freeze: gibt die letzten 20 freezes zurück (in Kompakter Darstellung, wie im state) - Dies dient einem schnellen Überblick, für detailliertere Auswertungen empfehle ich die Daten zu loggen.</li>
  1198. <li>log: gibt Zugriff auf die Logfiles die geschrieben werden, wenn fm_logFile aktiv ist</li>
  1199. </ul>
  1200. </ul>
  1201. <a name="freezemonReadings"></a>
  1202. <b>Readings</b>
  1203. <ul>
  1204. <ul>
  1205. <li>freezeTime: Dauer des Freezes</li>
  1206. <li>freezeDevice: Liste von möglicherweise den Freeze auslösenden Funktionen(Devices)</li>
  1207. <li>fcDay: kumulierte Anzahl der Freezes pro Tag</li>
  1208. <li>ftDay: kumulierte Dauer der Freezes pro Tag </li>
  1209. <li>fcDayLast: speichert die kumulierte Anzahl der Freezes des vergangenen Tages (um tageweise plots zu erstellen)</li>
  1210. <li>fcDayLast: speichert die kumulierte Dauer der Freezes des vergangenen Tages (um tageweise plots zu erstellen)</li>
  1211. <li>state: s:&lt;StartZeit&gt; e:&lt;EndeZeit&gt; f:&lt;Dauer&gt; d:&lt;Devices&gt;</li>
  1212. </ul>
  1213. </ul>
  1214. <a name="freezemonAttributes"></a>
  1215. <b>Attribute</b>
  1216. <ul>
  1217. <ul>
  1218. <li>fm_catchCallFn: wenn aktiviert, werden zusätzlich FHEM-interne Funktionsaufrufe überwacht, in einigen Fällen kann das zusätzliche Hinweise auf den Freeze-Verursacher geben</li>
  1219. <li>fm_catchCmds: wenn aktiviert, werden zusätzlich FHEM-Kommandos überwacht, in einigen Fällen kann das zusätzliche Hinweise auf den Freeze-Verursacher geben</li>
  1220. <li>fm_extDetail: stellt in einigen Fällen zusätzliche Details bei erkannten Freezes zur Verfügung. In wenigen Fällen wurde berichtet, dass FHEM crasht, also vorsichtig verwenden.</li>
  1221. <li>fm_freezeThreshold: Wert in Sekunden (Default: 1) - Nur Freezes länger als fm_freezeThreshold werden als Freeze betrachtet </li>
  1222. <li>fm_forceApptime: Wenn FREEZEMON aktiv ist wird automatisch apptime gestartet (falls nicht aktiv)</li>
  1223. <li>fm_ignoreDev: Liste von Komma-getrennten Devices. Wenn einzelne möglicherweise einen Freeze verursachenden Device in dieser Liste sind, wird der Freeze ignoriert (nicht geloggt). Bitte das Attribut fm_ignoreMode beachten</li>
  1224. <li>fm_ignoreMode: Kann die Werte off,single oder all annehmen. Wenn in fm_ignoreDev Devices angegeben sind wirken sich der ignoreMode wie folgt aus: <br>
  1225. all: Ein Freeze wird nur dann ignoriert, wenn alle möglicherweise den Freeze verursachenden Devices in der Ignore-Liste enthalten sind. Dies führt unter Umständen dazu, dass mehr Freezes geloggt werden als erwartet.<br>
  1226. single: Ein Freeze wird ignoriert, sobald ein möglicher Verursacher in der Ignorierliste enthalten ist. Dies führt möglicherweise dazu, dass Freezes übersehen werden.<br>
  1227. off: Alle Freezes werden geloggt.<br>
  1228. Sofern das Attribut nicht gesetzt ist, aber Ignore-Devices angegeben sind, wird im Modus "all" ignoriert.</li>
  1229. <li>fm_log: dynamischer Loglevel, nimmt einen String der Form 10:1 5:2 1:3 entgegen, was bedeutet: Freezes > 10 Sekunden werden mit Loglevel 1 geloggt, >5 Sekunden mit Loglevel 2 usw...</li>
  1230. <li>fm_logFile: ist ein gültiger Filename (wie z.B. ./log/freeze-%Y%m%d-%H%M%S.log). Wenn gesetzt, werdn Meldungen auf Loglevel 5 (auch wenn global Loglevel < 5 ist) vor einem Freeze in einem seperaten File geloggt.</li>
  1231. <li>fm_logExtraSeconds: dobsoletes Attribut, wird nicht mehr genutzt und sollte gelöscht werden</li>
  1232. <li>fm_logKeep: Eine Zahl, die angibt wieviele Logfiles behalten werden sollen. Wenn gesetzt, werden alle Logfiles ausser den letzten n Freezemon Logfiles regelmäßig gelöscht.</li>
  1233. <li>fm_whitelistSub: Komma-getrennte Liste von Subroutinen wo du sicher bist, dass sie keinen Freeze verursachen. Whitelisted Subs erscheinen nicht in der "possibly caused by" Liste. Typischerweise listet man hier Subroutinen, die regelmäßig in der "possibly caused by" Liste auftauchen, wo du aber wirklich sicher bist, dass sie nicht die Ursache sind. Anmerkung: Die Subroutine ist der initiale Teil (vor dem devicename in Klammern) in Freezemon Logmeldungen.</li>
  1234. <li>disable: aktivieren/deaktivieren der Freeze-Erkennung</li>
  1235. </ul>
  1236. </ul>
  1237. </ul>
  1238. </div>
  1239. =end html_DE
  1240. =cut