Reboot non sollicité du DS918 ...

[bruno78]

Bonjour,

ce matin je viens vers vous car mon ds918 a redémarré cette nuit, tout seul et sans raison apparente. Apparemment le redémarrage s'est par la suite bien déroulé, et il est ce matin parfaitement fonctionnel. Mais que s'est' il passé ??? Je précise qu'il est évidemment sur onduleur, qu'il n'y a pas eu de coupure de courant ni de passage sur onduleur, et qu'il n'y avait pas de tache planifiée à l'heure du redémarrage.

Ci dessous le journal :

Niveau	Journal	Heure	Utilisateur	Evénement
Information	Système	2020/07/15 00:00:33	SYSTEM	[Synology Drive Server] service was started.
Information	Système	2020/07/14 23:59:28	SYSTEM	[Cloud Sync] service was started.
Warning	Système	2020/07/14 23:59:16	SYSTEM	System booted up from an improper shutdown.
Information	Système	2020/07/14 23:58:59	SYSTEM	VPN profile [Connection] is connecting to [142.xx.xxx.1]. (protocol[OpenVPN], IP[10.10.10.2], interface[tun0])
Error	Système	2020/07/14 23:58:59	SYSTEM	Failed to send email. (Failed to resolve host address.).
Information	Système	2020/07/14 23:58:30	SYSTEM	IP address [169.254.90.208] and subnet mask [255.255.0.0] were assigned to the DHCP client on [ovs_eth1].
Information	Système	2020/07/14 23:57:49	SYSTEM	Local UPS was plugged in.
Information	Système	2020/07/14 23:57:38	SYSTEM	System started to boot up.
Information	Système	2020/07/14 19:49:02	SYSTEM	VPN profile [Connection] is connecting to [142.xx.xxx.1]. (protocol[OpenVPN], IP[10.10.10.2], interface[tun0])
Warning	Système	2020/07/14 19:48:58	SYSTEM	VPN profile [Connection] was disconnected by server.

Quelles seraient les pistes d'investigations ? quels journaux / logs seraient pertinents à aller vérifier ?

Merci d'avance

Bruno78

PS :

• a priori pas de perte de données, mais il faut que je vérifie plus en détail
• seul point visible : le cache SSD (R/W) est passé d'une utilisation à 93% (depuis plus d'un mois), à seulement 12% .... . Alors qu'a priori lors d'un reboot normal par l'opérateur, de mémoire, on ne perd pas le cache SSD.

PS2 :

j'étais hier en train de faire des tests pour un script automatique de suppression de fichiers logs et sauvegardes, avec essai réel à 1900, or si je regarde le Moniteur de Ressources :

 

=> Il s'est passé un truc bizarre à 1900 ! et pourtant le système répondait normalement .....

Modifié le 15 juillet 2020 par bruno78

[maxou56]

Bonjour, 

C'est quoi les traits rouges sur les captures?

 

Il y a 8 heures, bruno78 a dit :

seul point visible : le cache SSD (R/W) est passé d'une utilisation à 93% (depuis plus d'un mois), à seulement 12% .... . Alors qu'a priori lors d'un reboot normal par l'opérateur, de mémoire, on ne perd pas le cache SSD.

Oui il y a eu quelque chose car le cache en lecture et écriture est persistent (seul le cache en lecture seul est remis à zéro).

 

Il y a 8 heures, bruno78 a dit :

Il s'est passé un truc bizarre à 1900 ! et pourtant le système répondait normalement .....

Oui car il n'a pas sauvegardé le moniteur de ressource, cause possible saturation du CPU ou de la RAM...

Modifié le 15 juillet 2020 par maxou56

[.Shad.]

Peut-être as-tu créé un processus qui bouclait infiniment par une commande ton script, ce qui a amené à ce qu'évoque @maxou56

Tu es allé voir ce que disent /var/log/messages, /var/log/dmesg et /var/log/syslog.log ?

Modifié le 15 juillet 2020 par .Shad.

[bruno78]

Merci @maxou56, @.Shad.,

Les traits rouges je ne sais pas, mais c'est toujours pareil sur un PC particulier avec une vieille version de Firefox. Bug graphique sur le navigateur je suppose

