Logging
servedat produces a log of individual transactions, errors, and state changes. This information is vital to diagnosing problems, and can also be used to generate usage statistics and inform other processes of the state of transactions.
Logging output normally consists of UTF-8 encoded character lines in the format described below. Enabling Debugging may cause non-UTF-8 data to be written to the logs. See the Unicode section for more information about ExpeDat character encoding.
Log Locations
When servedat is run from a terminal or command shell, logs are sent to stderr by default.
Windows: If servedat is run as a Windows Service, it will default to writing diagnostics to the following path. You can also find this by following the "Shortcut to servedat.log" shortcut found in the "Server Files" folder of the installation package.
C:\ProgramData\DEI\servedat.log
All Others: If servedat is run as a root daemon in unix it will default to writing diagnostic output to the following path:
/var/log/servedat.log
To redirect logs to a file or pipe, use the -l command line option or the LogFile configuration variable. The argument can be a pathname, or the number "1" to specify stdout, or the number "2" to specify stderr. For example, the following commands both redirect output to the file "/tmp/servedat.log".
# servedat -l 1 >> /tmp/servedat.log C 20211207 14:35:52.643 servedat 1.20.0 "December 2021" DEI [24378] C 20211207 14:35:52.643 Switching logs to <stdout> # servedat -l /tmp/servedat.log C 20211207 14:36:17.898 servedat 1.20.0 "December 2021" DEI [24401] C 20211207 14:36:17.898 Switching logs to /tmp/servedat.log
The -l and LogFile options are processed as soon as they are found, so multiple declarations may cause the logfile to change multiple times during startup. Since command line options are processed first and have priority over configuration files, the best practice is to use "-l" to send logging output to your intended destination as soon as possible.
Example
V 20220222 13:30:35.751 servedat 1.20.0 "December 2021" DEI [160] (8080) C 20220222 13:30:35.755 (C)2021 Data Expedition, Inc.(R) US Pat. 7158479,7313627,7404003,7630315 C 20220222 13:30:35.755 servedat - 1.20.0 December 2021 - DEI, DOC-2.3.7 MTP-osx-4.4.0 3969 C 20220222 13:30:35.755 00000001: ExpeDat-1.20A Data Expedition Inc., DataExpedition.com C 20220222 13:30:35.783 Default Home: /Library/WebServer/Documents/downloads/ S 20220222 13:30:35.784 Load Current: 0, MaxConfig: 0, MaxStart: 0, TotalStart: 0, Errors: 0, Failures: 0, Warnings: 0, Denials: 0, Capacity Exceeded: 0, Bytes In: 0, Out: 0, Bandwidth In: 0, Out: 0 , Bad Checksums: 0, Bad Headers: 0 I 20220222 14:46:35.130 F5FBCE5C GET 10.72.0.7:49928 jdoe AES "tst/" "" F 20220222 14:46:35.131 F5FBCE5C GET 10.72.0.7:49928 jdoe AES "tst/" "" 256 (0,0) "0.00 seconds (2.05 megabits/sec)" I 20220222 14:46:38.883 F5FBCE5D GET 10.72.0.7:61412 jdoe AES "tst/test5gb.dat" "" P 20220222 14:51:38.884 F5FBCE5D GET 10.72.0.7:61412 jdoe AES "tst/test5gb.dat" "" 3522775013 5368709120 "300.01 seconds (93.7 megabits/sec)" 1 F 20220222 14:53:30.200 F5FBCE5D GET 10.72.0.7:61412 jdoe AES "tst/test5gb.dat" "" 5368709120 (0,0) "7.62 minutes (94.0 megabits/sec)" S 20220222 13:40:35.803 Load Current: 0, MaxConfig: 1, MaxStart: 1, TotalStart: 2, Errors: 0, Failures: 0, Warnings: 0, Denials: 0, Capacity Exceeded: 0, Bytes In: 0, Out: 5368709376, Bandwidth In: 0, Out: 0 , Bad Checksums: 0, Bad Headers: 0
Line Format
The purpose and format of each line is determined by the first character, the record type. All lines begin with the type, followed by the date and time, and then the log message:
[Type] [Date] [Time] [Message]
| Type | A single character denoting the type of message: |
| C | Comment or Configuration note. |
| D | Diagnostic output. |
| E | General server error. |
| F | The final disposition of an action. There will be exactly one of these per action. |
| I | Initiation of an action which has not yet completed. There will be at most one of these per action. |
| M | Message from one of the MTP libraries. |
| P | A progress update for an ongoing transaction. These occur at intervals of LogProgress seconds. |
| R | A session report from a client. |
| S | A status update showing server load and transaction counts. These occur at intervals of LogStatus seconds while the server is active. See the Monitoring section for details. |
| T | Message from one of the application toolkit libraries. |
| V | Version and process id, displayed once at each startup. |
| W | Warning or detailed error regarding an action in progress. |
| Date | Eight characters giving the year, month, and day as YYYYMMDD |
| Time | Twelve characters giving the hour, minute, seconds, and milliseconds in local time as "HH:MM:SS.mmm". You can adjust the time zone by setting the TZ environment variable. For example, placing "export TZ=UTC" in the servedat.rc launch script will switch servedat to logging in UTC. |
| Message | The message format will vary for C, D, E, M, and W. I, P, F, and S type messages conform to the format below. |
Particular attention should be paid to all E, M, T, and W messages as these may indicate improper operation.
Transaction Logs
Messages pertaining to the life-cycle of a transaction, I, P F, and R, share a common identifying prefix:
DocID SEND|GET Client User Encrypt "Path" "Action"
For example,
I 20240222 14:46:38.883 F5FBCE5D GET 10.72.0.7:61412:D jdoe AES "tst/test5gb.dat" "" P 20240222 14:51:38.884 F5FBCE5D GET 10.72.0.7:61412:D jdoe AES "tst/test5gb.dat" "" 3522775013 5368709120 "300.01 seconds (93.7 megabits/sec)" 1 F 20240222 14:53:30.200 F5FBCE5D GET 10.72.0.7:61412:D jdoe AES "tst/test5gb.dat" "" 5368709120 (0,0) "7.62 minutes (94.0 megabits/sec)"
This prefix uniquely identifies the transaction and describes what it is doing:
| DocID | An 8 character hexadecimal transaction identifier. No two transactions can have the same DocID at the same time, and IDs will not be reused for a long time. |
| SEND|GET | Incoming documents are be labeled "SEND". Outgoing documents and most actions are labeled "GET". |
| Client | The IP address, UDP port number, and client type of the client application, separated by colons. Common client types are: (D) ExpeDat Desktop, (U) DropDat, (M) movedat, (W) WebDat, (P) mtping, (S) syncdat, and (I) iOS Mobile. |
| User | The username used for authentication, or "-" if none was provided. |
| Encrypt | The content encryption method, or "-" if none was used. |
| Path | The pathname of the local file target. This may be absolute or relative to the applicable home directory. |
| Action | For actions or object handler requests, the specifier used to process the document will appear here. |
| Offset | The starting byte of this transaction. A non-zero value occurs when resuming a previous file transfer. |
(I) Initial lines mark the successful start of a transaction and contain only the identifying information. Transactions which fail immediately (such as due to a bad password) may skip the I and only display an F line.
(P) Progress lines occur at intervals of LogProgress seconds during long running transactions and have additional fields in the form: Progress Size "Duration (Speed)" Load
| Progress | The amount of network data transferred up to this point. |
| Size | The full size of the data, if this is known. Transactions involving compression, streaming, object handlers, or actions may set this field to 0. |
| Duration | The time elapsed so far. |
| Speed | The average network speed since the last update. |
| Load | The current server load. |
(F) Final lines occur at the end of every transaction and have additional fields in the form: Transfer (Class,Error) "Comment"
| Transfer | The amount of network data transferred up to the point of the log. If an error has occurred, this value may only be approximate or it may be given as "-" if a value is not known. Note that if a transfer is compressed or resumed, the amount here may be much less than the size of the file on disk. |
| Class | Zero for successes, otherwise an MTP/IP error class, indicating the source of the error. Most errors will be class "-4", indicating that servedat itself is reporting the error. |
| Error | Zero for successes, otherwise an MTP/IP error code, indicating the type of error. See DEI Tech Note 0013 for information about error classes and codes. |
| Comment | A human readable string describing the result. On success it will show the time elapsed and overall transfer rate. On failure, it will show an error message. |
(R) Report lines are created by client software, including syncdat, to provide information about sessions or other commentary. The "Path" portion of an R record contains the client's report which should be in the following format: Client-Version Operation UUID Message
| Client | The client type, such as "movedat" or "syncdat". |
| Version | The version number of the client executable. |
| Operation | The type of operation being reported. |
| UUID | A unique string matching this R record to others from the same operation. |
| Message | The remainder of the report depends on the client. See its documentation for details. |
Report lines are triggered using the built-in server action code "*rp".
Server Status
(V) Version lines occur when the server is first started or reloaded and can be useful in identifying server updates. It shows the servedat component version, publication date, process ID and UDP port number. It is usually followed by several C lines showing package and license informaion. For example:
V 20220222 13:30:35.751 servedat 1.20.0 "December 2021" DEI [160] (8080) C 20220222 13:30:35.755 (C)2021 Data Expedition, Inc.(R) US Pat. 7158479,7313627,7404003,7630315 C 20220222 13:30:35.755 servedat - 1.20.0 December 2021 - DEI, DOC-2.3.7 MTP-osx-4.4.0 3969 C 20220222 13:30:35.755 00000001: ExpeDat-1.20A Data Expedition Inc., DataExpedition.com
(S) Status lines occur at intervals of LogStatus seconds while the server is active and consist of the following comma separated fields:
| Load Current: | The current number of active transactions. |
| MaxConfig: | The peak load since the last configuration reload. |
| MaxStart: | The peak load since the last restart. |
| TotalStart: | The total number of transactions attempted since startup. |
| Errors: | The number of server errors since startup. If this number is non-zero, look for 'E' logs and correct any problems. Approximately equals the number of 'E' log entries. |
| Failures: | The number of transactions which started, but then failed before completion. |
| Warnings: | The number of server or transaction warnings issued since startup. Approximately equals the number of 'W' log entries. |
| Denials: | The number of transactions which were rejected due to authentication or other configuration issues. |
| Capacity Exceeded: | The number of transactions which were rejected because the Load had already reached the server's capacity. These events are also included in the Denials count. |
| Bytes In: Out: | The total bytes of data transferred in and out since the last configuration change. |
| Bandwidth In: Out | The bandwidth consumed incoming and outgoing averaged over the previous minute, in bits per second. |
| Bad Checksums | The number of datagrams dropped due to bad checksums. |
| Bad Headers | The number of datagrams dropped due to improperly formatted headers. |
Other Messages
The remaining message types, C D E M T and W provide additional diagnostic or commentary information about server operation or individual transactions. Warnings and Errors which are specific to a transaction will usually include its DocID and may include the entire transaction log prefix.
Log Filtering
By default, servedat logs the successful initiation and any completion for all transactions. You may reduce the amount of logging by setting the LogFilter level. This may be desirable if logs are being written to slow storage or parsed by another process, and high volume is impeding performance. Filtering applies first to "bulk" transactions such as SyncDat synchronizations and one-at-a-time directory transfers. At higher levels, it will be applied to regular transactions as well. The default filtering level is 0 (no filtering).
| 0 | No filtering: at least one line of output will be logged for every transaction. |
| 1 | Initiation of bulk transactions will not be logged. |
| 2 | Success reports for bulk transactions will also be suppressed. Bulk errors will still be reported. |
| 3 | All initiation lines and bulk successes will be suppressed. |
| 4 | Only errors will be logged. |
| 5 | Only server-wide and non-bulk errors will be logged. |
| 6 | Only server-wide errors will be logged |
Setting a debug level of 1 or higher will automatically reset LogFilter to level 0.
Log Rotation
During startup, servedat will check the size of the specified log file and rotate it if it has grown larger than LogRotate megabytes. Rotation consists of renaming the existing log file with the local date and time, then starting a new log file.
On unix systems, sending the HUP signal to a running servedat process will cause it to restart and reload all of its configuration settings. This includes closing and reopening the log file. If the existing log file has grown beyond the LogRotate limit, it will be rotated. You can manually rotate the log file by renaming it prior to sending HUP. Note that any active transactions will be interrupted by a HUP restart.
Diagnostics
If you experience difficulties configuring or communicating with the server, the servedat logs will provide important information about what happened. Each time servedat is started, it will display a V line indicating its version, process id, and network port. Whenever a log file is specified or diagnostic output is enabled, servedat will also display a list of all configuration settings and their origins. For example:
D 20220222 13:30:35.781 Configuration settings: D 20220222 13:30:35.781 AllowPath 4 System D 20220222 13:30:35.781 [-A] AuthFile 13 System /etc/svpasswd D 20220222 13:30:35.781 AuthReload 1 Default D 20220222 13:30:35.781 AuthHashes 18 Default clear,crypt,sha256 D 20220222 13:30:35.781 [-b] StreamSize 65536 Default D 20220222 13:30:35.781 [-c] Capacity 10 License D 20220222 13:30:35.781 [-d] Debug 0 System D 20220222 13:30:35.781 [-F] LogFilter 0 Default D 20220222 13:30:35.781 [-I] LogProgress 300 Default D 20220222 13:30:35.781 [-J] LogStatus 600 Default D 20220222 13:30:35.781 [-l] LogFile 27 System /usr/local/log/servedat.log D 20220222 13:30:35.781 LogRotate 25 Default D 20220222 13:30:35.781 [-M] FileMode 420 Default D 20220222 13:30:35.781 [-p] Port 8080 Default D 20220222 13:30:35.781 [-V] ServiceName 8 Default servedat D 20220222 13:30:35.781 [-S] SysAuth 1 System D 20220222 13:30:35.783 AllowEncrypt 1 Default D 20220222 13:30:35.783 HomeDir 39 System /Library/WebServer/Documents/downloads/
See the Troubleshooting section for common errors and warnings. Setting Debug level 1 will display additional diagnostic information as well as performance statistics which can be interpreted using Tech Note 0036.
If you need assistance, copy and compress the entire log file and submit a Technical Support Request. See Tech Note 0037 for best TSR practices to ensure a speedy resolution.