Error: "Insmod for DRIVER failed, returned -1"

More
10 Dec 2017 02:26 - 10 Dec 2017 17:12 #102857 by AndrewHsasku
After a long time, I have finally succeeded in compiling my driver with halcompile.
While starting LinuxCNC, I've got an error like below:
Print file information
RUN_IN_PLACE=no
LINUXCNC_DIR=
LINUXCNC_BIN_DIR=/usr/bin
LINUXCNC_TCL_DIR=/usr/lib/tcltk/linuxcnc
LINUXCNC_SCRIPT_DIR=
LINUXCNC_RTLIB_DIR=/usr/realtime-3.4-9-rtai-686-pae/modules/linuxcnc
LINUXCNC_CONFIG_DIR=
LINUXCNC_LANG_DIR=/usr/share/linuxcnc/tcl/msgs
INIVAR=inivar
HALCMD=halcmd
LINUXCNC_EMCSH=/usr/bin/wish8.5
LINUXCNC - 2.7.11
Machine configuration directory is '/home/a/linuxcnc/configs/lms'
Machine configuration file is 'lms.ini'
INIFILE=/home/a/linuxcnc/configs/lms/lms.ini
PARAMETER_FILE=linuxcnc.var
TASK=milltask
HALUI=
DISPLAY=axis
Starting LinuxCNC...
Starting LinuxCNC server program: linuxcncsvr
Loading Real Time OS, RTAPI, and HAL_LIB modules
Starting LinuxCNC IO program: io
emc/iotask/ioControl.cc 768: can't load tool table.
Found file(REL): ./lms.hal
Shutting down and cleaning up LinuxCNC...
Killing task linuxcncsvr, PID=3832
Removing HAL_LIB, RTAPI, and Real Time OS modules
Removing NML shared memory segments
Debug file information
./lms.hal:9: child did not exit normally
./lms.hal:9: insmod for lms_canopen_driver failed, returned -1
See the output of 'dmesg' for more information.
3832
  PID TTY      STAT   TIME COMMAND
