PHP Warning: ... database is locked ...

[ni.rieckmann]

Hello!

On OPNsense's dashboard the message "A problem was detected. Click here for more information.". Some more details:

System Information:
User-Agent Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:60.0) Gecko/20100101 Firefox/60.0
FreeBSD 11.1-RELEASE-p9  e86703e30(stable/18.1)
OPNsense 18.1.6-1ba9a4da3 [17.7.12_1-d0434f481] OpenSSL 1.0.2o  27 Mar 2018 (amd64)
Plugins os-monit-1.7 os-vmware-1.4
Time Mon, 14 May 2018 16:15:39 -0300

PHP Errors:
[03-May-2018 12:58:45 America/Fortaleza] PHP Warning:  SQLite3Stmt::execute(): Unable to execute statement: database is locked in /usr/local/opnsense/scripts/OPNsense/CaptivePortal/process_accounting_messages.php on line 67
[03-May-2018 14:31:00 America/Fortaleza] PHP Warning:  SQLite3Stmt::execute(): Unable to execute statement: database is locked in /usr/local/opnsense/scripts/OPNsense/CaptivePortal/process_accounting_messages.php on line 80

[there are many more messages but they are always the same]

I checked the file, but I rather don't change any of it without knowing exactly what the problem is. The system is working just fine, from time to time the users complain about the Captive Portal. The session times out for some users, but I suspect it's because too many users are trying to connect at the same SQL DB simultaneously. Anyway, I would like to know the impact of this "bug" before I determine that the problem is with the DB or not.

dmesg.boot:
Copyright (c) 1992-2017 The FreeBSD Project.
Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
   The Regents of the University of California. All rights reserved.
FreeBSD is a registered trademark of The FreeBSD Foundation.
FreeBSD 11.1-RELEASE-p9  e86703e30(stable/18.1) amd64
FreeBSD clang version 4.0.0 (tags/RELEASE_400/final 297347) (based on LLVM 4.0.0)
VT(vga): text 80x25
[HBSD LOG] logging to system: enabled
[HBSD LOG] logging to user: disabled
[HBSD HARDENING] procfs hardening: enabled
[HBSD ASLR] status: opt-out
[HBSD ASLR] mmap: 30 bit
[HBSD ASLR] exec base: 30 bit
[HBSD ASLR] stack: 42 bit
[HBSD ASLR] vdso: 28 bit
[HBSD ASLR] map32bit: 18 bit
[HBSD ASLR] disallow MAP_32BIT mode mmap: opt-in
[HBSD ASLR (compat)] status: opt-out
[HBSD ASLR (compat)] mmap: 14 bit
[HBSD ASLR (compat)] exec base: 14 bit
[HBSD ASLR (compat)] stack: 14 bit
[HBSD ASLR (compat)] vdso: 8 bit
[HBSD SEGVGUARD] status: opt-out
[HBSD SEGVGUARD] expiry: 120 sec
[HBSD SEGVGUARD] suspension: 600 sec
[HBSD SEGVGUARD] maxcrashes: 5
CPU: Intel(R) Xeon(R) CPU E5-2670 0 @ 2.60GHz (2593.75-MHz K8-class CPU)
  Origin="GenuineIntel"  Id=0x206d7  Family=0x6  Model=0x2d  Stepping=7
  Features=0x1fa3fbff
  Features2=0x9fba2203
  AMD Features=0x28100800
  AMD Features2=0x1
  Structured Extended Features=0x2
  TSC: P-state invariant
