thousands of "clock_get_time() failed" entries in WebServer (Apache) error log

Question

Level 1

56 points

thousands of "clock_get_time() failed" entries in WebServer (Apache) error log

We are running Server.app 2.2.1 on OS X 10.8.4. The "Websites" service is enabled. When viewing the WebServer > error_log in Console, we see thousands and thousands of these entries:

clock_get_time() failed: (ipc/rcv) invalid name

There is no date/time prefix for each entry, i.e. that's the whole line. There are so many of these entries, in fact, that recently the log had grown to well over 6 GB in size which I suspect caused some recent kernel panics related to httpd, because when I deleted this gigantic log the panics stopped.

The messages are still happening, but not perpetually, and the log is growing once again. What could be causing them? The only log entries prior to them starting are harmless "file does not exist" entries.

A few facts about our "Websites" service setup:

1) It's operating correctly. No obvious problems.

2) We are storing our "service data" on a volume other than the startup volume as allowed by the Server.app GUI.

3) We have the "Enable PHP web applications" checkbox checked.

4) For the server website, we have "Enable Server Side includes", "Allow overrides using .htaccess files", and "Allow CGI execution" enabled.

5) In order to enable user sites to load, i.e. server.name.com/~username, we have manually uncommented one line in /Library/Server/Web/Config/apache2, making sure that file permissions remained as they were:

Include /private/etc/apache2/extra/httpd-userdir.conf

Thank you for whatever insights or suggestions the community can offer.

Posted on Aug 16, 2013 10:16 AM

Reply

Answer 1

Linc Davis

Level 10

209,547 points

Aug 16, 2013 12:38 PM in response to Steve Rhyne

If you have more than one user account, you must be logged in as an administrator to carry out these instructions.

Launch the Console application in any of the following ways:

☞ Enter the first few letters of its name into a Spotlight search. Select it in the results (it should be at the top.)

☞ In the Finder, select Go ▹ Utilities from the menu bar, or press the key combination shift-command-U. The application is in the folder that opens.

☞ Open LaunchPad. Click Utilities, then Console in the icon grid.

Select the most recent panic log under the heading System Diagnostic Reports on the left. If you don't see that heading, select

View ▹ Show Log List

from the menu bar. Post the entire contents of the panic report — the text, please, not a screenshot. In the interest of privacy, I suggest you edit out the “Anonymous UUID,” a long string of letters, numbers, and dashes in the header and body of the report, if it’s present (it may not be.) Please don't post shutdownStall, spin, or hang reports.

Reply

Answer 2

Steve Rhyne Author

Level 1

56 points

Aug 16, 2013 7:04 PM in response to Steve Rhyne

UPDATE: In roughly 12 hours the log file has grown from about 11 MB to over 1 GB. The cause of the bloat is the same repeating message. Perhaps not so coincidentally, another kernel panic (and automatic restart) occured today. The panic report blames httpd. See below.

Thanks to any and all who can help shed some light on this.

=====================

Interval Since Last Panic Report: 458821 sec

Panics Since Last Report: 6

Fri Aug 16 14:41:15 2013

panic(cpu 6 caller 0xffffff8003e44078): "zalloc: \"ipc ports\" (24378039 elements) retry fail 3, kfree_nop_count: 0"@/SourceCache/xnu/xnu-2050.24.15/osfmk/kern/zalloc.c:1826

Backtrace (CPU 6), Frame : Return Address

0xffffff81d48f3d60 : 0xffffff8003e1d626

0xffffff81d48f3dd0 : 0xffffff8003e44078

0xffffff81d48f3eb0 : 0xffffff8003e13dcb

0xffffff81d48f3f10 : 0xffffff8003e14e12

0xffffff81d48f3f50 : 0xffffff8003e22acc

0xffffff81d48f3f70 : 0xffffff8003ea6536

0xffffff81d48f3fb0 : 0xffffff8003ece9e3

BSD process name corresponding to current thread: httpd

Mac OS version:

12E55

Kernel version:

Darwin Kernel Version 12.4.0: Wed May 1 17:57:12 PDT 2013; root:xnu-2050.24.15~1/RELEASE_X86_64

Kernel UUID: 896CB1E3-AB79-3DF1-B595-549DFFDF3D36

Kernel slide: 0x0000000003c00000

Kernel text base: 0xffffff8003e00000

System model name: MacPro5,1 (Mac-F221BEC8)

System uptime in nanoseconds: 100774199676748

vm objects:17414880

vm object hash entri:2186880

VM map entries:3022800

pagetable anchors:1421312

pv_list:6119424

vm pages:295862760