Stopping realtime threads
Unloading hal components
Error: Module lms_canopen_driver is in use
<commandline>:0: exit value: 1
<commandline>:0: rmmod failed, returned -1
<commandline>:0: unloadrt failed
Error: Module hal_lib is in use by: lms_canopen_driver
Error: Module rtapi is in use by: hal_lib lms_canopen_driver
Error: Module rtai_sched is in use by: rtapi
Error: Module rtai_hal is in use by: rtapi rtai_sched
Kernel message information
[    0.000000] Initializing cgroup subsys cpuset
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Linux version 3.4-9-rtai-686-pae (Debian 3.4.55-4linuxcnc) () (gcc version 4.6.3 (Debian 4.6.3-14) ) #1 SMP PREEMPT Debian 3.4.55-4linuxcnc
[    0.000000] BIOS-provided physical RAM map:
[    0.000000]  BIOS-e820: 0000000000000000 - 000000000009fc00 (usable)
[    0.000000]  BIOS-e820: 000000000009fc00 - 00000000000a0000 (reserved)
[    0.000000]  BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
[    0.000000]  BIOS-e820: 0000000000100000 - 000000003fff0000 (usable)
[    0.000000]  BIOS-e820: 000000003fff0000 - 0000000040000000 (ACPI data)
[    0.000000]  BIOS-e820: 00000000fec00000 - 00000000fec01000 (reserved)
[    0.000000]  BIOS-e820: 00000000fee00000 - 00000000fee01000 (reserved)
[    0.000000]  BIOS-e820: 00000000fffc0000 - 0000000100000000 (reserved)
[    0.000000] Notice: NX (Execute Disable) protection missing in CPU!
[    0.000000] SMBIOS 2.5 present.
[    0.000000] DMI: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
[    0.000000] e820 update range: 0000000000000000 - 0000000000010000 (usable) ==> (reserved)
[    0.000000] e820 remove range: 00000000000a0000 - 0000000000100000 (usable)
[    0.000000] last_pfn = 0x3fff0 max_arch_pfn = 0x100000
[    0.000000] MTRR default type: uncachable
[    0.000000] MTRR variable ranges disabled:
[    0.000000] x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106
[    0.000000] CPU MTRRs all blank - virtualized system.
[    0.000000] initial memory mapped : 0 - 01800000
[    0.000000] Base memory trampoline at [c009b000] 9b000 size 16384
[    0.000000] init_memory_mapping: 0000000000000000-00000000377fe000
[    0.000000]  0000000000 - 0000400000 page 4k
[    0.000000]  0000400000 - 0037400000 page 2M
[    0.000000]  0037400000 - 00377fe000 page 4k
[    0.000000] kernel direct mapping tables up to 0x377fdfff @ [mem 0x017f8000-0x017fffff]
[    0.000000] RAMDISK: 36528000 - 3728c000
[    0.000000] ACPI: RSDP 000e0000 00024 (v02 VBOX  )
[    0.000000] ACPI: XSDT 3fff0030 00034 (v01 VBOX   VBOXXSDT 00000001 ASL  00000061)
[    0.000000] ACPI: FACP 3fff00f0 000F4 (v04 VBOX   VBOXFACP 00000001 ASL  00000061)
[    0.000000] ACPI: DSDT 3fff0410 021FF (v02 VBOX   VBOXBIOS 00000002 INTL 20100528)
[    0.000000] ACPI: FACS 3fff0200 00040
[    0.000000] ACPI: SSDT 3fff0240 001CC (v01 VBOX   VBOXCPUT 00000002 INTL 20100528)
[    0.000000] 135MB HIGHMEM available.
[    0.000000] 887MB LOWMEM available.
[    0.000000]   mapped low ram: 0 - 377fe000
[    0.000000]   low ram: 0 - 377fe000
[    0.000000] Zone PFN ranges:
[    0.000000]   DMA      0x00000010 -> 0x00001000
[    0.000000]   Normal   0x00001000 -> 0x000377fe
[    0.000000]   HighMem  0x000377fe -> 0x0003fff0
[    0.000000] Movable zone start PFN for each node
[    0.000000] Early memory PFN ranges
[    0.000000]     0: 0x00000010 -> 0x0000009f
[    0.000000]     0: 0x00000100 -> 0x0003fff0
[    0.000000] On node 0 totalpages: 262015
[    0.000000] free_area_init_node: node 0, pgdat c1498a00, node_mem_map f5d28200
[    0.000000]   DMA zone: 32 pages used for memmap
[    0.000000]   DMA zone: 0 pages reserved
[    0.000000]   DMA zone: 3951 pages, LIFO batch:0
[    0.000000]   Normal zone: 1744 pages used for memmap
[    0.000000]   Normal zone: 221486 pages, LIFO batch:31
[    0.000000]   HighMem zone: 272 pages used for memmap
[    0.000000]   HighMem zone: 34530 pages, LIFO batch:7
[    0.000000] Using APIC driver default
[    0.000000] ACPI: PM-Timer IO Port: 0x4008
[    0.000000] SMP: Allowing 1 CPUs, 0 hotplug CPUs
[    0.000000] Found and enabled local APIC!
[    0.000000] nr_irqs_gsi: 16
[    0.000000] PM: Registered nosave memory: 000000000009f000 - 00000000000a0000
[    0.000000] PM: Registered nosave memory: 00000000000a0000 - 00000000000f0000
[    0.000000] PM: Registered nosave memory: 00000000000f0000 - 0000000000100000
[    0.000000] Allocating PCI resources starting at 40000000 (gap: 40000000:bec00000)
[    0.000000] setup_percpu: NR_CPUS:8 nr_cpumask_bits:8 nr_cpu_ids:1 nr_node_ids:1
[    0.000000] PERCPU: Embedded 17 pages/cpu @f77e5000 s48384 r0 d21248 u69632
[    0.000000] pcpu-alloc: s48384 r0 d21248 u69632 alloc=17*4096
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 259967
[    0.000000] Kernel command line: BOOT_IMAGE=/boot/vmlinuz-3.4-9-rtai-686-pae root=UUID=34b49d64-570f-4fc4-b6f5-964bcf98c7f1 ro initrd=/install/gtk/initrd.gz lapic quiet rootdelay=5
[    0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Initializing CPU#0
[    0.000000] xsave/xrstor: enabled xstate_bv 0x7, cntxt size 0x340
[    0.000000] allocated 2096896 bytes of page_cgroup
[    0.000000] please try 'cgroup_disable=memory' option if you don't want memory cgroups
[    0.000000] Initializing HighMem for node 0 (000377fe:0003fff0)
[    0.000000] Memory: 1017348k/1048512k available (3495k kernel code, 30712k reserved, 1237k data, 416k init, 139208k highmem)
[    0.000000] virtual kernel memory layout:
[    0.000000]     fixmap  : 0xfff17000 - 0xfffff000   ( 928 kB)
[    0.000000]     pkmap   : 0xff800000 - 0xffc00000   (4096 kB)
[    0.000000]     vmalloc : 0xf7ffe000 - 0xff7fe000   ( 120 MB)
[    0.000000]     lowmem  : 0xc0000000 - 0xf77fe000   ( 887 MB)
[    0.000000]       .init : 0xc14a0000 - 0xc1508000   ( 416 kB)
[    0.000000]       .data : 0xc1369d4a - 0xc149f480   (1237 kB)
[    0.000000]       .text : 0xc1000000 - 0xc1369d4a   (3495 kB)
[    0.000000] Checking if this processor honours the WP bit even in supervisor mode...Ok.
[    0.000000] Preemptible hierarchical RCU implementation.
[    0.000000] 	RCU dyntick-idle grace-period acceleration is enabled.
[    0.000000] NR_IRQS:2304 nr_irqs:256 16
[    0.000000] CPU 0 irqstacks, hard=f5806000 soft=f5808000
[    0.000000] Interrupt pipeline (release #3)
[    0.000000] Console: colour VGA+ 80x25
[    0.000000] console [tty0] enabled
[    0.000000] Fast TSC calibration failed
[    0.016000] TSC: Unable to calibrate against PIT
[    0.016000] TSC: using PMTIMER reference calibration
[    0.016000] Detected 2807.899 MHz processor.
[    0.000001] Calibrating delay loop (skipped), value calculated using timer frequency.. 5615.79 BogoMIPS (lpj=11231596)
[    0.000004] pid_max: default: 32768 minimum: 301
[    0.000038] Security Framework initialized
[    0.000041] AppArmor: AppArmor disabled by boot time parameter
[    0.000051] Mount-cache hash table entries: 512
[    0.000210] Initializing cgroup subsys cpuacct
[    0.000212] Initializing cgroup subsys memory
[    0.000216] Initializing cgroup subsys devices
[    0.000218] Initializing cgroup subsys freezer
[    0.000219] Initializing cgroup subsys net_cls
[    0.000221] Initializing cgroup subsys blkio
[    0.000225] Initializing cgroup subsys perf_event
[    0.000295] CPU: Physical Processor ID: 0
[    0.002496] mce: CPU supports 0 MCE banks
[    0.002805] SMP alternatives: switching to UP code
[    0.010103] Freeing SMP alternatives: 16k freed
[    0.010108] ACPI: Core revision 20120320
[    0.010857] ACPI: setting ELCR to 0200 (from 0e00)
[    0.010944] weird, boot CPU (#0) not listed by the BIOS.
[    0.010949] SMP motherboard not detected.
[    0.010952] Enabling APIC mode:  Flat.  Using 0 I/O APICs
[    0.117038] SMP disabled
[    0.117041] Performance Events: unsupported p6 CPU model 158 no PMU driver, software events only.
[    0.129879] NMI watchdog: disabled (cpu0): hardware events not enabled
[    0.130277] Brought up 1 CPUs
[    0.130292] Total of 1 processors activated (5615.79 BogoMIPS).
[    0.130599] devtmpfs: initialized
[    0.131009] dummy: 
[    0.131057] NET: Registered protocol family 16
[    0.131183] ACPI: bus type pci registered
[    0.131420] PCI: PCI BIOS revision 2.10 entry at 0xfda26, last bus=0
[    0.131422] PCI: Using configuration type 1 for base access
[    0.131951] bio: create slab <bio-0> at 0
[    0.132023] ACPI: Added _OSI(Module Device)
[    0.132025] ACPI: Added _OSI(Processor Device)
[    0.132028] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.132030] ACPI: Added _OSI(Processor Aggregator Device)
[    0.132678] ACPI: EC: Look up EC in DSDT
[    0.133068] ACPI: Executed 1 blocks of module-level executable AML code
[    0.135319] ACPI: Interpreter enabled
[    0.135328] ACPI: (supports S0 S5)
[    0.135336] ACPI: Using PIC for interrupt routing
[    0.138361] ACPI: No dock devices found.
[    0.138366] PCI: Ignoring host bridge windows from ACPI; if necessary, use "pci=use_crs" and report a bug
[    0.138445] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[    0.138557] pci_root PNP0A03:00: host bridge window [io  0x0000-0x0cf7] (ignored)
[    0.138559] pci_root PNP0A03:00: host bridge window [io  0x0d00-0xffff] (ignored)
[    0.138560] pci_root PNP0A03:00: host bridge window [mem 0x000a0000-0x000bffff] (ignored)
[    0.138562] pci_root PNP0A03:00: host bridge window [mem 0x40000000-0xfdffffff] (ignored)
[    0.138563] PCI: root bus 00: using default resources
[    0.138580] PCI host bridge to bus 0000:00
[    0.138581] pci_bus 0000:00: root bus resource [io  0x0000-0xffff]
[    0.138583] pci_bus 0000:00: root bus resource [mem 0x00000000-0xffffffff]
[    0.138627] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000
[    0.138980] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100
[    0.139526] pci 0000:00:01.1: [8086:7111] type 00 class 0x01018a
[    0.139974] pci 0000:00:01.1: reg 20: [io  0xd000-0xd00f]
[    0.140256] pci 0000:00:02.0: [80ee:beef] type 00 class 0x030000
[    0.140851] pci 0000:00:02.0: reg 10: [mem 0xe0000000-0xe0ffffff pref]
[    0.144011] pci 0000:00:03.0: [8086:100e] type 00 class 0x020000
[    0.144377] pci 0000:00:03.0: reg 10: [mem 0xf0000000-0xf001ffff]
[    0.144885] pci 0000:00:03.0: reg 18: [io  0xd010-0xd017]
[    0.146100] pci 0000:00:04.0: [80ee:cafe] type 00 class 0x088000
[    0.146369] pci 0000:00:04.0: reg 10: [io  0xd020-0xd03f]
[    0.146615] pci 0000:00:04.0: reg 14: [mem 0xf0400000-0xf07fffff]
[    0.146855] pci 0000:00:04.0: reg 18: [mem 0xf0800000-0xf0803fff pref]
[    0.147864] pci 0000:00:05.0: [8086:2415] type 00 class 0x040100
[    0.147956] pci 0000:00:05.0: reg 10: [io  0xd100-0xd1ff]
[    0.148022] pci 0000:00:05.0: reg 14: [io  0xd200-0xd23f]
[    0.148434] pci 0000:00:06.0: [106b:003f] type 00 class 0x0c0310
[    0.148719] pci 0000:00:06.0: reg 10: [mem 0xf0804000-0xf0804fff]
[    0.150318] pci 0000:00:07.0: [8086:7113] type 00 class 0x068000
[    0.150827] pci 0000:00:07.0: quirk: [io  0x4000-0x403f] claimed by PIIX4 ACPI
[    0.150837] pci 0000:00:07.0: quirk: [io  0x4100-0x410f] claimed by PIIX4 SMB
[    0.151017] pci 0000:00:0d.0: [8086:2829] type 00 class 0x010601
[    0.151419] pci 0000:00:0d.0: reg 10: [io  0xd240-0xd247]
[    0.151743] pci 0000:00:0d.0: reg 14: [io  0xd248-0xd24b]
[    0.152064] pci 0000:00:0d.0: reg 18: [io  0xd250-0xd257]
[    0.152346] pci 0000:00:0d.0: reg 1c: [io  0xd258-0xd25b]
[    0.152624] pci 0000:00:0d.0: reg 20: [io  0xd260-0xd26f]
[    0.152901] pci 0000:00:0d.0: reg 24: [mem 0xf0806000-0xf0807fff]
[    0.153392] pci_bus 0000:00: on NUMA node 0
[    0.153405] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
[    0.154376]  pci0000:00: Unable to request _OSC control (_OSC support mask: 0x0e)
[    0.159984] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 9 10 *11)
[    0.160157] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 9 *10 11)
[    0.160217] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 *9 10 11)
[    0.160277] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 9 10 *11)
[    0.160373] vgaarb: device added: PCI:0000:00:02.0,decodes=io+mem,owns=io+mem,locks=none
[    0.160376] vgaarb: loaded
[    0.160377] vgaarb: bridge control possible 0000:00:02.0
[    0.160392] PCI: Using ACPI for IRQ routing
[    0.160394] PCI: pci_cache_line_size set to 64 bytes
[    0.160579] reserve RAM buffer: 000000000009fc00 - 000000000009ffff 
[    0.160583] reserve RAM buffer: 000000003fff0000 - 000000003fffffff 
[    0.160688] pnp: PnP ACPI init
[    0.160693] ACPI: bus type pnp registered
[    0.160764] pnp 00:00: [bus 00-ff]
[    0.160766] pnp 00:00: [io  0x0cf8-0x0cff]
[    0.160767] pnp 00:00: [io  0x0000-0x0cf7 window]
[    0.160769] pnp 00:00: [io  0x0d00-0xffff window]
[    0.160770] pnp 00:00: [mem 0x000a0000-0x000bffff window]
[    0.160771] pnp 00:00: [mem 0x40000000-0xfdffffff window]
[    0.160788] pnp 00:00: Plug and Play ACPI device, IDs PNP0a03 (active)
[    0.160799] pnp 00:01: [io  0x0060]
[    0.160800] pnp 00:01: [io  0x0064]
[    0.160802] pnp 00:01: [irq 1]
[    0.160812] pnp 00:01: Plug and Play ACPI device, IDs PNP0303 (active)
[    0.160817] pnp 00:02: [io  0x0000-0x000f]
[    0.160818] pnp 00:02: [io  0x0080-0x008f]
[    0.160819] pnp 00:02: [io  0x00c0-0x00df]
[    0.160820] pnp 00:02: [dma 4]
[    0.160829] pnp 00:02: Plug and Play ACPI device, IDs PNP0200 (active)
[    0.160862] pnp 00:03: [irq 12]
[    0.160874] pnp 00:03: Plug and Play ACPI device, IDs PNP0f03 (active)
[    0.161495] pnp: PnP ACPI: found 4 devices
[    0.161496] ACPI: ACPI bus type pnp unregistered
[    0.161498] PnPBIOS: Disabled by ACPI PNP
[    0.196668] Switching to clocksource acpi_pm
[    0.196687] pci_bus 0000:00: resource 4 [io  0x0000-0xffff]
[    0.196689] pci_bus 0000:00: resource 5 [mem 0x00000000-0xffffffff]
[    0.196726] NET: Registered protocol family 2
[    0.196760] IP route cache hash table entries: 32768 (order: 5, 131072 bytes)
[    0.196841] TCP established hash table entries: 131072 (order: 8, 1048576 bytes)
[    0.196973] TCP bind hash table entries: 65536 (order: 7, 524288 bytes)
[    0.197039] TCP: Hash tables configured (established 131072 bind 65536)
[    0.197040] TCP: reno registered
[    0.197042] UDP hash table entries: 512 (order: 2, 16384 bytes)
[    0.197045] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[    0.197076] NET: Registered protocol family 1
[    0.197082] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
[    0.197694] pci 0000:00:01.0: Activating ISA DMA hang workarounds
[    0.197723] pci 0000:00:02.0: Boot video device
[    0.197990] ACPI: PCI Interrupt Link [LNKB] enabled at IRQ 10
[    0.197992] PCI: setting IRQ 10 as level-triggered
[    0.198244] PCI: CLS 0 bytes, default 64
[    0.198270] Unpacking initramfs...
[    0.464901] Freeing initrd memory: 13712k freed
[    0.466690] platform rtc_cmos: registered platform RTC device (no PNP device found)
[    0.467497] audit: initializing netlink socket (disabled)
[    0.467538] type=2000 audit(1512925101.372:1): initialized
[    0.477552] highmem bounce pool size: 64 pages
[    0.477555] HugeTLB registered 4 MB page size, pre-allocated 0 pages
[    0.477707] VFS: Disk quotas dquot_6.5.2
[    0.477721] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.477760] msgmni has been set to 1741
[    0.477849] alg: No test for stdrng (krng)
[    0.477863] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 253)
[    0.477865] io scheduler noop registered
[    0.477867] io scheduler deadline registered
[    0.477874] io scheduler cfq registered (default)
[    0.477909] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[    0.477919] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
[    0.477920] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
[    0.478133] GHES: HEST is not enabled!
[    0.478140] isapnp: Scanning for PnP cards...
[    0.848718] isapnp: No Plug & Play device found
[    0.848764] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    0.849035] Linux agpgart interface v0.103
[    0.849142] i8042: PNP: PS/2 Controller [PNP0303:PS2K,PNP0f03:PS2M] at 0x60,0x64 irq 1,12
[    0.849440] serio: i8042 KBD port at 0x60,0x64 irq 1
[    0.849454] serio: i8042 AUX port at 0x60,0x64 irq 12
[    0.849490] mousedev: PS/2 mouse device common for all mice
[    0.849668] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0
[    0.849933] rtc_cmos rtc_cmos: rtc core: registered rtc_cmos as rtc0
[    0.849951] rtc0: alarms up to one day, 114 bytes nvram
[    0.850019] TCP: cubic registered
[    0.850038] NET: Registered protocol family 10
[    0.850150] Mobile IPv6
[    0.850151] NET: Registered protocol family 17
[    0.850153] Registering the dns_resolver key type
[    0.850184] Using IPI No-Shortcut mode
[    0.850219] PM: Hibernation image not present or could not be loaded.
[    0.850227] registered taskstats version 1
[    0.850556] rtc_cmos rtc_cmos: setting system clock to 2017-12-10 16:58:22 UTC (1512925102)
[    0.850595] Freeing unused kernel memory: 416k freed
[    0.850663] Write protecting the kernel text: 3496k
[    0.850674] Write protecting the kernel read-only data: 984k
[    0.861205] udevd[44]: starting version 175
[    0.870376] SCSI subsystem initialized
[    0.873710] e1000: Intel(R) PRO/1000 Network Driver - version 7.3.21-k8-NAPI
[    0.873712] e1000: Copyright (c) 1999-2006 Intel Corporation.
[    0.873973] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 9
[    0.873975] PCI: setting IRQ 9 as level-triggered
[    0.874025] e1000 0000:00:03.0: setting latency timer to 64
[    0.877610] usbcore: registered new interface driver usbfs
[    0.877640] usbcore: registered new interface driver hub
[    0.894863] libata version 3.00 loaded.
[    0.899041] usbcore: registered new device driver usb
[    0.899353] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    0.899532] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    0.904031] microcode: CPU0 sig=0x906e9, pf=0x8, revision=0x0
[    0.930728] microcode: Microcode Update Driver: v2.00 <tigran@aivazian.fsnet.co.uk>, Peter Oruba
[    1.260010] e1000 0000:00:03.0: eth0: (PCI:33MHz:32-bit) 08:00:27:2e:e2:33
[    1.260018] e1000 0000:00:03.0: eth0: Intel(R) PRO/1000 Network Connection
[    1.260028] ata_piix 0000:00:01.1: version 2.13
[    1.260108] ata_piix 0000:00:01.1: setting latency timer to 64
[    1.260931] scsi0 : ata_piix
[    1.261011] scsi1 : ata_piix
[    1.261035] ata1: PATA max UDMA/33 cmd 0x1f0 ctl 0x3f6 bmdma 0xd000 irq 14
[    1.261037] ata2: PATA max UDMA/33 cmd 0x170 ctl 0x376 bmdma 0xd008 irq 15
[    1.261131] ohci_hcd 0000:00:06.0: setting latency timer to 64
[    1.261142] ohci_hcd 0000:00:06.0: OHCI Host Controller
[    1.261156] ohci_hcd 0000:00:06.0: new USB bus registered, assigned bus number 1
[    1.261175] ohci_hcd 0000:00:06.0: irq 10, io mem 0xf0804000
[    1.316424] usb usb1: New USB device found, idVendor=1d6b, idProduct=0001
[    1.316428] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.316431] usb usb1: Product: OHCI Host Controller
[    1.316433] usb usb1: Manufacturer: Linux 3.4-9-rtai-686-pae ohci_hcd
[    1.316436] usb usb1: SerialNumber: 0000:00:06.0
[    1.316573] hub 1-0:1.0: USB hub found
[    1.316588] hub 1-0:1.0: 12 ports detected
[    1.316923] ahci 0000:00:0d.0: version 3.0
[    1.317795] ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 11
[    1.317798] PCI: setting IRQ 11 as level-triggered
[    1.317892] ahci: SSS flag set, parallel bus scan disabled
[    1.318057] ahci 0000:00:0d.0: AHCI 0001.0100 32 slots 1 ports 3 Gbps 0x1 impl SATA mode
[    1.318060] ahci 0000:00:0d.0: flags: 64bit ncq stag only ccc 
[    1.318088] ahci 0000:00:0d.0: setting latency timer to 64
[    1.318553] scsi2 : ahci
[    1.318603] ata3: SATA max UDMA/133 abar m8192@0xf0806000 port 0xf0806100 irq 11
[    1.414996] ata2.00: ATAPI: VBOX CD-ROM, 1.0, max UDMA/133
[    1.415406] ata2.00: configured for UDMA/33
[    1.415924] scsi 1:0:0:0: CD-ROM            VBOX     CD-ROM           1.0  PQ: 0 ANSI: 5
[    1.474405] Refined TSC clocksource calibration: 2807.689 MHz.
[    1.474410] Switching to clocksource tsc
[    1.639010] ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[    1.639233] ata3.00: ATA-6: VBOX HARDDISK, 1.0, max UDMA/133
[    1.639236] ata3.00: 16777216 sectors, multi 128: LBA48 NCQ (depth 31/32)
[    1.639313] ata3.00: configured for UDMA/133
[    1.654104] scsi 2:0:0:0: Direct-Access     ATA      VBOX HARDDISK    1.0  PQ: 0 ANSI: 5
[    1.659519] sr0: scsi3-mmc drive: 32x/32x xa/form2 tray
[    1.659521] cdrom: Uniform CD-ROM driver Revision: 3.20
[    1.660293] sr 1:0:0:0: Attached scsi CD-ROM sr0
[    1.660848] sd 2:0:0:0: [sda] 16777216 512-byte logical blocks: (8.58 GB/8.00 GiB)
[    1.660871] sd 2:0:0:0: [sda] Write Protect is off
[    1.660873] sd 2:0:0:0: [sda] Mode Sense: 00 3a 00 00
[    1.660882] sd 2:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    1.661509]  sda: sda1 sda2 < sda5 >
[    1.661625] sd 2:0:0:0: [sda] Attached SCSI disk
[    1.662659] sr 1:0:0:0: Attached scsi generic sg0 type 5
[    1.662694] sd 2:0:0:0: Attached scsi generic sg1 type 0
[    1.721865] usb 1-1: new full-speed USB device number 2 using ohci_hcd
[    1.988281] usb 1-1: New USB device found, idVendor=80ee, idProduct=0021
[    1.988285] usb 1-1: New USB device strings: Mfr=1, Product=3, SerialNumber=0
[    1.988289] usb 1-1: Product: USB Tablet
[    1.988291] usb 1-1: Manufacturer: VirtualBox
[    2.012267] input: VirtualBox USB Tablet as /devices/pci0000:00/0000:00:06.0/usb1/1-1/1-1:1.0/input/input1
[    2.012505] generic-usb 0003:80EE:0021.0001: input,hidraw0: USB HID v1.10 Mouse [VirtualBox USB Tablet] on usb-0000:00:06.0-1/input0
[    2.013000] usbcore: registered new interface driver usbhid
[    2.013005] usbhid: USB HID core driver
[    7.027825] PM: Starting manual resume from disk
[    7.027825] PM: Hibernation image partition 8:5 present
[    7.027825] PM: Looking for hibernation image.
[    7.028313] PM: Image not found (code -22)
[    7.028315] PM: Hibernation image not present or could not be loaded.
[    7.034072] EXT4-fs (sda1): INFO: recovery required on readonly filesystem
[    7.034075] EXT4-fs (sda1): write access will be enabled during recovery
[    7.094548] EXT4-fs (sda1): orphan cleanup on readonly fs
[    7.094554] EXT4-fs (sda1): ext4_orphan_cleanup: deleting unreferenced inode 151817
[    7.094583] EXT4-fs (sda1): ext4_orphan_cleanup: deleting unreferenced inode 151816
[    7.094591] EXT4-fs (sda1): ext4_orphan_cleanup: deleting unreferenced inode 131270
[    7.094597] EXT4-fs (sda1): 3 orphan inodes deleted
[    7.094598] EXT4-fs (sda1): recovery complete
[    7.101416] EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null)
[    7.422664] udevd[319]: starting version 175
[    7.557173] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input2
[    7.557177] ACPI: Power Button [PWRF]
[    7.557805] input: Sleep Button as /devices/LNXSYSTM:00/LNXSLPBN:00/input/input3
[    7.557813] ACPI: Sleep Button [SLPF]
[    7.622175] input: Video Bus as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A03:00/LNXVIDEO:00/input/input4
[    7.622180] ACPI: Video Device [GFX0] (multi-head: yes  rom: no  post: no)
[    7.656221] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11
[    7.656911] vgdrvHeartbeatInit: Setting up heartbeat to trigger every 2000 milliseconds
[    7.656999] input: Unspecified device as /devices/pci0000:00/0000:00:04.0/input/input5
[    7.657424] vboxguest: misc device minor 59, IRQ 11, I/O port d020, MMIO at 00000000f0400000 (size 0x400000)
[    7.657426] vboxguest: Successfully loaded version 5.2.2 (interface 0x00010004)
[    7.668787] ACPI: AC Adapter [AC] (off-line)
[    7.669858] ACPI: Battery Slot [BAT0] (battery present)
[    7.670784] piix4_smbus 0000:00:07.0: SMBus Host Controller at 0x4100, revision 0
[    7.673838] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input6
[    7.700732] intel8x0: disable (unknown or VT-d) VM optimization
[    7.700767] snd_intel8x0 0000:00:05.0: setting latency timer to 64
[    8.820909] intel8x0: white list rate for 1028:0177 is 48000
[    9.231743] Adding 392188k swap on /dev/sda5.  Priority:-1 extents:1 across:392188k 
[    9.249745] EXT4-fs (sda1): re-mounted. Opts: (null)
[    9.341434] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro
[    9.366090] loop: module loaded
[   10.159034] RPC: Registered named UNIX socket transport module.
[   10.159036] RPC: Registered udp transport module.
[   10.159037] RPC: Registered tcp transport module.
[   10.159038] RPC: Registered tcp NFSv4.1 backchannel transport module.
[   10.166501] FS-Cache: Loaded
[   10.172197] NFS: Registering the id_resolver key type
[   10.172209] FS-Cache: Netfs 'nfs' registered for caching
[   10.176478] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
[   11.171681] vboxsf: Successfully loaded version 5.2.2 (interface 0x00010004)
[   11.636406] Bluetooth: Core ver 2.16
[   11.636645] NET: Registered protocol family 31
[   11.636647] Bluetooth: HCI device and connection manager initialized
[   11.636648] Bluetooth: HCI socket layer initialized
[   11.636649] Bluetooth: L2CAP socket layer initialized
[   11.636653] Bluetooth: SCO socket layer initialized
[   11.648761] Bluetooth: RFCOMM TTY layer initialized
[   11.648771] Bluetooth: RFCOMM socket layer initialized
[   11.648776] Bluetooth: RFCOMM ver 1.11
[   11.649553] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   11.649554] Bluetooth: BNEP filters: protocol multicast
[   11.783398] input: ACPI Virtual Keyboard Device as /devices/virtual/input/input7
[   11.822293] lp: driver loaded but no devices found
[   11.824766] ppdev: user-space parallel port driver
[   12.240267] ADDRCONF(NETDEV_UP): eth0: link is not ready
[   12.242023] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
[   12.242577] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   12.346213] VBoxService 5.2.2 r119230 (verbosity: 0) linux.x86 (Nov 22 2017 17:24:10) release log
[   12.346214] 00:00:00.000134 main     Log opened 2017-12-10T16:58:34.018021000Z
[   12.346268] 00:00:00.000227 main     OS Product: Linux
[   12.346295] 00:00:00.000260 main     OS Release: 3.4-9-rtai-686-pae
[   12.346321] 00:00:00.000286 main     OS Version: #1 SMP PREEMPT Debian 3.4.55-4linuxcnc
[   12.346366] 00:00:00.000315 main     Executable: /opt/VBoxGuestAdditions-5.2.2/sbin/VBoxService
[   12.346366] 00:00:00.000316 main     Process ID: 2905
[   12.346367] 00:00:00.000317 main     Package type: LINUX_32BITS_GENERIC
[   12.347543] 00:00:00.001504 main     5.2.2 r119230 started. Verbose level = 0
[   12.429762] hrtimer: interrupt took 5003042 ns
[   22.835863] eth0: no IPv6 routers present
[   77.913640] I-pipe: head domain RTAI registered.
[   77.913647] RTAI[hal]: compiled with gcc version 4.7.2 (Debian 4.7.2-5) .
[   77.913651] RTAI[hal]: mounted (IPIPE-NOTHREADS, IMMEDIATE (INTERNAL IRQs DISPATCHED), ISOL_CPUS_MASK: 0).
[   77.913654] SYSINFO: CPUs 1, LINUX APIC IRQ 2312, TIM_FREQ 62493414, CLK_FREQ 2807899000, CPU_FREQ 2807899000
[   77.913655] RTAI_APIC_TIMER_IPI: RTAI DEFINED 2314, VECTOR 2314; LINUX_APIC_TIMER_IPI: RTAI DEFINED 2312, VECTOR 2312
[   77.913660] TIMER NAME: lapic; VARIOUSLY FOUND APIC FREQs: 62493414, 62493414, 55655500
[   77.927816] RTAI[malloc]: global heap size = 2097152 bytes, <BSD>.
[   77.927857] , <uses LINUX SYSCALLs>, kstacks pool size = 524288 bytes.
[   77.927859] RTAI[sched]: hard timer type/freq = APIC/62493414(Hz); default timing: oneshot; linear timed lists.
[   77.927861] RTAI[sched]: Linux timer freq = 250 (Hz), TimeBase freq = 2807899000 hz.
[   77.927862] RTAI[sched]: timer setup = 999 ns, resched latency = 2944 ns.
[   77.936208] RTAI[math]: loaded.
[   78.100499] BUG: unable to handle kernel NULL pointer dereference at   (null)
[   78.100503] IP: [<f848e069>] add_inverter_to_list+0xa/0x13 [lms_canopen_driver]
[   78.100507] *pde = 00000000 
[   78.100509] Oops: 0000 [#1] PREEMPT SMP 
[   78.100511] Modules linked in: lms_canopen_driver(O+) motmod(O) trivkins(O) hal_lib(O) rtapi(O) rtai_math(O) rtai_sched(O) rtai_hal(O) parport_pc ppdev lp parport bnep rfcomm bluetooth rfkill vboxsf(O) uinput nfsd nfs nfs_acl auth_rpcgss fscache lockd sunrpc loop joydev snd_intel8x0 snd_ac97_codec snd_pcm snd_page_alloc snd_seq snd_seq_device snd_timer i2c_piix4 psmouse battery serio_raw ac i2c_core evdev power_supply snd vboxguest(O) video crc32c_intel thermal_sys aesni_intel aes_i586 aes_generic cryptd soundcore ac97_bus button ext4 crc16 jbd2 mbcache usbhid hid sg sd_mod crc_t10dif sr_mod cdrom ata_generic ahci libahci microcode ohci_hcd ehci_hcd ata_piix usbcore usb_common e1000 libata scsi_mod [last unloaded: scsi_wait_scan]
[   78.100549] 
[   78.100551] Pid: 3859, comm: insmod Tainted: G           O 3.4-9-rtai-686-pae #1 innotek GmbH VirtualBox/VirtualBox
[   78.100555] EIP: 0060:[<f848e069>] EFLAGS: 00210246 CPU: 0
[   78.100556] EIP is at add_inverter_to_list+0xa/0x13 [lms_canopen_driver]
[   78.100558] EAX: f84e1c20 EBX: f84e1c20 ECX: f8526530 EDX: 00000000
[   78.100559] ESI: f848f15d EDI: 0000007b EBP: 00000000 ESP: ec791ea8
[   78.100560]  DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
[   78.100562] CR0: 8005003b CR2: 00000000 CR3: 2c502000 CR4: 000406d0
[   78.100565] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[   78.100566] DR6: ffff0ff0 DR7: 00000400
[   78.100568] Process insmod (pid: 3859, ti=ec790000 task=f2c4a600 task.ti=ec790000)
[   78.100569] I-pipe domain Linux
[   78.100570] Stack:
[   78.100571]  f848e110 ec791e5c f8490004 000004c7 00000001 f848e15a 00000000 ec791f10
[   78.100575]  00000000 00000002 00000001 00000001 0002c78b fffffffe 00000000 00000000
[   78.100580]  f8490004 f848e000 6de4d304 f8490004 c1001112 c1024a11 00000002 00000000
[   78.100584] Call Trace:
[   78.100587]  [<f848e110>] ? add_inverter+0x9e/0xa8 [lms_canopen_driver]
[   78.100589]  [<f848e15a>] ? init_module+0x40/0xee6 [lms_canopen_driver]
[   78.100592]  [<f848e000>] ? 0xf848dfff
[   78.100595]  [<c1001112>] ? do_one_initcall+0x32/0x190
[   78.100598]  [<c1024a11>] ? set_memory_ro+0x31/0x40
[   78.100600]  [<f848e11a>] ? add_inverter+0xa8/0xa8 [lms_canopen_driver]
[   78.100603]  [<c1075bbd>] ? sys_init_module+0x8bd/0x1ad0
[   78.100610]  [<c1368c28>] ? sysenter_do_call+0x12/0x16
[   78.100611] Code: 48 f8 6a 03 e8 99 80 01 00 3e 0f ba 35 5c 01 49 f8 00 19 c0 59 58 c3 a1 00 00 49 f8 e9 d1 7c fd ff 8b 15 58 01 49 f8 eb 02 89 ca <8b> 0a 85 c9 75 f8 89 02 c3 57 89 d7 56 89 c6 53 b8 14 00 00 00 
[   78.100642] EIP: [<f848e069>] add_inverter_to_list+0xa/0x13 [lms_canopen_driver] SS:ESP 0068:ec791ea8
[   78.100645] CR2: 0000000000000000
[   78.100647] ---[ end trace 7fa60f5f662be3fe ]---
[   80.311079] RTAI[math]: unloaded.
dmesg doesnt provide any more informations that would look useful.
What does such error mean?

lms.hal (without comment lines; line number in brackets):
[6] loadrt trivkins
[7] loadrt [EMCMOT]EMCMOT servo_period_nsec=[EMCMOT]SERVO_PERIOD num_joints=[TRAJ]AXES
[9] loadrt lms_canopen_driver
[12] loadrt pid names=x-pid,y-pid,z-pid,a-pid
[30] addf lms_canopen_driver.read servo-thread
[32] addf motion-command-handler servo-thread
[33] addf motion-controller servo-thread
[35] addf x-pid.do-pid-calcs servo-thread
[36] addf y-pid.do-pid-calcs servo-thread
[37] addf z-pid.do-pid-calcs servo-thread
[38] addf a-pid.do-pid-calcs servo-thread
[40] addf lms_canopen_driver.write servo-thread
[46] net voltage-on => iocontrol.0.emc-enable-in

Working on a pure copy of linuxcnc-2.7-wheezy.iso installed on VirtualBox.
edit: Thanks @BigJohnT for informations on how to copy window content
Attachments:
Last edit: 10 Dec 2017 17:12 by AndrewHsasku.

Please Log in or Create an account to join the conversation.

More
10 Dec 2017 12:05 #102865 by BigJohnT
Press the "Select All" button to select the text from the error then press the middle mouse button or wheel to copy to the clipboard then press the middle mouse button or wheel in a blank text file to paste.

JT

Please Log in or Create an account to join the conversation.

More
10 Dec 2017 18:11 - 10 Dec 2017 20:09 #102875 by AndrewHsasku
Error seems to be caused by driver, my own .c code.
Developing and finding errors seems to be a nightmare: I have to restart my machine to test changes after each code recompiling.
As far, errors detection is possible only by deducting from kernel message for me
Starting LinuxCNC form terminal with DEBUG = 1 in ini file, doesn't cause printing rtapi_print_msg
Last edit: 10 Dec 2017 20:09 by AndrewHsasku.

Please Log in or Create an account to join the conversation.

More
12 Dec 2017 01:51 #102964 by andypugh
Debugging realtime code is fairly painful. (I do a lot of it).
Sometimes I end up adding an rtapi_print() after every single line if where the problem seems to be.
There is also this:
github.com/LinuxCNC/linuxcnc/blob/master/docs/rtfaults.txt
Which can be useful.

If you are using preempt-rt then you can actually use a debugger:
wiki.linuxcnc.org/cgi-bin/wiki.pl?DebuggingRtapi

Please Log in or Create an account to join the conversation.

Time to create page: 0.136 seconds
Powered by Kunena Forum