Actions
Anomalie #4497
ferméLogs kernel inquiétantes sur la vm bastion
Début:
22/05/2020
Echéance:
% réalisé:
0%
Temps estimé:
Difficulté:
2 Facile
Description
Les fichiers de log /var/log/messages* ne contiennent que des logs kernels bizarre :
Jan 8 01:59:03 bastion kernel: [1555109.098927] Code: df 5b e9 ab fe ff ff 48 c7 c7 78 0c e4 89 e8 bd fd d5 ff 0f 0b 8b 45 08 e9 24 df ff ff 90 90 90 90 90 66 66 66 66 90 48 8b 07 <48> 85 c0 74 0f 48 3b 70 c8 73 0a 48 8b 40 10 48 85 c0 75 f1 c3 76 Jan 8 01:59:03 bastion kernel: [1555109.098927] RIP: 0010:elv_rb_find+0x8/0x30 Jan 8 01:59:03 bastion kernel: [1555109.098928] RAX: 0000000000000000 RBX: 0000000000001c20 RCX: 0000000000000001 Jan 8 01:59:03 bastion kernel: [1555109.098928] RSP: 0018:ffffb3870024f848 EFLAGS: 00000246 ORIG_RAX: ffffffffffffffd2 Jan 8 01:59:03 bastion kernel: [1555109.098929] RBP: ffff9bec4f337670 R08: ffff9bec4f14bc00 R09: 0000000000000001 Jan 8 01:59:03 bastion kernel: [1555109.098929] RDX: 0000000000000000 RSI: 0000000000001c20 RDI: ffff9bec4e97b880 Jan 8 01:59:03 bastion kernel: [1555109.098930] R10: 0000000000001000 R11: ffff9bec44fc5001 R12: ffffb3870024f878 Jan 8 01:59:03 bastion kernel: [1555109.098930] R13: 0000000000000001 R14: 00000000ffffffff R15: ffffb3870024fc18 Jan 8 01:59:03 bastion kernel: [1555109.098932] ? elv_merge+0x63/0xe0 Jan 8 01:59:03 bastion kernel: [1555109.098933] dd_request_merge+0x3f/0x80 Jan 8 01:59:03 bastion kernel: [1555109.098934] blk_mq_sched_try_merge+0x31/0x170 Jan 8 01:59:03 bastion kernel: [1555109.098936] dd_bio_merge+0x51/0x90 Jan 8 01:59:03 bastion kernel: [1555109.098937] blk_mq_make_request+0xd7/0x530 Jan 8 01:59:03 bastion kernel: [1555109.098939] generic_make_request+0x1a4/0x400 Jan 8 01:59:03 bastion kernel: [1555109.098940] submit_bio+0x45/0x140 Jan 8 01:59:03 bastion kernel: [1555109.098942] ? get_swap_bio+0xbb/0xf0 Jan 8 01:59:03 bastion kernel: [1555109.098943] swap_readpage+0x13f/0x1e0 Jan 8 01:59:03 bastion kernel: [1555109.098945] read_swap_cache_async+0x58/0x60 Jan 8 01:59:03 bastion kernel: [1555109.098947] swap_cluster_readahead+0x273/0x2f0 Jan 8 01:59:03 bastion kernel: [1555109.098948] ? blk_mq_make_request+0x1e5/0x530 Jan 8 01:59:03 bastion kernel: [1555109.098949] swapin_readahead+0x334/0x4c0 Jan 8 01:59:03 bastion kernel: [1555109.098951] ? radix_tree_lookup_slot+0x1e/0x50 Jan 8 01:59:03 bastion kernel: [1555109.098952] ? find_get_entry+0x19/0xf0 Jan 8 01:59:03 bastion kernel: [1555109.098953] ? pagecache_get_page+0x30/0x2c0 Jan 8 01:59:03 bastion kernel: [1555109.098954] do_swap_page+0x44b/0x960 Jan 8 01:59:03 bastion kernel: [1555109.098955] ? __switch_to_asm+0x41/0x70 Jan 8 01:59:03 bastion kernel: [1555109.098956] ? __switch_to_asm+0x35/0x70 Jan 8 01:59:03 bastion kernel: [1555109.098957] ? __switch_to_asm+0x41/0x70 Jan 8 01:59:03 bastion kernel: [1555109.098958] __handle_mm_fault+0x876/0x1270 Jan 8 01:59:03 bastion kernel: [1555109.098959] ? __switch_to_asm+0x35/0x70 Jan 8 01:59:03 bastion kernel: [1555109.098960] handle_mm_fault+0xd6/0x200 Jan 8 01:59:03 bastion kernel: [1555109.098961] __do_page_fault+0x249/0x4f0 Jan 8 01:59:03 bastion kernel: [1555109.098962] async_page_fault+0x1e/0x30
Dans /var/log/syslog, c'est plus discret mais ça coïncide avec la coupure Mumble April de ce matin (#4447) :
May 22 10:59:40 bastion icinga2[510]: [2020-05-22 10:59:40 +0200] information/RemoteCheckQueue: items: 0, rate: 0/s (6/min 30/5min 90/15min); May 22 10:59:50 bastion icinga2[510]: [2020-05-22 10:59:50 +0200] information/RemoteCheckQueue: items: 0, rate: 0/s (12/min 60/5min 180/15min); May 22 11:00:00 bastion icinga2[510]: [2020-05-22 11:00:00 +0200] information/RemoteCheckQueue: items: 0, rate: 0/s (6/min 30/5min 90/15min); May 22 11:00:00 bastion kernel: [1027919.996688] warn_alloc: 62 callbacks suppressed May 22 11:00:00 bastion kernel: [1027919.996692] ksoftirqd/0: page allocation failure: order:0, mode:0x480020(GFP_ATOMIC), nodemask=(null) May 22 11:00:00 bastion kernel: [1027919.996693] ksoftirqd/0 cpuset=/ mems_allowed=0 May 22 11:00:00 bastion kernel: [1027919.996698] CPU: 0 PID: 9 Comm: ksoftirqd/0 Not tainted 4.19.0-9-amd64 #1 Debian 4.19.118-2 May 22 11:00:00 bastion kernel: [1027919.996699] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014 May 22 11:00:00 bastion kernel: [1027919.996700] Call Trace: May 22 11:00:00 bastion kernel: [1027919.996719] dump_stack+0x66/0x90 May 22 11:00:00 bastion kernel: [1027919.996726] warn_alloc.cold.120+0x6c/0xec May 22 11:00:00 bastion kernel: [1027919.996730] __alloc_pages_slowpath+0xc73/0xcb0 May 22 11:00:00 bastion kernel: [1027919.996733] __alloc_pages_nodemask+0x28b/0x2b0 May 22 11:00:00 bastion kernel: [1027919.996734] page_frag_alloc+0x124/0x150 May 22 11:00:00 bastion kernel: [1027919.996737] __napi_alloc_skb+0x88/0xe0 May 22 11:00:00 bastion kernel: [1027919.996740] ? dev_gro_receive+0x39b/0x660 May 22 11:00:00 bastion kernel: [1027919.996755] page_to_skb+0x62/0x330 [virtio_net] May 22 11:00:00 bastion kernel: [1027919.996758] receive_buf+0x61d/0x14c0 [virtio_net] May 22 11:00:00 bastion kernel: [1027919.996762] ? enqueue_entity+0x108/0x640 May 22 11:00:00 bastion kernel: [1027919.996766] ? vring_unmap_one+0x16/0x70 [virtio_ring] May 22 11:00:00 bastion kernel: [1027919.996768] ? detach_buf+0x69/0x110 [virtio_ring] May 22 11:00:00 bastion kernel: [1027919.996770] virtnet_poll+0x143/0x328 [virtio_net] May 22 11:00:00 bastion kernel: [1027919.996773] net_rx_action+0x149/0x3b0 May 22 11:00:00 bastion kernel: [1027919.996776] __do_softirq+0xde/0x2d8 May 22 11:00:00 bastion kernel: [1027919.996779] ? sort_range+0x20/0x20 May 22 11:00:00 bastion kernel: [1027919.996782] run_ksoftirqd+0x26/0x40 May 22 11:00:00 bastion kernel: [1027919.996785] smpboot_thread_fn+0xc5/0x160 May 22 11:00:00 bastion kernel: [1027919.996788] kthread+0x112/0x130 May 22 11:00:00 bastion kernel: [1027919.996789] ? kthread_bind+0x30/0x30 May 22 11:00:00 bastion kernel: [1027919.996791] ret_from_fork+0x35/0x40 May 22 11:00:00 bastion kernel: [1027919.996795] warn_alloc_show_mem: 9 callbacks suppressed May 22 11:00:00 bastion kernel: [1027919.996796] Mem-Info: May 22 11:00:00 bastion kernel: [1027919.996799] active_anon:3924 inactive_anon:5484 isolated_anon:0 May 22 11:00:00 bastion kernel: [1027919.996799] active_file:11966 inactive_file:10683 isolated_file:0 May 22 11:00:00 bastion kernel: [1027919.996799] unevictable:0 dirty:2253 writeback:0 unstable:0 May 22 11:00:00 bastion kernel: [1027919.996799] slab_reclaimable:10120 slab_unreclaimable:9080 May 22 11:00:00 bastion kernel: [1027919.996799] mapped:7645 shmem:454 pagetables:452 bounce:0 May 22 11:00:00 bastion kernel: [1027919.996799] free:1485 free_pcp:81 free_cma:0 May 22 11:00:00 bastion kernel: [1027919.996802] Node 0 active_anon:15696kB inactive_anon:21936kB active_file:47864kB inactive_file:42732kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:30580kB dirty:9012kB writeback:0kB shmem:1816kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no May 22 11:00:00 bastion kernel: [1027919.996803] Node 0 DMA free:2004kB min:140kB low:172kB high:204kB active_anon:372kB inactive_anon:500kB active_file:2352kB inactive_file:4644kB unevictable:0kB writepending:64kB present:15992kB managed:15908kB mlocked:0kB kernel_stack:256kB pagetables:36kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB May 22 11:00:00 bastion kernel: [1027919.996806] lowmem_reserve[]: 0 184 184 184 184 May 22 11:00:00 bastion kernel: [1027919.996808] Node 0 DMA32 free:3936kB min:1664kB low:2080kB high:2496kB active_anon:15324kB inactive_anon:21436kB active_file:45508kB inactive_file:38088kB unevictable:0kB writepending:8940kB present:245604kB managed:220820kB mlocked:0kB kernel_stack:1680kB pagetables:1772kB bounce:0kB free_pcp:324kB local_pcp:324kB free_cma:0kB May 22 11:00:00 bastion kernel: [1027919.996811] lowmem_reserve[]: 0 0 0 0 0Questions :
- Faut-il s'inquiéter ?
- D'où viennent ces logs ?
- Quel impact sur les services ? Coupure Mumble ?
Actions