Bug 37357

Summary: При запущенном сервисе не подключаются USB-устройства
Product: Sisyphus Reporter: Evgeniy Korneechev <ekorneechev>
Component: haspdAssignee: Vitaly Lipatov <lav>
Status: CLOSED WONTFIX QA Contact: qa-sisyphus
Severity: normal    
Priority: P3 CC: alex, lav
Version: unstableKeywords: RS
Hardware: all   
OS: Linux   

Description Evgeniy Korneechev 2019-10-18 18:26:08 MSK 
При установке на Рабочую станцию (для использования ключа 1С на локальной базе),
обнаружили следующую проблему. При запущенном сервисе 1С после первого подключения USB-носителя и его безопасного извлекания, подключить его повторно, или любой другой, не получится. Даже lsblk не видит его. Спасает только перезагрузка, но только на первый USB.

Воспроизводится на p8 и p9, x86_64 и i586.

В dmesg иногда просачивается во время того как подключен носитель, но его ОС не видит:
 [  493.115038] INFO: task kworker/0:3:548 blocked for more than 120 seconds.
[  493.115041]       Tainted: G           O    4.9.185-std-def-alt0.M80P.1 #1
[  493.115042] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  493.115044] kworker/0:3     D    0   548      2 0x00000000
[  493.115067] Workqueue: usb_hub_wq hub_event [usbcore]
[  493.115069]  0000000000000046 ffff88010e87ec00 0000000000000000 ffffffff81c11500
[  493.115087]  ffff8801388b62c0 ffff88013fc189c0 ffffc9000095fc98 ffffffff8168ecdf
[  493.115090]  0000000000000000 0000000000000000 0000000000000000 0000000000000000
[  493.115092] Call Trace:
[  493.115101]  [] ? __schedule+0x24f/0x710
[  493.115103]  [] schedule+0x36/0x80
[  493.115105]  [] schedule_preempt_disabled+0xe/0x10
[  493.115107]  [] __mutex_lock_slowpath+0xcd/0x140
[  493.115109]  [] mutex_lock+0x17/0x30
[  493.115116]  [] hub_event+0x68/0x1340 [usbcore]
[  493.115118]  [] ? __switch_to_asm+0x35/0x70
[  493.115120]  [] ? __switch_to_asm+0x41/0x70
[  493.115122]  [] ? __switch_to_asm+0x35/0x70
[  493.115124]  [] ? __switch_to_asm+0x41/0x70
[  493.115126]  [] ? __switch_to_asm+0x35/0x70
[  493.115130]  [] ? __switch_to+0x266/0x5f0
[  493.115132]  [] ? __switch_to_asm+0x41/0x70
[  493.115133]  [] ? __switch_to_asm+0x41/0x70
[  493.115142]  [] process_one_work+0x169/0x4f0
[  493.115145]  [] worker_thread+0x126/0x570
[  493.115147]  [] ? process_one_work+0x4f0/0x4f0
[  493.115149]  [] kthread+0xe6/0x100
[  493.115150]  [] ? __switch_to+0x266/0x5f0
[  493.115152]  [] ? kthread_park+0x60/0x60
[  493.115154]  [] ret_from_fork+0x57/0x70
[  493.115181] INFO: task aksusbd:1445 blocked for more than 120 seconds.
[  493.115182]       Tainted: G           O    4.9.185-std-def-alt0.M80P.1 #1
[  493.115183] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  493.115184] aksusbd         D    0  1445      1 0x20020004
[  493.115187]  0000000000000086 ffff88012931d400 0000000000000000 ffff88013a51c300
[  493.115189]  ffff88012936e380 ffff88013fd189c0 ffffc90001323d48 ffffffff8168ecdf
[  493.115192]  ffffc90001323d80 ffffffff8102f7a6 0000000081694bf1 ffffffff81694be5
[  493.115194] Call Trace:
[  493.115196]  [] ? __schedule+0x24f/0x710
[  493.115198]  [] ? __switch_to+0x266/0x5f0
[  493.115200]  [] ? __switch_to_asm+0x35/0x70
[  493.115202]  [] schedule+0x36/0x80
[  493.115204]  [] schedule_preempt_disabled+0xe/0x10
[  493.115206]  [] __mutex_lock_slowpath+0xcd/0x140
[  493.115208]  [] mutex_lock+0x17/0x30
[  493.115215]  [] usb_device_read+0x81/0x160 [usbcore]
[  493.115217]  [] ? do_nanosleep+0x92/0xf0
[  493.115224]  [] full_proxy_read+0x54/0x90
[  493.115232]  [] __vfs_read+0x18/0x40
[  493.115233]  [] vfs_read+0x93/0x130
[  493.115235]  [] SyS_read+0x5c/0xe0
[  493.115238]  [] do_int80_syscall_32+0x76/0xf0
[  493.115240]  [] entry_INT80_compat+0x72/0xa0
[  493.115245] INFO: task SACSrv:1839 blocked for more than 120 seconds.
[  493.115246]       Tainted: G           O    4.9.185-std-def-alt0.M80P.1 #1
[  493.115247] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  493.115248] SACSrv          D    0  1839      1 0x00000000
[  493.115250]  0000000000000086 ffff880138c7b800 0000000000000000 ffff88013a580100
[  493.115252]  ffff88012ee14280 ffff88013fc189c0 ffffc9000171bc78 ffffffff8168ecdf
[  493.115255]  ffff880113e8e1e2 ffff880193e8e1b9 00000000a03f0512 ffff880113e8e1e6
[  493.115257] Call Trace:
[  493.115259]  [] ? __schedule+0x24f/0x710
[  493.115261]  [] schedule+0x36/0x80
[  493.115263]  [] schedule_preempt_disabled+0xe/0x10
[  493.115264]  [] __mutex_lock_slowpath+0xcd/0x140
[  493.115287]  [] mutex_lock+0x17/0x30
[  493.115294]  [] usb_device_dump+0x25d/0xad0 [usbcore]
[  493.115301]  [] usb_device_read+0xf5/0x160 [usbcore]
[  493.115303]  [] full_proxy_read+0x54/0x90
[  493.115305]  [] __vfs_read+0x18/0x40
[  493.115306]  [] vfs_read+0x93/0x130
[  493.115308]  [] SyS_read+0x5c/0xe0
[  493.115310]  [] do_syscall_64+0x80/0x120
[  493.115313]  [] entry_SYSCALL_64_after_swapgs+0x58/0xc6
[  493.115340] INFO: task pool:2720 blocked for more than 120 seconds.
[  493.115341]       Tainted: G           O    4.9.185-std-def-alt0.M80P.1 #1
[  493.115341] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  493.115342] pool            D    0  2720      1 0x00000000
[  493.115344]  0000000000000086 ffff880132ddb800 ffff880132ddb800 ffff88012bea2340
[  493.115347]  ffff880113c04380 ffff88013fd189c0 ffffc90001f23908 ffffffff8168ecdf
[  493.115349]  0000000081694be5 0000001081694bf1 0000000013c04380 ffffc90001f23a50
[  493.115352] Call Trace:
[  493.115354]  [] ? __schedule+0x24f/0x710
[  493.115356]  [] schedule+0x36/0x80
[  493.115358]  [] schedule_timeout+0x21f/0x4c0
[  493.115366]  [] ? add_timer+0x13f/0x2d0
[  493.115368]  [] wait_for_completion+0xc7/0x170
[  493.115374]  [] ? wake_up_q+0x70/0x70
[  493.115377]  [] __synchronize_srcu+0x127/0x170
[  493.115379]  [] ? trace_raw_output_rcu_utilization+0x60/0x60
[  493.115381]  [] synchronize_srcu+0x23/0x40
[  493.115383]  [] debugfs_remove+0x72/0xa0
[  493.115389]  [] bdi_unregister+0x1af/0x2c0
[  493.115391]  [] ? free_percpu+0xd0/0x1b0
[  493.115400]  [] blk_cleanup_queue+0x16d/0x1a0
[  493.115414]  [] __scsi_remove_device+0x4e/0xd0 [scsi_mod]
[  493.115421]  [] scsi_forget_host+0x60/0x70 [scsi_mod]
[  493.115426]  [] scsi_remove_host+0x77/0x110 [scsi_mod]
[  493.115431]  [] usb_stor_disconnect+0x54/0xe0 [usb_storage]
[  493.115439]  [] usb_unbind_interface+0x70/0x240 [usbcore]
[  493.115449]  [] __device_release_driver+0xa1/0x160
[  493.115485]  [] device_release_driver+0x23/0x30
[  493.115489]  [] bus_remove_device+0xf8/0x140
[  493.115491]  [] device_del+0x139/0x270
[  493.115498]  [] ? usb_remove_ep_devs+0x1f/0x30 [usbcore]
[  493.115505]  [] usb_disable_device+0xa0/0x1e0 [usbcore]
[  493.115512]  [] usb_set_configuration+0xff/0x880 [usbcore]
[  493.115523]  [] ? __kmalloc+0x1b5/0x5b0
[  493.115530]  [] remove_store+0x50/0x60 [usbcore]
[  493.115532]  [] dev_attr_store+0x18/0x30
[  493.115535]  [] sysfs_kf_write+0x37/0x40
[  493.115537]  [] kernfs_fop_write+0x11a/0x190
[  493.115538]  [] __vfs_write+0x18/0x40
[  493.115540]  [] vfs_write+0xb8/0x1b0
[  493.115542]  [] SyS_write+0x5c/0xe0
[  493.115544]  [] do_syscall_64+0x80/0x120
[  493.115547]  [] entry_SYSCALL_64_after_swapgs+0x58/0xc6
Comment 1 Vitaly Lipatov 2019-10-19 13:07:51 MSK 
Отправил В Сизиф haspd-7.90, попробуйте с ним.
И указывайте, пожалуйста, версию пакета, с которой пробуете.
Но вообще если у вас ядро где-то застревает, это проблема ядра и железа, а не программы (haspd).
Так что пробуйте на другом компе.
Comment 2 Evgeniy Korneechev 2019-10-21 10:28:29 MSK 
Проблема воспроизводится и ВМ PVE, и в VirtualBox, и на нескольких АРМ.
Установил новую версию - поведение тоже самое...