kalloc.64:4026368

kalloc.128:4730880

kalloc.256:5365760

kalloc.512:1961984

kalloc.1024:2105344

kalloc.2048:1331200

kalloc.4096:2658304

kalloc.8192:3129344

ipc ports:4290534864

semaphores:1886281920

threads:1930600

uthreads:1143856

vnodes:21401160

namecache:8208960

HFS node:26396128

HFS fork:7200768

cluster_write:4419360

buf.4096:2551808

buf.8192:97034240

ubc_info zone:3929688

pfrkentry:2338848

vnode pager structur:2186880

Kernel Stacks:3604480

PageTables:74792960

Kalloc.Large:20237339

Backtrace suspected of leaking: (outstanding bytes: 690624)

0xffffff8003e43d29

0xffffff8003e15769

0xffffff8003e339c3

0xffffff8003e566bc

0xffffff8003e20b3d

0xffffff8003e10448

0xffffff8003e1961b

0xffffff8003ea6536

last loaded kext at 167506238195: com.apple.filesystems.smbfs 1.8.4 (addr 0xffffff7f86078000, size 229376)

last unloaded kext at 125891310058: com.apple.driver.AppleIntel8254XEthernet 3.1.1b1 (addr 0xffffff7f84982000, size 69632)

loaded kexts:

com.apple.filesystems.smbfs 1.8.4

com.apple.driver.AudioAUUC 1.60

com.apple.driver.AppleHWSensor 1.9.5d0

com.apple.filesystems.autofs 3.0

com.apple.iokit.IOBluetoothSerialManager 4.1.4f2

com.apple.driver.AppleTyMCEDriver 1.0.2d2

com.apple.driver.AGPM 100.12.87

com.apple.driver.AppleMikeyHIDDriver 122

com.apple.driver.AppleHDA 2.3.7fc4

com.apple.driver.AppleUSBDisplays 357

com.apple.driver.AppleUpstreamUserClient 3.5.10

com.apple.driver.AppleMCCSControl 1.1.11

com.apple.kext.AMDFramebuffer 8.1.2

com.apple.iokit.IOUserEthernet 1.0.0d1

com.apple.driver.AppleMikeyDriver 2.3.7fc4

com.apple.AMDRadeonAccelerator 1.0.8

com.apple.Dont_Steal_Mac_OS_X 7.0.0

com.apple.iokit.BroadcomBluetoothHCIControllerUSBTransport 4.1.4f2

com.apple.driver.ApplePolicyControl 3.4.5

com.apple.driver.AppleLPC 1.6.0

com.apple.driver.ACPI_SMC_PlatformPlugin 1.0.0

com.apple.driver.AppleRAID 4.0.6

com.apple.driver.XsanFilter 404

com.apple.iokit.IOAHCIBlockStorage 2.3.1

com.apple.driver.Oxford_Semi 3.1.7

com.apple.iokit.SCSITaskUserClient 3.5.5

com.apple.AppleFSCompression.AppleFSCompressionTypeDataless 1.0.0d1

com.apple.AppleFSCompression.AppleFSCompressionTypeZlib 1.0.0d1

com.apple.BootCache 34

com.apple.driver.AppleFWOHCI 4.9.6

com.apple.driver.AppleUSBHub 5.5.5

com.apple.driver.AirPort.Brcm4331 615.20.17

com.apple.driver.Intel82574L 2.3.0b5

com.apple.driver.AppleAHCIPort 2.5.2

com.apple.driver.AppleUSBEHCI 5.5.0

com.apple.driver.AppleUSBUHCI 5.2.5

com.apple.driver.AppleEFINVRAM 1.7

com.apple.driver.AppleRTC 1.5

com.apple.driver.AppleHPET 1.8

com.apple.driver.AppleACPIButtons 1.7

com.apple.driver.AppleSMBIOS 1.9

com.apple.driver.AppleACPIEC 1.7

com.apple.driver.AppleAPIC 1.6

com.apple.driver.AppleIntelCPUPowerManagementClient 196.0.0

com.apple.nke.applicationfirewall 4.0.39

com.apple.security.quarantine 2.1

com.apple.driver.AppleIntelCPUPowerManagement 196.0.0

com.apple.kext.triggers 1.0

com.apple.iokit.IOSerialFamily 10.0.6

com.apple.driver.DspFuncLib 2.3.7fc4

com.apple.iokit.IOAudioFamily 1.8.9fc11

com.apple.kext.OSvKernDSPLib 1.6

com.apple.iokit.IOSurface 86.0.4

com.apple.iokit.IOBluetoothFamily 4.1.4f2

