-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 On Sunday, 2019-02-03 at 14:33 +0100, Carlos E. R. wrote:
Hi,
Last December I reported this problem on my laptop, and now my desktop also exhibits it.
After several days running, this morning it locked as soon as I changed workspaces. I noticed kswapd0 was busy long time, and that firefox had about 10 gigs of virtual memory. The disk activity led was solid blue. I couldn't find out more, the machine froze and had to be hard rebooted.
A week before it also froze, but that time I could not observe anything.
Well, it happened tonight and I got data: the culprit appears to be alsa, of all things. I was writing an email. I send it, then I think of seeing a google search I had clicked minutes before, and then I notice the mouse does not respond (nor the keyboard LEDs). I look on another computer that has an ssh open to this one, running top, and top is also frozen. Nevertheless, I type "k" to try kill something. On another tab, I try to open an ssh shell, but does not respond. Back to top, the "k" has responded and asks for the PID. I give the one for Firefox (for no reason, except that it is big ram). Typing is slow, one char per second. A few seconds later I notice that Thunderbird updates and the mouse is again responsive. Recovery! On a terminal, I was running "top -d 60 -b > top_01.log &" for days. I stop it and look at the log - 185M. This is the relevant part: Here think it was acting normal: top - 03:36:13 up 3 days, 13:42, 3 users, load average: 0,20, 0,39, 0,53 Tasks: 438 total, 2 running, 435 sleeping, 0 stopped, 1 zombie %Cpu(s): 9,2 us, 1,7 sy, 0,6 ni, 87,3 id, 1,2 wa, 0,0 hi, 0,0 si, 0,0 st KiB Mem : 8161400 total, 457912 free, 6722988 used, 980500 buff/cache KiB Swap: 25165820 total, 20518908 free, 4646912 used. 930768 avail Mem PID USER PR NI VIRT RES SHR SWAP S %CPU %MEM TIME+ COMMAND 5089 cer 20 0 3911352 1,224g 73108 167316 S 14,28 15,72 286:13.57 Web Content 4233 cer 20 0 10,501g 916988 218760 296076 S 7,042 11,24 248:14.02 firefox ... top - 03:37:13 up 3 days, 13:43, 3 users, load average: 0,51, 0,46, 0,55 Tasks: 433 total, 2 running, 430 sleeping, 0 stopped, 1 zombie %Cpu(s): 9,9 us, 1,7 sy, 0,6 ni, 86,7 id, 1,2 wa, 0,0 hi, 0,0 si, 0,0 st KiB Mem : 8161400 total, 790104 free, 6544820 used, 826476 buff/cache KiB Swap: 25165820 total, 20515068 free, 4650752 used. 1128644 avail Mem PID USER PR NI VIRT RES SHR SWAP S %CPU %MEM TIME+ COMMAND 5089 cer 20 0 3911352 1,085g 72988 167412 S 12,60 13,94 286:21.14 Web Content 4237 cer 20 0 4469680 989,6m 64872 415528 R 10,17 12,42 270:39.08 thunderbird-bin 4233 cer 20 0 10,515g 839364 196276 296368 S 5,992 10,28 248:17.62 firefox 5118 cer 20 0 4120348 989144 82060 401296 S 5,443 12,12 206:04.71 Web Content 4680 cer 39 19 2066432 17936 0 22908 S 2,730 0,220 141:46.84 tracker-extract 5910 root 20 0 56480 10888 2164 4844 S 2,480 0,133 119:53.00 iotop 5136 cer 20 0 2909700 798180 37236 274392 S 2,330 9,780 123:13.72 Web Content 3868 root 20 0 642944 138192 100996 21996 S 1,531 1,693 28:58.50 X 5041 cer 20 0 3449000 1,048g 22120 404768 S 1,431 13,47 76:04.77 Web Content 5871 cer 20 0 40396 804 0 248 S 0,599 0,010 29:51.17 top 11922 root 20 0 41584 968 172 256 S 0,549 0,012 29:41.31 top 4169 cer 9 -11 2479296 5276 3608 2408 S 0,350 0,065 34:27.52 pulseaudio 4234 cer 20 0 301208 6220 4112 13900 S 0,250 0,076 12:34.62 gkrellm 4324 cer 20 0 523528 15388 8264 15244 S 0,216 0,189 10:18.53 panel-6-weather 52 root 20 0 0 0 0 0 S 0,200 0,000 3:20.59 kswapd0 4330 cer 20 0 523268 15364 8388 13388 S 0,200 0,188 10:21.99 panel-14-weathe 4702 cer 20 0 732548 38432 72 3692 S 0,200 0,471 10:45.17 tracker-store 4196 cer 20 0 473192 5224 1768 9440 S 0,150 0,064 5:13.63 gvfs-udisks2-vo 4242 cer 20 0 738936 31148 8280 21180 S 0,067 0,382 4:18.89 xfce4-terminal 4322 cer 20 0 251216 2840 1952 15268 S 0,067 0,035 2:59.17 panel-23-multil 4181 cer 20 0 425860 11584 6560 15104 S 0,050 0,142 1:11.06 xfce4-panel I say it was normal here because each capture happened at the 13 second. The next one is delayed and kswapd0 is going mad: top - 03:39:26 up 3 days, 13:45, 3 users, load average: 61,19, 21,98, 8,28 Tasks: 436 total, 2 running, 433 sleeping, 0 stopped, 1 zombie %Cpu(s): 7,1 us, 12,7 sy, 0,3 ni, 13,9 id, 65,7 wa, 0,0 hi, 0,4 si, 0,0 st KiB Mem : 8161400 total, 117196 free, 7740016 used, 304188 buff/cache KiB Swap: 25165820 total, 20514556 free, 4651264 used. 20184 avail Mem PID USER PR NI VIRT RES SHR SWAP S %CPU %MEM TIME+ COMMAND 52 root 20 0 0 0 0 0 D 83,74 0,000 4:17.49 kswapd0 4237 cer 20 0 4491088 1,263g 10332 417144 D 29,80 16,22 270:59.33 thunderbird-bin 5118 cer 20 0 4137756 1,518g 36252 402496 D 17,35 19,50 206:16.50 Web Content 4233 cer 20 0 10,467g 865432 157420 296732 D 9,154 10,60 248:23.84 firefox 5089 cer 20 0 3911352 1,246g 23044 175308 D 5,151 16,01 286:24.64 Web Content 4680 cer 39 19 2066432 17936 0 22908 S 2,414 0,220 141:48.48 tracker-extract 5136 cer 20 0 2909700 767112 7208 274476 D 1,840 9,399 123:14.97 Web Content 5910 root 20 0 56480 8828 0 4808 D 1,413 0,108 119:53.96 iotop 2318 mysql 20 0 1887764 8052 0 63360 S 1,030 0,099 1:24.20 mysqld 5041 cer 20 0 3449000 1,026g 0 405020 D 0,986 13,18 76:05.44 Web Content 3868 root 20 0 636132 124360 86816 21944 D 0,898 1,524 28:59.11 X 6744 cer 20 0 4057688 69632 16 120816 S 0,824 0,853 2:10.61 java 3828 vscan 20 0 882152 0 0 628960 S 0,515 0,000 1:06.06 clamd 5871 cer 20 0 40396 1636 832 248 R 0,515 0,020 29:51.52 top 11922 root 20 0 41584 800 0 252 D 0,515 0,010 29:41.66 top 2307 named 20 0 532424 95288 0 99532 S 0,486 1,168 2:16.24 named 4169 cer 9 -11 2479296 2156 452 2376 S 0,368 0,026 34:27.77 pulseaudio 4234 cer 20 0 301208 2108 0 13900 D 0,309 0,026 12:34.83 gkrellm 4250 cer 20 0 1074168 20364 16 16208 D 0,309 0,250 1:01.59 konversation 4149 cer 20 0 240120 276 0 136 S 0,294 0,003 0:12.73 gpg-agent 4330 cer 20 0 523268 7296 356 13424 D 0,280 0,089 10:22.18 panel-14-weathe 4324 cer 20 0 523528 7504 332 15196 D 0,265 0,092 10:18.71 panel-6-weather 2929 ntp 20 0 53120 188 0 568 D 0,206 0,002 0:10.89 ntpd ... top - 03:40:42 up 3 days, 13:46, 3 users, load average: 57,19, 29,27, 11,83 Tasks: 433 total, 2 running, 430 sleeping, 0 stopped, 1 zombie %Cpu(s): 0,1 us, 7,1 sy, 0,0 ni, 0,0 id, 92,3 wa, 0,0 hi, 0,5 si, 0,0 st KiB Mem : 8161400 total, 130404 free, 7719124 used, 311872 buff/cache KiB Swap: 25165820 total, 20509948 free, 4655872 used. 37236 avail Mem PID USER PR NI VIRT RES SHR SWAP S %CPU %MEM TIME+ COMMAND 52 root 20 0 0 0 0 0 S 12,26 0,000 4:34.80 kswapd0 4233 cer 20 0 10,436g 865072 157416 297044 D 0,489 10,60 248:24.53 firefox 4237 cer 20 0 4491088 1,265g 10332 418312 D 0,319 16,25 270:59.78 thunderbird-bin 2307 named 20 0 532424 95276 0 99544 S 0,262 1,167 2:16.61 named 5118 cer 20 0 4137756 1,517g 36252 403572 D 0,227 19,49 206:16.82 Web Content 6744 cer 20 0 4057688 69364 16 121084 S 0,212 0,850 2:10.91 java 2318 mysql 20 0 1887764 8052 0 63360 S 0,205 0,099 1:24.49 mysqld 4250 cer 20 0 1074168 20364 16 16208 D 0,149 0,250 1:01.80 konversation 3868 root 20 0 636132 124808 87176 21864 S 0,120 1,529 28:59.28 X 5089 cer 20 0 3911352 1,244g 23044 177360 D 0,120 15,99 286:24.81 Web Content 1 root 20 0 158452 3004 0 772 D 0,113 0,037 1:03.57 systemd 5136 cer 20 0 2909700 766300 7208 275288 D 0,113 9,389 123:15.13 Web Content 5871 cer 20 0 40396 804 0 248 R 0,113 0,010 29:51.68 top 4686 cer 39 19 936648 44816 4 12380 D 0,106 0,549 1:44.15 tracker-miner-f 5041 cer 20 0 3449000 1,026g 0 405288 D 0,106 13,18 76:05.59 Web Content 4234 cer 20 0 301208 2108 0 13900 D 0,085 0,026 12:34.95 gkrellm 4315 cer 20 0 710624 3976 44 15404 S 0,085 0,049 2:44.29 panel-19-pulsea 4322 cer 20 0 251216 1012 44 15188 D 0,085 0,012 2:59.43 panel-23-multil 4772 cer 20 0 463636 6232 0 15788 S 0,078 0,076 0:54.68 contarcorreo 11922 root 20 0 41584 828 0 224 S 0,078 0,010 29:41.77 top 4169 cer 9 -11 2479296 2136 432 2376 S 0,071 0,026 34:27.87 pulseaudio 663 root 20 0 82288 5740 5396 456 D 0,064 0,070 0:44.02 systemd-journal and back to normal after killing firefox: top - 03:41:43 up 3 days, 13:47, 4 users, load average: 24,51, 25,39, 11,62 Tasks: 427 total, 1 running, 425 sleeping, 0 stopped, 1 zombie %Cpu(s): 2,9 us, 2,2 sy, 0,8 ni, 80,3 id, 13,6 wa, 0,0 hi, 0,2 si, 0,0 st KiB Mem : 8161400 total, 5307944 free, 2265236 used, 588220 buff/cache KiB Swap: 25165820 total, 22424060 free, 2741760 used. 5610332 avail Mem PID USER PR NI VIRT RES SHR SWAP S %CPU %MEM TIME+ COMMAND 4237 cer 20 0 4490112 1,297g 41488 418224 S 5,156 16,67 271:02.92 thunderbird-bin 4680 cer 39 19 2066432 20592 2652 22904 S 2,709 0,252 141:50.13 tracker-extract 52 root 20 0 0 0 0 0 S 2,512 0,000 4:36.33 kswapd0 5910 root 20 0 56480 13328 4472 4792 S 1,839 0,163 119:55.16 iotop 3868 root 20 0 507876 78808 41164 21852 S 0,821 0,966 28:59.78 X 4169 cer 9 -11 1430364 6500 4696 2276 S 0,624 0,080 34:28.25 pulseaudio 5871 cer 20 0 40396 900 96 248 S 0,575 0,011 29:52.03 top 11922 root 20 0 41584 984 156 224 S 0,542 0,012 29:42.10 top 4196 cer 20 0 473192 7124 3676 9464 S 0,509 0,087 5:13.94 gvfs-udisks2-vo 4702 cer 20 0 732548 44488 6116 3660 S 0,296 0,545 10:45.47 tracker-store 4234 cer 20 0 301208 10440 8332 13900 S 0,230 0,128 12:35.09 gkrellm 4242 cer 20 0 738936 32448 9312 20916 S 0,230 0,398 4:19.09 xfce4-terminal 2307 named 20 0 532424 95276 0 99544 S 0,197 1,167 2:16.73 named 23937 cer 20 0 21484 11452 3368 0 S 0,197 0,140 0:00.12 bash 4330 cer 20 0 523268 13144 6208 13428 S 0,181 0,161 10:22.38 panel-14-weathe 4207 cer 20 0 775472 49928 16244 14340 S 0,164 0,612 0:36.44 xfdesktop 4324 cer 20 0 523528 13480 6316 15204 S 0,164 0,165 10:18.90 panel-6-weather 1 root 20 0 240380 7116 3984 688 S 0,115 0,087 1:03.64 systemd 5907 cer 20 0 217984 7020 3144 8828 S 0,115 0,086 0:46.97 dirmngr 663 root 20 0 82592 8028 7416 428 S 0,099 0,098 0:44.08 systemd-journal 4315 cer 20 0 710624 8924 4956 15368 S 0,099 0,109 2:44.35 panel-19-pulsea 4250 cer 20 0 1074168 27412 7064 16208 S 0,082 0,336 1:01.85 konversation 6744 cer 20 0 4057688 69368 16 121080 S 0,082 0,850 2:10.96 java So the issue happened betwen 03:37:13 and 03:39:26 hours. As the 3:38:13 entry is missing, at that moment things were already wrong. Let's go see syslog - as this time I was sitting there and killed something, it is properly registered. This is postfix sending an email, everything normal: <22>1 2019-02-09T03:37:27.328452+01:00 Telcontar postfix 23861 - - A584E3209C9: to=<...@opensuse.org>, relay=mail.gmx.es ... status=sent (250 Requested mail action okay, completed: id=...) <22>1 2019-02-09T03:37:27.330347+01:00 Telcontar postfix 23861 - - > mail.gmx.es[212.227.17.184]:25: QUIT <22>1 2019-02-09T03:37:27.330518+01:00 Telcontar postfix 23861 - - name_mask: resource <22>1 2019-02-09T03:37:27.331005+01:00 Telcontar postfix 23861 - - name_mask: software <22>1 2019-02-09T03:37:27.385482+01:00 Telcontar postfix 23861 - - disposing SASL state information <22>1 2019-02-09T03:37:27.385789+01:00 Telcontar postfix 3974 - - A584E3209C9: removed <39>1 2019-02-09T03:37:34.187629+01:00 Telcontar gcr-prompter 23840 - - 10 second inactivity timeout, quitting <39>1 2019-02-09T03:37:34.187844+01:00 Telcontar gcr-prompter 23840 - - Gcr: unregistering prompter <39>1 2019-02-09T03:37:34.190225+01:00 Telcontar gcr-prompter 23840 - - Gcr: disposing prompter <39>1 2019-02-09T03:37:34.190251+01:00 Telcontar gcr-prompter 23840 - - Gcr: finalizing prompter Here definitely things are going bad (no edited lines here), but we know it started earlier, before 3:38:13 and after 3:37:27 - the gcr-prompter entry above may be suspicious, but the alsa entries below definitely indicate a problem: <30>1 2019-02-09T03:39:04.102993+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 4553784 bytes (25815 ms). <30>1 2019-02-09T03:40:01.963938+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_hda_intel'. Please report this issue to the ALSA developers. <30>1 2019-02-09T03:40:29.388806+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: snd_pcm_dump(): <30>1 2019-02-09T03:40:38.256922+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: Soft volume PCM <30>1 2019-02-09T03:40:47.447909+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: Control: PCM Playback Volume <30>1 2019-02-09T03:40:49.856184+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: min_dB: -51 <30>1 2019-02-09T03:40:49.931352+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: max_dB: 0 <30>1 2019-02-09T03:40:49.931597+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: resolution: 256 <30>1 2019-02-09T03:40:49.931769+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: Its setup is: <30>1 2019-02-09T03:40:49.931930+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: stream : PLAYBACK <30>1 2019-02-09T03:40:49.932090+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: access : MMAP_INTERLEAVED <30>1 2019-02-09T03:40:49.932249+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: format : S16_LE <30>1 2019-02-09T03:40:49.932408+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: subformat : STD <30>1 2019-02-09T03:40:49.932566+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: channels : 2 <30>1 2019-02-09T03:40:49.932734+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: rate : 44100 <30>1 2019-02-09T03:40:49.932893+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: exact rate : 44100 (44100/1) <30>1 2019-02-09T03:40:49.933052+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: msbits : 16 <30>1 2019-02-09T03:40:49.933222+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: buffer_size : 88192 <30>1 2019-02-09T03:40:49.933396+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: period_size : 44096 <30>1 2019-02-09T03:40:49.933559+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: period_time : 999909 <30>1 2019-02-09T03:40:49.933717+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: tstamp_mode : ENABLE <30>1 2019-02-09T03:40:49.933876+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: tstamp_type : MONOTONIC <30>1 2019-02-09T03:40:49.934035+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: period_step : 1 <30>1 2019-02-09T03:40:49.934194+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: avail_min : 84401 <30>1 2019-02-09T03:40:49.934352+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: period_event : 0 <30>1 2019-02-09T03:40:49.934511+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: start_threshold : -1 <30>1 2019-02-09T03:40:49.934676+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: stop_threshold : 6205960286516543488 <30>1 2019-02-09T03:40:49.934841+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: silence_threshold: 0 <30>1 2019-02-09T03:40:49.934999+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: silence_size : 0 <30>1 2019-02-09T03:40:49.935157+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: boundary : 6205960286516543488 <30>1 2019-02-09T03:40:49.935316+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: Slave: Hardware PCM card 0 'HDA Creative' device 0 subdevice 0 <30>1 2019-02-09T03:40:49.935560+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: Its setup is: <30>1 2019-02-09T03:40:49.935724+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: stream : PLAYBACK <30>1 2019-02-09T03:40:49.935886+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: access : MMAP_INTERLEAVED <30>1 2019-02-09T03:40:49.936044+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: format : S16_LE <30>1 2019-02-09T03:40:49.936202+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: subformat : STD <30>1 2019-02-09T03:40:49.936361+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: channels : 2 <30>1 2019-02-09T03:40:49.936524+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: rate : 44100 <30>1 2019-02-09T03:40:50.047919+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: exact rate : 44100 (44100/1) <30>1 2019-02-09T03:40:50.048217+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: msbits : 16 <30>1 2019-02-09T03:40:50.048390+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: buffer_size : 88192 <30>1 2019-02-09T03:40:50.048549+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: period_size : 44096 <30>1 2019-02-09T03:40:50.048708+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: period_time : 999909 <30>1 2019-02-09T03:40:50.048866+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: tstamp_mode : ENABLE <30>1 2019-02-09T03:40:50.049029+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: tstamp_type : MONOTONIC <30>1 2019-02-09T03:40:50.049189+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: period_step : 1 <30>1 2019-02-09T03:40:50.049347+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: avail_min : 84401 <30>1 2019-02-09T03:40:50.049505+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: period_event : 0 <30>1 2019-02-09T03:40:50.049662+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: start_threshold : -1 <30>1 2019-02-09T03:40:50.049919+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: stop_threshold : 6205960286516543488 <30>1 2019-02-09T03:40:50.050079+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: silence_threshold: 0 <30>1 2019-02-09T03:40:50.050237+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: silence_size : 0 <30>1 2019-02-09T03:40:50.050400+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: boundary : 6205960286516543488 <30>1 2019-02-09T03:40:50.050571+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: appl_ptr : 12514060050 <30>1 2019-02-09T03:40:50.050729+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: hw_ptr : 12515110304 <30>1 2019-02-09T03:40:50.050892+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: snd_pcm_delay() returned a value that is exceptionally large: -26371280 bytes (-149497 ms). <30>1 2019-02-09T03:40:50.051052+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_hda_intel'. Please report this issue to the ALSA developers. <30>1 2019-02-09T03:40:50.051261+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: snd_pcm_dump(): <30>1 2019-02-09T03:40:50.051431+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: Soft volume PCM <30>1 2019-02-09T03:40:50.051589+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: Control: PCM Playback Volume <30>1 2019-02-09T03:40:50.051747+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: min_dB: -51 <30>1 2019-02-09T03:40:50.051909+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: max_dB: 0 <30>1 2019-02-09T03:40:50.052067+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: resolution: 256 <30>1 2019-02-09T03:40:50.052230+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: Its setup is: <30>1 2019-02-09T03:40:50.052394+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: stream : PLAYBACK <30>1 2019-02-09T03:40:50.052557+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: access : MMAP_INTERLEAVED <30>1 2019-02-09T03:40:50.052716+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: format : S16_LE <30>1 2019-02-09T03:40:50.052875+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: subformat : STD <30>1 2019-02-09T03:40:50.053033+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: channels : 2 <30>1 2019-02-09T03:40:50.053191+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: rate : 44100 <30>1 2019-02-09T03:40:50.053349+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: exact rate : 44100 (44100/1) <30>1 2019-02-09T03:40:50.053512+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: msbits : 16 <30>1 2019-02-09T03:40:50.053670+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: buffer_size : 88192 <30>1 2019-02-09T03:40:50.053828+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: period_size : 44096 <30>1 2019-02-09T03:40:50.053987+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: period_time : 999909 <30>1 2019-02-09T03:40:50.054146+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: tstamp_mode : ENABLE <30>1 2019-02-09T03:40:50.054305+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: tstamp_type : MONOTONIC <30>1 2019-02-09T03:40:50.054476+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: period_step : 1 <30>1 2019-02-09T03:40:50.054635+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: avail_min : 84401 <30>1 2019-02-09T03:40:50.054801+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: period_event : 0 <30>1 2019-02-09T03:40:50.054959+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: start_threshold : -1 <30>1 2019-02-09T03:40:50.055117+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: stop_threshold : 6205960286516543488 <30>1 2019-02-09T03:40:50.055275+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: silence_threshold: 0 <30>1 2019-02-09T03:40:50.055456+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: silence_size : 0 <30>1 2019-02-09T03:40:50.055615+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: boundary : 6205960286516543488 <30>1 2019-02-09T03:40:50.055773+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: Slave: Hardware PCM card 0 'HDA Creative' device 0 subdevice 0 <30>1 2019-02-09T03:40:50.081352+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: Its setup is: <30>1 2019-02-09T03:40:50.081608+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: stream : PLAYBACK <30>1 2019-02-09T03:40:50.081768+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: access : MMAP_INTERLEAVED <30>1 2019-02-09T03:40:50.081927+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: format : S16_LE <30>1 2019-02-09T03:40:50.082085+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: subformat : STD <30>1 2019-02-09T03:40:50.082243+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: channels : 2 <30>1 2019-02-09T03:40:50.082400+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: rate : 44100 <30>1 2019-02-09T03:40:50.082557+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: exact rate : 44100 (44100/1) <30>1 2019-02-09T03:40:50.082714+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: msbits : 16 <30>1 2019-02-09T03:40:50.082871+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: buffer_size : 88192 <30>1 2019-02-09T03:40:50.083034+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: period_size : 44096 <30>1 2019-02-09T03:40:50.083192+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: period_time : 999909 <30>1 2019-02-09T03:40:50.083349+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: tstamp_mode : ENABLE <30>1 2019-02-09T03:40:50.083537+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: tstamp_type : MONOTONIC <30>1 2019-02-09T03:40:50.083703+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: period_step : 1 <30>1 2019-02-09T03:40:50.083862+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: avail_min : 84401 <30>1 2019-02-09T03:40:50.084019+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: period_event : 0 <30>1 2019-02-09T03:40:50.084177+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: start_threshold : -1 <30>1 2019-02-09T03:40:50.084337+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: stop_threshold : 6205960286516543488 <30>1 2019-02-09T03:40:50.084501+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: silence_threshold: 0 <30>1 2019-02-09T03:40:50.084665+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: silence_size : 0 <30>1 2019-02-09T03:40:50.084824+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: boundary : 6205960286516543488 <30>1 2019-02-09T03:40:50.084981+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: appl_ptr : 12514102116 <30>1 2019-02-09T03:40:50.085140+01:00 Telcontar pulseaudio 4169 - - E: [alsa-sink-CA0110-IBG Analog] alsa-util.c: hw_ptr : 12520694936 <4>1 2019-02-09T03:40:50.580980+01:00 Telcontar kernel - - - [308811.279237] show_signal_msg: 45 callbacks suppressed <6>1 2019-02-09T03:40:50.580996+01:00 Telcontar kernel - - - [308811.279240] Chrome_~dThread[5139]: segfault at 0 ip 00007fe7cca17cd3 sp 00007fe7c987bb10 error 6 in libxul.so[7fe7cc4fd000+5874000] <6>1 2019-02-09T03:40:50.596756+01:00 Telcontar kernel - - - [308811.303156] Socket Thread[5100]: segfault at 0 ip 0000560342364c51 sp 00007f9566efe670 error 6 in firefox[56034235f000+31000] <6>1 2019-02-09T03:40:50.618242+01:00 Telcontar kernel - - - [308811.324121] Cameras IPC[9191]: segfault at 0 ip 000055c3285a8c51 sp 00007f9ade5fd8b0 error 6 in firefox[55c3285a3000+31000] <6>1 2019-02-09T03:40:50.683429+01:00 Telcontar kernel - - - [308811.390212] Chrome_~dThread[5044]: segfault at 0 ip 00007fef1d717cd3 sp 00007fef1a57bb10 error 6 in libxul.so[7fef1d1fd000+5874000] <30>1 2019-02-09T03:40:51.102534+01:00 Telcontar systemd 1 - - Created slice User Slice of news. <30>1 2019-02-09T03:40:51.103841+01:00 Telcontar systemd 1 - - Starting User Manager for UID 9... <30>1 2019-02-09T03:40:51.104264+01:00 Telcontar systemd 1 - - Created slice system-systemd\x2dcoredump.slice. <30>1 2019-02-09T03:40:51.147417+01:00 Telcontar systemd 1 - - Started Process Core Dump (PID 23890/UID 0). <30>1 2019-02-09T03:40:51.149551+01:00 Telcontar systemd 1 - - Started Process Core Dump (PID 23888/UID 0). <86>1 2019-02-09T03:40:51.156209+01:00 Telcontar systemd - - - pam_unix(systemd-user:session): session opened for user news by (uid=0) <30>1 2019-02-09T03:40:51.156952+01:00 Telcontar systemd 1 - - Started Process Core Dump (PID 23887/UID 0). <30>1 2019-02-09T03:40:51.163051+01:00 Telcontar systemd 1 - - Started Process Core Dump (PID 23889/UID 0). <30>1 2019-02-09T03:40:51.173282+01:00 Telcontar systemd 1 - - Started Session 1722 of user news. <30>1 2019-02-09T03:40:51.180118+01:00 Telcontar systemd 1 - - Started Session 1721 of user cer. <86>1 2019-02-09T03:40:51.186204+01:00 Telcontar cron 23880 - - pam_unix(crond:session): session opened for user cer by (uid=0) <30>1 2019-02-09T03:40:51.275496+01:00 Telcontar systemd-coredump 23896 - - Resource limits disable core dumping for process 5136 (Web Content). <10>1 2019-02-09T03:40:51.288537+01:00 Telcontar systemd-coredump 23896 - - Process 5136 (Web Content) of user 1000 dumped core. <30>1 2019-02-09T03:40:51.294905+01:00 Telcontar systemd-coredump 23894 - - Resource limits disable core dumping for process 5041 (Web Content). <10>1 2019-02-09T03:40:51.295785+01:00 Telcontar systemd-coredump 23894 - - Process 5041 (Web Content) of user 1000 dumped core. <30>1 2019-02-09T03:40:51.306329+01:00 Telcontar systemd-coredump 23898 - - Resource limits disable core dumping for process 5118 (Web Content). <10>1 2019-02-09T03:40:51.306830+01:00 Telcontar systemd-coredump 23898 - - Process 5118 (Web Content) of user 1000 dumped core. <30>1 2019-02-09T03:40:51.308720+01:00 Telcontar systemd-coredump 23895 - - Resource limits disable core dumping for process 5089 (Web Content). <10>1 2019-02-09T03:40:51.309167+01:00 Telcontar systemd-coredump 23895 - - Process 5089 (Web Content) of user 1000 dumped core. <30>1 2019-02-09T03:40:51.379583+01:00 Telcontar systemd 1 - - Started User Manager for UID 9. <86>1 2019-02-09T03:40:51.380313+01:00 Telcontar cron 23881 - - pam_unix(crond:session): session opened for user news by (uid=0) <63>1 2019-02-09T03:40:51.517680+01:00 Telcontar fetchnews 23921 - - config: debugmode is 1 <63>1 2019-02-09T03:40:51.517970+01:00 Telcontar fetchnews 23921 - - config: maxfetch is 5000 <63>1 2019-02-09T03:40:51.517993+01:00 Telcontar fetchnews 23921 - - config: maxage is 0 <63>1 2019-02-09T03:40:51.518051+01:00 Telcontar fetchnews 23921 - - config: postings have max. 500000 bytes <63>1 2019-02-09T03:40:51.518074+01:00 Telcontar fetchnews 23921 - - config: timeout_long is 100 days <63>1 2019-02-09T03:40:51.518095+01:00 Telcontar fetchnews 23921 - - config: timeout_fetchnews is 90 seconds <63>1 2019-02-09T03:40:51.518115+01:00 Telcontar fetchnews 23921 - - config: newsadmin is postmaster@telcontar.valinor <63>1 2019-02-09T03:40:51.518136+01:00 Telcontar fetchnews 23921 - - config: allow_8bit_headers is 1 <86>1 2019-02-09T03:40:52.037118+01:00 Telcontar CRON 23880 - - pam_unix(crond:session): session closed for user cer <63>1 2019-02-09T03:40:54.518456+01:00 Telcontar fetchnews 23921 - - leafnode 1.11.11: verbosity level is 2, debugmode is 1 <63>1 2019-02-09T03:40:54.518488+01:00 Telcontar fetchnews 23921 - - try_lock(timeout=5), fqdn="Telcontar.valinor" <63>1 2019-02-09T03:40:54.707342+01:00 Telcontar fetchnews 23921 - - Last LIST done 1666132 seconds ago: NEWGROUPS <63>1 2019-02-09T03:40:54.831086+01:00 Telcontar fetchnews 23921 - - <200 The server welcomes 208.red-83-32-232.dynamicip.rima-tde.net (83.32.232.208). Authorization required for reading and posting. <62>1 2019-02-09T03:40:54.831118+01:00 Telcontar fetchnews 23921 - - News.Individual.NET: connected to 130.133.4.11:119, reply: 200 <63>1 2019-02-09T03:40:54.831480+01:00 Telcontar fetchnews 23921 - - >AUTHINFO USER robinson <63>1 2019-02-09T03:40:54.892724+01:00 Telcontar fetchnews 23921 - - <381 PASS required <63>1 2019-02-09T03:40:54.892755+01:00 Telcontar fetchnews 23921 - - >AUTHINFO PASS <password not shown> things are back to normal here, as the nntp daemon is starting a fetch loop normally. Telcontar:~ # coredumpctl TIME PID UID GID SIG COREFILE EXE Sat 2019-02-09 03:40:51 CET 5136 1000 100 11 none /usr/lib64/firefox/firefox Sat 2019-02-09 03:40:51 CET 5041 1000 100 11 none /usr/lib64/firefox/firefox Sat 2019-02-09 03:40:51 CET 5118 1000 100 11 none /usr/lib64/firefox/firefox Sat 2019-02-09 03:40:51 CET 5089 1000 100 11 none /usr/lib64/firefox/firefox Telcontar:~ # No coredump files, sorry (I don't remember if I disabled them or it is a system limit not my doing). dmesg -e log has almost nothing registered: [Feb 9 02:51] usb 4-2: USB disconnect, device number 3 [Feb 9 03:41] show_signal_msg: 45 callbacks suppressed [ +0,000003] Chrome_~dThread[5139]: segfault at 0 ip 00007fe7cca17cd3 sp 00007fe7c987bb10 error 6 in libxul.so[7fe7cc4fd000+5874000] [ +0,023916] Socket Thread[5100]: segfault at 0 ip 0000560342364c51 sp 00007f9566efe670 error 6 in firefox[56034235f000+31000] [ +0,020965] Cameras IPC[9191]: segfault at 0 ip 000055c3285a8c51 sp 00007f9ade5fd8b0 error 6 in firefox[55c3285a3000+31000] [ +0,066091] Chrome_~dThread[5044]: segfault at 0 ip 00007fef1d717cd3 sp 00007fef1a57bb10 error 6 in libxul.so[7fef1d1fd000+5874000] cer@Telcontar:~> There are some strange lines above: <4>1 2019-02-09T03:40:50.580980+01:00 Telcontar kernel - - - [308811.279237] show_signal_msg: 45 callbacks suppressed <6>1 2019-02-09T03:40:50.580996+01:00 Telcontar kernel - - - [308811.279240] Chrome_~dThread[5139]: segfault at 0 ip 00007fe7cca17cd3 sp 0000 <6>1 2019-02-09T03:40:50.596756+01:00 Telcontar kernel - - - [308811.303156] Socket Thread[5100]: segfault at 0 ip 0000560342364c51 sp 00007f <6>1 2019-02-09T03:40:50.618242+01:00 Telcontar kernel - - - [308811.324121] Cameras IPC[9191]: segfault at 0 ip 000055c3285a8c51 sp 00007f9a <6>1 2019-02-09T03:40:50.683429+01:00 Telcontar kernel - - - [308811.390212] Chrome_~dThread[5044]: segfault at 0 ip 00007fef1d717cd3 sp 0000 Chrome? I don't remember having Chrome running. I may have started it once to check something, but it should have been exited. Cameras IPC? No idea what is that. My "top" log doesn't show any "chrome" process except this one much earlier, and none afterwards: top - 10:37:54 up 1 day, 20:43, 3 users, load average: 2,05, 1,44, 0,91 ... 10299 cer 20 0 293572 21076 384 0 S 0,000 0,258 0:00.35 chrome-gnome-sh So, what do you think? The system is running, I can do tests. - -- Cheers, Carlos E. R. (from openSUSE 15.0 x86_64 at Telcontar) -----BEGIN PGP SIGNATURE----- iHoEARECADoWIQQZEb51mJKK1KpcU/W1MxgcbY1H1QUCXF5YYhwccm9iaW4ubGlz dGFzQHRlbGVmb25pY2EubmV0AAoJELUzGBxtjUfVm80AoI8J4x3Q6MvDSE1/4Wmx VwCqBKgbAJoCTCYcCViGl35P8WhE5KOaDavXMA== =5td3 -----END PGP SIGNATURE----- -- To unsubscribe, e-mail: opensuse-support+unsubscribe@opensuse.org To contact the owner, e-mail: opensuse-support+owner@opensuse.org