Также при остановке сервиса - остается процесс aksusbd (и не убить его никак):
# systemctl status haspd
● haspd.service - LSB: Hasp keys support
   Loaded: loaded (/etc/rc.d/init.d/haspd; generated)
   Active: inactive (dead) since Mon 2019-10-21 10:25:07 MSK; 2min 39s ago
     Docs: man:systemd-sysv-generator(8)
  Process: 3420 ExecStop=/etc/rc.d/init.d/haspd stop (code=exited, status=0/SUCC
  Process: 3080 ExecStart=/etc/rc.d/init.d/haspd start (code=exited, status=0/SU
    Tasks: 2 (limit: 4718)
   Memory: 404.0K
   CGroup: /system.slice/haspd.service
           └─3112 [aksusbd]

окт 21 10:25:00 alt-p8-eiw7u haspd[3420]: Stopping hasplm... [ DONE ]
окт 21 10:25:00 alt-p8-eiw7u haspd[3420]: Stopping winehasp... [ DONE ]
окт 21 10:25:00 alt-p8-eiw7u aksusbd[3112]: terminating due to SIGTERM
окт 21 10:25:07 alt-p8-eiw7u haspd[3420]: Stopping aksusbd... .......[FAILED]
окт 21 10:25:07 alt-p8-eiw7u haspd[3420]: Stopping skeyd... [PASSED]
окт 21 10:25:07 alt-p8-eiw7u haspd[3420]: Stopping usbsentinel... [PASSED]
окт 21 10:25:07 alt-p8-eiw7u haspd[3420]: Stopping SntlKeysSrvrlnx... [PASSED]
окт 21 10:25:07 alt-p8-eiw7u haspd[3420]: Stopping workaround for /proc/bus/usb[
окт 21 10:25:07 alt-p8-eiw7u haspd[3420]: Unloading HASP LPT kernel module... [P
окт 21 10:25:07 alt-p8-eiw7u systemd[1]: Stopped LSB: Hasp keys support.

# ps -A | grep aksusb
 3112 ?        00:00:00 aksusbd <defunct>
Comment 3 Vitaly Lipatov 2019-10-21 12:07:40 MSK 
(В ответ на комментарий №2)
> Проблема воспроизводится и ВМ PVE, и в VirtualBox, и на нескольких АРМ.
> Установил новую версию - поведение тоже самое...
> 
> Также при остановке сервиса - остается процесс aksusbd (и не убить его никак):
...
> # ps -A | grep aksusb
>  3112 ?        00:00:00 aksusbd <defunct>
Потому что он у вас падает в ядре. Он же не всегда остаётся, а только после проблемы.

Но проблема у вас в ядре, так что перевешивайте багу на другой компонент.
Comment 4 Vitaly Lipatov 2023-04-23 22:07:11 MSK 
пакет haspd удалён:
https://bugzilla.altlinux.org/show_bug.cgi?id=45923