com.apple.iokit.IOAcceleratorFamily 74.5.1

com.apple.driver.AppleSMBusController 1.0.11d0

com.apple.driver.AppleSMBusPCI 1.0.11d0

com.apple.iokit.AppleBluetoothHCIControllerUSBTransport 4.1.4f2

com.apple.driver.AppleHDAController 2.3.7fc4

com.apple.iokit.IOHDAFamily 2.3.7fc4

com.apple.driver.AppleGraphicsControl 3.4.5

com.apple.iokit.IONDRVSupport 2.3.7

com.apple.kext.AMD5000Controller 8.1.2

com.apple.kext.AMDSupport 8.1.2

com.apple.iokit.IOGraphicsFamily 2.3.7

com.apple.iokit.IOFireWireIP 2.2.5

com.apple.driver.AppleSMC 3.1.4d2

com.apple.driver.IOPlatformPluginLegacy 1.0.0

com.apple.driver.IOPlatformPluginFamily 5.3.0d51

com.apple.driver.AppleUSBHIDKeyboard 170.2

com.apple.driver.AppleHIDKeyboard 170.2

com.apple.driver.AppleUSBMergeNub 5.5.5

com.apple.iokit.IOSCSIReducedBlockCommandsDevice 3.5.5

com.apple.driver.AppleUSBHIDMouse 175.8

com.apple.iokit.IOUSBHIDDriver 5.2.5

com.apple.driver.AppleHIDMouse 175.8

com.apple.driver.AppleUSBComposite 5.2.5

com.apple.iokit.IOSCSIBlockCommandsDevice 3.5.5

com.apple.iokit.IOFireWireSerialBusProtocolTransport 2.1.1

com.apple.iokit.IOFireWireSBP2 4.2.2

com.apple.iokit.IOSCSIMultimediaCommandsDevice 3.5.5

com.apple.iokit.IOBDStorageFamily 1.7

com.apple.iokit.IODVDStorageFamily 1.7.1

com.apple.iokit.IOCDStorageFamily 1.7.1

com.apple.iokit.IOAHCISerialATAPI 2.5.1

com.apple.iokit.IOSCSIArchitectureModelFamily 3.5.5

com.apple.iokit.IOFireWireFamily 4.5.5

com.apple.iokit.IOUSBUserClient 5.5.5

com.apple.iokit.IO80211Family 530.4

com.apple.iokit.IONetworkingFamily 3.0

com.apple.iokit.IOAHCIFamily 2.3.1

com.apple.iokit.IOUSBFamily 5.6.0

com.apple.driver.AppleEFIRuntime 1.7

com.apple.iokit.IOHIDFamily 1.8.1

com.apple.iokit.IOSMBusFamily 1.1

com.apple.security.sandbox 220.3

com.apple.kext.AppleMatch 1.0.0d1

com.apple.security.TMSafetyNet 7

com.apple.driver.DiskImages 345

com.apple.iokit.IOStorageFamily 1.8

com.apple.driver.AppleKeyStore 28.21

com.apple.driver.AppleACPIPlatform 1.7

com.apple.iokit.IOPCIFamily 2.7.3

com.apple.iokit.IOACPIFamily 1.4

com.apple.kec.corecrypto 1.0

Model: MacPro5,1, BootROM MP51.007F.B03, 4 processors, Quad-Core Intel Xeon, 3.2 GHz, 16 GB, SMC 1.39f11

Graphics: ATI Radeon HD 5770, ATI Radeon HD 5770, PCIe, 1024 MB

Memory Module: DIMM 1, 4 GB, DDR3 ECC, 1066 MHz, 0x802C, 0x31384A53463531323732415A2D3147344431

Memory Module: DIMM 2, 4 GB, DDR3 ECC, 1066 MHz, 0x802C, 0x31384A53463531323732415A2D3147344431

Memory Module: DIMM 3, 4 GB, DDR3 ECC, 1066 MHz, 0x802C, 0x31384A53463531323732415A2D3147344431

Memory Module: DIMM 4, 4 GB, DDR3 ECC, 1066 MHz, 0x802C, 0x31384A53463531323732415A2D3147344431

AirPort: spairport_wireless_card_type_airport_extreme (0x14E4, 0x8E), Broadcom BCM43xx 1.0 (5.106.98.100.17)

Bluetooth: Version 4.1.4f2 12041, 2 service, 11 devices, 1 incoming serial ports

Network Service: Ethernet 1, Ethernet, en0

PCI Card: ATI Radeon HD 5770, sppci_displaycontroller, Slot-1