j'ai commencé à regarder /var/log/messages,

• je ne trouve rien d'évident pour le moment  (en fait mes manips ont été faites à 19:42, soit après la perte du moniteur). Rien fait de spécial à 19:00.
• entre 19:00 et 23:58, la où le moniteur de ressources semble planté, le monitoring Grafana ne rapport rien d'anormal.
• 
• 

A 2330 puis 2345, c'est l'antivirus Essentials qui demarre le scan système puis le scan personnalisé

Je vais aller voir les autres logs que vous indiquez.

Merci

Bruno78

[bruno78]

Bonjour,

27557    0 -rw-r--r--  1 root         root                  0 Jul 15 00:57 dmesg
28746   52 -rw-r--r--  1 root         root              49864 Jul 14 23:58 dmesg.1.xz

dmesg est vide, tandis que les fichiers dmesg.{1,2,3,4}.xz sont illisibles.

Quant à /var/log/syslog.log : (l'IP du NAS est 192.168.1.171)

2020-07-14T09:51:43+02:00 ds918blam syslog-ng[4665]: Configuration reload request received, reloading configuration;
2020-07-14T21:55:02+02:00 ds918blam syslog-ng[4665]: Configuration reload request received, reloading configuration;
2020-07-14T23:57:37+02:00 ds918blam syslog-ng[4727]: syslog-ng starting up; version='3.7.3'
2020-07-14T23:57:46+02:00 ds918blam syslog-ng[4727]: Connection failed; fd='33', server='AF_UNIX(/var/run/synologan.sock)', local='AF_UNIX(anonymous)', error='No such file or directory (2)'
2020-07-14T23:57:46+02:00 ds918blam syslog-ng[4727]: Initiating connection failed, reconnecting; time_reopen='10'
2020-07-14T23:57:46+02:00 ds918blam syslog-ng[4727]: Error binding socket; addr='AF_UNIX(/var/packages/DNSServer/target/named/dev/log)', error='No such file or directory (2)'
2020-07-14T23:57:46+02:00 ds918blam syslog-ng[4727]: Connection failed; fd='39', server='AF_INET(192.168.1.171:9527)', local='AF_INET(0.0.0.0:0)', error='Network is unreachable (101)'
2020-07-14T23:57:46+02:00 ds918blam syslog-ng[4727]: Initiating connection failed, reconnecting; time_reopen='10'
2020-07-14T23:57:46+02:00 ds918blam syslog-ng[4727]: Connection failed; fd='39', server='AF_INET(192.168.1.171:9528)', local='AF_INET(0.0.0.0:0)', error='Network is unreachable (101)'
2020-07-14T23:57:46+02:00 ds918blam syslog-ng[4727]: Initiating connection failed, reconnecting; time_reopen='10'
2020-07-14T23:57:46+02:00 ds918blam syslog-ng[4727]: Connection failed; fd='39', server='AF_INET(192.168.1.171:9529)', local='AF_INET(0.0.0.0:0)', error='Network is unreachable (101)'
2020-07-14T23:57:46+02:00 ds918blam syslog-ng[4727]: Initiating connection failed, reconnecting; time_reopen='10'
2020-07-14T23:57:46+02:00 ds918blam syslog-ng[4727]: Connection failed; fd='39', server='AF_INET(192.168.1.171:9526)', local='AF_INET(0.0.0.0:0)', error='Network is unreachable (101)'
2020-07-14T23:57:46+02:00 ds918blam syslog-ng[4727]: Initiating connection failed, reconnecting; time_reopen='10'
2020-07-14T23:57:46+02:00 ds918blam syslog-ng[4727]: Configuration reload request received, reloading configuration;
2020-07-14T23:57:56+02:00 ds918blam syslog-ng[4727]: Connection failed; fd='48', server='AF_UNIX(/var/run/synologan.sock)', local='AF_UNIX(anonymous)', error='No such file or directory (2)'
2020-07-14T23:57:56+02:00 ds918blam syslog-ng[4727]: Initiating connection failed, reconnecting; time_reopen='10'
2020-07-14T23:57:56+02:00 ds918blam syslog-ng[4727]: Syslog connection accepted; fd='52', client='AF_INET(192.168.1.171:34343)', local='AF_INET(0.0.0.0:9527)'
2020-07-14T23:57:56+02:00 ds918blam syslog-ng[4727]: Syslog connection accepted; fd='53', client='AF_INET(192.168.1.171:41453)', local='AF_INET(0.0.0.0:9528)'
2020-07-14T23:57:56+02:00 ds918blam syslog-ng[4727]: Syslog connection accepted; fd='54', client='AF_INET(192.168.1.171:41176)', local='AF_INET(0.0.0.0:9529)'
2020-07-14T23:57:56+02:00 ds918blam syslog-ng[4727]: Syslog connection accepted; fd='55', client='AF_INET(192.168.1.171:41584)', local='AF_INET(0.0.0.0:9526)'
2020-07-14T23:57:56+02:00 ds918blam syslog-ng[4727]: Syslog connection established; fd='48', server='AF_INET(192.168.1.171:9527)', local='AF_INET(0.0.0.0:0)'
2020-07-14T23:57:56+02:00 ds918blam syslog-ng[4727]: Syslog connection established; fd='49', server='AF_INET(192.168.1.171:9528)', local='AF_INET(0.0.0.0:0)'
2020-07-14T23:57:56+02:00 ds918blam syslog-ng[4727]: Syslog connection established; fd='50', server='AF_INET(192.168.1.171:9529)', local='AF_INET(0.0.0.0:0)'
2020-07-14T23:57:56+02:00 ds918blam syslog-ng[4727]: Syslog connection established; fd='51', server='AF_INET(192.168.1.171:9526)', local='AF_INET(0.0.0.0:0)'
2020-07-14T23:58:06+02:00 ds918blam syslog-ng[4727]: Connection failed; fd='40', server='AF_UNIX(/var/run/synologan.sock)', local='AF_UNIX(anonymous)', error='No such file or directory (2)'
2020-07-14T23:58:06+02:00 ds918blam syslog-ng[4727]: Initiating connection failed, reconnecting; time_reopen='10'
2020-07-14T23:58:16+02:00 ds918blam syslog-ng[4727]: Syslog connection established; fd='28', server='AF_UNIX(/var/run/synologan.sock)', local='AF_UNIX(anonymous)'
2020-07-14T23:58:56+02:00 ds918blam syslog-ng[4727]: Transport aux data overflow, some fields may not be associated with the message, please increase aux buffer size; aux_size='1024'
2020-07-14T23:59:04+02:00 ds918blam syslog-ng[4727]: Configuration reload request received, reloading configuration;
2020-07-14T23:59:25+02:00 ds918blam syslog-ng[4727]: Configuration reload request received, reloading configuration;
2020-07-15T00:00:11+02:00 ds918blam syslog-ng: SYSTEM:	Last message 'Configuration reload' repeated 1 times, suppressed by syslog-ng on ds918blam
2020-07-15T00:00:11+02:00 ds918blam syslog-ng[4727]: Configuration reload request received, reloading configuration;
2020-07-15T00:03:33+02:00 ds918blam syslog-ng[4727]: Configuration reload request received, reloading configuration;
2020-07-15T00:03:52+02:00 ds918blam syslog-ng[4727]: Configuration reload request received, reloading configuration;

bizarre bizarre ...

[bruno78]

Bonjour, sur le /var/log/message :

• il ne se passe rien à 1900 : entre 13:42 et 19:48, rien. A 19:48 c'est le VPN qui redemarre (après 24h).

2020-07-14T13:42:01+02:00 ds918blam synoupgrade_SYNO.Core.Upgrade.Server_2_check[20303]: updatechecker.cpp:69 synoinstall: Failed to get security json
2020-07-14T13:42:01+02:00 ds918blam synoupgrade_SYNO.Core.Upgrade.Server_2_check[20303]: updatechecker.cpp:224 synoinstall: Failed to get parser
2020-07-14T19:48:58+02:00 ds918blam synovpnc: connection.c:1530 SLIBCSzHashGetValue(ds_dns) failed
2020-07-14T19:48:58+02:00 ds918blam synonetd: base_hook.cpp:74 Hook environment is not valid
2020-07-14T19:48:58+02:00 ds918blam synovpnc: connection.c:246 Fail to get interface info.
2020-07-14T19:48:58+02:00 ds918blam openvpn[1736]: WARNING: file '/tmp/ovpn_client_up' is group or others accessible
2020-07-14T19:48:58+02:00 ds918blam openvpn[1739]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts

• ensuite à 23:57:37 c'est le reboot alors que l'antivirus a demarré quelques minutes plus tôt

2020-07-14T19:49:15+02:00 ds918blam synomustache: synomustache.cpp:88 Failed to load /var/packages/Spreadsheet/target/etc/Spreadsheet.mustache [No such file or directory]
2020-07-14T19:49:15+02:00 ds918blam synomustache: synomustache.cpp:88 Failed to load /var/packages/Spreadsheet/target/etc/Spreadsheet.mustache [No such file or directory]
2020-07-14T19:49:17+02:00 ds918blam synomustache: SYSTEM:	Last message 'synomustache.cpp:88 ' repeated 1 times, suppressed by syslog-ng on ds918blam
2020-07-14T19:49:17+02:00 ds918blam [3302117.064932] init: scsi_plugin_server main process (6343) killed by TERM signal
2020-07-14T19:57:08+02:00 ds918blam [3302588.061774] init: synoscheduler-vmtouch main process (12602) killed by TERM signal
2020-07-14T23:41:59+02:00 ds918blam synoavscan: synoav_engine.c:122 Initialize engine with 25873
2020-07-14T23:52:57+02:00 ds918blam synoavscan: synoav_engine.c:122 Initialize engine with 25873
2020-07-14T23:57:37+02:00 ds918blam kernel: [    0.000000] ACPI: RSDP 0x000000007AFFE014 000024 (v02 INSYDE)
2020-07-14T23:57:37+02:00 ds918blam kernel: [    0.000000] ACPI: XSDT 0x000000007AFDA188 0000DC (v01 INSYDE INSYDE   00000003      01000013)
2020-07-14T23:57:37+02:00 ds918blam kernel: [    0.000000] ACPI: FACP 0x000000007AFF5000 000114 (v06 INSYDE INSYDE   00000003 ACPI 00040000)
2020-07-14T23:57:37+02:00 ds918blam kernel: [    0.000000] ACPI: DSDT 0x000000007AFE6000 00772B (v02 INSYDE INSYDE   00000003 ACPI 00040000)
2020-07-14T23:57:37+02:00 ds918blam kernel: [    0.000000] ACPI: FACS 0x000000007AFAF000 000040
2020-07-14T23:57:37+02:00 ds918blam kernel: [    0.000000] ACPI: FACS 0x000000007AFAF000 000040
2020-07-14T23:57:37+02:00 ds918blam kernel: SYSTEM:	Last message '[    0.000000] ACPI:' repeated 1 times, suppressed by syslog-ng on ds918blam
2020-07-14T23:57:37+02:00 ds918blam kernel: [    0.000000] ACPI: UEFI 0x000000007AFFD000 000236 (v01 INSYDE INSYDE   00000001 ACPI 00040000)
2020-07-14T23:57:37+02:00 ds918blam kernel: [    0.000000] ACPI: BDAT 0x000000007AFFB000 000030 (v02 INSYDE INSYDE   00000000 ACPI 00040000)
2020-07-14T23:57:37+02:00 ds918blam kernel: [    0.000000] ACPI: UEFI 0x000000007AFFA000 000042 (v01 INSYDE INSYDE   00000002 ACPI 00040000)
2020-07-14T23:57:37+02:00 ds918blam kernel: [    0.000000] ACPI: SSDT 0x000000007AFF9000 000554 (v01 INSYDE Tpm2Tabl 00001000 ACPI 00040000)
2020-07-14T23:57:37+02:00 ds918blam kernel: [    0.000000] ACPI: TPM2 0x000000007AFF8000 000034 (v03 INSYDE INSYDE   00000002 ACPI 00040000)

 

[.Shad.]

Pour dmesg c'est une commande globale, donc en root tu tapes :

dmesg -T

Ce sont les informations liées au kernel et au hardware.

Modifié le 15 juillet 2020 par .Shad.

[bruno78]

Merci @.Shad.,

dmesg -T donne le résultat suivant, mais le reboot est déjà en route ! on ne voit pas ce qui se passe juste avant :

[Tue Jul 14 23:56:07 2020] Initializing cgroup subsys cpuset
[Tue Jul 14 23:56:07 2020] Initializing cgroup subsys cpu
[Tue Jul 14 23:56:07 2020] Initializing cgroup subsys cpuacct
[Tue Jul 14 23:56:07 2020] Linux version 4.4.59+ (root@build3) (gcc version 4.9.3 20150311 (prerelease) (crosstool-NG 1.20.0) ) #25426 SMP PREEMPT Tue May 12 04:54:55 CST 2020
[Tue Jul 14 23:56:07 2020] Command line: root=/dev/md0 earlyprintk=apl console=ttyS2,115200n8 ihd_num=4 netif_num=2 HddHotplug=1 SataPortMap=23 sata_remap=0>2:1>3:2>0:3>1 syno_hw_version=DS918+ vender_format_version=2 syno_hdd_detect=18,179,176,175 syno_hdd_enable=21,20,19,9 syno_usb_vbus_gpio=13@0000:00:15.0@1,11@0000:00:15.0@2 sn=xxxxxxxxxx macs=xxxxxxxxxx,xxxxxxxxxx
[Tue Jul 14 23:56:07 2020] KERNEL supported cpus:
[Tue Jul 14 23:56:07 2020]   Intel GenuineIntel
[Tue Jul 14 23:56:07 2020] x86/fpu: xstate_offset[3]:  960, xstate_sizes[3]:   64
[Tue Jul 14 23:56:07 2020] x86/fpu: xstate_offset[4]: 1024, xstate_sizes[4]:   64
[Tue Jul 14 23:56:07 2020] x86/fpu: Supporting XSAVE feature 0x01: 'x87 floating point registers'
[Tue Jul 14 23:56:07 2020] x86/fpu: Supporting XSAVE feature 0x02: 'SSE registers'
[Tue Jul 14 23:56:07 2020] x86/fpu: Supporting XSAVE feature 0x08: 'MPX bounds registers'
[Tue Jul 14 23:56:07 2020] x86/fpu: Supporting XSAVE feature 0x10: 'MPX CSR'
[Tue Jul 14 23:56:07 2020] x86/fpu: Enabled xstate features 0x1b, context size is 1088 bytes, using 'standard' format.
[Tue Jul 14 23:56:07 2020] e820: BIOS-provided physical RAM map:
[Tue Jul 14 23:56:07 2020] BIOS-e820: [mem 0x0000000000000000-0x0000000000057fff] usable
[Tue Jul 14 23:56:07 2020] BIOS-e820: [mem 0x0000000000058000-0x0000000000058fff] reserved
[Tue Jul 14 23:56:07 2020] BIOS-e820: [mem 0x0000000000059000-0x0000000000085fff] usable
[Tue Jul 14 23:56:07 2020] BIOS-e820: [mem 0x0000000000086000-0x00000000000fffff] reserved
[Tue Jul 14 23:56:07 2020] BIOS-e820: [mem 0x0000000000100000-0x000000000fffffff] usable
[Tue Jul 14 23:56:07 2020] BIOS-e820: [mem 0x0000000010000000-0x0000000012150fff] reserved
[Tue Jul 14 23:56:07 2020] BIOS-e820: [mem 0x0000000012151000-0x0000000067c17fff] usable

J'ai ouvert un ticket de support, et j'ai eu comme réponse un "plantage de la Virtualization / kvm", sans autre forme de procès ... : "kernel panic caused by kvm functions"

A priori j'ai retrouvé une situation stable et saine, et je ne pense pas avoir perdu de données malgré le vidage des caches NVME.

Je vais continuer à surveiller de prêt.

Cdt

Bruno78