Hypervisor: Origin = "VMwareVMware"
real memory  = 2147483648 (2048 MB)
avail memory = 2033065984 (1938 MB)
Event timer "LAPIC" quality 600
ACPI APIC Table:
FreeBSD/SMP: Multiprocessor System Detected: 4 CPUs
FreeBSD/SMP: 2 package(s) x 2 core(s)
random: unblocking device.
MADT: Forcing active-low polarity and level trigger for SCI
ioapic0  irqs 0-23 on motherboard
SMP: AP CPU #1 Launched!
SMP: AP CPU #2 Launched!
SMP: AP CPU #3 Launched!
random: entropy device external interface
wlan: mac acl policy registered
netmap: loaded module
module_register_init: MOD_LOAD (vesa, 0xffffffff810ab110, 0) error 19
kbd1 at kbdmux0
nexus0
vtvga0:  on motherboard
cryptosoft0:  on motherboard
acpi0:  on motherboard
acpi0: Power Button (fixed)
hpet0:  iomem 0xfed00000-0xfed003ff on acpi0
Timecounter "HPET" frequency 14318180 Hz quality 950
cpu0:  numa-domain 0 on acpi0
cpu1:  numa-domain 0 on acpi0
cpu2:  numa-domain 0 on acpi0
cpu3:  numa-domain 0 on acpi0
attimer0:  port 0x40-0x43 irq 0 on acpi0
Timecounter "i8254" frequency 1193182 Hz quality 0
Event timer "i8254" frequency 1193182 Hz quality 100
atrtc0:  port 0x70-0x71 irq 8 on acpi0
Event timer "RTC" frequency 32768 Hz quality 0
Timecounter "ACPI-fast" frequency 3579545 Hz quality 900
acpi_timer0: <24-bit timer at 3.579545MHz> port 0x1008-0x100b on acpi0
pcib0:  port 0xcf8-0xcff on acpi0
pci0:  on pcib0
pcib1:  at device 1.0 on pci0
pci1:  on pcib1
isab0:  at device 7.0 on pci0
isa0:  on isab0
atapci0:  port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0x1060-0x106f at device 7.1 on pci0
ata0:  at channel 0 on atapci0
ata1:  at channel 1 on atapci0
pci0:  at device 7.3 (no driver attached)
vgapci0:  port 0x1070-0x107f mem 0xe8000000-0xefffffff,0xfe000000-0xfe7fffff irq 16 at device 15.0 on pci0
vgapci0: Boot video device
mpt0:  port 0x1400-0x14ff mem 0xfeba0000-0xfebbffff,0xfebc0000-0xfebdffff irq 17 at device 16.0 on pci0
mpt0: MPI Version=1.2.0.0
pcib2:  at device 17.0 on pci0
pci2:  on pcib2
pcib3:  at device 21.0 on pci0
pcib3: [GIANT-LOCKED]
pci3:  on pcib3
vmx0:  port 0x4000-0x400f mem 0xfd5fc000-0xfd5fcfff,0xfd5fd000-0xfd5fdfff,0xfd5fe000-0xfd5fffff irq 18 at device 0.0 on pci3
vmx0: Ethernet address: <address>
pcib4:  at device 21.1 on pci0
pcib4: [GIANT-LOCKED]
pcib5:  at device 21.2 on pci0
pcib5: [GIANT-LOCKED]
pcib6:  at device 21.3 on pci0
pcib6: [GIANT-LOCKED]
pcib7:  at device 21.4 on pci0
pcib7: [GIANT-LOCKED]
pcib8:  at device 21.5 on pci0
pcib8: [GIANT-LOCKED]
pcib9:  at device 21.6 on pci0
pcib9: [GIANT-LOCKED]
pcib10:  at device 21.7 on pci0
pcib10: [GIANT-LOCKED]
pcib11:  at device 22.0 on pci0
pcib11: [GIANT-LOCKED]
pci4:  on pcib11
vmx1:  port 0x5000-0x500f mem 0xfd4fc000-0xfd4fcfff,0xfd4fd000-0xfd4fdfff,0xfd4fe000-0xfd4fffff irq 19 at device 0.0 on pci4
vmx1: Ethernet address: <address>
pcib12:  at device 22.1 on pci0
pcib12: [GIANT-LOCKED]
pcib13:  at device 22.2 on pci0
pcib13: [GIANT-LOCKED]
pcib14:  at device 22.3 on pci0
pcib14: [GIANT-LOCKED]
pcib15:  at device 22.4 on pci0
pcib15: [GIANT-LOCKED]
pcib16:  at device 22.5 on pci0
pcib16: [GIANT-LOCKED]
pcib17:  at device 22.6 on pci0
pcib17: [GIANT-LOCKED]
pcib18:  at device 22.7 on pci0
pcib18: [GIANT-LOCKED]
pcib19:  at device 23.0 on pci0
pcib19: [GIANT-LOCKED]
pci5:  on pcib19
vmx2:  port 0x6000-0x600f mem 0xfd3fc000-0xfd3fcfff,0xfd3fd000-0xfd3fdfff,0xfd3fe000-0xfd3fffff irq 16 at device 0.0 on pci5
vmx2: Ethernet address: <address>
pcib20:  at device 23.1 on pci0
pcib20: [GIANT-LOCKED]
pcib21:  at device 23.2 on pci0
pcib21: [GIANT-LOCKED]
pcib22:  at device 23.3 on pci0
pcib22: [GIANT-LOCKED]
pcib23:  at device 23.4 on pci0
pcib23: [GIANT-LOCKED]
pcib24:  at device 23.5 on pci0
pcib24: [GIANT-LOCKED]
pcib25:  at device 23.6 on pci0
pcib25: [GIANT-LOCKED]
pcib26:  at device 23.7 on pci0
pcib26: [GIANT-LOCKED]
pcib27:  at device 24.0 on pci0
pcib27: [GIANT-LOCKED]
pcib28:  at device 24.1 on pci0
pcib28: [GIANT-LOCKED]
pcib29:  at device 24.2 on pci0
pcib29: [GIANT-LOCKED]
pcib30:  at device 24.3 on pci0
pcib30: [GIANT-LOCKED]
pcib31:  at device 24.4 on pci0
pcib31: [GIANT-LOCKED]
pcib32:  at device 24.5 on pci0
pcib32: [GIANT-LOCKED]
pcib33:  at device 24.6 on pci0
pcib33: [GIANT-LOCKED]
pcib34:  at device 24.7 on pci0
pcib34: [GIANT-LOCKED]
acpi_acad0:  on acpi0
atkbdc0:  port 0x60,0x64 irq 1 on acpi0
atkbd0:  irq 1 on atkbdc0
kbd0 at atkbd0
atkbd0: [GIANT-LOCKED]
psm0:  irq 12 on atkbdc0
psm0: [GIANT-LOCKED]
psm0: model IntelliMouse, device ID 3
acpi_syscontainer0:  on acpi0
fdc0:  port 0x3f0-0x3f5,0x3f7 irq 6 drq 2 on acpi0
fd0: <1440-KB 3.5" drive> on fdc0 drive 0
orm0:  at iomem 0xc0000-0xc7fff,0xc8000-0xc9fff,0xca000-0xcafff,0xcb000-0xcbfff,0xcc000-0xccfff,0xdc000-0xdffff,0xe0000-0xe7fff on isa0
vga0:  at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
ppc0: cannot reserve I/O port range
Timecounters tick every 1.000 msec
usb_needs_explore_all: no devclass
nvme cam probe device init
da0 at mpt0 bus 0 scbus2 target 0 lun 0
da0:  Fixed Direct Access SPC-4 SCSI device
da0: 320.000MB/s transfers (160.000MHz DT, offset 127, 16bit)
da0: Command Queueing enabled
da0: 20480MB (41943040 512 byte sectors)
da0: quirks=0x140
cd0 at ata1 bus 0 scbus1 target 0 lun 0
cd0:  Removable CD-ROM SCSI device
cd0: Serial Number 10000000000000000001
cd0: 33.300MB/s transfers (UDMA2, ATAPI 12bytes, PIO 65534bytes)
cd0: Attempt to query device size failed: NOT READY, Medium not present
cd0: quirks=0x40
Trying to mount root from ufs:/dev/gpt/rootfs [rw,noatime]...
VMware memory control driver initialized
vlan0: changing name to <name>
vlan1: changing name to <name>
vlan2: changing name to <name>
vlan3: changing name to <name>
vlan4: changing name to <name>
vlan5: changing name to <name>
vlan6: changing name to <name>
vlan7: changing name to <name>
vlan8: changing name to <name>
vlan9: changing name to <name>
vlan10: changing name to <name>
vlan11: changing name to <name>
vlan12: changing name to <name>
vlan13: changing name to <name>
vlan14: changing name to <name>
vmx0: link state changed to UP
vmx1: link state changed to UP
arp: 00:50:56:b6:18:37 is using my IP address <adrress> on vmx0!
pflog0: promiscuous mode enabled
ipfw2 (+ipv6) initialized, divert loadable, nat loadable, default to accept, logging disabled
DUMMYNET 0 with IPv6 initialized (100409)
load_dn_sched dn_sched FIFO loaded
load_dn_sched dn_sched QFQ loaded
load_dn_sched dn_sched RR loaded
load_dn_sched dn_sched WF2Q+ loaded
load_dn_sched dn_sched PRIO loaded
load_dn_sched dn_sched FQ_CODEL loaded
load_dn_sched dn_sched FQ_PIE loaded
load_dn_aqm dn_aqm CODEL loaded
load_dn_aqm dn_aqm PIE loaded
pflog0: promiscuous mode disabled
Waiting (max 60 seconds) for system process `vnlru' to stop... done
Waiting (max 60 seconds) for system process `bufdaemon' to stop... done
Waiting (max 60 seconds) for system process `syncer' to stop...
Syncing disks, vnodes remaining... 9 7 0 0 done
All buffers synced.
Uptime: 2m41s
Copyright (c) 1992-2017 The FreeBSD Project.
Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
   The Regents of the University of California. All rights reserved.
FreeBSD is a registered trademark of The FreeBSD Foundation.
FreeBSD 11.1-RELEASE-p9  e86703e30(stable/18.1) amd64
FreeBSD clang version 4.0.0 (tags/RELEASE_400/final 297347) (based on LLVM 4.0.0)
VT(vga): text 80x25
[HBSD LOG] logging to system: enabled
[HBSD LOG] logging to user: disabled
[HBSD HARDENING] procfs hardening: enabled
[HBSD ASLR] status: opt-out
[HBSD ASLR] mmap: 30 bit
[HBSD ASLR] exec base: 30 bit
[HBSD ASLR] stack: 42 bit
[HBSD ASLR] vdso: 28 bit
[HBSD ASLR] map32bit: 18 bit
[HBSD ASLR] disallow MAP_32BIT mode mmap: opt-in
[HBSD ASLR (compat)] status: opt-out
[HBSD ASLR (compat)] mmap: 14 bit
[HBSD ASLR (compat)] exec base: 14 bit
[HBSD ASLR (compat)] stack: 14 bit
[HBSD ASLR (compat)] vdso: 8 bit
[HBSD SEGVGUARD] status: opt-out
[HBSD SEGVGUARD] expiry: 120 sec
[HBSD SEGVGUARD] suspension: 600 sec
[HBSD SEGVGUARD] maxcrashes: 5
CPU: Intel(R) Xeon(R) CPU E5-2670 0 @ 2.60GHz (2593.75-MHz K8-class CPU)
  Origin="GenuineIntel"  Id=0x206d7  Family=0x6  Model=0x2d  Stepping=7
  Features=0x1fa3fbff
  Features2=0x9fba2203
  AMD Features=0x28100800
  AMD Features2=0x1
  Structured Extended Features=0x2
  TSC: P-state invariant
Hypervisor: Origin = "VMwareVMware"
real memory  = 2147483648 (2048 MB)
avail memory = 2033065984 (1938 MB)
Event timer "LAPIC" quality 600
ACPI APIC Table:
FreeBSD/SMP: Multiprocessor System Detected: 4 CPUs
FreeBSD/SMP: 2 package(s) x 2 core(s)
random: unblocking device.
MADT: Forcing active-low polarity and level trigger for SCI
ioapic0  irqs 0-23 on motherboard
SMP: AP CPU #1 Launched!
SMP: AP CPU #3 Launched!
SMP: AP CPU #2 Launched!
random: entropy device external interface
wlan: mac acl policy registered
netmap: loaded module
module_register_init: MOD_LOAD (vesa, 0xffffffff810ab110, 0) error 19
kbd1 at kbdmux0
nexus0
vtvga0:  on motherboard
cryptosoft0:  on motherboard
acpi0:  on motherboard
acpi0: Power Button (fixed)
hpet0:  iomem 0xfed00000-0xfed003ff on acpi0
Timecounter "HPET" frequency 14318180 Hz quality 950
cpu0:  numa-domain 0 on acpi0
cpu1:  numa-domain 0 on acpi0
cpu2:  numa-domain 0 on acpi0
cpu3:  numa-domain 0 on acpi0
attimer0:  port 0x40-0x43 irq 0 on acpi0
Timecounter "i8254" frequency 1193182 Hz quality 0
Event timer "i8254" frequency 1193182 Hz quality 100
atrtc0:  port 0x70-0x71 irq 8 on acpi0
Event timer "RTC" frequency 32768 Hz quality 0
Timecounter "ACPI-fast" frequency 3579545 Hz quality 900
acpi_timer0: <24-bit timer at 3.579545MHz> port 0x1008-0x100b on acpi0
pcib0:  port 0xcf8-0xcff on acpi0
pci0:  on pcib0
pcib1:  at device 1.0 on pci0
pci1:  on pcib1
isab0:  at device 7.0 on pci0
isa0:  on isab0
atapci0:  port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0x1060-0x106f at device 7.1 on pci0
ata0:  at channel 0 on atapci0
ata1:  at channel 1 on atapci0
pci0:  at device 7.3 (no driver attached)
vgapci0:  port 0x1070-0x107f mem 0xe8000000-0xefffffff,0xfe000000-0xfe7fffff irq 16 at device 15.0 on pci0
vgapci0: Boot video device
mpt0:  port 0x1400-0x14ff mem 0xfeba0000-0xfebbffff,0xfebc0000-0xfebdffff irq 17 at device 16.0 on pci0
mpt0: MPI Version=1.2.0.0
pcib2:  at device 17.0 on pci0
pci2:  on pcib2
pcib3:  at device 21.0 on pci0
pcib3: [GIANT-LOCKED]
pci3:  on pcib3
vmx0:  port 0x4000-0x400f mem 0xfd5fc000-0xfd5fcfff,0xfd5fd000-0xfd5fdfff,0xfd5fe000-0xfd5fffff irq 18 at device 0.0 on pci3
vmx0: Ethernet address: <adrress>
pcib4:  at device 21.1 on pci0
pcib4: [GIANT-LOCKED]
pcib5:  at device 21.2 on pci0
pcib5: [GIANT-LOCKED]
pcib6:  at device 21.3 on pci0
pcib6: [GIANT-LOCKED]
pcib7:  at device 21.4 on pci0
pcib7: [GIANT-LOCKED]
pcib8:  at device 21.5 on pci0
pcib8: [GIANT-LOCKED]
pcib9:  at device 21.6 on pci0
pcib9: [GIANT-LOCKED]
pcib10:  at device 21.7 on pci0
pcib10: [GIANT-LOCKED]
pcib11:  at device 22.0 on pci0
pcib11: [GIANT-LOCKED]
pci4:  on pcib11
vmx1:  port 0x5000-0x500f mem 0xfd4fc000-0xfd4fcfff,0xfd4fd000-0xfd4fdfff,0xfd4fe000-0xfd4fffff irq 19 at device 0.0 on pci4
vmx1: Ethernet address: <adrress>
pcib12:  at device 22.1 on pci0
pcib12: [GIANT-LOCKED]
pcib13:  at device 22.2 on pci0
pcib13: [GIANT-LOCKED]
pcib14:  at device 22.3 on pci0
pcib14: [GIANT-LOCKED]
pcib15:  at device 22.4 on pci0
pcib15: [GIANT-LOCKED]
pcib16:  at device 22.5 on pci0
pcib16: [GIANT-LOCKED]
pcib17:  at device 22.6 on pci0
pcib17: [GIANT-LOCKED]
pcib18:  at device 22.7 on pci0
pcib18: [GIANT-LOCKED]
pcib19:  at device 23.0 on pci0
pcib19: [GIANT-LOCKED]
pci5:  on pcib19
vmx2:  port 0x6000-0x600f mem 0xfd3fc000-0xfd3fcfff,0xfd3fd000-0xfd3fdfff,0xfd3fe000-0xfd3fffff irq 16 at device 0.0 on pci5
vmx2: Ethernet address: <adrress>
pcib20:  at device 23.1 on pci0
pcib20: [GIANT-LOCKED]
pcib21:  at device 23.2 on pci0
pcib21: [GIANT-LOCKED]
pcib22:  at device 23.3 on pci0
pcib22: [GIANT-LOCKED]
pcib23:  at device 23.4 on pci0
pcib23: [GIANT-LOCKED]
pcib24:  at device 23.5 on pci0
pcib24: [GIANT-LOCKED]
pcib25:  at device 23.6 on pci0
pcib25: [GIANT-LOCKED]
pcib26:  at device 23.7 on pci0
pcib26: [GIANT-LOCKED]
pcib27:  at device 24.0 on pci0
pcib27: [GIANT-LOCKED]
pcib28:  at device 24.1 on pci0
pcib28: [GIANT-LOCKED]
pcib29:  at device 24.2 on pci0
pcib29: [GIANT-LOCKED]
pcib30:  at device 24.3 on pci0
pcib30: [GIANT-LOCKED]
pcib31:  at device 24.4 on pci0
pcib31: [GIANT-LOCKED]
pcib32:  at device 24.5 on pci0
pcib32: [GIANT-LOCKED]
pcib33:  at device 24.6 on pci0
pcib33: [GIANT-LOCKED]
pcib34:  at device 24.7 on pci0
pcib34: [GIANT-LOCKED]
acpi_acad0:  on acpi0
atkbdc0:  port 0x60,0x64 irq 1 on acpi0
atkbd0:  irq 1 on atkbdc0
kbd0 at atkbd0
atkbd0: [GIANT-LOCKED]
psm0:  irq 12 on atkbdc0
psm0: [GIANT-LOCKED]
psm0: model IntelliMouse, device ID 3
acpi_syscontainer0:  on acpi0
fdc0:  port 0x3f0-0x3f5,0x3f7 irq 6 drq 2 on acpi0
fd0: <1440-KB 3.5" drive> on fdc0 drive 0
orm0:  at iomem 0xc0000-0xc7fff,0xc8000-0xc9fff,0xca000-0xcafff,0xcb000-0xcbfff,0xcc000-0xccfff,0xdc000-0xdffff,0xe0000-0xe7fff on isa0
vga0:  at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
ppc0: cannot reserve I/O port range
Timecounters tick every 1.000 msec
usb_needs_explore_all: no devclass
nvme cam probe device init
da0 at mpt0 bus 0 scbus2 target 0 lun 0
da0:  Fixed Direct Access SPC-4 SCSI device
da0: 320.000MB/s transfers (160.000MHz, offset 127, 16bit)
da0: Command Queueing enabled
da0: 20480MB (41943040 512 byte sectors)
da0: quirks=0x140
cd0 at ata1 bus 0 scbus1 target 0 lun 0
cd0:  Removable CD-ROM SCSI device
cd0: Serial Number 10000000000000000001
cd0: 33.300MB/s transfers (UDMA2, ATAPI 12bytes, PIO 65534bytes)
cd0: Attempt to query device size failed: NOT READY, Medium not present
cd0: quirks=0x40
Trying to mount root from ufs:/dev/gpt/rootfs [rw,noatime]...


Thanks a lot for your help!

[franco]

Hi there!

The timeout for the database is 30 seconds and by the sound of it the complains go hand in hand with the issue you are seeing.

How many simultaneous captive portal users are we talking about?

The box could be undersized, or we are missing an unlock in a database or a stuck task for one reason or another.


Cheers,
Franco

[ni.rieckmann]

Hello, Franco,

I'm not sure how to check how many users simultaneously try to access it, but as far as I can see there are over 200 active sessions on Captive Portal every day! We had to break one OPNsense server into 4 new ones, counting all the sessions it hits almost 1k sessions. We provide Internet access to 350 schools, each school has approximately 200 students and teachers during the day (7am ~ 10pm). I'm not sure if breaking one server into four was the best solution, but for some time it did solve the problem and users stopped complaining for some time.

Which box (where) should I change to check if it fixes the bug? Or do you need other informations to go on?

Thanks a lot!
N

[ni.rieckmann]

Hello!!!

Anyone else having the same issue as I? I still get those problem reports, not sure how to solve them.

Thanks a lot!