Serial ATA Device: HL-DT-ST DVD-RW GH61N

Serial ATA Device: WDC WD1001FALS-41Y6A1, 1 TB

Serial ATA Device: Hitachi HDS722020ALA330, 2 TB

USB Device: hub_device, apple_vendor_id, 0x9130, 0xfa200000 / 2

USB Device: Apple Optical USB Mouse, apple_vendor_id, 0x0304, 0xfa210000 / 5

USB Device: Keyboard Hub, apple_vendor_id, 0x1006, 0xfa230000 / 4

USB Device: Apple Keyboard, apple_vendor_id, 0x024f, 0xfa232000 / 6

USB Device: Apple Cinema Display, apple_vendor_id, 0x9222, 0xfa220000 / 3

USB Device: BRCM2046 Hub, 0x0a5c (Broadcom Corp.), 0x4500, 0x5a100000 / 2

USB Device: Bluetooth USB Host Controller, apple_vendor_id, 0x8215, 0x5a110000 / 3

USB Device: TRIPP LITE UPS, 0x09ae (Tripp Lite), 0x2007, 0x3d100000 / 2

FireWire Device: unknown_device, OWC Mercury Elite-AL Pro RAID, 800mbit_speed

FireWire Device: built-in_hub, 800mbit_speed

FireWire Device: OXFORD IDE Device, KANO TECH, 800mbit_speed

Reply

Answer 3

Linc Davis

Level 10

209,547 points

Aug 16, 2013 8:22 PM in response to Steve Rhyne

Please take these steps when you notice the problem.

Launch the Activity Monitor application in any of the following ways:

☞ Enter the first few letters of its name into a Spotlight search. Select it in the results (it should be at the top.)

☞ In the Finder, select Go ▹ Utilities from the menu bar, or press the key combination shift-command-U. The application is in the folder that opens.

☞ Open LaunchPad. Click Utilities, then Activity Monitor in the icon grid.

Select All Processes from the menu in the toolbar, if not already selected.

From the top menu bar, select

View ▹ Columns ▹ # Ports

if not already selected. Click the heading of the Ports column in the process table to sort the entries by port usage. You may have to click it twice to get the highest value at the top. What is it, and what is the process?

Reply

Answer 4

Steve Rhyne Author

Level 1

56 points

Aug 17, 2013 8:57 AM in response to Linc Davis

Thanks for whatever insights you can offer, Linc. Here are the five processes using the most ports as of this morning. The server has been running for roughly 18 hours since the last kernel panic / reboot:

PID	PROCESS NAME	%CPU	THREADS	REAL MEM	KIND	PORTS
26	opendirectoryd	0.0	6	21.1 MB	Intel (64 bit)	1,008
4491	loginwindow	0.0	2	19.8 MB	Intel (64 bit)	300
325	launchd	0.0	2	2.4 MB	Intel (64 bit)	272
1	launchd	0.0	3	2.6 MB	Intel (64 bit)	270
775	coreaudiod	0.0	3	6.8 MB	Intel (64 bit)	269

Reply

Answer 5

Linc Davis

Level 10

209,547 points

Aug 17, 2013 9:20 AM in response to Steve Rhyne

Are you still getting the log messages?

Reply

Answer 6

Steve Rhyne Author

Level 1

56 points

Aug 17, 2013 10:39 AM in response to Linc Davis

There haven't been any entries since yesterday's kernel panic / restart. The entries seem to come in gigantic spurts. The last spurt was yesterday right before the kernel panic / restart. I tried to count the entires in the log by copying and pasting into a text editor with a line count function, but there are so many of them, it's impossible. By counting log pages of the error in Console, I can estimate well over a million entries before the kernel panic / restart.

The only entries in the Apache error_log prior to the start of the clock_get_time() failed: (ipc/rcv) invalid name errors are a bunch of innocuous "file does not exist" entries for about a day and half. (This is an academic server with a lot of student web sites, so those kinds of errors are common.)

Meanwhile, in an effort to put a "band aid" on the situation, I've taken this article's advice and set up Apache log rotation:

http://codedmemes.com/lib/newsyslog-automatic-log-rotation/

It worked as expected, so fresh Apache logs will start every night at 12:30 AM. I believe the log rotation also results in a "graceful" Apache restart. That might help with the kernel panics, too, at least in the short term, but only time will tell.

Reply

Answer 7

Linc Davis

Level 10

209,547 points

Aug 17, 2013 11:21 AM in response to Steve Rhyne

The kernel panics are not caused by the log filling. Something seems to have been leaking IPC ports and causing both the panics and the log filling. If it happens again, please repeat the last test and post the results. You're looking for a process that binds an inordinate number of ports, much more than what you showed.

Reply

Answer 8

Steve Rhyne Author

Level 1

56 points

Aug 18, 2013 2:05 PM in response to Linc Davis

Here's another sample taking today around 2 PM today (Sunday). The httpd process seems to be using a heck of a lot of "ports" and that is the process mentioned in the kernel panic reports:

PID	PROCESS NAME	%CPU	THREADS	REAL MEM	KIND	PORTS
9669	httpd	0.0	2	10.3 MB	Intel (64 bit)	129,688
9666	httpd	0.0	2	9.4 MB	Intel (64 bit)	18,835
26	opendirectoryd	0.0	10	21.5 MB	Intel (64 bit)	1,064
1	launchd	0.0	3	2.6 MB	Intel (64 bit)	368
5121	loginwindow	0.0	2	19.6 MB	Intel (64 bit)	300

There have been no "clock_get_time()" errors in the Apache error_log since before the last kernel panic on Friday afternoon.

Reply

Answer 9

Steve Rhyne Author

Level 1

56 points

Aug 18, 2013 2:16 PM in response to Steve Rhyne

And now, less than 10 minutes later, I checked again and the top five are:

PID	PROCESS NAME	%CPU	THREADS	REAL MEM	KIND	PORTS
9666	httpd	0.0	2	9.8 MB	Intel (64 bit)	47,368
26	opendirectoryd	0.0	9	21.5 MB	Intel (64 bit)	1,047
1	launchd	0.0	3	2.6 MB	Intel (64 bit)	343
5121	loginwindow	0.0	2	19.6 MB	Intel (64 bit)	300
325	launchd	0.0	2	2.9 MB	Intel (64 bit)	286

So the httpd process that was using 129,688 ports (PID 9669) is no longer in the top five. So I checked all of the httpd processes. There are three of them:

PID	PROCESS NAME	USER	%CPU	THREADS	REAL MEM	KIND	PORTS
9669	httpd	_www	0.0	2	10.2 MB	Intel (64 bit)	0
285	httpd	root	0.0	1	14.7 MB	Intel (64 bit)	24
9666	httpd	_www	0.0	2	9.8 MB	Intel (64 bit)	47,368

So it has dropped to zero. Do you know if it's normal for there to be three httpd processes?

FYI: Still no "clock_get_time()" errors since the last kernel panic / restart on Friday afternoon.

Reply

Answer 10

Linc Davis

Level 10

209,547 points

Aug 18, 2013 2:58 PM in response to Steve Rhyne

It's normal to have more than one httpd process. It looks like you're triggering a port-leak bug in Apache, but unfortunately, that's about all I can tell you. I'm no expert on it. Maybe you've installed a non-standard module. If you're running a public web server, maybe it's under attack. Try asking a question in an Apache user forum.

Edit: Anything can happen with PHP.

Reply

Answer 11

Steve Rhyne Author

Level 1

56 points

Aug 21, 2013 9:27 AM in response to Steve Rhyne

FYI to those who might have interest in this discussion:

There hasn't been a kernel panic or any "clock_get_time()" errors for five days now, and although I still occasionally see httpd processes in Activity Monitor that are using ports in the 100K+ range, they always disappear on their own. I'm attributing this stability to one of two steps that I've taken:

1) I implemented nightly (midnight) Apache log rotation which, by necessity, "gracefully" restarts Apache at the same time each night. This may or may not be contributing to the solution.

http://codedmemes.com/lib/newsyslog-automatic-log-rotation/

2) I installed and configured IceFloor to protect against attacks, including "emerging threats". 10.8 Server's adaptive firewall just wasn't working as advertised.

http://www.hanynet.com/icefloor/

I'm attributing one or both of these steps to solving or at least staving off the httpd-related kernel panics / restarts.

Reply

Answer 12

Steve Rhyne Author

Level 1

56 points

Sep 16, 2013 12:20 PM in response to Steve Rhyne

I thought I'd follow up with some new developments just in case anyone out there runs into the same problem:

The problem returned again on 9/6 and again five days later on 9/11. I have a new theory for the cause and have attempted another solution:

Our server's primary website uses PHP iCalendar. While digging around this time I noticed that the "clock_get_time() failed: (ipc/rcv) invalid name" messages started filling the error log within seconds of a web bot / crawler loading a URL from the PHP iCalendar directory. In one case, it started at the exact same second.

So I added a robots.txt file to the root of our site, instructing cooperative bots / crawlers to ignore our PHP iCalendar subdirectory.

Time will tell if this solves the problem.

Reply